Mail Archives: cygwin/2012/02/11/12:24:53
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."
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
- Raw text -