From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.org!not-for-mail From: Len Trigg Newsgroups: gmane.emacs.bugs Subject: bug#122: 23.0.60; Slowdown in directory scanning over time. Date: Mon, 01 Sep 2008 09:57:13 +1200 Organization: NetValue Ltd. Message-ID: References: <87r68bwgu9.fsf@cyd.mit.edu> Reply-To: Len Trigg , 122@emacsbugs.donarmstrong.com NNTP-Posting-Host: lo.gmane.org Mime-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka") Content-Type: text/plain; charset=US-ASCII X-Trace: ger.gmane.org 1220220474 8499 80.91.229.12 (31 Aug 2008 22:07:54 GMT) X-Complaints-To: usenet@ger.gmane.org NNTP-Posting-Date: Sun, 31 Aug 2008 22:07:54 +0000 (UTC) Cc: 122@emacsbugs.donarmstrong.com To: Chong Yidong Original-X-From: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane.org@gnu.org Mon Sep 01 00:08:48 2008 Return-path: Envelope-to: geb-bug-gnu-emacs@m.gmane.org Original-Received: from lists.gnu.org ([199.232.76.165]) by lo.gmane.org with esmtp (Exim 4.50) id 1KZv6F-0005tc-Kr for geb-bug-gnu-emacs@m.gmane.org; Mon, 01 Sep 2008 00:08:48 +0200 Original-Received: from localhost ([127.0.0.1]:33752 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.43) id 1KZv5G-0007gX-P4 for geb-bug-gnu-emacs@m.gmane.org; Sun, 31 Aug 2008 18:07:46 -0400 Original-Received: from mailman by lists.gnu.org with tmda-scanned (Exim 4.43) id 1KZv56-0007an-QM for bug-gnu-emacs@gnu.org; Sun, 31 Aug 2008 18:07:36 -0400 Original-Received: from exim by lists.gnu.org with spam-scanned (Exim 4.43) id 1KZv53-0007X5-7H for bug-gnu-emacs@gnu.org; Sun, 31 Aug 2008 18:07:35 -0400 Original-Received: from [199.232.76.173] (port=38855 helo=monty-python.gnu.org) by lists.gnu.org with esmtp (Exim 4.43) id 1KZv53-0007X2-4J for bug-gnu-emacs@gnu.org; Sun, 31 Aug 2008 18:07:33 -0400 Original-Received: from rzlab.ucr.edu ([138.23.92.77]:47062) by monty-python.gnu.org with esmtps (TLS-1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.60) (envelope-from ) id 1KZv52-0007sy-CI for bug-gnu-emacs@gnu.org; Sun, 31 Aug 2008 18:07:32 -0400 Original-Received: from rzlab.ucr.edu (rzlab.ucr.edu [127.0.0.1]) by rzlab.ucr.edu (8.13.8/8.13.8/Debian-3) with ESMTP id m7VM7UBe032319; Sun, 31 Aug 2008 15:07:30 -0700 Original-Received: (from debbugs@localhost) by rzlab.ucr.edu (8.13.8/8.13.8/Submit) id m7VM57pN031015; Sun, 31 Aug 2008 15:05:07 -0700 X-Loop: don@donarmstrong.com Resent-From: Len Trigg Resent-To: bug-submit-list@donarmstrong.com Resent-CC: Emacs Bugs Resent-Date: Sun, 31 Aug 2008 22:05:06 +0000 Resent-Message-ID: Resent-Sender: don@donarmstrong.com X-Emacs-PR-Message: report 122 X-Emacs-PR-Package: emacs X-Emacs-PR-Keywords: Original-Received: via spool by 122-submit@emacsbugs.donarmstrong.com id=B122.122021984528289 (code B ref 122); Sun, 31 Aug 2008 22:05:06 +0000 Original-Received: (at 122) by emacsbugs.donarmstrong.com; 31 Aug 2008 21:57:25 +0000 Original-Received: from netvalue.net.nz (office.netvalue.net.nz [202.37.129.7] (may be forged)) by rzlab.ucr.edu (8.13.8/8.13.8/Debian-3) with ESMTP id m7VLvKOE028283 for <122@emacsbugs.donarmstrong.com>; Sun, 31 Aug 2008 14:57:21 -0700 Original-Received: from localhost (localhost [127.0.0.1]) by netvalue.net.nz (Postfix) with ESMTP id 9EF6E148888; Mon, 1 Sep 2008 09:50:10 +1200 (NZST) X-Virus-Scanned: Debian amavisd-new at netvalue.net.nz Original-Received: from netvalue.net.nz ([127.0.0.1]) by localhost (netvalue.net.nz [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 0L-hlRGBqs6P; Mon, 1 Sep 2008 09:50:08 +1200 (NZST) Original-Received: from nepenthes.nz.reeltwo.com (colosus.18londonst.co.nz [131.203.126.193]) by netvalue.net.nz (Postfix) with ESMTP id 040C5148105; Mon, 1 Sep 2008 09:50:08 +1200 (NZST) In-Reply-To: <87r68bwgu9.fsf@cyd.mit.edu> User-Agent: Wanderlust/2.15.6 (Almost Unreal) SEMI/1.14.6 (Maruoka) FLIM/1.14.9 =?UTF-8?Q?(Goj=C5=8D)?= APEL/10.7 Emacs/23.0.60 (i686-pc-linux-gnu) MULE/6.0 (HANACHIRUSATO) X-Payment: hashcash 1.2 1:10:080831:cyd@stupidchicken.com::x3607d0/t/zmZ1Dt:0000000000000000000000000000000000000000005e X-Hashcash: 1:10:080831:cyd@stupidchicken.com::x3607d0/t/zmZ1Dt:0000000000000000000000000000000000000000005e X-Payment: hashcash 1.2 1:10:080831:122@emacsbugs.donarmstrong.com::rHQLTQadbskmP7vW:00000000000000000000000000000000092 X-Hashcash: 1:10:080831:122@emacsbugs.donarmstrong.com::rHQLTQadbskmP7vW:00000000000000000000000000000000092 X-detected-kernel: by monty-python.gnu.org: Linux 2.6 (newer, 3) Resent-Date: Sun, 31 Aug 2008 18:07:35 -0400 X-BeenThere: bug-gnu-emacs@gnu.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: "Bug reports for GNU Emacs, the Swiss army knife of text editors" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Original-Sender: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane.org@gnu.org Errors-To: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane.org@gnu.org Xref: news.gmane.org gmane.emacs.bugs:19943 Archived-At: 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.