bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

[-- Attachment #1.1: Type: text/plain, Size: 719 bytes --]

I've worked with a few other profilers than profiler.el so far and one
striking difference is that they allowed you to start a profiling run,
stop it and then retrieve the profiling log between these two points in
time.  profiler.el on the other hand flatout refuses to display a report
after stopping which is especially puzzling given the `profiler-stop`
docstring: "Stop started profilers.  Profiler logs will be kept."  If
the logs are kept after all, why can't I take a look at them?

I've attached a patch that solves this by caching the last accessable
profiler log.  This allows both workflows to work, be it displaying a
report while the profiler is still running or displaying it after
stopping the profiler.

[-- Attachment #1.2: Type: text/html, Size: 804 bytes --]

[-- Attachment #2: 0001-Allow-for-retrieving-profiler-logs-after-stopping.patch --]
[-- Type: text/x-diff, Size: 3675 bytes --]

From 3464446b83151ad894ff4ee7f62ed1cb7852b1b6 Mon Sep 17 00:00:00 2001
From: Vasilij Schneidermann <v.schneidermann@gmail.com>
Date: Tue, 8 Dec 2015 09:01:15 +0100
Subject: [PATCH] Allow for retrieving profiler logs after stopping

---
 lisp/profiler.el | 59 +++++++++++++++++++++++++++++++++-----------------------
 1 file changed, 35 insertions(+), 24 deletions(-)

diff --git a/lisp/profiler.el b/lisp/profiler.el
index f28bbfe..10cdcfb 100644
--- a/lisp/profiler.el
+++ b/lisp/profiler.el
@@ -214,21 +214,23 @@ Optional argument MODE means only check for the specified mode (cpu or mem)."
         (t (or (profiler-running-p 'cpu)
                (profiler-running-p 'mem)))))
 
+(defvar profiler-cpu-log nil)
+
+(defvar profiler-memory-log nil)
+
 (defun profiler-cpu-profile ()
   "Return CPU profile."
-  (when (profiler-running-p 'cpu)
-    (profiler-make-profile
-     :type 'cpu
-     :timestamp (current-time)
-     :log (profiler-cpu-log))))
+  (profiler-make-profile
+   :type 'cpu
+   :timestamp (current-time)
+   :log profiler-cpu-log))
 
 (defun profiler-memory-profile ()
   "Return memory profile."
-  (when (profiler-memory-running-p)
-    (profiler-make-profile
-     :type 'memory
-     :timestamp (current-time)
-     :log (profiler-memory-log))))
+  (profiler-make-profile
+   :type 'memory
+   :timestamp (current-time)
+   :log profiler-memory-log))
 
 \f
 ;;; Calltrees
@@ -828,7 +830,11 @@ Also, if MODE is `mem' or `cpu+mem', then memory profiler will be started."
 (defun profiler-stop ()
   "Stop started profilers.  Profiler logs will be kept."
   (interactive)
-  (let ((cpu (if (fboundp 'profiler-cpu-stop) (profiler-cpu-stop)))
+  (when (and (fboundp 'profiler-cpu-running-p) (profiler-cpu-running-p))
+    (setq profiler-cpu-log (profiler-cpu-log)))
+  (when (profiler-memory-running-p)
+    (setq profiler-memory-log (profiler-memory-log)))
+  (let ((cpu (when (fboundp 'profiler-cpu-stop) (profiler-cpu-stop)))
         (mem (profiler-memory-stop)))
     (message "%s profiler stopped"
              (cond ((and mem cpu) "CPU and memory")
@@ -839,26 +845,31 @@ Also, if MODE is `mem' or `cpu+mem', then memory profiler will be started."
 (defun profiler-reset ()
   "Reset profiler logs."
   (interactive)
-  (when (fboundp 'profiler-cpu-log)
-    (ignore (profiler-cpu-log)))
-  (ignore (profiler-memory-log))
-  t)
+  (when (and (fboundp 'profiler-cpu-running-p) (profiler-cpu-running-p))
+    (profiler-cpu-stop))
+  (when (profiler-memory-running-p)
+    (profiler-memory-stop))
+  (setq profiler-cpu-log nil
+        profiler-memory-log nil))
 
 (defun profiler-report-cpu ()
-  (let ((profile (profiler-cpu-profile)))
-    (when profile
-      (profiler-report-profile-other-window profile))))
+  (when profiler-cpu-log
+    (profiler-report-profile-other-window (profiler-cpu-profile))))
 
 (defun profiler-report-memory ()
-  (let ((profile (profiler-memory-profile)))
-    (when profile
-      (profiler-report-profile-other-window profile))))
+  (when profiler-memory-log
+    (profiler-report-profile-other-window (profiler-memory-profile))))
 
 (defun profiler-report ()
   "Report profiling results."
-  (interactive)
-  (profiler-report-cpu)
-  (profiler-report-memory))
+  (when (and (fboundp 'profiler-cpu-running-p) (profiler-cpu-running-p))
+    (setq profiler-cpu-log (profiler-cpu-log)))
+  (when (profiler-memory-running-p)
+    (setq profiler-memory-log (profiler-memory-log)))
+  (if (and (not profiler-cpu-log) (not profiler-memory-log))
+      (user-error "No profiler run recorded")
+    (profiler-report-cpu)
+    (profiler-report-memory)))
 
 ;;;###autoload
 (defun profiler-find-profile (filename)
-- 
2.6.2

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> Date: Tue, 8 Dec 2015 09:13:58 +0100
> From: Vasilij Schneidermann <v.schneidermann@gmail.com>
> 
> I've worked with a few other profilers than profiler.el so far and one
> striking difference is that they allowed you to start a profiling run,
> stop it and then retrieve the profiling log between these two points in
> time. profiler.el on the other hand flatout refuses to display a report
> after stopping which is especially puzzling given the `profiler-stop`
> docstring: "Stop started profilers. Profiler logs will be kept." If
> the logs are kept after all, why can't I take a look at them?
> 
> I've attached a patch that solves this by caching the last accessable
> profiler log. This allows both workflows to work, be it displaying a
> report while the profiler is still running or displaying it after
> stopping the profiler.

Thanks.  But I don't see why we would need to keep a copy of the
profile around (and it looks weird to do that anyway, when we have a
function that reports it).  When profiler-cpu-log is called, it
returns the profile before it resets it, so the data is available and
should simply be used.

I don't really understand why profiler.el insists on having the
profiler running for providing the profile.  The much simpler patch
below makes it possible for me to invoke profiler-report whether a
profile is running or not.  Does it work for you?  If not, can you
tell what I missed?

--- lisp/profiler.el~4	2015-11-11 07:57:32.000000000 +0200
+++ lisp/profiler.el	2015-12-08 17:54:27.380084700 +0200
@@ -216,19 +216,17 @@
 
 (defun profiler-cpu-profile ()
   "Return CPU profile."
-  (when (profiler-running-p 'cpu)
-    (profiler-make-profile
-     :type 'cpu
-     :timestamp (current-time)
-     :log (profiler-cpu-log))))
+  (profiler-make-profile
+   :type 'cpu
+   :timestamp (current-time)
+   :log (profiler-cpu-log)))
 
 (defun profiler-memory-profile ()
   "Return memory profile."
-  (when (profiler-memory-running-p)
-    (profiler-make-profile
-     :type 'memory
-     :timestamp (current-time)
-     :log (profiler-memory-log))))
+  (profiler-make-profile
+   :type 'memory
+   :timestamp (current-time)
+   :log (profiler-memory-log)))
 
 \f
 ;;; Calltrees
@@ -846,12 +844,12 @@
 
 (defun profiler-report-cpu ()
   (let ((profile (profiler-cpu-profile)))
-    (when profile
+    (when (and profile (profiler-profile-log profile))
       (profiler-report-profile-other-window profile))))
 
 (defun profiler-report-memory ()
   (let ((profile (profiler-memory-profile)))
-    (when profile
+    (when (and profile (profiler-profile-log profile))
       (profiler-report-profile-other-window profile))))
 
 (defun profiler-report ()

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

> Thanks.  But I don't see why we would need to keep a copy of the
> profile around (and it looks weird to do that anyway, when we have a
> function that reports it).  When profiler-cpu-log is called, it
> returns the profile before it resets it, so the data is available and
> should simply be used.
> 
> I don't really understand why profiler.el insists on having the
> profiler running for providing the profile.  The much simpler patch
> below makes it possible for me to invoke profiler-report whether a
> profile is running or not.  Does it work for you?  If not, can you
> tell what I missed?

This works only once.  If the profiler has been stopped and you retrieve
the log, it resets and subsequent access will yield an error.  While
your variant may be simpler, it is less user-friendly as viewing the
report a second time will yield an incomprehensible error.  Avoiding
this either requires fixing the function retrieving the log (which is at
the C level and out of my reach) or using a workaround like the two
extra variables in my patch.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> Date: Tue, 8 Dec 2015 17:32:08 +0100
> From: Vasilij Schneidermann <v.schneidermann@gmail.com>
> Cc: 22114@debbugs.gnu.org
> 
> > Thanks.  But I don't see why we would need to keep a copy of the
> > profile around (and it looks weird to do that anyway, when we have a
> > function that reports it).  When profiler-cpu-log is called, it
> > returns the profile before it resets it, so the data is available and
> > should simply be used.
> > 
> > I don't really understand why profiler.el insists on having the
> > profiler running for providing the profile.  The much simpler patch
> > below makes it possible for me to invoke profiler-report whether a
> > profile is running or not.  Does it work for you?  If not, can you
> > tell what I missed?
> 
> This works only once.  If the profiler has been stopped and you retrieve
> the log, it resets and subsequent access will yield an error.

But why would you need a subsequent access to the same data?  The
profiler report is in the buffer, and you can review it whenever you
want.  The buffer has the time of the report creation as part of its
name, so the next report will not destroy the buffer.  You can also
save the report to a file (there's a separate command to do that).  By
contrast,producing a report again from the same data will simply
produce an identical report.

I guess I don't see a use case where the user would need to produce
the same report twice.  I never needed that myself, FWIW.

> While your variant may be simpler, it is less user-friendly as
> viewing the report a second time will yield an incomprehensible
> error.

If the error message needs improvement, we could do that as well.

> Avoiding this either requires fixing the function retrieving the log
> (which is at the C level and out of my reach) or using a workaround
> like the two extra variables in my patch.

The code implemented in C resets the data deliberately (there are
comments there that explain why), so it cannot be fixed.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[John Wiegley]

[-- Attachment #1: Type: text/plain, Size: 1247 bytes --]

>>>>> Eli Zaretskii <eliz@gnu.org> writes:

> But why would you need a subsequent access to the same data? The profiler
> report is in the buffer, and you can review it whenever you want. The buffer
> has the time of the report creation as part of its name, so the next report
> will not destroy the buffer. You can also save the report to a file (there's
> a separate command to do that). By contrast,producing a report again from
> the same data will simply produce an identical report.

> I guess I don't see a use case where the user would need to produce the same
> report twice. I never needed that myself, FWIW.

I think the OP wants to:

  1. Start a profile
  2. View the "results in progress"
  3. Allow it to continue execution
  4. View the "results at the end"

It's step #2 that's missing. If we can only view the results in progress by
taking away the option for #4, this is less optimal.

This is something that other profilers do let you do; I use Instruments on the
Mac to view "statistics as they happen" all the time, to spot trends, for
example.

-- 
John Wiegley                  GPG fingerprint = 4710 CF98 AF9B 327B B80F
http://newartisans.com                          60E1 46C4 BD1A 7AC1 4BA2

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 629 bytes --]

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

> I think the OP wants to:
> 
>   1. Start a profile
>   2. View the "results in progress"
>   3. Allow it to continue execution
>   4. View the "results at the end"

This would be a nice addition to have, but is currently not possible
(and not what I'm after with this patch).  The very act of viewing the
results in progress (which requires accessing the profiler log) creates
a log *and* resets the profiler.  If you access the log again while the
profiler is still running, you'll get a new log starting from that point
of time and spanning until access time.  This can be repeated ad nauseam
and is IMO rather unhelpful.

What can be fixed though is the behaviour of profiler report with a
stopped profiler.  You are still limited to accessing the profiler log
once, but if you make profiler.el cache it (be it by storing it in a
variable before stopping or by opening an already existing profiler
report buffer), the user won't be aware of this limitation, because no
matter how often they display the report, it will stay exactly the same
and not throw an error.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[John Wiegley]

>>>>> Vasilij Schneidermann <v.schneidermann@gmail.com> writes:

> This would be a nice addition to have, but is currently not possible (and
> not what I'm after with this patch). The very act of viewing the results in
> progress (which requires accessing the profiler log) creates a log *and*
> resets the profiler. If you access the log again while the profiler is still
> running, you'll get a new log starting from that point of time and spanning
> until access time. This can be repeated ad nauseam and is IMO rather
> unhelpful.

I see.

> What can be fixed though is the behaviour of profiler report with a stopped
> profiler. You are still limited to accessing the profiler log once, but if
> you make profiler.el cache it (be it by storing it in a variable before
> stopping or by opening an already existing profiler report buffer), the user
> won't be aware of this limitation, because no matter how often they display
> the report, it will stay exactly the same and not throw an error.

You just want the profiler report display to be idempotent? Wouldn't this mean
necessitating another command call in order to reset results? Some people may
be used to the fact that a report resets the results.

-- 
John Wiegley                  GPG fingerprint = 4710 CF98 AF9B 327B B80F
http://newartisans.com                          60E1 46C4 BD1A 7AC1 4BA2

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

> You just want the profiler report display to be idempotent? Wouldn't this mean
> necessitating another command call in order to reset results? Some people may
> be used to the fact that a report resets the results.

That's correct.  I consider an implementation using a variable more
resilient than relying on the user not to kill the buffer (which isn't
as unlikely as you'd think, given newbie questions of how to make Emacs
open less buffers).  Resetting does already have a command,
`profiler-reset`.  I've adjusted it in my patch to set the variables to
`nil` so that it will behave correctly in accordance with the other
changes.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> From: John Wiegley <jwiegley@gmail.com>
> Cc: Vasilij Schneidermann <v.schneidermann@gmail.com>,  22114@debbugs.gnu.org
> Date: Tue, 08 Dec 2015 09:42:37 -0800
> 
> > But why would you need a subsequent access to the same data? The profiler
> > report is in the buffer, and you can review it whenever you want. The buffer
> > has the time of the report creation as part of its name, so the next report
> > will not destroy the buffer. You can also save the report to a file (there's
> > a separate command to do that). By contrast,producing a report again from
> > the same data will simply produce an identical report.
> 
> > I guess I don't see a use case where the user would need to produce the same
> > report twice. I never needed that myself, FWIW.
> 
> I think the OP wants to:
> 
>   1. Start a profile
>   2. View the "results in progress"
>   3. Allow it to continue execution
>   4. View the "results at the end"
> 
> It's step #2 that's missing. If we can only view the results in progress by
> taking away the option for #4, this is less optimal.

This is a completely different issue, and AFAIU the proposed patch
didn't allow that.  The C-level implementation of producing a profiler
log (which is then used to format a report) resets the profile data
once it returns the log, and then starts collecting the profile data
anew.  The OP's patch didn't change that.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[John Wiegley]

>>>>> Eli Zaretskii <eliz@gnu.org> writes:

> This is a completely different issue, and AFAIU the proposed patch didn't
> allow that. The C-level implementation of producing a profiler log (which is
> then used to format a report) resets the profile data once it returns the
> log, and then starts collecting the profile data anew. The OP's patch didn't
> change that.

Ah right, thanks for clarifying.

-- 
John Wiegley                  GPG fingerprint = 4710 CF98 AF9B 327B B80F
http://newartisans.com                          60E1 46C4 BD1A 7AC1 4BA2

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

> This is a completely different issue, and AFAIU the proposed patch
> didn't allow that.  The C-level implementation of producing a profiler
> log (which is then used to format a report) resets the profile data
> once it returns the log, and then starts collecting the profile data
> anew.  The OP's patch didn't change that.

How feasible would it be to make the log a regular hash table, fill it
with vectors of the right size and then manipulate these vectors every
time a profiling signal is received?  Or alternatively, fiddle with the
hash table values?  A successful patch doing that would remove the need
for being clever about storing logs/reports, resetting logs and on top
of that allow you to view in-progress reports like John Wiegley
suggested.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

Meanwhile, I've come up with a simpler approach to solving this at the C
level.  Basically the problem is that if log is exposed, it cannot be
used again from profiler.el.  What if one would just create a deep copy
of the log that can be safely used externally?

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

[-- Attachment #1: Type: text/plain, Size: 712 bytes --]

On 12/13/15 at 09:33pm, Vasilij Schneidermann wrote:
> What if one would just create a deep copy of the log that can be
> safely used externally?

Apparently not even that is necessary.  I wrote another variant of the
patch that disables the check for a running profiler before generating a
report, avoids erroring out if generating a report for a non-running
profiler and doesn't reset the log after stopping.  Either my testing
has been too superficial and something unexpected will come bite me or
the comments are simply outdated.

I've taken the liberty to include Paul Eggert and Stefan Monnier into
the CC as they've contributed several patches to profiler.c and should
be able to illuminate this matter.

[-- Attachment #2: 0001-Disable-profiler-log-reset-on-stop.patch --]
[-- Type: text/x-diff, Size: 3829 bytes --]

From 7153c42d55d14ad6d367f4e7f8a5482cb814e810 Mon Sep 17 00:00:00 2001
From: Vasilij Schneidermann <v.schneidermann@gmail.com>
Date: Sun, 13 Dec 2015 23:09:12 +0100
Subject: [PATCH] Disable profiler log reset on stop

---
 lisp/profiler.el | 31 +++++++++++++++----------------
 src/profiler.c   | 16 +---------------
 2 files changed, 16 insertions(+), 31 deletions(-)

diff --git a/lisp/profiler.el b/lisp/profiler.el
index f28bbfe..90a4241 100644
--- a/lisp/profiler.el
+++ b/lisp/profiler.el
@@ -216,19 +216,17 @@ Optional argument MODE means only check for the specified mode (cpu or mem)."
 
 (defun profiler-cpu-profile ()
   "Return CPU profile."
-  (when (profiler-running-p 'cpu)
-    (profiler-make-profile
-     :type 'cpu
-     :timestamp (current-time)
-     :log (profiler-cpu-log))))
+  (profiler-make-profile
+   :type 'cpu
+   :timestamp (current-time)
+   :log (profiler-cpu-log)))
 
 (defun profiler-memory-profile ()
   "Return memory profile."
-  (when (profiler-memory-running-p)
-    (profiler-make-profile
-     :type 'memory
-     :timestamp (current-time)
-     :log (profiler-memory-log))))
+  (profiler-make-profile
+   :type 'memory
+   :timestamp (current-time)
+   :log (profiler-memory-log)))
 
 \f
 ;;; Calltrees
@@ -845,20 +843,21 @@ Also, if MODE is `mem' or `cpu+mem', then memory profiler will be started."
   t)
 
 (defun profiler-report-cpu ()
+  (when (profiler-cpu-log))
   (let ((profile (profiler-cpu-profile)))
-    (when profile
-      (profiler-report-profile-other-window profile))))
+    (profiler-report-profile-other-window profile)))
 
 (defun profiler-report-memory ()
   (let ((profile (profiler-memory-profile)))
-    (when profile
-      (profiler-report-profile-other-window profile))))
+    (profiler-report-profile-other-window profile)))
 
 (defun profiler-report ()
   "Report profiling results."
   (interactive)
-  (profiler-report-cpu)
-  (profiler-report-memory))
+  (when (and (fboundp 'profiler-cpu-log) (profiler-cpu-log))
+    (profiler-report-cpu))
+  (when (profiler-memory-log)
+    (profiler-report-memory)))
 
 ;;;###autoload
 (defun profiler-find-profile (filename)
diff --git a/src/profiler.c b/src/profiler.c
index efdb1d9..4cd6bb0 100644
--- a/src/profiler.c
+++ b/src/profiler.c
@@ -41,9 +41,7 @@ static Lisp_Object
 make_log (EMACS_INT heap_size, EMACS_INT max_stack_depth)
 {
   /* We use a standard Elisp hash-table object, but we use it in
-     a special way.  This is OK as long as the object is not exposed
-     to Elisp, i.e. until it is returned by *-profiler-log, after which
-     it can't be used any more.  */
+     a special way.  */
   Lisp_Object log = make_hash_table (hashtest_profiler,
 				     make_number (heap_size),
 				     make_float (DEFAULT_REHASH_SIZE),
@@ -412,12 +410,6 @@ Before returning, a new log is allocated for future samples.  */)
   (void)
 {
   Lisp_Object result = cpu_log;
-  /* Here we're making the log visible to Elisp, so it's not safe any
-     more for our use afterwards since we can't rely on its special
-     pre-allocated keys anymore.  So we have to allocate a new one.  */
-  cpu_log = (profiler_cpu_running
-	     ? make_log (profiler_log_size, profiler_max_stack_depth)
-	     : Qnil);
   Fputhash (Fmake_vector (make_number (1), Qautomatic_gc),
 	    make_number (cpu_gc_count),
 	    result);
@@ -487,12 +479,6 @@ Before returning, a new log is allocated for future samples.  */)
   (void)
 {
   Lisp_Object result = memory_log;
-  /* Here we're making the log visible to Elisp , so it's not safe any
-     more for our use afterwards since we can't rely on its special
-     pre-allocated keys anymore.  So we have to allocate a new one.  */
-  memory_log = (profiler_memory_running
-		? make_log (profiler_log_size, profiler_max_stack_depth)
-		: Qnil);
   return result;
 }
 
-- 
2.6.2

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Stefan Monnier]

> profiler and doesn't reset the log after stopping.  Either my testing
> has been too superficial and something unexpected will come bite me or
> the comments are simply outdated.

Your testing was too superficial.  IIRC The problem to which the comments
refer can only show up if you modify the hash-table.

The problem is corner-case, but real.  And there's no reason not to plug
that hole.  E.g. I don't think you need to the C-side changes to get the
Elisp side to provide the functionality you're looking for.


        Stefan

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

[-- Attachment #1: Type: text/plain, Size: 1161 bytes --]

> Your testing was too superficial.  IIRC The problem to which the comments
> refer can only show up if you modify the hash-table.
> 
> The problem is corner-case, but real.  And there's no reason not to plug
> that hole.

I see, I can trigger this by removing a key from the log.  I haven't
thought about that possibility yet, because, why would you do that?
Nevertheless, if I'd want to fix this, I'd just need to use
`copy-hash-table` on the log and return its result?

> E.g. I don't think you need to the C-side changes to get the Elisp
> side to provide the functionality you're looking for.

I've initially provided an elisp-only patch that works around the
profiler resetting the log with an extra level of indirection:  Before
stopping the profiler or accessing the log while it's still running, the
log is saved to a variable, the other code just accesses that variable
instead of retrieving the log directly.  I'm not really happy with it
though as it does need more code than the other variant and does only
fix the UI aspect of viewing a report after the profiler has been
stopped.  In case you haven't seen it yet, I'll attach it to this
message.

[-- Attachment #2: 0001-Allow-for-retrieving-profiler-logs-after-stopping.patch --]
[-- Type: text/x-diff, Size: 3675 bytes --]

From 3464446b83151ad894ff4ee7f62ed1cb7852b1b6 Mon Sep 17 00:00:00 2001
From: Vasilij Schneidermann <v.schneidermann@gmail.com>
Date: Tue, 8 Dec 2015 09:01:15 +0100
Subject: [PATCH] Allow for retrieving profiler logs after stopping

---
 lisp/profiler.el | 59 +++++++++++++++++++++++++++++++++-----------------------
 1 file changed, 35 insertions(+), 24 deletions(-)

diff --git a/lisp/profiler.el b/lisp/profiler.el
index f28bbfe..10cdcfb 100644
--- a/lisp/profiler.el
+++ b/lisp/profiler.el
@@ -214,21 +214,23 @@ Optional argument MODE means only check for the specified mode (cpu or mem)."
         (t (or (profiler-running-p 'cpu)
                (profiler-running-p 'mem)))))
 
+(defvar profiler-cpu-log nil)
+
+(defvar profiler-memory-log nil)
+
 (defun profiler-cpu-profile ()
   "Return CPU profile."
-  (when (profiler-running-p 'cpu)
-    (profiler-make-profile
-     :type 'cpu
-     :timestamp (current-time)
-     :log (profiler-cpu-log))))
+  (profiler-make-profile
+   :type 'cpu
+   :timestamp (current-time)
+   :log profiler-cpu-log))
 
 (defun profiler-memory-profile ()
   "Return memory profile."
-  (when (profiler-memory-running-p)
-    (profiler-make-profile
-     :type 'memory
-     :timestamp (current-time)
-     :log (profiler-memory-log))))
+  (profiler-make-profile
+   :type 'memory
+   :timestamp (current-time)
+   :log profiler-memory-log))
 
 \f
 ;;; Calltrees
@@ -828,7 +830,11 @@ Also, if MODE is `mem' or `cpu+mem', then memory profiler will be started."
 (defun profiler-stop ()
   "Stop started profilers.  Profiler logs will be kept."
   (interactive)
-  (let ((cpu (if (fboundp 'profiler-cpu-stop) (profiler-cpu-stop)))
+  (when (and (fboundp 'profiler-cpu-running-p) (profiler-cpu-running-p))
+    (setq profiler-cpu-log (profiler-cpu-log)))
+  (when (profiler-memory-running-p)
+    (setq profiler-memory-log (profiler-memory-log)))
+  (let ((cpu (when (fboundp 'profiler-cpu-stop) (profiler-cpu-stop)))
         (mem (profiler-memory-stop)))
     (message "%s profiler stopped"
              (cond ((and mem cpu) "CPU and memory")
@@ -839,26 +845,31 @@ Also, if MODE is `mem' or `cpu+mem', then memory profiler will be started."
 (defun profiler-reset ()
   "Reset profiler logs."
   (interactive)
-  (when (fboundp 'profiler-cpu-log)
-    (ignore (profiler-cpu-log)))
-  (ignore (profiler-memory-log))
-  t)
+  (when (and (fboundp 'profiler-cpu-running-p) (profiler-cpu-running-p))
+    (profiler-cpu-stop))
+  (when (profiler-memory-running-p)
+    (profiler-memory-stop))
+  (setq profiler-cpu-log nil
+        profiler-memory-log nil))
 
 (defun profiler-report-cpu ()
-  (let ((profile (profiler-cpu-profile)))
-    (when profile
-      (profiler-report-profile-other-window profile))))
+  (when profiler-cpu-log
+    (profiler-report-profile-other-window (profiler-cpu-profile))))
 
 (defun profiler-report-memory ()
-  (let ((profile (profiler-memory-profile)))
-    (when profile
-      (profiler-report-profile-other-window profile))))
+  (when profiler-memory-log
+    (profiler-report-profile-other-window (profiler-memory-profile))))
 
 (defun profiler-report ()
   "Report profiling results."
-  (interactive)
-  (profiler-report-cpu)
-  (profiler-report-memory))
+  (when (and (fboundp 'profiler-cpu-running-p) (profiler-cpu-running-p))
+    (setq profiler-cpu-log (profiler-cpu-log)))
+  (when (profiler-memory-running-p)
+    (setq profiler-memory-log (profiler-memory-log)))
+  (if (and (not profiler-cpu-log) (not profiler-memory-log))
+      (user-error "No profiler run recorded")
+    (profiler-report-cpu)
+    (profiler-report-memory)))
 
 ;;;###autoload
 (defun profiler-find-profile (filename)
-- 
2.6.2

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Stefan Monnier]

>> Your testing was too superficial.  IIRC The problem to which the comments
>> refer can only show up if you modify the hash-table.
>> The problem is corner-case, but real.  And there's no reason not to plug
>> that hole.
> I see, I can trigger this by removing a key from the log.  I haven't
> thought about that possibility yet, because, why would you do that?
> Nevertheless, if I'd want to fix this, I'd just need to use
> `copy-hash-table` on the log and return its result?

Yes, copying the hash table would solve this, tho if you still share the
keys there's a risk of interference (e.g. if you go and modify one of
the arrays used as keys), but there shouldn't be any risk of a crash,
at least.

> Before stopping the profiler or accessing the log while it's still
> running, the log is saved to a variable, the other code just accesses
> that variable instead of retrieving the log directly.
[...]
> In case you haven't seen it yet, I'll attach it to this message.

That looks OK to me.

> I'm not really happy with it though as it does need more code than the
> other variant and does only fix the UI aspect of viewing a report
> after the profiler has been stopped.

What are the other aspects that worry you?


        Stefan

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

> What are the other aspects that worry you?

If you perform `M-x profiler-report` while the profiler is still
running, every time you do the report, the profiler is reset.  This can
be easily observed by starting it, performing an intensive computation,
viewing the report, then viewing it again after a short while.  The
second report has a lower number of CPU cycles/memory usage.  This isn't
really helpful.  Preserving the profiler status on the other hand would
be because you could then take a look at the usage throughout the stages
of an interesting computation, then later stop it to freeze its status
and inspect the final report.  My elisp-only patch achieves the latter,
the patch involving C however does the former as well.

The only remaining thing I'd need to figure out is how to incorporate a
reset function as profiler.el relies on accessing a log to reset the
profiler...

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Stefan Monnier]

>> What are the other aspects that worry you?
> If you perform `M-x profiler-report` while the profiler is still
> running, every time you do the report, the profiler is reset.

Indeed.  But I think the right way to solve this is to write code that
can merge profiler logs.  It should be pretty easy, especially if you
constrain yourself to logs that have the same stack depth.


        Stefan

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Lars Ingebrigtsen]

Vasilij Schneidermann <v.schneidermann@gmail.com> writes:

> Subject: [PATCH] Allow for retrieving profiler logs after stopping

I've now applied your patch to the Emacs trunk.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

[-- Attachment #1: Type: text/plain, Size: 357 bytes --]

Hello Lars,

> I've now applied your patch to the Emacs trunk.

Thanks!  I've tested it on trunk and noticed a big oversight on my part:
My patch removed the `(interactive)` declaration of the
`profiler-report` command, therefore turning it into a regular function.
Could someone please add that line back before it makes it into the next
release?

Vasilij

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Basil L. Contovounesios]

Vasilij Schneidermann <v.schneidermann@gmail.com> writes:

>> I've now applied your patch to the Emacs trunk.
>
> Thanks!  I've tested it on trunk and noticed a big oversight on my part:
> My patch removed the `(interactive)` declaration of the
> `profiler-report` command, therefore turning it into a regular function.
> Could someone please add that line back before it makes it into the next
> release?

Done[1], thanks.

[1: f24d47359d]: ; Fix last change to profiler-report
  2019-06-30 13:30:03 +0100
  https://git.savannah.gnu.org/cgit/emacs.git/commit/?id=f24d47359d9b6621215f20795d585c5024d91783

-- 
Basil

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

Or imposing a restriction on the profiler workflow such as that it must
be running to produce a profiler report...

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> Date: Tue, 8 Dec 2015 17:40:49 +0100
> From: Vasilij Schneidermann <v.schneidermann@gmail.com>
> Cc: 22114@debbugs.gnu.org
> 
> Or imposing a restriction on the profiler workflow such as that it must
> be running to produce a profiler report...

Sorry, I don't understand this comment.  If the report can be produced
when the profiler is stopped, then the limitation is lifted, right?

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

> Sorry, I don't understand this comment.  If the report can be produced
> when the profiler is stopped, then the limitation is lifted, right?

This was specifically targeted at an earlier comment of yours:

> I don't really understand why profiler.el insists on having the
> profiler running for providing the profile.

My theory as for the code was written this way is that its author
noticed that accessing the log without getting an error is only possible
while the profiler is still running, so he implemented exactly that.
That's why I've discarded my earlier version of the patch (which pretty
much looks like what you've proposed) and replaced it with something
more elaborate working around this problem.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> Date: Tue, 8 Dec 2015 18:44:41 +0100
> From: Vasilij Schneidermann <v.schneidermann@gmail.com>
> Cc: 22114@debbugs.gnu.org
> 
> > Sorry, I don't understand this comment.  If the report can be produced
> > when the profiler is stopped, then the limitation is lifted, right?
> 
> This was specifically targeted at an earlier comment of yours:
> 
> > I don't really understand why profiler.el insists on having the
> > profiler running for providing the profile.
> 
> My theory as for the code was written this way is that its author
> noticed that accessing the log without getting an error is only possible
> while the profiler is still running, so he implemented exactly that.

But that was because of a very simple bug, not some inherent
limitation of the profiler.

> That's why I've discarded my earlier version of the patch (which pretty
> much looks like what you've proposed) and replaced it with something
> more elaborate working around this problem.

I prefer to solve the problem rather than work around it.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Vasilij Schneidermann]

[-- Attachment #1: Type: text/plain, Size: 1426 bytes --]

> I prefer to solve the problem rather than work around it.

I'm not sure I'm understanding this correctly.  How is your suggestion
of just removing the check for whether the profiler is running not a
workaround?  The only way I see of solving this without extra code in
the frontend is by fixing the underlying C code, but you've confirmed
that this is not an option.  At least not without restructuring
profiler.c heavily.

To prove that I'm not the crazy one here, I've written two example
programs in Ruby (with ruby-prof) and Python (with cProfile).  Both of
them calculate a Fibonacci number in a profiler run, then display the
recorded data.  You can easily verify that the profiler behaves
idempotently and does not just discard data on a whim by editing these.
This does make a lot of sense if you consider that profiling data is
precious and would make sure it isn't easily lost unless someone
intentionally discards it.  I've been told by others that other tools
like gprof, perf and callgrind don't reset either, therefore my
conclusion on the topic is that Emacs is the odd one in this group.

Considering that this problem hasn't been reported before, I doubt
anyone has been using the profiler seriously and this change will not
disrupt anyone's workflow (which would need to be weird anyways because
the only user-visible part that did change is that stopping doesn't
prevent you from viewing a profiler run).

[-- Attachment #2: profile.rb --]
[-- Type: application/x-ruby, Size: 238 bytes --]

[-- Attachment #3: profile.py --]
[-- Type: text/x-python, Size: 338 bytes --]

import cProfile, pstats, io

def fib(n):
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n-1) + fib(n-2)

pr = cProfile.Profile()
pr.enable()
fib(30)
pr.disable()

s= io.StringIO()
sortby = 'cumulative'
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[John Wiegley]

>>>>> Vasilij Schneidermann <v.schneidermann@gmail.com> writes:

> Considering that this problem hasn't been reported before, I doubt anyone
> has been using the profiler seriously and this change will not disrupt
> anyone's workflow (which would need to be weird anyways because the only
> user-visible part that did change is that stopping doesn't prevent you from
> viewing a profiler run).

I would like to maintain UI consistency with well-established tools, since
this module is fairly new. How does that sound, Eli?

-- 
John Wiegley                  GPG fingerprint = 4710 CF98 AF9B 327B B80F
http://newartisans.com                          60E1 46C4 BD1A 7AC1 4BA2

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> From: John Wiegley <jwiegley@gmail.com>
> Cc: Eli Zaretskii <eliz@gnu.org>,  John Wiegley <jwiegley@gmail.com>,  22114@debbugs.gnu.org
> Date: Tue, 08 Dec 2015 11:21:15 -0800
> 
> I would like to maintain UI consistency with well-established tools, since
> this module is fairly new. How does that sound, Eli?

I don't see any consistency issue here.  But since I've already
managed to irritate, I guess it's time for me to crawl back under my
rock and let you decide.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[John Wiegley]

>>>>> Eli Zaretskii <eliz@gnu.org> writes:

> I don't see any consistency issue here. But since I've already managed to
> irritate, I guess it's time for me to crawl back under my rock and let you
> decide.

Based on research by the OP, it seems that both Python and Ruby's debuggers
are idempotent in asking for results. Although, like you, I've never before
asked for the same results twice, however, we should keep consistent with
other tools, if only because there's no real reason not to.

-- 
John Wiegley                  GPG fingerprint = 4710 CF98 AF9B 327B B80F
http://newartisans.com                          60E1 46C4 BD1A 7AC1 4BA2

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> Date: Tue, 8 Dec 2015 20:15:23 +0100
> From: Vasilij Schneidermann <v.schneidermann@gmail.com>
> Cc: 22114@debbugs.gnu.org
> 
> > I prefer to solve the problem rather than work around it.
> 
> I'm not sure I'm understanding this correctly.  How is your suggestion
> of just removing the check for whether the profiler is running not a
> workaround?

Removing the check is not what I alluded to.  Removing the check just
lifts the artificial limitation that shouldn't have been there to
begin with.

The problem I didn't want to work around is the one solved by this
hunk:

  @@ -846,12 +844,12 @@

   (defun profiler-report-cpu ()
     (let ((profile (profiler-cpu-profile)))
  -    (when profile
  +    (when (and profile (profiler-profile-log profile))
	 (profiler-report-profile-other-window profile))))

   (defun profiler-report-memory ()
     (let ((profile (profiler-memory-profile)))
  -    (when profile
  +    (when (and profile (profiler-profile-log profile))
	 (profiler-report-profile-other-window profile))))


IOW, the original test was incorrect, and caused errors if only one of
the 2 profiles was collected (as it usually is, since the memory
profiler is mostly useless, so the only really useful one is the cpu
one).

> Considering that this problem hasn't been reported before, I doubt
> anyone has been using the profiler seriously

Actually, I use it all the time.  I just never need to produce again
the same report, that's all.

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Lars Ingebrigtsen]

Eli Zaretskii <eliz@gnu.org> writes:

> I don't really understand why profiler.el insists on having the
> profiler running for providing the profile.  The much simpler patch
> below makes it possible for me to invoke profiler-report whether a
> profile is running or not.  Does it work for you?  If not, can you
> tell what I missed?
>
> --- lisp/profiler.el~4	2015-11-11 07:57:32.000000000 +0200
> +++ lisp/profiler.el	2015-12-08 17:54:27.380084700 +0200
> @@ -216,19 +216,17 @@
>
>  (defun profiler-cpu-profile ()
>    "Return CPU profile."
> -  (when (profiler-running-p 'cpu)
> -    (profiler-make-profile
> -     :type 'cpu
> -     :timestamp (current-time)
> -     :log (profiler-cpu-log))))
> +  (profiler-make-profile
> +   :type 'cpu
> +   :timestamp (current-time)
> +   :log (profiler-cpu-log)))

[etc]

The discussion then turned to other things (like getting in-progress
reports), but this seems like the simplest solution that solves the
originally stated problem.  But it wasn't applied -- I can do that now,
if that's convenient...

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#22114: 24.5; [PATCH] Allow profiler.el to display reports after stopping

[Eli Zaretskii]

> From: Lars Ingebrigtsen <larsi@gnus.org>
> Cc: Vasilij Schneidermann <v.schneidermann@gmail.com>,  22114@debbugs.gnu.org
> Date: Tue, 25 Jun 2019 16:46:47 +0200
> 
> Eli Zaretskii <eliz@gnu.org> writes:
> 
> > I don't really understand why profiler.el insists on having the
> > profiler running for providing the profile.  The much simpler patch
> > below makes it possible for me to invoke profiler-report whether a
> > profile is running or not.  Does it work for you?  If not, can you
> > tell what I missed?
> >
> > --- lisp/profiler.el~4	2015-11-11 07:57:32.000000000 +0200
> > +++ lisp/profiler.el	2015-12-08 17:54:27.380084700 +0200
> > @@ -216,19 +216,17 @@
> >
> >  (defun profiler-cpu-profile ()
> >    "Return CPU profile."
> > -  (when (profiler-running-p 'cpu)
> > -    (profiler-make-profile
> > -     :type 'cpu
> > -     :timestamp (current-time)
> > -     :log (profiler-cpu-log))))
> > +  (profiler-make-profile
> > +   :type 'cpu
> > +   :timestamp (current-time)
> > +   :log (profiler-cpu-log)))
> 
> [etc]
> 
> The discussion then turned to other things (like getting in-progress
> reports), but this seems like the simplest solution that solves the
> originally stated problem.  But it wasn't applied -- I can do that now,
> if that's convenient...

I think Stefan endorsed the last patch posted there, so maybe that's
what should be pushed.