emacs-x11 takes 30-40 sec to open after upgrading to cygwin-1.7

[Markus Hoenicka]

Dan Tsafrir <dants@cs.technion.ac.il> was heard to say:

> The two numbers at the beginning of each strace output line (like the
> ones you quoted above) answer this question. I believe the first
> number is elapsed microseconds since the previous line and the second
> number is elapsed microseconds since the beginning of the run.
>
> If this is correct then the block above takes about 8ms. Note,
> however, that the strace log of xclock's startup is comprised of
> 414,669 lines, a fact that coincides with the several minutes it has
> taken the straced xclock to open.
>

Oh, I see. I never could make sense of those numbers. I've noticed  
that the problem is not 100% reproducible here. I've tried this quite  
often today, restarted the X server, tried again and so on. Sometimes  
xterm starts up fairly quick, but more often than not it starts up  
with a huge delay. Also, I've noticed that writing a log to a file  
with "strace -o file xterm", or even with "strace xterm|tee file" does  
not correctly show the kind of delay I was talking about. The  
following snippet is copied+pasted from MinTTY after running "strace  
xterm":

7551448 12884434 [main] xterm 3524 readv: readv (5, 0x2295C4, 1)  
blocking, sigcatchers 0
    59 12884493 [main] xterm 3524 readv: no need to call ready_for_read
   211 12884704 [main] xterm 3524 fhandler_base::read: returning  
65536, binary mode
    45 12884749 [main] xterm 3524 readv: 65536 = readv (5, 0x2295C4,  
1), errno 2
8089730 20974479 [main] xterm 3524 readv: readv (5, 0x2295C4, 1)  
blocking, sigcatchers 0
    57 20974536 [main] xterm 3524 readv: no need to call ready_for_read
   213 20974749 [main] xterm 3524 fhandler_base::read: returning  
65536, binary mode
    43 20974792 [main] xterm 3524 readv: 65536 = readv (5, 0x2295C4,  
1), errno 2
7699688 28674480 [main] xterm 3524 readv: readv (5, 0x2295C4, 1)  
blocking, sigcatchers 0
    62 28674542 [main] xterm 3524 readv: no need to call ready_for_read
   221 28674763 [main] xterm 3524 fhandler_base::read: returning  
65536, binary mode
    45 28674808 [main] xterm 3524 readv: 65536 = readv (5, 0x2295C4,  
1), errno 2
7870040 36544848 [main] xterm 3524 readv: readv (5, 0x2295C4, 1)  
blocking, sigcatchers 0
    54 36544902 [main] xterm 3524 readv: no need to call ready_for_read
   195 36545097 [main] xterm 3524 fhandler_base::read: returning  
65536, binary mode
    42 36545139 [main] xterm 3524 readv: 65536 = readv (5, 0x2295C4,  
1), errno 2
7927224 44472363 [main] xterm 3524 readv: readv (5, 0x2295C4, 1)  
blocking, sigcatchers 0
    57 44472420 [main] xterm 3524 readv: no need to call ready_for_read
   216 44472636 [main] xterm 3524 fhandler_base::read: returning  
65536, binary mode
    40 44472676 [main] xterm 3524 readv: 65536 = readv (5, 0x2295C4,  
1), errno 2
7598403 52071079 [main] xterm 3524 readv: readv (5, 0x2295C4, 1)  
blocking, sigcatchers 0
    55 52071134 [main] xterm 3524 readv: no need to call ready_for_read
   209 52071343 [main] xterm 3524 fhandler_base::read: returning  
65536, binary mode
    43 52071386 [main] xterm 3524 readv: 65536 = readv (5, 0x2295C4,  
1), errno 2
8083403 60154789 [main] xterm 3524 readv: readv (5, 0x2295C4, 1)  
blocking, sigcatchers 0
    57 60154846 [main] xterm 3524 readv: no need to call ready_for_read
   178 60155024 [main] xterm 3524 fhandler_base::read: returning  
51051, binary mode
    47 60155071 [main] xterm 3524 readv: 51051 = readv (5, 0x2295C4,  
1), errno 2

Please note the readv calls, some of which take around 7-8 seconds. I  
have no idea why those numbers don't show up in logs written directly  
to a file, as the overall startup time appears to be similar in both  
cases.

Anyway, we may be looking at unrelated problems. If you can't see  
readv calls with excessive times while watching the strace output,  
this may not be the cause of your problem. OTOH searching for "open"  
in your and my logs returns 62744 and 381 counts, respectively. This  
is more likely to cause the kind of delay you see.

regards,
Markus


-- 
Markus Hoenicka
http://www.mhoenicka.de
AQ score 38



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