Re: File operations really slow in emacs

[Ryan Johnson <ryan dot johnson at cs dot utoronto dot ca>]

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