This is the mail archive of the cygwin-xfree mailing list for the Cygwin XFree86 project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

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


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/


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]