[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
bug#122: 23.0.60; Slowdown in directory scanning over time.
|
From: |
Len Trigg |
|
Subject: |
bug#122: 23.0.60; Slowdown in directory scanning over time. |
|
Date: |
Mon, 01 Sep 2008 09:57:13 +1200 |
|
User-agent: |
Wanderlust/2.15.6 (Almost Unreal) SEMI/1.14.6 (Maruoka) FLIM/1.14.9 (Gojō) APEL/10.7 Emacs/23.0.60 (i686-pc-linux-gnu) MULE/6.0 (HANACHIRUSATO) |
Chong Yidong wrote:
> I can't reproduce this. Do you still see the problem? If so, could you
> try to make a recipe for reproducing the bug?
I updated my emacs to latest CVS last Wednesday (GNU Emacs 23.0.60.1
(i686-pc-linux-gnu, GTK+ Version 2.10.4) of 2008-08-27 on noir), and
evaluated the following lisp code in *scratch*:
(let ((time-initial (current-time))
(files (directory-files "/usr/bin"))
(time-retrieve (current-time)))
(insert "\n")
(insert-date)
(insert (format " %d files took %d seconds to list"
(length files)
(time-to-seconds (time-subtract time-retrieve
time-initial)))))
I repeated it at various times. As you can see below, less than a
week later, there is a huge degradation.
Mon Sep 1, 2008 9:35 AM 2471 files took 30 seconds to list
Mon Sep 1, 2008 9:34 AM 2471 files took 30 seconds to list
Sat Aug 30, 2008 9:03 AM 2471 files took 11 seconds to list
Sat Aug 30, 2008 9:02 AM 2471 files took 11 seconds to list
Thu Aug 28, 2008 11:42 AM 2471 files took 1 seconds to list
Thu Aug 28, 2008 11:35 AM 2471 files took 2 seconds to list
Wed Aug 27, 2008 3:20 PM 2471 files took 0 seconds to list
While waiting for the output, emacs is using 100% CPU.
Here is hopefully the relevant output of strace -T -r -p EMACSPID I
haven't really used the -T and -r before, but I think the first number
in the output shows relative time between invocations, and the last
number in brackets is the time spent in the system call itself, thus
it confirms the time is being spent in emacs, not system calls.
0.000068 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0,
999834}}, NULL) = 0 <0.000018>
0.000313 gettimeofday({1220219283, 414241}, NULL) = 0 <0.000015>
0.000132 open("/usr/bin", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) =
14 <0.000043>
0.000110 fstat64(14, {st_mode=S_IFDIR|0755, st_size=69632, ...}) = 0
<0.000015>
0.000139 fcntl64(14, F_SETFD, FD_CLOEXEC) = 0 <0.000015>
0.000080 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0 <0.000015>
0.000087 gettimeofday({1220219283, 414785}, NULL) = 0 <0.000013>
0.000065 gettimeofday({1220219283, 414850}, NULL) = 0 <0.000014>
0.000067 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0,
998841}}, NULL) = 0 <0.000017>
0.000084 rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0 <0.000014>
0.000091 getdents64(14, /* 125 entries */, 4096) = 4088 <0.000147>
0.196466 gettimeofday({1220219283, 611650}, NULL) = 0 <0.000090>
0.134968 gettimeofday({1220219283, 746638}, NULL) = 0 <0.000101>
0.668723 --- SIGALRM (Alarm clock) @ 0 (0) ---
0.000157 sigreturn() = ? (mask now []) <0.000019>
0.010949 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0 <0.000019>
0.000115 gettimeofday({1220219284, 426474}, NULL) = 0 <0.000015>
0.000076 gettimeofday({1220219284, 426549}, NULL) = 0 <0.000017>
0.000074 rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0 <0.000017>
0.183893 gettimeofday({1220219284, 610605}, NULL) = 0 <0.000090>
0.155338 gettimeofday({1220219284, 765992}, NULL) = 0 <0.000129>
0.264379 getdents64(14, /* 125 entries */, 4096) = 4088 <0.000467>
0.618443 gettimeofday({1220219285, 648821}, NULL) = 0 <0.000146>
0.216144 gettimeofday({1220219285, 864973}, NULL) = 0 <0.000146>
0.725045 getdents64(14, /* 121 entries */, 4096) = 4096 <0.000212>
0.232641 gettimeofday({1220219286, 822618}, NULL) = 0 <0.000116>
0.186857 gettimeofday({1220219287, 9393}, NULL) = 0 <0.000019>
0.953455 gettimeofday({1220219287, 962841}, NULL) = 0 <0.000021>
0.221155 gettimeofday({1220219288, 184246}, NULL) = 0 <0.000264>
0.332566 getdents64(14, /* 122 entries */, 4096) = 4088 <0.000432>
0.654922 gettimeofday({1220219289, 171578}, NULL) = 0 <0.000120>
0.181435 gettimeofday({1220219289, 353032}, NULL) = 0 <0.000130>
0.847072 getdents64(14, /* 126 entries */, 4096) = 4080 <0.000338>
0.133808 gettimeofday({1220219290, 333910}, NULL) = 0 <0.000133>
0.183397 gettimeofday({1220219290, 517394}, NULL) = 0 <0.000203>
0.881111 gettimeofday({1220219291, 398399}, NULL) = 0 <0.000119>
0.185942 gettimeofday({1220219291, 584516}, NULL) = 0 <0.000282>
0.423669 getdents64(14, /* 125 entries */, 4096) = 4080 <0.000333>
0.515814 gettimeofday({1220219292, 523830}, NULL) = 0 <0.000124>
0.185801 gettimeofday({1220219292, 709673}, NULL) = 0 <0.000154>
0.883796 gettimeofday({1220219293, 593418}, NULL) = 0 <0.000115>
0.186351 gettimeofday({1220219293, 779819}, NULL) = 0 <0.000153>
0.000620 getdents64(14, /* 123 entries */, 4096) = 4080 <0.000276>
0.950282 gettimeofday({1220219294, 730672}, NULL) = 0 <0.000117>
0.186529 gettimeofday({1220219294, 917379}, NULL) = 0 <0.000284>
0.502483 getdents64(14, /* 128 entries */, 4096) = 4096 <0.000317>
0.520920 gettimeofday({1220219295, 949368}, NULL) = 0 <0.008892>
0.302211 gettimeofday({1220219296, 242849}, NULL) = 0 <0.000141>
0.895065 gettimeofday({1220219297, 137880}, NULL) = 0 <0.000116>
0.184786 gettimeofday({1220219297, 322849}, NULL) = 0 <0.000288>
0.144951 getdents64(14, /* 123 entries */, 4096) = 4096 <0.000502>
0.783568 gettimeofday({1220219298, 251184}, NULL) = 0 <0.000116>
0.186041 gettimeofday({1220219298, 437276}, NULL) = 0 <0.000155>
0.638823 getdents64(14, /* 126 entries */, 4096) = 4096 <0.000062>
0.365309 gettimeofday({1220219299, 441391}, NULL) = 0 <0.000146>
0.293914 gettimeofday({1220219299, 735296}, NULL) = 0 <0.000131>
0.885331 gettimeofday({1220219300, 620602}, NULL) = 0 <0.000115>
0.185862 gettimeofday({1220219300, 806530}, NULL) = 0 <0.000160>
0.247335 getdents64(14, /* 123 entries */, 4096) = 4096 <0.000391>
0.680369 gettimeofday({1220219301, 734169}, NULL) = 0 <0.000116>
0.185810 gettimeofday({1220219301, 920024}, NULL) = 0 <0.000151>
0.695677 getdents64(14, /* 125 entries */, 4096) = 4096 <0.000639>
0.213305 gettimeofday({1220219302, 829112}, NULL) = 0 <0.000267>
0.186323 gettimeofday({1220219303, 15327}, NULL) = 0 <0.000150>
0.900804 gettimeofday({1220219303, 916096}, NULL) = 0 <0.000123>
0.187633 gettimeofday({1220219304, 103903}, NULL) = 0 <0.000288>
0.366357 getdents64(14, /* 122 entries */, 4096) = 4088 <0.000191>
0.624951 gettimeofday({1220219305, 95037}, NULL) = 0 <0.000121>
0.321246 gettimeofday({1220219305, 416307}, NULL) = 0 <0.000138>
0.757553 getdents64(14, /* 123 entries */, 4096) = 4072 <0.000409>
0.165275 gettimeofday({1220219306, 339126}, NULL) = 0 <0.000136>
0.184346 gettimeofday({1220219306, 523504}, NULL) = 0 <0.000157>
0.909111 gettimeofday({1220219307, 432564}, NULL) = 0 <0.000119>
0.188846 gettimeofday({1220219307, 621582}, NULL) = 0 <0.000281>
0.397529 getdents64(14, /* 124 entries */, 4096) = 4080 <0.000393>
0.566455 gettimeofday({1220219308, 585390}, NULL) = 0 <0.000116>
0.191020 gettimeofday({1220219308, 776594}, NULL) = 0 <0.000289>
0.844134 getdents64(14, /* 125 entries */, 4096) = 4088 <0.000183>
0.274177 gettimeofday({1220219309, 894724}, NULL) = 0 <0.000118>
0.188975 gettimeofday({1220219310, 83747}, NULL) = 0 <0.000156>
0.960998 gettimeofday({1220219311, 44852}, NULL) = 0 <0.000273>
0.292174 gettimeofday({1220219311, 336893}, NULL) = 0 <0.000132>
0.430172 getdents64(14, /* 123 entries */, 4096) = 4080 <0.006762>
0.530705 gettimeofday({1220219312, 297744}, NULL) = 0 <0.000129>
0.188943 gettimeofday({1220219312, 486861}, NULL) = 0 <0.000279>
0.931694 getdents64(14, /* 127 entries */, 4096) = 4088 <0.000476>
0.056997 gettimeofday({1220219313, 475415}, NULL) = 0 <0.000149>
0.185205 gettimeofday({1220219313, 660754}, NULL) = 0 <0.000280>
0.903955 gettimeofday({1220219314, 564452}, NULL) = 0 <0.000021>
0.188058 gettimeofday({1220219314, 752530}, NULL) = 0 <0.000019>
0.539996 getdents64(14, /* 125 entries */, 4096) = 4088 <0.000339>
0.462233 gettimeofday({1220219315, 754826}, NULL) = 0 <0.000116>
0.187881 gettimeofday({1220219315, 942756}, NULL) = 0 <0.000154>
0.886213 gettimeofday({1220219316, 828929}, NULL) = 0 <0.000119>
0.187752 gettimeofday({1220219317, 16732}, NULL) = 0 <0.000165>
0.062955 getdents64(14, /* 110 entries */, 4096) = 3696 <0.000290>
0.942788 gettimeofday({1220219318, 22447}, NULL) = 0 <0.000146>
0.276459 gettimeofday({1220219318, 298898}, NULL) = 0 <0.000129>
0.428554 getdents64(14, /* 0 entries */, 4096) = 0 <0.000156>
0.000337 close(14) = 0 <0.000208>
0.011102 gettimeofday({1220219318, 738956}, NULL) = 0 <0.000181>
0.000579 time(NULL) = 1220219318 <0.000101>
0.000326 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2434,
...}) = 0 <0.000140>
0.000397 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2434,
...}) = 0 <0.000103>
0.000317 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2434,
...}) = 0 <0.000085>
0.013005 gettimeofday({1220219318, 753515}, NULL) = 0 <0.000131>
0.000311 gettimeofday({1220219318, 753755}, NULL) = 0 <0.000081>
0.000392 gettimeofday({1220219318, 754156}, NULL) = 0 <0.000088>
0.002620 rt_sigprocmask(SIG_BLOCK, [WINCH], [], 8) = 0 <0.000129>
0.000295 rt_sigprocmask(SIG_BLOCK, [IO], [WINCH], 8) = 0 <0.000063>
0.000198 rt_sigprocmask(SIG_BLOCK, [IO], [WINCH IO], 8) = 0 <0.000062>
0.000173 ioctl(8, FIONREAD, [0]) = 0 <0.000023>
0.000077 ioctl(6, FIONREAD, [0]) = 0 <0.000017>
0.000065 ioctl(3, FIONREAD, [0]) = 0 <0.000016>
0.000069 rt_sigprocmask(SIG_SETMASK, [WINCH IO], [WINCH IO], 8) = 0
<0.000014>
0.000084 gettimeofday({1220219318, 757661}, NULL) = 0 <0.000014>
0.000474 gettimeofday({1220219318, 758137}, NULL) = 0 <0.000015>
0.000074 write(8, "\33[1;24r\33[15;1H\33[1L\33[1;50r\33[50;1H"..., 71) =
71 <0.000107>
Cheers,
Len.