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