Re: profiler-report seems to be missing data?

[Charlie Andrews <andrews.charlie@gmail.com>]

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