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: