profiler-report seems to be missing data?

profiler-report seems to be missing data?

[Charlie Andrews]

I'm trying to profile the usually excellent `find-things-fast` package to
figure out why it's slow in my project.

I started profiling with `profiler-start`, executed the command that's slow
(`ftf-find-file`), then immediately ran `profiler-report`.

This generated the following report:

    Functions                                                 CPU samples  %
    - command-execute                                                1770
88%
     - call-interactively                                            1770
88%
      - apply                                                        1770
88%
       - call-interactively@ido-cr+-record-current-command
 1770  88%
        - apply                                                      1770
88%
         - #<subr call-interactively>                                1770
88%
          - funcall-interactively                                    1770
88%
           - ftf-find-file                                           1597
80%
            - ftf-project-files-alist                                1522
76%
             - ftf-project-files-hash                                1330
66%
              - let                                                  1330
66%
               - mapcar                                              1330
66%
                - #<lambda 0x5458e8e0>                               1024
51%
                 - let*                                              1008
50%
                    cons                                               24
 1%
                + split-string                                        282
14%
             + maphash                                                192
 9%
            + ido-completing-read                                      67
 3%
           + next-line                                                 75
 3%
           + ido-switch-buffer                                         41
 2%
           + ido-switch-buffer-other-window                            38
 1%
           + profiler-report                                           19
 0%
    + ...                                                             145
 7%
    + redisplay_internal (C function)                                  37
 1%
    + timer-event-handler                                              26
 1%
      undefined                                                         5
 0%
    + gui-set-selection                                                 4
 0%
      internal-echo-keystrokes-prefix                                   2
 0%

The profiler report seems to blame the `let*` function within
`ftf-project-files-hash`.

However, looking at that function:

    (defun ftf-project-files-hash ()
      "Returns a hashtable filled with file names as the key and "
      (let ((default-directory (ftf-project-directory))
            (table (make-hash-table :test 'equal)))
        (mapcar (lambda (file)
                  (let* ((file-name (file-name-nondirectory file))
                         (full-path (expand-file-name file))
                         (pathlist (cons full-path (gethash file-name table
nil))))
                    (puthash file-name pathlist table)))
                (split-string (ftf-project-files-string)))
        table))

It seems incredibly unlikely that `let*` is the slow part, but rather one
of the functions called within that `let*`.

Why is `profiler-report` stopping at `let*` rather than telling me which
component of that `let*` is slow? How can I dig deeper to find which
exactly function is slow?

(FWIW, I've tried increasing profiler-max-stack-depth from 16 to 30 to no
avail.)

Re: profiler-report seems to be missing data?

[Eli Zaretskii]

> From: Charlie Andrews <andrews.charlie@gmail.com>
> Date: Wed, 15 Aug 2018 11:00:50 -0400
> 
> The profiler report seems to blame the `let*` function within
> `ftf-project-files-hash`.
> 
> However, looking at that function:
> 
>     (defun ftf-project-files-hash ()
>       "Returns a hashtable filled with file names as the key and "
>       (let ((default-directory (ftf-project-directory))
>             (table (make-hash-table :test 'equal)))
>         (mapcar (lambda (file)
>                   (let* ((file-name (file-name-nondirectory file))
>                          (full-path (expand-file-name file))
>                          (pathlist (cons full-path (gethash file-name table
> nil))))
>                     (puthash file-name pathlist table)))
>                 (split-string (ftf-project-files-string)))
>         table))
> 
> It seems incredibly unlikely that `let*` is the slow part, but rather one
> of the functions called within that `let*`.
> 
> Why is `profiler-report` stopping at `let*` rather than telling me which
> component of that `let*` is slow? How can I dig deeper to find which
> exactly function is slow?

Was the code you profiled byte-compiled?  If so, load the relevant .el
file, and then re-run the profiling session.  You might obtain a much
more detailed and accurate profile.

Re: profiler-report seems to be missing data?

[Charlie Andrews]

(I apologize if this messes up the threading - I saw Eli's response
<https://lists.gnu.org/archive/html/help-gnu-emacs/2018-08/msg00046.html>
on lists.gnu.org, but the mail didn't show up in my Gmail inbox. I'm
replying to it here.)

The version of the package that I'm profiling is unfortunately not byte
compiled. I did this by running M-x locate-library <enter> find-things-fast
<enter>, which returned "~/github/find-things-fast/find-things-fast.el".
This is my local development version of the library, not the ELPA version
of the library which also includes the byte-compiled version.

If I remove that github version from my path and reload emacs, the same
command reutrns
"~/.emacs.d/elpa/find-things-fast-20150519.1526/find-things-fast.elc" (the
byte compiled version) as expected. I'm just not sure why a non
byte-compiled version would be so sparse on details regarding what
functions are taking up time.

On Wed, Aug 15, 2018 at 11:00 AM Charlie Andrews <andrews.charlie@gmail.com>
wrote:

> I'm trying to profile the usually excellent `find-things-fast` package to
> figure out why it's slow in my project.
>
> I started profiling with `profiler-start`, executed the command that's
> slow (`ftf-find-file`), then immediately ran `profiler-report`.
>
> This generated the following report:
>
>     Functions                                                 CPU samples
> %
>     - command-execute                                                1770
> 88%
>      - call-interactively                                            1770
> 88%
>       - apply                                                        1770
> 88%
>        - call-interactively@ido-cr+-record-current-command
>  1770  88%
>         - apply                                                      1770
> 88%
>          - #<subr call-interactively>                                1770
> 88%
>           - funcall-interactively                                    1770
> 88%
>            - ftf-find-file                                           1597
> 80%
>             - ftf-project-files-alist                                1522
> 76%
>              - ftf-project-files-hash                                1330
> 66%
>               - let                                                  1330
> 66%
>                - mapcar                                              1330
> 66%
>                 - #<lambda 0x5458e8e0>                               1024
> 51%
>                  - let*                                              1008
> 50%
>                     cons                                               24
>  1%
>                 + split-string                                        282
> 14%
>              + maphash                                                192
>  9%
>             + ido-completing-read                                      67
>  3%
>            + next-line                                                 75
>  3%
>            + ido-switch-buffer                                         41
>  2%
>            + ido-switch-buffer-other-window                            38
>  1%
>            + profiler-report                                           19
>  0%
>     + ...                                                             145
>  7%
>     + redisplay_internal (C function)                                  37
>  1%
>     + timer-event-handler                                              26
>  1%
>       undefined                                                         5
>  0%
>     + gui-set-selection                                                 4
>  0%
>       internal-echo-keystrokes-prefix                                   2
>  0%
>
> The profiler report seems to blame the `let*` function within
> `ftf-project-files-hash`.
>
> However, looking at that function:
>
>     (defun ftf-project-files-hash ()
>       "Returns a hashtable filled with file names as the key and "
>       (let ((default-directory (ftf-project-directory))
>             (table (make-hash-table :test 'equal)))
>         (mapcar (lambda (file)
>                   (let* ((file-name (file-name-nondirectory file))
>                          (full-path (expand-file-name file))
>                          (pathlist (cons full-path (gethash file-name
> table nil))))
>                     (puthash file-name pathlist table)))
>                 (split-string (ftf-project-files-string)))
>         table))
>
> It seems incredibly unlikely that `let*` is the slow part, but rather one
> of the functions called within that `let*`.
>
> Why is `profiler-report` stopping at `let*` rather than telling me which
> component of that `let*` is slow? How can I dig deeper to find which
> exactly function is slow?
>
> (FWIW, I've tried increasing profiler-max-stack-depth from 16 to 30 to no
> avail.)
>

Re: profiler-report seems to be missing data?

[Eli Zaretskii]

> From: Charlie Andrews <andrews.charlie@gmail.com>
> Date: Thu, 16 Aug 2018 09:47:30 -0400
> 
> (I apologize if this messes up the threading - I saw Eli's response
> <https://lists.gnu.org/archive/html/help-gnu-emacs/2018-08/msg00046.html>
> on lists.gnu.org, but the mail didn't show up in my Gmail inbox. I'm
> replying to it here.)
> 
> The version of the package that I'm profiling is unfortunately not byte
> compiled. I did this by running M-x locate-library <enter> find-things-fast
> <enter>, which returned "~/github/find-things-fast/find-things-fast.el".
> This is my local development version of the library, not the ELPA version
> of the library which also includes the byte-compiled version.

In that case, perhaps the bindings done by let* take a lot of time
because these are variables that become local when set, and you have
many buffers in your session?  Do you see any changes in the profile
if you run the code in a fresh session?

Btw, the profile says that quite a lot of time is spent in these
functions:
> >            - ftf-find-file                                           1597
> > 80%
> >             - ftf-project-files-alist                                1522
> > 76%
> >              - ftf-project-files-hash                                1330
> > 66%
> >               - let                                                  1330
> > 66%
> >                - mapcar                                              1330
> > 66%
> >                 - #<lambda 0x5458e8e0>                               1024
> > 51%

So I'd suggest to look at them as well.

Re: profiler-report seems to be missing data?

[Michael Heerdegen]

Eli Zaretskii <eliz@gnu.org> writes:

> In that case, perhaps the bindings done by let* take a lot of time
> because these are variables that become local when set, and you have
> many buffers in your session?

I think you are right - one doesn't even have to bind buffer local
variables to get a profiler report where 'let' takes a lot of time
though nothing inside 'let' seems to be responsible.  If I profile this
for example:

#+begin_src emacs-lisp
(defun test ()
  (interactive)
  (mapcar (lambda (x)
            (let ((y1 1)
                  (y2 2)
                  (y3 3))
              (ignore y3)
              (cons x (cons y1 y2))))
          (number-sequence 1 1000000))
  nil)
#+end_src

I get a similar profiler report.  Obviously, the list mapped over is so
huge that simply binding the variables inside the loop takes a
significant part of time if the rest is fast (calling 'cons' in
the example, 'puthash' in the code we speak about).  Things will be
different when running byte compiled code, I guess.


Michael.

Re: profiler-report seems to be missing data?

[Charlie Andrews]

Any tips on making these let bindings faster? I've read online that
enabling lexical binding for the plugin might help.

On Thu, Aug 16, 2018 at 12:34 PM Michael Heerdegen <michael_heerdegen@web.de>
wrote:

> Eli Zaretskii <eliz@gnu.org> writes:
>
> > In that case, perhaps the bindings done by let* take a lot of time
> > because these are variables that become local when set, and you have
> > many buffers in your session?
>
> I think you are right - one doesn't even have to bind buffer local
> variables to get a profiler report where 'let' takes a lot of time
> though nothing inside 'let' seems to be responsible.  If I profile this
> for example:
>
> #+begin_src emacs-lisp
> (defun test ()
>   (interactive)
>   (mapcar (lambda (x)
>             (let ((y1 1)
>                   (y2 2)
>                   (y3 3))
>               (ignore y3)
>               (cons x (cons y1 y2))))
>           (number-sequence 1 1000000))
>   nil)
> #+end_src
>
> I get a similar profiler report.  Obviously, the list mapped over is so
> huge that simply binding the variables inside the loop takes a
> significant part of time if the rest is fast (calling 'cons' in
> the example, 'puthash' in the code we speak about).  Things will be
> different when running byte compiled code, I guess.
>
>
> Michael.
>
>

Re: profiler-report seems to be missing data?

[Eli Zaretskii]

> From: Charlie Andrews <andrews.charlie@gmail.com>
> Date: Thu, 16 Aug 2018 13:12:23 -0400
> Cc: eliz@gnu.org, help-gnu-emacs@gnu.org
> 
> Any tips on making these let bindings faster? I've read online that enabling lexical binding for the plugin might
> help.

If you have a lot of dead buffers, this should be much faster in the
next release.

If the problem is that you have a lot of live buffers, maybe you
should install some feature that deletes those of them that haven't
been used for a while, from time to time.

Re: profiler-report seems to be missing data?

[Charlie Andrews]

Sorry for the silly question: unless I'm changing some emacs-wide variable
that might logically force some recomputation in those buffers (like
changing the gutter after which characters on a given line are highlighted
red, for example) or Emacs is under memory pressure, why would the number
of buffers affect the time required for let to run?

On Thu, Aug 16, 2018 at 1:30 PM Eli Zaretskii <eliz@gnu.org> wrote:

> > From: Charlie Andrews <andrews.charlie@gmail.com>
> > Date: Thu, 16 Aug 2018 13:12:23 -0400
> > Cc: eliz@gnu.org, help-gnu-emacs@gnu.org
> >
> > Any tips on making these let bindings faster? I've read online that
> enabling lexical binding for the plugin might
> > help.
>
> If you have a lot of dead buffers, this should be much faster in the
> next release.
>
> If the problem is that you have a lot of live buffers, maybe you
> should install some feature that deletes those of them that haven't
> been used for a while, from time to time.
>
>

Re: profiler-report seems to be missing data?

[Eli Zaretskii]

> From: Charlie Andrews <andrews.charlie@gmail.com>
> Date: Thu, 16 Aug 2018 13:33:19 -0400
> Cc: help-gnu-emacs@gnu.org
> 
> Sorry for the silly question: unless I'm changing some emacs-wide variable that might logically force some
> recomputation in those buffers (like changing the gutter after which characters on a given line are highlighted
> red, for example) or Emacs is under memory pressure, why would the number of buffers affect the time
> required for let to run?

When you bind a variable that automatically becomes buffer-local when
set, Emacs needs to make that variable buffer-local in every other
buffer you have, and that can take time if you have a lot of buffers.
Emacs used to do this even in dead buffers (those which were killed,
but not yet GCed), but we fixed that lately.

Re: profiler-report seems to be missing data?

[Michael Heerdegen]

Eli Zaretskii <eliz@gnu.org> writes:

> When you bind a variable that automatically becomes buffer-local when
> set [...]

AFAICT in the scenario we speak about the variables bound are not of
that kind.

Michael.

Re: profiler-report seems to be missing data?

[Michael Heerdegen]

Charlie Andrews <andrews.charlie@gmail.com> writes:

> Any tips on making these let bindings faster? I've read online that
> enabling lexical binding for the plugin might help.

Are you even sure the problem persists when you run the code byte
compiled (I mean the problem that binding takes so much time, not that
the code in general is slow)?

In any case, for the function we speak about it's maybe the simplest
approach to get rid of the bindings at all and replace the function
arguments with the according expressions.

Michael.

Re: profiler-report seems to be missing data?

[Eli Zaretskii]

> From: Michael Heerdegen <michael_heerdegen@web.de>
> Cc: help-gnu-emacs@gnu.org
> Date: Thu, 16 Aug 2018 20:48:54 +0200
> 
> Eli Zaretskii <eliz@gnu.org> writes:
> 
> > When you bind a variable that automatically becomes buffer-local when
> > set [...]
> 
> AFAICT in the scenario we speak about the variables bound are not of
> that kind.

Then what I described is probably not the reason.

Re: profiler-report seems to be missing data?

[Stefan Monnier]

> I'm trying to profile the usually excellent `find-things-fast` package to
> figure out why it's slow in my project.

The presence of `let*` in the profile indicates that the code is not
byte-compiled.  The difference in performance when byte-compiled can be
large enough, so I'd suggest you first byte-compile your code and only
then would I recommend you profile it (if still needed).

>                 - #<lambda 0x5458e8e0>                               1024 51%
>                  - let*                                              1008 50%
>                     cons                                               24  1%

This suggests that a lot of time is spent in `let*` which may simply be
because #<lambda 0x5458e8e0> is called many many times and doesn't do
much more than `let*`.

Looking at your function, I'm indeed surprised that even tough this
`let*` was found 1008 times none of those times also found
file-name-nondirectory or expand-file-name or gethash in the stack.

Maybe this hints at a bug in the profiler code.  Can you try and run
this code many more times, so as to increase the "1008" to a larger
number, making it yet more statistically unlikely that none of
file-name-nondirectory or expand-file-name or gethash are found?


        Stefan

Re: profiler-report seems to be missing data?

[Charlie Andrews]

Byte compiling the file didn't seem to have much effect: let* was still
blamed for the vast majority of the runtime (57%).  I verified that the
byte compiled version was the one loaded with M-x locate-library, which
returned the .elc version of the library.

Eliminating the let* by inlining its intermediate variables led to
interesting results:

- command-execute                                                1737  92%
 - call-interactively                                            1737  92%
  - apply                                                        1737  92%
   - call-interactively@ido-cr+-record-current-command               1737
92%
    - apply                                                      1737  92%
     - #<subr call-interactively>                                1737  92%
      - funcall-interactively                                    1737  92%
       - ftf-find-file                                           1732  92%
        - ftf-project-files-alist                                1641  87%
         - ftf-project-files-hash                                1425  75%
          - let*                                                 1425  75%
           - mapcar                                              1112  59%
            - #<lambda 0x3601f12d>                               1104  58%
             - puthash                                           1092  58%
              - cons                                              884  47%
                 gethash                                          188  10%
           + split-string                                         265  14%
         + maphash                                                212  11%
        + ido-completing-read                                      83   4%
          mapcar                                                    4   0%
       + profiler-report                                            5   0%
+ ...                                                             138   7%
+ timer-event-handler                                               1   0%

The interesting parts here:

   - The overall number of CPU samples didn't change, I think indicating
   that eliminating the let* didn't in fact speed up the code. (In both cases,
   I ran ftf-find-file once, which took 4-5 seconds.)
   - The samples that were originally blamed on let* are instead blamed
   largely on cons and gethash now, which in my opinion seems more likely

My suspicion here is that let* and the profiler are having some bad
interaction where the samples are incorrectly being attributed to let* when
they should be instead attributed to code called within the let*. Stefan,
do you think I'm interpreting this correctly?

On Thu, Aug 16, 2018 at 6:47 PM Stefan Monnier <monnier@iro.umontreal.ca>
wrote:

> > I'm trying to profile the usually excellent `find-things-fast` package to
> > figure out why it's slow in my project.
>
> The presence of `let*` in the profile indicates that the code is not
> byte-compiled.  The difference in performance when byte-compiled can be
> large enough, so I'd suggest you first byte-compile your code and only
> then would I recommend you profile it (if still needed).
>
> >                 - #<lambda 0x5458e8e0>
>  1024 51%
> >                  - let*
> 1008 50%
> >                     cons
>  24  1%
>
> This suggests that a lot of time is spent in `let*` which may simply be
> because #<lambda 0x5458e8e0> is called many many times and doesn't do
> much more than `let*`.
>
> Looking at your function, I'm indeed surprised that even tough this
> `let*` was found 1008 times none of those times also found
> file-name-nondirectory or expand-file-name or gethash in the stack.
>
> Maybe this hints at a bug in the profiler code.  Can you try and run
> this code many more times, so as to increase the "1008" to a larger
> number, making it yet more statistically unlikely that none of
> file-name-nondirectory or expand-file-name or gethash are found?
>
>
>         Stefan
>
>
>

Re: profiler-report seems to be missing data?

[Stefan Monnier]

> Byte compiling the file didn't seem to have much effect: let* was still
> blamed for the vast majority of the runtime (57%).

`let*` does not exist in byte-compiled code (it's decomposed into
various other byte-codes instead), so its presence in the profile
indicates that somehow non-compiled code is executed.

>    - The overall number of CPU samples didn't change, I think indicating
>    that eliminating the let* didn't in fact speed up the code. (In both cases,
>    I ran ftf-find-file once, which took 4-5 seconds.)
>    - The samples that were originally blamed on let* are instead blamed
>    largely on cons and gethash now, which in my opinion seems more likely
>
> My suspicion here is that let* and the profiler are having some bad
> interaction where the samples are incorrectly being attributed to let* when
> they should be instead attributed to code called within the let*. Stefan,
> do you think I'm interpreting this correctly?

Sounds possible, yes.  Not sure if it's specific to `let*`, tho.
[ E.g. maybe it's just that the leaf of each stack trace gets lost?  ]


        Stefan