Stef did his measurement in a context where the expand-file-name was not called
as the expand-if-relative optimisation was still active.
I have redone the measurements with expand-if-relative re-defined
as a simple call to expand-file-name.
With this, I have not observed a significant nr of file system access
when doing find-tag.
So, I think the problem is just the size our 4 TAGS files:
One is about 62 MB, 914_000 lines, of those lines, about 59_000 are file names lines,
another one 46 MB, 629_000 lines, also 59_000 file names lines.
We have 2 other smaller TAGS file (8MB and 9MB).
I have run emacs under valgrind --tool=callgrind.
valgrind points at expand-file-name eating significant cpu (see attachment).
I have also used the lisp profiler when loading the TAGS files.
- call-interactively 10141 84%
- funcall-interactively 10077 84%
- find-tag 10069 83%
- find-tag-noselect 10069 83%
- visit-tags-table-buffer 9584 79%
- tags-table-including 9578 79%
- tags-table-extend-computed-list 4327 36%
- tags-verify-table 3274 27%
- apply 3274 27%
- ad-Advice-tags-verify-table 3274 27%
+ #<compiled 0x809ae9> 3274 27%
+ tags-included-tables 1053 8%
- mapcar 4097 34%
expand-if-relative 4076 34%
+ tags-table-files 1144 9%
+ tags-table-check-computed-list 1 0%
+ tags-table-list-member 1 0%
+ find-tag-in-order 485 4%
+ execute-extended-command 8 0%
+ byte-code 43 0%
+ find-tag-interactive 21 0%
+ ... 1091 9%
+ redisplay_internal (C function) 735 6%
+ timer-event-handler 18 0%
Maybe this allows to points at what could be optimised ?
Note that as far as I can see, the ad-Advice-tags-verify-table is created by our site lisp code containing vlf-1.7.1.
Not clear to me why this advice seems to be cpu costly, I was expecting this advice to only run a few times. i.e;
for each TAGS file opening.
Thanks
Philippe
> -----Original Message-----
> From: VAN VLIERBERGHE Stef <stef.van-vlierberghe@eurocontrol.int>
> Sent: 26 May 2022 15:51
> To: Eli Zaretskii <eliz@gnu.org>
> Cc: DE BACKER Jurgen (EXT) <jurgen.de-backer.ext@eurocontrol.int>; 55636@debbugs.gnu.org; WAROQUIERS Philippe
> <philippe.waroquiers@eurocontrol.int>
> Subject: RE: bug#55636: 27.2; etags performance fix when working with very big TAGS files
>
> You are right, I tried an strace and only see the tags files being read.
>
> I also can't get the 10 sec behaviour any more, maybe some other factors were involved that made the emacs tag file processing slow.
>
> What I did at the time to analyze was to enable debugger on Ctrl-G and then I notices emacs was busy here :
>
> Debugger entered--Lisp error: (quit)
> expand-file-name(#("/cm/ot/TOOL/GTK!27.0.0.1/build_G!27.IP.L7/sources/..." 0 88 (charset iso-8859-1)))
> mapcar(expand-file-name (#("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 81 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 80 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 83 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 83 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1))
> #("/cm/build9/cm/ot/TOOL/G!27.IP.L7/build_G!27.IP.L7/..." 0 82 (charset iso-8859-1)) ...))
> tags-table-including("/tmp/vvl.Tstatus.out" t)
> visit-tags-table-buffer()
> find-tag-noselect("-tv_summary.adb" nil nil)
>
> From that I concluded the expand-file-name was the cause.
>
> Hope this helps and all the best,
> Stef
>
> -----Original Message-----
> From: Eli Zaretskii <eliz@gnu.org>
> Sent: 26 May 2022 07:07
> To: VAN VLIERBERGHE Stef <stef.van-vlierberghe@eurocontrol.int>
> Cc: DE BACKER Jurgen (EXT) <jurgen.de-backer.ext@eurocontrol.int>; 55636@debbugs.gnu.org; WAROQUIERS Philippe
> <philippe.waroquiers@eurocontrol.int>
> Subject: Re: bug#55636: 27.2; etags performance fix when working with very big TAGS files
>
> > From: VAN VLIERBERGHE Stef <stef.van-vlierberghe@eurocontrol.int>
> > CC: "55636@debbugs.gnu.org" <55636@debbugs.gnu.org>, WAROQUIERS Philippe
> > <philippe.waroquiers@eurocontrol.int>
> > Date: Wed, 25 May 2022 20:42:16 +0000
> >
> > For us the 10 sec is reduced to below 1 sec, loading the tags file is no longer noticed after this change.
> >
> > I assume the reason is a huge amount of files all accessed over NFS, and expand-file-name does a lot of system calls that translate
> into network packets.
>
> Actually, expand-file-name is a purely syntactical function that is supposed not to hit the filesystem at all, at l;east on Posix systems.
> So I wonder why it seems to happen in your case. Any chances that you could show a trace of system calls for those 10 sec?
>
> Of course, making a simple change that you suggested is a no-brainer, so we might as well do it without further ado, but I'm just
> curious and think maybe we will learn something useful if we dig a bit deeper into your use case.
>
> > An alternative approach is to add some switch that allows a customization that simply never calls the expand-file-name, we generate
> tags files that already contain absolute paths so don't need any of this logic and disabling it would also be ok for us.
>
> That'd be less clean, I think: if we can do something automatically, it's better to do that instead of placing the burden on the user.
>
> Again, I'm not asking these questions because I see some problem in your proposed change. If we arrive at the conclusion that
> there's no reason to investigate more, we can just install that change, as it cannot possibly hurt.
>
> Thanks.