Mail Archives: cygwin/2012/02/11/09:21:43
On 11/02/2012 5:11 AM, Corinna Vinschen wrote:
> On Feb 10 20:18, Ryan Johnson wrote:
>> Hi all,
>>
>> For some reason file operations have become very slow inside emacs
>> starting yesterday. It's especially painful when saving a file
>> that's managed by mercurial (more than 20 seconds!), but I've seen
>> it on the command line as well (x-server takes a similar amount of
>> time to start, for example). I'm running the latest everything and
>> I've run rebaseall. I verified that Windows Defender did not
>> silently re-enable itself since I last disabled it (you can't
>> actually uninstall it) and no other BLODA are present on my machine.
>> The problem persists across reboots.
>>
>> I have vague memories that this has turned up in the past (maybe
>> 12-15 months ago?) but Google isn't turning up anything. Attaching
>> strace to emacs during the save makes it take a full 35 seconds and
>> reports the following:
>>
>> $ cat emacs.strace | awk '{if ($1> 1000000) { print }}' | grep -v
>> timer_thread
>> 26910790 26912157 [main] emacs-X11 5188 child_copy: dll bss - hp
>> 0x264 low 0x611FC000, high 0x61230770, res 1
>> 1128419 2125655 [main] python2.6 5188 read: read(5, 0x8009DB60,
>> 65536) blocking
>> 25850184 32830582 [main] python2.6 5188 stat_worker: 0 =
>> (\??\C:\cygwin\cygdrive,0x28BB68)
> ^^^^^^^^^^^^^^^^^^^^^^^
> This looks suspicious. I assume you're suffering from SMB network
> scanning.
Hmm. I'm feeling both confused and enlightened now...
1. What about child_copy? (see below)
2. Running that same stat operation from the shell is equally painful:
$ time strace -mall -o stat.strace stat /cygdrive
File: `/cygdrive'
Size: 0 Blocks: 0 IO Block: 65536 directory
Device: 620000h/6422528d Inode: 2 Links: 4
Access: (0555/dr-xr-xr-x) Uid: ( 1000/ Ryan) Gid: ( 513/ None)
Access: 2012-02-11 09:17:12.000000000 -0500
Modify: 2012-02-11 09:17:12.000000000 -0500
Change: 2006-11-30 19:00:00.000000000 -0500
Birth: 2006-11-30 19:00:00.000000000 -0500
real 0m26.186s
user 0m0.030s
sys 0m0.015s
3. How might I diagnose what network activity could be the culprit? I
didn't think I was hosting or mounting any SMB shares... and certainly
not through cygwin (Q: below is my ThinkPad's recovery partition):
$ mount
C:/cygwin/bin on /usr/bin type ntfs (binary,auto)
C:/cygwin/lib on /usr/lib type ntfs (binary,auto)
C:/cygwin on / type ntfs (binary,auto)
C: on /cygdrive/c type ntfs (binary,posix=0,user,noumount,auto)
Q: on /cygdrive/q type ntfs (binary,posix=0,user,noumount,auto)
Thoughts?
Ryan
=== More details about #1 ===
So, what about the 26.9s call to child_copy? I ran a few more times and
the two don't strike me as strongly correlated. It's more like the true
cause sometimes hits both together:
$ strace -mall -p $(pgrep emacs) | awk '{if ($1 > 1000000) { print }}' |
grep -v timer_thread
[-- open hg-managed file -- ]
25799065 25801126 [main] emacs-X11 8016 child_copy: dll bss - hp 0x288
low 0x611FC000, high 0x61230770, res 1
32048267 32049470 [main] emacs-X11 7584 child_copy: dll bss - hp 0x278
low 0x611FC000, high 0x61230770, res 1
1127799 1841167 [main] python2.6 7584 read: read(5, 0x8009DB60, 65536)
blocking
1272387 38372453 [main] emacs 7284
fhandler_base_overlapped::wait_overlapped: wfres 0, wores 1, bytes 3
[-- save --]
50382655 50383904 [main] emacs-X11 1248 child_copy: dll bss - hp 0x290
low 0x611FC000, high 0x61230770, res 1
1095874 56238299 [main] emacs 7284
fhandler_base_overlapped::wait_overlapped: wfres 0, wores 1, bytes 16
[-- save --]
87436648 87439221 [main] emacs-X11 7668 child_copy: dll bss - hp 0x278
low 0x611FC000, high 0x61230770, res 1
26064678 31598419 [main] python2.6 7668 stat_worker: 0 =
(\??\C:\cygwin\cygdrive,0x28BB68)
1575028 168999100 [main] emacs 7284 select_stuff::wait: woke up.
wait_ret 2. verifying
[-- save --]
170053330 170056051 [main] emacs-X11 7000 child_copy: dll bss - hp 0x22C
low 0x611FC000, high 0x61230770, res 1
1065439 1965054 [main] python2.6 7000 read: read(5, 0x8009DB60, 65536)
blocking
25893986 30974179 [main] python2.6 7000 stat_worker: 0 =
(\??\C:\cygwin\cygdrive,0x28BB68)
Also, here's a run that traces all mentions of C:\cygwin\cygdrive (this
time I created a new file in an hg-managed dir):
$ strace -mall -p $(pgrep emacs) | awk '/C:.cygwin.cygdrive/ { print }
{if ($1 > 1000000) { print }}' | grep -v timer_thread
41 4893387 [main] emacs 7652 mount_info::conv_to_win32_path:
src_path /cygdrive, dst C:\cygwin\cygdrive, flags 0x3000A, rc 0
36 4910555 [main] emacs 7652 mount_info::conv_to_win32_path:
src_path /cygdrive, dst C:\cygwin\cygdrive, flags 0x3000A, rc 0
34 4957910 [main] emacs 7652 mount_info::conv_to_win32_path:
src_path /cygdrive, dst C:\cygwin\cygdrive, flags 0x3000A, rc 0
9686534 9689074 [main] emacs-X11 5736 child_copy: dll bss - hp 0x27C low
0x611FC000, high 0x61230770, res 1
1063066 1765712 [main] python2.6 5736 read: read(5, 0x8009DB60, 65536)
blocking
33 5904760 [main] python2.6 5736 mount_info::conv_to_win32_path:
src_path /cygdrive, dst C:\cygwin\cygdrive, flags 0x3000A, rc 0
37 5904838 [main] python2.6 5736 stat_worker:
(\??\C:\cygwin\cygdrive, 0x28BB68, 0x612666A4), file_attributes 17
25766283 31671159 [main] python2.6 5736 stat_worker: 0 =
(\??\C:\cygwin\cygdrive,0x28BB68)
25766283 31671159 [main] python2.6 5736 stat_worker: 0 =
(\??\C:\cygwin\cygdrive,0x28BB68)
1368187 42267858 [main] emacs 7652
fhandler_base_overlapped::wait_overlapped: wfres 0, wores 1, bytes 36
42558979 42560468 [main] emacs-X11 7988 child_copy: dll bss - hp 0x26C
low 0x611FC000, high 0x61230770, res 1
1071523 1569246 [main] python2.6 7988 read: read(5, 0x8009DB60, 65536)
blocking
40 5738526 [main] python2.6 7988 mount_info::conv_to_win32_path:
src_path /cygdrive, dst C:\cygwin\cygdrive, flags 0x3000A, rc 0
41 5738609 [main] python2.6 7988 stat_worker:
(\??\C:\cygwin\cygdrive, 0x28BB68, 0x612666A4), file_attributes 17
455 5739102 [main] python2.6 7988 stat_worker: 0 =
(\??\C:\cygwin\cygdrive,0x28BB68)
So... why would python/hg feel a need to look at /cygdrive at all, and
why does looking at it take such a long time?
--
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
- Raw text -