Message-ID: <4F367957.8030306@cs.utoronto.ca>
Date: Sat, 11 Feb 2012 09:21:11 -0500
From: Ryan Johnson <ryan DOT johnson AT cs DOT utoronto DOT ca>
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:10.0) Gecko/20120129 Thunderbird/10.0
MIME-Version: 1.0
To: cygwin AT cygwin DOT com
Subject: Re: File operations really slow in emacs
References: <4F35C1E0 DOT 2020308 AT cs DOT utoronto DOT ca> <20120211101158 DOT GC9823 AT calimero DOT vinschen DOT de>
In-Reply-To: <20120211101158.GC9823@calimero.vinschen.de>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
Sender: cygwin-owner AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com

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