File operations really slow in emacs

[Ryan Johnson]

On 11/02/2012 12:24 PM, Christopher Faylor wrote:
> On Sat, Feb 11, 2012 at 09:21:11AM -0500, Ryan Johnson wrote:
>> 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:
> I don't see anything in the above which indicates a 26.9s call to
> child_copy.  The delta number you see in front of an strace line doesn't
> mean "this is how long this operation took".  It means "this is how long
> it's been since the previous line in the file."
So for situations where cpu usage is ~0% and the latency is measured in 
seconds, is it reasonable to infer that the preceding line with the same 
pid might be the culprit?

Ryan


--
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