X-Recipient: archive-cygwin AT delorie DOT com
X-SWARE-Spam-Status: No, hits=-0.7 required=5.0	tests=AWL,BAYES_00,SPF_NEUTRAL,TO_NO_BRKTS_PCNT
X-Spam-Check-By: sourceware.org
Message-ID: <4F36C687.7030007@cs.utoronto.ca>
Date: Sat, 11 Feb 2012 14:50:31 -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> <4F367957 DOT 8030306 AT cs DOT utoronto DOT ca> <20120211172416 DOT GB26664 AT ednor DOT casa DOT cgf DOT cx>
In-Reply-To: <20120211172416.GB26664@ednor.casa.cgf.cx>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
X-IsSubscribed: yes
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
List-Id: <cygwin.cygwin.com>
List-Subscribe: <mailto:cygwin-subscribe AT cygwin DOT com>
List-Archive: <http://sourceware.org/ml/cygwin/>
List-Post: <mailto:cygwin AT cygwin DOT com>
List-Help: <mailto:cygwin-help AT cygwin DOT com>, <http://sourceware.org/ml/#faqs>
Sender: cygwin-owner AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
Delivered-To: mailing list cygwin AT cygwin DOT com

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