Commands slow in wait_sig.

[Christopher Faylor]

On Wed, Aug 03, 2011 at 04:44:29PM +0900, texas salsa wrote:
>
>Hello there,
>
>I use Cygwin to do some complex text processing jobs using shell scripts on Thinkpad X200s Windows XP sp3. It had worked fine before but at some point I noticed the job started to take much time to complete. It is taking about ten times period compare to before. I don't know what had triggered this exactly.
>
>$ while true ;do /usr/bin/date ;done|uniq -c
>????? 1 Wed Aug? 3 16:21:05???? 2011
>????? 1 Wed Aug? 3 16:21:06???? 2011
>????? 1 Wed Aug? 3 16:21:08???? 2011
>????? 1 Wed Aug? 3 16:21:09???? 2011
>????? 1 Wed Aug? 3 16:21:10???? 2011
>????? 2 Wed Aug? 3 16:21:11???? 2011
>????? 1 Wed Aug? 3 16:21:12???? 2011
>$ time date
>Wed Aug? 3 16:23:19???? 2011
>real??? 0m0.905s
>user??? 0m0.077s
>sys???? 0m0.562s
>
>$ uname -a
>CYGWIN_NT-5.1 IBM-8DE0336DAA4 1.7.9(0.237/5/3) 2011-03-29 10:10 i686 Cygwin
>????? 
>So one command take about 1 sec to complete. On other machines with similar configuration the above testing shows about 10 forks/sec on average.
>
>The following is strace date information
>
>?7070??? 9351 [main] date 1780 _cygtls::remove: wait 0xFFFFFFFF
>?? 76??? 9427 [main] date 1780 _cygtls::remove: removed 0x22CE64 element 0
>?? 64??? 9491 [main] date 1780 _cygtls::remove: wait 0xFFFFFFFF
>?? 34??? 9525 [main] date 1780 _cygtls::remove: removed 0x22CE64 element 0
>? 218??? 9743 [sig] date 1780 wait_sig: entering ReadFile loop, my_readsig 0x764, my_sendsig 0x760
>332702? 342445 [main] date 1780 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\admuser, no-keep-rel, no-add-slash)
>?? 80? 342525 [main] date 1780 normalize_win32_path: C:\cygwin\home\admuser = normalize_win32_path (C:\cygwin\home\admuser)
>? 165? 342690 [main] date 1780 mount_info::conv_to_posix_path: /home/admuser = conv_to_posix_path (C:\cygwin\home\admuser)
>?2047? 344737 [main] date 1780 _cygwin_istext_for_stdio: fd 0: not open
>?
>It looks like that "wait_sig: entering ReadFile loop" taking much time
>in the command processing.  So firstly I supposed "Slow performance
>Win7/64" discussion last month may apply to this.  I tested 2011-08-01
>snapshot and it doubled the performance like 2 forks/sec, but wait_sig
>still taking much time and I suspect there is another problem in the
>code or specific problem in my PC.

Nothing in the above indicates that there is a problem in wait_sig.
The delta times in an strace do not mean "This is how long an operation
took".  They just indicate the number of microseconds since the last
update to strace output.

What the above says is:

1) wait_sig is about to call ReadFile.  It has been 9743 microseconds
since strace last reported anytinng.

2) There was a lag of 342445 microseconds before something happened in
main.  That could be symptomatic of the problem which the 8/01 snapshot
works around.  Or not.

If it is only happening on one system that obviously points to BLODA.

cgf

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple