Date: Sat, 11 Feb 2012 16:01:40 -0500
From: Christopher Faylor <cgf-use-the-mailinglist-please AT cygwin DOT com>
To: cygwin AT cygwin DOT com
Subject: Re: File operations really slow in emacs
Message-ID: <20120211210140.GA28967@ednor.casa.cgf.cx>
Reply-To: cygwin AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
References: <4F35C1E0 DOT 2020308 AT cs DOT utoronto DOT ca> <20120211101158 DOT GC9823 AT calimero DOT vinschen DOT de> <4F367957 DOT 8030306 AT cs DOT utoronto DOT ca> <20120211172416 DOT GB26664 AT ednor DOT casa DOT cgf DOT cx> <4F36C687 DOT 7030007 AT cs DOT utoronto DOT ca>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <4F36C687.7030007@cs.utoronto.ca>
User-Agent: Mutt/1.5.20 (2009-06-14)
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
Precedence: bulk
Sender: cygwin-owner AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com

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