This is the mail archive of the cygwin mailing list for the Cygwin project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Re: File operations really slow in emacs


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


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]