Subject: bug#55636: 27.2; etags performance fix when working with very big TAGS files

From: WAROQUIERS Philippe <[email-masked]>
Date: Thu, 26 May 2022 14:54:04 +0000

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 <[email-masked]>

> Sent: 26 May 2022 15:51

> To: Eli Zaretskii <[email-masked]>

> Cc: DE BACKER Jurgen (EXT) <[email-masked]>; [email-masked]; WAROQUIERS Philippe

> <[email-masked]>

> 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 <[email-masked]>

> Sent: 26 May 2022 07:07

> To: VAN VLIERBERGHE Stef <[email-masked]>

> Cc: DE BACKER Jurgen (EXT) <[email-masked]>; [email-masked]; WAROQUIERS Philippe

> <[email-masked]>

> Subject: Re: bug#55636: 27.2; etags performance fix when working with very big TAGS files

> > From: VAN VLIERBERGHE Stef <[email-masked]>

> > CC: "[email-masked]" <[email-masked]>, WAROQUIERS Philippe

> >          <[email-masked]>

> > 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.

____

This message and any files transmitted with it are legally privileged and intended for the sole use of the individual(s) or entity to whom they are addressed. If you are not the intended recipient, please notify the sender by reply and delete the message and any attachments from your system. Any unauthorised use or disclosure of the content of this message is strictly prohibited and may be unlawful.

Nothing in this e-mail message amounts to a contractual or legal commitment on the part of EUROCONTROL, unless it is confirmed by appropriately signed hard copy.

Any views expressed in this message are those of the sender.