Re: [PATCH] Babel evaluation: location and timing information (v2)
Hi All, I’ve now resolved all the documentation issues Ihor raised, and since there were no other concerns raised, I’ve just pushed this as e8a797e1437d7aef2ce414694d2b642683f79976. All the best, Timothy
Re: [PATCH] Babel evaluation: location and timing information (v2)
Timothy writes: > * lisp/ob-core.el (org-babel-execute-src-block, > org-babel-format-result): Record the babel execution time, and then > supplement the "Code block evaluation complete." (etc.) messages with > the execution time when >0.05s. I'd also mention the new optional arguments. > -(defun org-babel-execute-src-block (&optional arg info params) > +(defun org-babel-execute-src-block (&optional arg info params executor) >"Execute the current source code block and return the result. > Insert the results of execution into the buffer. Source code > execution and the collection and formatting of results can be > @@ -729,13 +729,31 @@ (defun org-babel-execute-src-block (&optional arg info > params) > > Optionally supply a value for PARAMS which will be merged with > the header arguments specified at the front of the source code > -block." > +block. > + > +EXECUTOR is the type of the org element responsible for the > +execution of the source block. If not provided then this is > +inferred to be a source block or inline source block, inspecting > +the buffer content at the block location to determine which." This argument name executor sounds awkward. Why not something like src-block-type? > + (executor > + (or executor > + ;; If `executor' is unset, then this cannot be a babel > + ;; call (as `org-babel-lob-execute-maybe' provides the > + ;; type of the execution triggering element) and so this > + ;; must be an inline src block or src block. We can > + ;; easily pick between the two by just looking at the > + ;; first character of each case. In case something > + ;; strange happens, this can be set to unknown. This comment is confusing. From my reading of it, you only consider internal usage of `org-babel-execute-src-block' in Org code. But `org-babel-execute-src-block' is not an internal function and hence we cannot assume the callers. I think that it is sufficient to stick to what the docstring says about nil EXECUTOR value. -- Ihor Radchenko, 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
Re: [PATCH] Babel evaluation: location and timing information (v2)
Hi All, Ihor raised a concern about the time needed to determine element type. This information is now passed on from other parts of Org, so there’s no overhead from this any more. Since this also applies to inline types, I’ve switched to showing the point position instead of the line number. As a side effect, that renders concerns about the performance of `line-number-at-pos' moot. So, I think this set of patches should be good to go. Let me know if you can spot anything else that looks like it should be tweaked. All the best, Timothy >From 81c5cf82cffd2b01fac39eaaf7a1a6ee58802e25 Mon Sep 17 00:00:00 2001 From: TEC Date: Sat, 17 Sep 2022 17:53:01 +0800 Subject: [PATCH 3/3] ob-core: Display babel execution time * lisp/ob-core.el (org-babel-execute-src-block, org-babel-format-result): Record the babel execution time, and then supplement the "Code block evaluation complete." (etc.) messages with the execution time when >0.05s. --- lisp/ob-core.el | 30 -- 1 file changed, 20 insertions(+), 10 deletions(-) diff --git a/lisp/ob-core.el b/lisp/ob-core.el index c2f5eccfd..e6802e739 100644 --- a/lisp/ob-core.el +++ b/lisp/ob-core.el @@ -791,7 +791,7 @@ (defun org-babel-execute-src-block (&optional arg info params executor) (make-directory d 'parents) d (cmd (intern (concat "org-babel-execute:" lang))) - result) + result exec-start-time) (unless (fboundp cmd) (error "No org-babel-execute function for %s!" lang)) (message "executing %s %s %s..." @@ -806,7 +806,8 @@ (defun org-babel-execute-src-block (&optional arg info params executor) (if name (format "(%s)" name) (format "at point %d" (nth 5 info) - (setq result + (setq exec-start-time (current-time) + result (let ((r (funcall cmd body params))) (if (and (eq (cdr (assq :result-type params)) 'value) (or (member "vector" result-params) @@ -849,7 +850,8 @@ (defun org-babel-execute-src-block (&optional arg info params executor) (if (member "none" result-params) (message "result silenced") (org-babel-insert-result - result result-params info new-hash lang))) + result result-params info new-hash lang + (time-subtract (current-time) exec-start-time (run-hooks 'org-babel-after-execute-hook) result))) @@ -2260,7 +2262,7 @@ (defun org-babel-format-result (result &optional sep) ;; scalar result (funcall echo-res result -(defun org-babel-insert-result (result &optional result-params info hash lang) +(defun org-babel-insert-result (result &optional result-params info hash lang exec-time) "Insert RESULT into the current buffer. By default RESULT is inserted after the end of the current source @@ -2268,7 +2270,8 @@ (defun org-babel-insert-result (result &optional result-params info hash lang) wrapped inside a `results' macro and placed on the same line as the inline source block. The macro is stripped upon export. Multiline and non-scalar RESULTS from inline source blocks are -not allowed. With optional argument RESULT-PARAMS controls +not allowed. When EXEC-TIME is provided it may be included in a +generated message. With optional argument RESULT-PARAMS controls insertion of results in the Org mode file. RESULT-PARAMS can take the following values: @@ -2573,11 +2576,18 @@ (defun org-babel-insert-result (result &optional result-params info hash lang) (not (and (listp result) (member "append" result-params (indent-rigidly beg end indent)) - (if (null result) - (if (member "value" result-params) - (message "Code block returned no value.") - (message "Code block produced no output.")) - (message "Code block evaluation complete."))) +(let ((time-info + ;; Only show the time when something other than + ;; 0s will be shown, i.e. check if the time is at + ;; least half of the displayed precision. + (if (and exec-time (> (float-time exec-time) 0.05)) + (format " (took %.1fs)" (float-time exec-time)) + ""))) + (if (null result) + (if (member "value" result-params) + (message "Code block returned no value%s." time-info) +(message "Code block produced no output%s." time-info)) +(message "Code block evaluation complete%s." time-info (set-marker end nil) (when outside-scope (narrow-to-region visible-beg visible-end)) (set-marker visible-beg nil) -- 2.37.1 >From 753d441ea9c190055566a53f88dc0d687ee72808 Mon Sep 17 00:00:00 2001 From: TEC Date: Sat, 17 Sep 2022 17:39:16 +0800 Subject: [PATCH 2/3] ob-core: Display type of element babel executes * lisp/ob-cor
Re: [PATCH] Babel evaluation: location and timing information
Timothy writes: > Hi Ihor, > >>> - (message “executing %s code block%s…” >>> + (message “executing %s %s %s…” >>> (capitalize lang) >>> + (pcase (org-element-type (org-element-at-point)) >>> + (’src-block “code block”) >>> + (’babel-call “call”) >>> + (’paragraph “inline code block”)) >> >> This will not work, for example, when inline src block is located inside >> a headline. One can think of various other non-paragraph scenarios as well. > > Good point. Does assuming anything other than a src block or babel call is an > inline src block sound reasonable? Yes. All other elements (from org-element-all-elements) are non-source-blocks. It will be a good idea to spell out this fact right in the code (in comment). >> Also, even though org-element-at-point should be caching recent calls, >> I’d try to test the performance before/after the patch on large number >> of src blocks (like in your config). org-element-at-point can add a fair >> bit of CPU load in some scenarios where we have fallback to the full >> O(Log N) AVL-tree lookup. > > I’ll see about giving this a shot at some point. Since parsing would be > required > before this point I assumed the document structure would be cached and this > should be fairly cheap. Would `org-element-at-point-no-context' be better > potentially? No, `org-element-at-point-no-context' will not be better. It is only useful in very specific situations when buffer changes are large, frequent, affect large portions of cache, and parsing from the parent heading is faster than updating the change all the way to the top-parent org-data element. It will be better to re-use the element queried during src block execution. >>> +(let ((time-info >>> + (if (and exec-time (> (float-time exec-time) 0.05)) >>> + (format “ (took %.1fs)” (float-time exec-time)) >> >> Why 0.05?? > > Because that’s half the resolution at which the time is displayed at. The idea > is to only show the time when it will show something greater than zero. Makes sense. Could you please add this comment to the code? -- Ihor Radchenko, 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
Re: [PATCH] Babel evaluation: location and timing information
Max Nikulin writes: > While I work with my notes file, performance degrades after some > operations. E.g. searches become significantly slower after caching > refile targets. Previous discussion of the issue: > Ihor Radchenko. Re: profiling latency in large org-mode buffers (under > both main & org-fold feature) Sun, 27 Feb 2022 14:43:29 +0800. > https://list.orgmode.org/87y21wkdwu.fsf@localhost > > My experience is that e.g. emacsclient with particular line causes > several seconds hang. > > Despite improvements since Emacs-26 in line counting, still I believe > that the `line-number-at-pos' function may still be excessively > expensive in real live when unconditionally used just for a bit nicer > logging. May I ask if other Org operations are also slow in that problematic file with many markers? If so, I do not think that we need to worry about performance of `line-number-at-pos'. Rather we just wait for Emacs to fix problems with markers. See the discussion in https://yhetil.org/emacs-devel/jwvsfntduas.fsf-monnier+em...@gnu.org -- Ihor Radchenko, 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
Re: [PATCH] Babel evaluation: location and timing information
On 22/09/2022 14:03, Timothy wrote: On 18/09/2022 10:09, Timothy wrote: and now this might look like so: ┌ │ executing Emacs-Lisp call on line 143… │ Code block evaluation complete (took 0.2s). └ I do not mind to have such feature, but I am unsure concerning its price. I just have tried (benchmark-run 1 (line-number-at-pos)) (2.244481896 0 0.0) What on earth did you run that on? I ran that on the last line of the Org manual and here’s what I got: ┌ │ (0.000219268 0 0.0) └ Intel(R) Core(TM) i5-4210U CPU @ 1.70GHz It is an 8 years old laptop, minimal CPU frequency is 0.8GHz. Org manual is ~5 times smaller than my file with notes and the former contains not so much not ASCII characters. For your test I get reasonable numbers Emacs-26 0.038 or 0.084 Emacs-27 0.0066 or 0.0092 I am comfortable with performance. It seems, some optimization has been done in Emacs since 26 release. I do not see dependence on Org version. While I work with my notes file, performance degrades after some operations. E.g. searches become significantly slower after caching refile targets. Previous discussion of the issue: Ihor Radchenko. Re: profiling latency in large org-mode buffers (under both main & org-fold feature) Sun, 27 Feb 2022 14:43:29 +0800. https://list.orgmode.org/87y21wkdwu.fsf@localhost My experience is that e.g. emacsclient with particular line causes several seconds hang. Despite improvements since Emacs-26 in line counting, still I believe that the `line-number-at-pos' function may still be excessively expensive in real live when unconditionally used just for a bit nicer logging.
Re: [PATCH] Babel evaluation: location and timing information
Hi Ihor, >> -(message “executing %s code block%s…” >> +(message “executing %s %s %s…” >> (capitalize lang) >> + (pcase (org-element-type (org-element-at-point)) >> + (’src-block “code block”) >> + (’babel-call “call”) >> + (’paragraph “inline code block”)) > > This will not work, for example, when inline src block is located inside > a headline. One can think of various other non-paragraph scenarios as well. Good point. Does assuming anything other than a src block or babel call is an inline src block sound reasonable? > Also, even though org-element-at-point should be caching recent calls, > I’d try to test the performance before/after the patch on large number > of src blocks (like in your config). org-element-at-point can add a fair > bit of CPU load in some scenarios where we have fallback to the full > O(Log N) AVL-tree lookup. I’ll see about giving this a shot at some point. Since parsing would be required before this point I assumed the document structure would be cached and this should be fairly cheap. Would `org-element-at-point-no-context' be better potentially? >> +(let ((time-info >> + (if (and exec-time (> (float-time exec-time) 0.05)) >> + (format “ (took %.1fs)” (float-time exec-time)) > > Why 0.05?? Because that’s half the resolution at which the time is displayed at. The idea is to only show the time when it will show something greater than zero. All the best, Timothy
Re: [PATCH] Babel evaluation: location and timing information
Hi Max, > On 18/09/2022 10:09, Timothy wrote: >> and now this might look like so: >> ┌ >> │ executing Emacs-Lisp call on line 143… >> │ Code block evaluation complete (took 0.2s). >> └ > > I do not mind to have such feature, but I am unsure concerning its price. I > just > have tried > > (benchmark-run 1 (line-number-at-pos)) > > (2.244481896 0 0.0) > > It is time in seconds… What on earth did you run that on? I ran that on the last line of the Org manual and here’s what I got: ┌ │ (0.000219268 0 0.0) └ All the best, Timothy
Re: [PATCH] Babel evaluation: location and timing information
Timothy writes:
> - (message "executing %s code block%s..."
> + (message "executing %s %s %s..."
>(capitalize lang)
> + (pcase (org-element-type (org-element-at-point))
> + ('src-block "code block")
> + ('babel-call "call")
> + ('paragraph "inline code block"))
This will not work, for example, when inline src block is located inside
a headline. One can think of various other non-paragraph scenarios as well.
Also, even though org-element-at-point should be caching recent calls,
I'd try to test the performance before/after the patch on large number
of src blocks (like in your config). org-element-at-point can add a fair
bit of CPU load in some scenarios where we have fallback to the full
O(Log N) AVL-tree lookup.
> +(let ((time-info
> + (if (and exec-time (> (float-time exec-time) 0.05))
> + (format " (took %.1fs)" (float-time exec-time))
Why 0.05??
--
Ihor Radchenko,
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
Re: [PATCH] Babel evaluation: location and timing information
On 18/09/2022 10:09, Timothy wrote: and now this might look like so: ┌ │ executing Emacs-Lisp call on line 143... │ Code block evaluation complete (took 0.2s). └ I do not mind to have such feature, but I am unsure concerning its price. I just have tried (benchmark-run 1 (line-number-at-pos)) (2.244481896 0 0.0) It is time in seconds...
Re: [PATCH] Babel evaluation: location and timing information
Dear Timothy, this looks very useful. I've not tested it but would ask for one (hopefully minor) addition: could the position information provided include point as well as line number? I tend to use 1 line per paragraph (with visual line mode and org indent mode) and some of my paragraphs might have multiple inline src elements. But not a big deal if not, of course, but I'm a big fan of more information rather than less. I can see the evaluation time being quite useful in profiling! Thank you, eric -- : Eric S Fraga, with org release_9.5.4-768-g5bb699 in Emacs 29.0.50
[PATCH] Babel evaluation: location and timing information
Hi All,
This is a small set of patches to add a bit more information to the messages
emitted in the course of babel evaluation. Specifically about
⁃ What type of element is responsible for the evaluation (source block, babel
call,
inline source)
⁃ Where the element is (if no name is set)
⁃ How long evaluation took
For example, previously `C-c C-c' on a babel call would have produced a message
like this:
┌
│ executing Emacs-Lisp code block...
│ Code block evaluation complete.
└
and now this might look like so:
┌
│ executing Emacs-Lisp call on line 143...
│ Code block evaluation complete (took 0.2s).
└
I think this is a pretty sensible change, but feedback is always nice.
If there are no objections, I expect I’ll merge this in a few days.
All the best,
Timothy
>From 5be372f8185aa8b482f63f182ee1cf252a777c3b Mon Sep 17 00:00:00 2001
From: TEC
Date: Tue, 13 Sep 2022 18:55:06 +0800
Subject: [PATCH 1/3] ob-core: Display line number of exec babel blocks
* lisp/ob-core.el (org-babel-execute-src-block): When an unnamed babel
block is executed, show the line number of the block.
This makes it easier to track the execution without having to name every
block.
---
lisp/ob-core.el | 6 +-
1 file changed, 5 insertions(+), 1 deletion(-)
diff --git a/lisp/ob-core.el b/lisp/ob-core.el
index 8a963fa8e..0a179f379 100644
--- a/lisp/ob-core.el
+++ b/lisp/ob-core.el
@@ -779,7 +779,11 @@ (defun org-babel-execute-src-block (&optional arg info params)
(message "executing %s code block%s..."
(capitalize lang)
(let ((name (nth 4 info)))
- (if name (format " (%s)" name) "")))
+ (if name
+ (format "(%s)" name)
+ (format "on line %d"
+ (line-number-at-pos
+ (or (nth 5 info) org-babel-current-src-block-location))
(setq result
(let ((r (funcall cmd body params)))
(if (and (eq (cdr (assq :result-type params)) 'value)
--
2.37.1
>From 8e55a3e90f4c7bcec796d450e05e953ce3871e81 Mon Sep 17 00:00:00 2001
From: TEC
Date: Sat, 17 Sep 2022 17:39:16 +0800
Subject: [PATCH 2/3] ob-core: Display type of element babel executes
* lisp/ob-core.el (org-babel-execute-src-block): The babel execute
function is run on more than just source blocks, so it makes sense to
note the type of element being executed.
---
lisp/ob-core.el | 6 +-
1 file changed, 5 insertions(+), 1 deletion(-)
diff --git a/lisp/ob-core.el b/lisp/ob-core.el
index 0a179f379..f95bd56e6 100644
--- a/lisp/ob-core.el
+++ b/lisp/ob-core.el
@@ -776,8 +776,12 @@ (defun org-babel-execute-src-block (&optional arg info params)
result)
(unless (fboundp cmd)
(error "No org-babel-execute function for %s!" lang))
- (message "executing %s code block%s..."
+ (message "executing %s %s %s..."
(capitalize lang)
+ (pcase (org-element-type (org-element-at-point))
+ ('src-block "code block")
+ ('babel-call "call")
+ ('paragraph "inline code block"))
(let ((name (nth 4 info)))
(if name
(format "(%s)" name)
--
2.37.1
>From f661b72d7c4837f5fed4201e0c764d0e0c6b0993 Mon Sep 17 00:00:00 2001
From: TEC
Date: Sat, 17 Sep 2022 17:53:01 +0800
Subject: [PATCH 3/3] ob-core: Display babel execution time
* lisp/ob-core.el (org-babel-execute-src-block,
org-babel-format-result): Record the babel execution time, and then
supplement the "Code block evaluation complete." (etc.) messages with
the execution time when >0.05s.
---
lisp/ob-core.el | 27 +--
1 file changed, 17 insertions(+), 10 deletions(-)
diff --git a/lisp/ob-core.el b/lisp/ob-core.el
index f95bd56e6..946b37595 100644
--- a/lisp/ob-core.el
+++ b/lisp/ob-core.el
@@ -773,7 +773,7 @@ (defun org-babel-execute-src-block (&optional arg info params)
(make-directory d 'parents)
d
(cmd (intern (concat "org-babel-execute:" lang)))
- result)
+ result exec-start-time)
(unless (fboundp cmd)
(error "No org-babel-execute function for %s!" lang))
(message "executing %s %s %s..."
@@ -788,7 +788,8 @@ (defun org-babel-execute-src-block (&optional arg info params)
(format "on line %d"
(line-number-at-pos
(or (nth 5 info) org-babel-current-src-block-location))
- (setq result
+ (setq exec-start-time (current-time)
+ result
(let ((r (funcall cmd body params)))
(if (and (eq (cdr (assq :result-type params)) 'value)
(or (member "vector" result-params)
@@ -831,7 +832,8 @@ (defun org-babel-execute-src-block (&optional arg info params)
(if (member "none" result-params)
(message "result silenced")
(org-babel-insert-result
- result result-params info new-hash lang)))
+
