On Sat, Feb 11, 2012 at 02:50:31PM -0500, Ryan Johnson wrote:
>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?
It completely depends on what the previous line was. There could be a long
period of frantic activity which was never straced so you can't necessarily
infer anything.
cgf
--
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
