* profiler-report seems to be missing data?
@ 2018-08-15 15:00 Charlie Andrews
2018-08-15 18:46 ` Eli Zaretskii
` (2 more replies)
0 siblings, 3 replies; 15+ messages in thread
From: Charlie Andrews @ 2018-08-15 15:00 UTC (permalink / raw)
To: help-gnu-emacs
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.)
^ permalink raw reply [flat|nested] 15+ messages in thread* Re: profiler-report seems to be missing data?
2018-08-15 15:00 profiler-report seems to be missing data? Charlie Andrews
@ 2018-08-15 18:46 ` Eli Zaretskii
2018-08-16 13:47 ` Charlie Andrews
2018-08-16 22:47 ` Stefan Monnier
2 siblings, 0 replies; 15+ messages in thread
From: Eli Zaretskii @ 2018-08-15 18:46 UTC (permalink / raw)
To: help-gnu-emacs
> 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.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-15 15:00 profiler-report seems to be missing data? Charlie Andrews
2018-08-15 18:46 ` Eli Zaretskii
@ 2018-08-16 13:47 ` Charlie Andrews
2018-08-16 14:19 ` Eli Zaretskii
2018-08-16 22:47 ` Stefan Monnier
2 siblings, 1 reply; 15+ messages in thread
From: Charlie Andrews @ 2018-08-16 13:47 UTC (permalink / raw)
To: help-gnu-emacs
(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.)
>
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-16 13:47 ` Charlie Andrews
@ 2018-08-16 14:19 ` Eli Zaretskii
2018-08-16 15:32 ` Michael Heerdegen
0 siblings, 1 reply; 15+ messages in thread
From: Eli Zaretskii @ 2018-08-16 14:19 UTC (permalink / raw)
To: help-gnu-emacs
> 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.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-16 14:19 ` Eli Zaretskii
@ 2018-08-16 15:32 ` Michael Heerdegen
2018-08-16 17:12 ` Charlie Andrews
0 siblings, 1 reply; 15+ messages in thread
From: Michael Heerdegen @ 2018-08-16 15:32 UTC (permalink / raw)
To: Eli Zaretskii; +Cc: help-gnu-emacs
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.
^ permalink raw reply [flat|nested] 15+ messages in thread* Re: profiler-report seems to be missing data?
2018-08-16 15:32 ` Michael Heerdegen
@ 2018-08-16 17:12 ` Charlie Andrews
2018-08-16 17:28 ` Eli Zaretskii
2018-08-16 18:54 ` Michael Heerdegen
0 siblings, 2 replies; 15+ messages in thread
From: Charlie Andrews @ 2018-08-16 17:12 UTC (permalink / raw)
To: michael_heerdegen; +Cc: help-gnu-emacs
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.
>
>
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-16 17:12 ` Charlie Andrews
@ 2018-08-16 17:28 ` Eli Zaretskii
2018-08-16 17:33 ` Charlie Andrews
2018-08-16 18:54 ` Michael Heerdegen
1 sibling, 1 reply; 15+ messages in thread
From: Eli Zaretskii @ 2018-08-16 17:28 UTC (permalink / raw)
To: help-gnu-emacs
> 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.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-16 17:28 ` Eli Zaretskii
@ 2018-08-16 17:33 ` Charlie Andrews
2018-08-16 18:00 ` Eli Zaretskii
0 siblings, 1 reply; 15+ messages in thread
From: Charlie Andrews @ 2018-08-16 17:33 UTC (permalink / raw)
To: eliz; +Cc: help-gnu-emacs
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.
>
>
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-16 17:33 ` Charlie Andrews
@ 2018-08-16 18:00 ` Eli Zaretskii
2018-08-16 18:48 ` Michael Heerdegen
0 siblings, 1 reply; 15+ messages in thread
From: Eli Zaretskii @ 2018-08-16 18:00 UTC (permalink / raw)
To: help-gnu-emacs
> 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.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-16 17:12 ` Charlie Andrews
2018-08-16 17:28 ` Eli Zaretskii
@ 2018-08-16 18:54 ` Michael Heerdegen
1 sibling, 0 replies; 15+ messages in thread
From: Michael Heerdegen @ 2018-08-16 18:54 UTC (permalink / raw)
To: Charlie Andrews; +Cc: help-gnu-emacs
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.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: profiler-report seems to be missing data?
2018-08-15 15:00 profiler-report seems to be missing data? Charlie Andrews
2018-08-15 18:46 ` Eli Zaretskii
2018-08-16 13:47 ` Charlie Andrews
@ 2018-08-16 22:47 ` Stefan Monnier
2018-08-17 15:36 ` Charlie Andrews
2 siblings, 1 reply; 15+ messages in thread
From: Stefan Monnier @ 2018-08-16 22:47 UTC (permalink / raw)
To: help-gnu-emacs
> 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
^ permalink raw reply [flat|nested] 15+ messages in thread* Re: profiler-report seems to be missing data?
2018-08-16 22:47 ` Stefan Monnier
@ 2018-08-17 15:36 ` Charlie Andrews
2018-08-19 5:06 ` Stefan Monnier
0 siblings, 1 reply; 15+ messages in thread
From: Charlie Andrews @ 2018-08-17 15:36 UTC (permalink / raw)
To: monnier; +Cc: help-gnu-emacs
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
>
>
>
^ permalink raw reply [flat|nested] 15+ messages in thread* Re: profiler-report seems to be missing data?
2018-08-17 15:36 ` Charlie Andrews
@ 2018-08-19 5:06 ` Stefan Monnier
0 siblings, 0 replies; 15+ messages in thread
From: Stefan Monnier @ 2018-08-19 5:06 UTC (permalink / raw)
To: help-gnu-emacs
> 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
^ permalink raw reply [flat|nested] 15+ messages in thread
end of thread, other threads:[~2018-08-19 5:06 UTC | newest]
Thread overview: 15+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2018-08-15 15:00 profiler-report seems to be missing data? Charlie Andrews
2018-08-15 18:46 ` Eli Zaretskii
2018-08-16 13:47 ` Charlie Andrews
2018-08-16 14:19 ` Eli Zaretskii
2018-08-16 15:32 ` Michael Heerdegen
2018-08-16 17:12 ` Charlie Andrews
2018-08-16 17:28 ` Eli Zaretskii
2018-08-16 17:33 ` Charlie Andrews
2018-08-16 18:00 ` Eli Zaretskii
2018-08-16 18:48 ` Michael Heerdegen
2018-08-16 18:59 ` Eli Zaretskii
2018-08-16 18:54 ` Michael Heerdegen
2018-08-16 22:47 ` Stefan Monnier
2018-08-17 15:36 ` Charlie Andrews
2018-08-19 5:06 ` Stefan Monnier
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).