bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Ihor Radchenko]

Hello,

Since ~few months ago, I started having issues with profiler dumps
shared by users.  The latest example is in
https://list.orgmode.org/87r0axvu7y.fsf@gmail.com/T/#u

When trying to open the profiler data with M-x profiler-find-profile, I
keep getting
profiler-find-profile: Invalid read syntax: "#<", 2, 64028
or similar errors.

In other words, unreadable objects are somehow dumped, rendering the
profiles useless.

To reproduce,
1. emacs -Q
2. M-x profiler-start RET cpu RET
3. M-x profiler-report
4. M-x profiler-report-write-profile /tmp/1.eld
5. M-x profiler-find-profile /tmp/1.eld

In GNU Emacs 31.0.50 (build 1, x86_64-pc-linux-gnu, GTK+ Version
 3.24.42, cairo version 1.18.0) of 2024-07-26 built on localhost
Repository revision: ba708a0681eced555585fb8281f24b75b32c4178
Repository branch: master
Windowing system distributor 'The X.Org Foundation', version 11.0.12101013
System Description: Gentoo Linux

-- 
Ihor Radchenko // yantar92,
Org mode contributor,
Learn more about Org mode at <https://orgmode.org/>.
Support Org development at <https://liberapay.com/org-mode>,
or support my work at <https://liberapay.com/yantar92>

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Eli Zaretskii]

> From: Ihor Radchenko <yantar92@posteo.net>
> Date: Sat, 10 Aug 2024 12:41:52 +0000
> 
> Since ~few months ago, I started having issues with profiler dumps
> shared by users.  The latest example is in
> https://list.orgmode.org/87r0axvu7y.fsf@gmail.com/T/#u
> 
> When trying to open the profiler data with M-x profiler-find-profile, I
> keep getting
> profiler-find-profile: Invalid read syntax: "#<", 2, 64028
> or similar errors.
> 
> In other words, unreadable objects are somehow dumped, rendering the
> profiles useless.

Does this happen on the emacs-30 branch as well?

In any case, bisection would be useful.

Thanks.

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Ihor Radchenko]

Eli Zaretskii <eliz@gnu.org> writes:

>> In other words, unreadable objects are somehow dumped, rendering the
>> profiles useless.
>
> Does this happen on the emacs-30 branch as well?

Yes

GNU Emacs 30.0.60 (build 1, x86_64-pc-linux-gnu, cairo version 1.18.0) of 2024-06-29
CPU profiler started
You can run the command ‘profiler-report’ with M-x pr-repo
File ‘/tmp/2.eld’ exists; overwrite? (y or n) y
Saving file /tmp/2.eld...
Wrote /tmp/2.eld
profiler-find-profile: Invalid read syntax: "#<", 2, 1990

> In any case, bisection would be useful.

It may take some time. I have a long Org mode backlog to work on in the
coming days.

-- 
Ihor Radchenko // yantar92,
Org mode contributor,
Learn more about Org mode at <https://orgmode.org/>.
Support Org development at <https://liberapay.com/org-mode>,
or support my work at <https://liberapay.com/yantar92>

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Pip Cet via Bug reports for GNU Emacs, the Swiss army knife of text editors]

"Ihor Radchenko" <yantar92@posteo.net> writes:

> Since ~few months ago, I started having issues with profiler dumps
> shared by users.  The latest example is in
> https://list.orgmode.org/87r0axvu7y.fsf@gmail.com/T/#u
>
> When trying to open the profiler data with M-x profiler-find-profile, I
> keep getting
> profiler-find-profile: Invalid read syntax: "#<", 2, 64028
> or similar errors.

(Just trying to save others the work of going to character 64028 in that
dump).

In that example, the relevant section of the dump looks like this:

#[0 "..." [#<killed buffer> buffer-name kill-buffer] 2]

Which looks like a byte code closure produced by make-closure, probably
by with-temp-buffer:

(defmacro with-temp-buffer (&rest body)
  "Create a temporary buffer, and evaluate BODY there like `progn'.
The buffer does not run the hooks `kill-buffer-hook',
`kill-buffer-query-functions', and `buffer-list-update-hook'.
See also `with-temp-file' and `with-output-to-string'."
  (declare (indent 0) (debug t))
  (let ((temp-buffer (make-symbol "temp-buffer")))
    `(let ((,temp-buffer (generate-new-buffer " *temp*" t)))
       ;; `kill-buffer' can change current-buffer in some odd cases.
       (with-current-buffer ,temp-buffer
         (unwind-protect
	     (progn ,@body)
           (and (buffer-name ,temp-buffer)
                (kill-buffer ,temp-buffer)))))))

No idea what a good fix would be, though.

Pip

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Eli Zaretskii]

> Cc: 72559@debbugs.gnu.org
> Date: Sat, 10 Aug 2024 13:56:49 +0000
> From:  Pip Cet via "Bug reports for GNU Emacs,
>  the Swiss army knife of text editors" <bug-gnu-emacs@gnu.org>
> 
> "Ihor Radchenko" <yantar92@posteo.net> writes:
> 
> > Since ~few months ago, I started having issues with profiler dumps
> > shared by users.  The latest example is in
> > https://list.orgmode.org/87r0axvu7y.fsf@gmail.com/T/#u
> >
> > When trying to open the profiler data with M-x profiler-find-profile, I
> > keep getting
> > profiler-find-profile: Invalid read syntax: "#<", 2, 64028
> > or similar errors.
> 
> (Just trying to save others the work of going to character 64028 in that
> dump).
> 
> In that example, the relevant section of the dump looks like this:
> 
> #[0 "..." [#<killed buffer> buffer-name kill-buffer] 2]
> 
> Which looks like a byte code closure produced by make-closure, probably
> by with-temp-buffer:
> 
> (defmacro with-temp-buffer (&rest body)
>   "Create a temporary buffer, and evaluate BODY there like `progn'.
> The buffer does not run the hooks `kill-buffer-hook',
> `kill-buffer-query-functions', and `buffer-list-update-hook'.
> See also `with-temp-file' and `with-output-to-string'."
>   (declare (indent 0) (debug t))
>   (let ((temp-buffer (make-symbol "temp-buffer")))
>     `(let ((,temp-buffer (generate-new-buffer " *temp*" t)))
>        ;; `kill-buffer' can change current-buffer in some odd cases.
>        (with-current-buffer ,temp-buffer
>          (unwind-protect
> 	     (progn ,@body)
>            (and (buffer-name ,temp-buffer)
>                 (kill-buffer ,temp-buffer)))))))
> 
> No idea what a good fix would be, though.

Thanks, adding Stefan in the hope that he could have some ideas.

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Eli Zaretskii]

> Cc: 72559@debbugs.gnu.org
> Date: Sat, 10 Aug 2024 13:56:49 +0000
> From:  Pip Cet via "Bug reports for GNU Emacs,
>  the Swiss army knife of text editors" <bug-gnu-emacs@gnu.org>
> 
> "Ihor Radchenko" <yantar92@posteo.net> writes:
> 
> > Since ~few months ago, I started having issues with profiler dumps
> > shared by users.  The latest example is in
> > https://list.orgmode.org/87r0axvu7y.fsf@gmail.com/T/#u
> >
> > When trying to open the profiler data with M-x profiler-find-profile, I
> > keep getting
> > profiler-find-profile: Invalid read syntax: "#<", 2, 64028
> > or similar errors.
> 
> (Just trying to save others the work of going to character 64028 in that
> dump).
> 
> In that example, the relevant section of the dump looks like this:
> 
> #[0 "..." [#<killed buffer> buffer-name kill-buffer] 2]
> 
> Which looks like a byte code closure produced by make-closure, probably
> by with-temp-buffer:

I think the problem is that we now dump the buttons into the saved
profile.  We also write symbols as strings.  Two examples:

  ["redisplay_internal (C function)" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil"]

  [#("vertical-motion" 0 15 (help-args (vertical-motion) category help-function-button button (t))) #("line-move-visual" 0 16 (help-args (line-move-visual) category help-function-button button (t))) #("line-move" 0 9 (help-args (line-move) category help-function-button button (t))) #("previous-line" 0 13 (help-args (previous-line) category help-function-button button (t))) #("funcall-interactively" 0 21 (help-args (funcall-interactively) category help-function-button button (t))) #("call-interactively" 0 18 (help-args (call-interactively) category help-function-button button (t))) #("command-execute" 0 15 (help-args (command-execute) category help-function-button button (t))) "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil" "nil"]

And finally, even reading a profile written by Emacs 29 produces bogus
entries, like #<string 847> instead of  #<compiled 0xe6a63a01a3790bb>.

So something is seriously foobar in profiler.el, or maybe in the
printing infrastructure it uses.

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Stefan Monnier via Bug reports for GNU Emacs, the Swiss army knife of text editors]

> I think the problem is that we now dump the buttons into the saved
> profile.  We also write symbols as strings.  Two examples:

Yup, I introduced the bug in commit a1f8702e8345.
I think the patch below is in order (it partly undoes commit
a1f8702e8345).

Can someone confirm that it fixes the problem for them as well?


        Stefan

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: Pip Cet <pipcet@protonmail.com>,  yantar92@posteo.net,
>   72559@debbugs.gnu.org
> Date: Wed, 14 Aug 2024 08:21:07 -0400
> 
> > I think the problem is that we now dump the buttons into the saved
> > profile.  We also write symbols as strings.  Two examples:
> 
> Yup, I introduced the bug in commit a1f8702e8345.
> I think the patch below is in order (it partly undoes commit
> a1f8702e8345).
> 
> Can someone confirm that it fixes the problem for them as well?

ENOPATCH

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Stefan Monnier via Bug reports for GNU Emacs, the Swiss army knife of text editors]

> I think the patch below is in order (it partly undoes commit
> a1f8702e8345).

Yeah, yeah,


        Stefan


diff --git a/lisp/profiler.el b/lisp/profiler.el
index eb72f128c07..a5d62e20e3a 100644
--- a/lisp/profiler.el
+++ b/lisp/profiler.el
@@ -103,8 +103,13 @@ profiler-format
 \f
 ;;; Backtraces
 
+(defun profiler-fixup-entry (entry)
+  (if (symbolp entry)
+      entry
+    (substring-no-properties (help-fns-function-name entry))))
+
 (defun profiler-fixup-backtrace (backtrace)
-  (apply #'vector (mapcar #'help-fns-function-name backtrace)))
+  (apply #'vector (mapcar #'profiler-fixup-entry backtrace)))
 
 \f
 ;;; Logs

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: Pip Cet <pipcet@protonmail.com>,  yantar92@posteo.net,
>   72559@debbugs.gnu.org
> Date: Wed, 14 Aug 2024 08:48:43 -0400
> 
> > I think the patch below is in order (it partly undoes commit
> > a1f8702e8345).
> 
> Yeah, yeah,

Thanks, installed on the emacs-30 branch.

This seems to avoid errors, but I still see problems in the profile
read from a file, which is displayed like this:

     Samples    %   Function
          35  31%   redisplay_internal (C function)
          28  25% + command-execute
          28  25%   Automatic GC
           8   7% + #<string 540>
           7   6% + ...
           4   3% + #<string 54A>
           2   1% + #<string 57C>

Those "<string XYZ>" thingies are actually written in the file as
"#<byte-code-function F85>" strings, and I suspect that they should
have been written as function objects, not as strings.

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Stefan Monnier via Bug reports for GNU Emacs, the Swiss army knife of text editors]

> This seems to avoid errors, but I still see problems in the profile
> read from a file, which is displayed like this:
>
>      Samples    %   Function
>           35  31%   redisplay_internal (C function)
>           28  25% + command-execute
>           28  25%   Automatic GC
>            8   7% + #<string 540>
>            7   6% + ...
>            4   3% + #<string 54A>
>            2   1% + #<string 57C>
>
> Those "<string XYZ>" thingies are actually written in the file as
> "#<byte-code-function F85>" strings, and I suspect that they should
> have been written as function objects, not as strings.

I don't think we want to write them as function objects, because then
we'll again bump into the problem that some function objects contain
unprintable objects like buffers.

Better would be to print the "#<byte-code-function F85>" strings
as-is instead of printing them as #<string 540>.

Of course, we could also try to print the function objects and then
verify that they are printed readably and only print them as strings
when that fails.


        Stefan

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: pipcet@protonmail.com,  yantar92@posteo.net,  72559@debbugs.gnu.org
> Date: Sat, 17 Aug 2024 10:07:59 -0400
> 
> > This seems to avoid errors, but I still see problems in the profile
> > read from a file, which is displayed like this:
> >
> >      Samples    %   Function
> >           35  31%   redisplay_internal (C function)
> >           28  25% + command-execute
> >           28  25%   Automatic GC
> >            8   7% + #<string 540>
> >            7   6% + ...
> >            4   3% + #<string 54A>
> >            2   1% + #<string 57C>
> >
> > Those "<string XYZ>" thingies are actually written in the file as
> > "#<byte-code-function F85>" strings, and I suspect that they should
> > have been written as function objects, not as strings.
> 
> I don't think we want to write them as function objects, because then
> we'll again bump into the problem that some function objects contain
> unprintable objects like buffers.

But Emacs 29 does succeed there, at least in my testing, including
when the profile shows byte-compiled functions.  So how come Emacs 30
cannot?

> Better would be to print the "#<byte-code-function F85>" strings
> as-is instead of printing them as #<string 540>.

Again, Emacs 30 shows the functions called by such byte-compiled
functions.

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Stefan Monnier via Bug reports for GNU Emacs, the Swiss army knife of text editors]

>> I don't think we want to write them as function objects, because then
>> we'll again bump into the problem that some function objects contain
>> unprintable objects like buffers.
> But Emacs 29 does succeed there, at least in my testing, including
> when the profile shows byte-compiled functions.  So how come Emacs 30
> cannot?

Emacs-29 did:

    (defun profiler-format-entry (entry)
      "Format ENTRY in human readable string.
    ENTRY would be a function name of a function itself."
      (cond ((memq (car-safe entry) '(closure lambda))
             (format "#<lambda %#x>" (sxhash entry)))
            ((byte-code-function-p entry)
             (format "#<compiled %#x>" (sxhash entry)))
            ((or (subrp entry) (symbolp entry) (stringp entry))
             (format "%s" entry))
            (t
             (format "#<unknown %#x>" (sxhash entry)))))

    (defun profiler-fixup-entry (entry)
      (if (symbolp entry)
          entry
        (profiler-format-entry entry)))

IOW it did not save the actual function object but only some kind of
"name" (like we do now).

And then when using such a saved backtrace, the `stringp` above made it
print just that name.  My suggestion above (as in the patch below) just
re-instates that previous behavior.


        Stefan


diff --git a/lisp/profiler.el b/lisp/profiler.el
index a5d62e20e3a..34e4d7032df 100644
--- a/lisp/profiler.el
+++ b/lisp/profiler.el
@@ -452,6 +452,11 @@ profiler-report-make-entry-part
   (let ((string (cond
 		 ((eq entry t)
 		  "Others")
+		 ;; When we save profile data into a file, the function
+                 ;; objects are replaced with their "names".  When we see
+                 ;; a string here, that's presumably why, so just print
+                 ;; it as-is.
+		 ((stringp entry) entry)
 		 (t (propertize (help-fns-function-name entry)
 		                ;; Override the `button-map' which
 		                ;; otherwise adds RET, mouse-1, and TAB

bug#72559: 31.0.50; profiler-report-write-profile produced unreadable data

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: pipcet@protonmail.com,  yantar92@posteo.net,  72559@debbugs.gnu.org
> Date: Sat, 17 Aug 2024 13:35:07 -0400
> 
> >> I don't think we want to write them as function objects, because then
> >> we'll again bump into the problem that some function objects contain
> >> unprintable objects like buffers.
> > But Emacs 29 does succeed there, at least in my testing, including
> > when the profile shows byte-compiled functions.  So how come Emacs 30
> > cannot?
> 
> Emacs-29 did:
> 
>     (defun profiler-format-entry (entry)
>       "Format ENTRY in human readable string.
>     ENTRY would be a function name of a function itself."
>       (cond ((memq (car-safe entry) '(closure lambda))
>              (format "#<lambda %#x>" (sxhash entry)))
>             ((byte-code-function-p entry)
>              (format "#<compiled %#x>" (sxhash entry)))
>             ((or (subrp entry) (symbolp entry) (stringp entry))
>              (format "%s" entry))
>             (t
>              (format "#<unknown %#x>" (sxhash entry)))))
> 
>     (defun profiler-fixup-entry (entry)
>       (if (symbolp entry)
>           entry
>         (profiler-format-entry entry)))
> 
> IOW it did not save the actual function object but only some kind of
> "name" (like we do now).
> 
> And then when using such a saved backtrace, the `stringp` above made it
> print just that name.  My suggestion above (as in the patch below) just
> re-instates that previous behavior.

Thanks, installed on the emacs-30 branch, and closing the bug.