emacs-orgmode@gnu.org archives
 help / color / mirror / code / Atom feed
* [PATCH] Babel evaluation: location and timing information
@ 2022-09-18  3:09 Timothy
  2022-09-19 12:28 ` Fraga, Eric
                   ` (3 more replies)
  0 siblings, 4 replies; 13+ messages in thread
From: Timothy @ 2022-09-18  3:09 UTC (permalink / raw)
  To: emacs-orgmode

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

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

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-ob-core-Display-line-number-of-exec-babel-blocks.patch --]
[-- Type: text/x-patch, Size: 1258 bytes --]

From 5be372f8185aa8b482f63f182ee1cf252a777c3b Mon Sep 17 00:00:00 2001
From: TEC <git@tecosaur.net>
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


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #3: 0002-ob-core-Display-type-of-element-babel-executes.patch --]
[-- Type: text/x-patch, Size: 1228 bytes --]

From 8e55a3e90f4c7bcec796d450e05e953ce3871e81 Mon Sep 17 00:00:00 2001
From: TEC <git@tecosaur.net>
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


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #4: 0003-ob-core-Display-babel-execution-time.patch --]
[-- Type: text/x-patch, Size: 4087 bytes --]

From f661b72d7c4837f5fed4201e0c764d0e0c6b0993 Mon Sep 17 00:00:00 2001
From: TEC <git@tecosaur.net>
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)))
+	         result result-params info new-hash lang
+                 (time-subtract (current-time) exec-start-time))))
 	    (run-hooks 'org-babel-after-execute-hook)
 	    result)))))))
 
@@ -2242,7 +2244,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
@@ -2250,7 +2252,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:
 
@@ -2555,11 +2558,15 @@ (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
+                       (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


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-18  3:09 [PATCH] Babel evaluation: location and timing information Timothy
@ 2022-09-19 12:28 ` Fraga, Eric
  2022-09-19 14:52 ` Max Nikulin
                   ` (2 subsequent siblings)
  3 siblings, 0 replies; 13+ messages in thread
From: Fraga, Eric @ 2022-09-19 12:28 UTC (permalink / raw)
  To: Timothy; +Cc: emacs-orgmode@gnu.org

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

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-18  3:09 [PATCH] Babel evaluation: location and timing information Timothy
  2022-09-19 12:28 ` Fraga, Eric
@ 2022-09-19 14:52 ` Max Nikulin
  2022-09-22  7:03   ` Timothy
  2022-09-20  8:29 ` [PATCH] Babel evaluation: location and timing information Ihor Radchenko
  2022-09-23 16:46 ` [PATCH] Babel evaluation: location and timing information (v2) Timothy
  3 siblings, 1 reply; 13+ messages in thread
From: Max Nikulin @ 2022-09-19 14:52 UTC (permalink / raw)
  To: emacs-orgmode

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



^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-18  3:09 [PATCH] Babel evaluation: location and timing information Timothy
  2022-09-19 12:28 ` Fraga, Eric
  2022-09-19 14:52 ` Max Nikulin
@ 2022-09-20  8:29 ` Ihor Radchenko
  2022-09-22  7:05   ` Timothy
  2022-09-23 16:46 ` [PATCH] Babel evaluation: location and timing information (v2) Timothy
  3 siblings, 1 reply; 13+ messages in thread
From: Ihor Radchenko @ 2022-09-20  8:29 UTC (permalink / raw)
  To: Timothy; +Cc: emacs-orgmode

Timothy <orgmode@tec.tecosaur.net> 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


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-19 14:52 ` Max Nikulin
@ 2022-09-22  7:03   ` Timothy
  2022-09-22 12:15     ` Max Nikulin
  0 siblings, 1 reply; 13+ messages in thread
From: Timothy @ 2022-09-22  7:03 UTC (permalink / raw)
  To: emacs-orgmode; +Cc: emacs-orgmode

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

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

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-20  8:29 ` [PATCH] Babel evaluation: location and timing information Ihor Radchenko
@ 2022-09-22  7:05   ` Timothy
  2022-09-23  2:27     ` Ihor Radchenko
  0 siblings, 1 reply; 13+ messages in thread
From: Timothy @ 2022-09-22  7:05 UTC (permalink / raw)
  To: emacs-orgmode; +Cc: Timothy, emacs-orgmode

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

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

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-22  7:03   ` Timothy
@ 2022-09-22 12:15     ` Max Nikulin
  2022-09-23  2:22       ` Ihor Radchenko
  0 siblings, 1 reply; 13+ messages in thread
From: Max Nikulin @ 2022-09-22 12:15 UTC (permalink / raw)
  To: emacs-orgmode

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.



^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-22 12:15     ` Max Nikulin
@ 2022-09-23  2:22       ` Ihor Radchenko
  2022-09-23 16:21         ` line-number-at-pos performance and cache-long-scans Max Nikulin
  0 siblings, 1 reply; 13+ messages in thread
From: Ihor Radchenko @ 2022-09-23  2:22 UTC (permalink / raw)
  To: Max Nikulin; +Cc: emacs-orgmode

Max Nikulin <manikulin@gmail.com> 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+emacs@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


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information
  2022-09-22  7:05   ` Timothy
@ 2022-09-23  2:27     ` Ihor Radchenko
  0 siblings, 0 replies; 13+ messages in thread
From: Ihor Radchenko @ 2022-09-23  2:27 UTC (permalink / raw)
  To: Timothy; +Cc: emacs-orgmode

Timothy <orgmode@tec.tecosaur.net> 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


^ permalink raw reply	[flat|nested] 13+ messages in thread

* line-number-at-pos performance and cache-long-scans
  2022-09-23  2:22       ` Ihor Radchenko
@ 2022-09-23 16:21         ` Max Nikulin
  0 siblings, 0 replies; 13+ messages in thread
From: Max Nikulin @ 2022-09-23 16:21 UTC (permalink / raw)
  To: emacs-orgmode

On 23/09/2022 09:22, Ihor Radchenko wrote:
> Max Nikulin writes:
> 
>> 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+emacs@gnu.org

Thank you for the link. It would be great if that branch were merged. My 
primary complain concerning line numbers is that there is no way to 
disable the feature.

Ihor, the following is not answer to your question. I am impressed by 
such observation, however it is not latest Emacs version and built-in 
Org that uses overlays, not text properties.

It seems, in the case of `line-number-at-pos' another "optimization" 
causes performance degradation by orders of magnitude, not markers as 
for conversion between byte offset and position in buffers. I have found 
a discussion of a change in Emacs-28 (So it is not clear for me why I 
see performance difference between Emacs-26 and 27, maybe more optimal 
code generated by newer gcc)
https://debbugs.gnu.org/cgi/bugreport.cgi?bug=22763
25.1.50; Feature Request -- A faster method to obtain line number at 
position.

I noticed `cache-long-scans' and tried to disable it.

If my document (4Mb, 100k lines) is open as .txt file in Emacs-26
getting line number at the end takes 0.03…0.04 s. If I enable org-mode 
the same operation requires 6s, but after

    (setq cache-long-scans nil)

0.006 s is enough to get the same line number. Enabling the cache again 
causes performance degradation by 3 orders of magnitude. Cache works to 
some extent because first call takes 12 s while following ones "only" 6 s.

I have not tried if disabling newline cache causes problems with other 
operation.



^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information (v2)
  2022-09-18  3:09 [PATCH] Babel evaluation: location and timing information Timothy
                   ` (2 preceding siblings ...)
  2022-09-20  8:29 ` [PATCH] Babel evaluation: location and timing information Ihor Radchenko
@ 2022-09-23 16:46 ` Timothy
  2022-09-24  3:11   ` Ihor Radchenko
  3 siblings, 1 reply; 13+ messages in thread
From: Timothy @ 2022-09-23 16:46 UTC (permalink / raw)
  To: emacs-orgmode; +Cc: emacs-orgmode

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

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

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0003-ob-core-Display-babel-execution-time.patch --]
[-- Type: text/x-patch, Size: 4266 bytes --]

From 81c5cf82cffd2b01fac39eaaf7a1a6ee58802e25 Mon Sep 17 00:00:00 2001
From: TEC <git@tecosaur.net>
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


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #3: 0002-ob-core-Display-type-of-element-babel-executes.patch --]
[-- Type: text/x-patch, Size: 4993 bytes --]

From 753d441ea9c190055566a53f88dc0d687ee72808 Mon Sep 17 00:00:00 2001
From: TEC <git@tecosaur.net>
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-lob.el (org-babel-lob-execute-maybe): Pass the type of the
execution triggering element to `org-babel-execute-src-block'.

* lisp/org.el (org-ctrl-c-ctrl-c): When executing a babel call, pass the
type of the execution triggering element to
`org-babel-execute-src-block'.
---
 lisp/ob-core.el | 32 ++++++++++++++++++++++++++++----
 lisp/ob-lob.el  |  5 +++--
 lisp/org.el     |  2 +-
 3 files changed, 32 insertions(+), 7 deletions(-)

diff --git a/lisp/ob-core.el b/lisp/ob-core.el
index 767586376..c2f5eccfd 100644
--- a/lisp/ob-core.el
+++ b/lisp/ob-core.el
@@ -715,7 +715,7 @@ (defvar *this*) ; Dynamically bound in `org-babel-execute-src-block'
                 ; and `org-babel-read'
 
 ;;;###autoload
-(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."
   (interactive)
   (let* ((org-babel-current-src-block-location
 	  (or org-babel-current-src-block-location
 	      (nth 5 info)
 	      (org-babel-where-is-src-block-head)))
-	 (info (if info (copy-tree info) (org-babel-get-src-block-info))))
+	 (info (if info (copy-tree info) (org-babel-get-src-block-info)))
+         (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.
+              (pcase (char-after org-babel-current-src-block-location)
+                (?s 'inline-src-block)
+                (?# 'src-block)
+                (_ 'unknown)))))
     ;; Merge PARAMS with INFO before considering source block
     ;; evaluation since both could disagree.
     (cl-callf org-babel-merge-params (nth 2 info) params)
@@ -776,8 +794,14 @@ (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 executor
+                       ('src-block "code block")
+                       ('inline-src-block "inline code block")
+                       ('babel-call "call")
+                       ('inline-babel-call "inline call")
+                       (e (symbol-name e)))
 		     (let ((name (nth 4 info)))
 		       (if name
                            (format "(%s)" name)
diff --git a/lisp/ob-lob.el b/lisp/ob-lob.el
index 8da91bdaf..c6be8be80 100644
--- a/lisp/ob-lob.el
+++ b/lisp/ob-lob.el
@@ -78,9 +78,10 @@ (defun org-babel-lob-execute-maybe ()
 Detect if this is context for a Library Of Babel source block and
 if so then run the appropriate source block from the Library."
   (interactive)
-  (let ((info (org-babel-lob-get-info)))
+  (let* ((datum (org-element-context))
+         (info (org-babel-lob-get-info datum)))
     (when info
-      (org-babel-execute-src-block nil info)
+      (org-babel-execute-src-block nil info nil (org-element-type datum))
       t)))
 
 (defun org-babel-lob--src-info (ref)
diff --git a/lisp/org.el b/lisp/org.el
index 142d5451b..a5d6bb931 100644
--- a/lisp/org.el
+++ b/lisp/org.el
@@ -17297,7 +17297,7 @@ (defun org-ctrl-c-ctrl-c (&optional arg)
 	       "`\\[org-ctrl-c-ctrl-c]' can do nothing useful here"))))
 	((or `babel-call `inline-babel-call)
 	 (let ((info (org-babel-lob-get-info context)))
-	   (when info (org-babel-execute-src-block nil info))))
+	   (when info (org-babel-execute-src-block nil info nil type))))
 	(`clock (org-clock-update-time-maybe))
 	(`dynamic-block
 	 (save-excursion
-- 
2.37.1


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #4: 0001-ob-core-Display-position-of-executed-babel-blocks.patch --]
[-- Type: text/x-patch, Size: 1188 bytes --]

From 5566c371f20228b0b33be54537c95f2d2fb6b191 Mon Sep 17 00:00:00 2001
From: TEC <git@tecosaur.net>
Date: Tue, 13 Sep 2022 18:55:06 +0800
Subject: [PATCH 1/3] ob-core: Display position of executed babel blocks

* lisp/ob-core.el (org-babel-execute-src-block): When an unnamed babel
block is executed, show the position of the block.

This makes it easier to track the execution without having to name every
block.

ob-core: point

* lisp/ob-core.el (org-babel-execute-src-block):
---
 lisp/ob-core.el | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/lisp/ob-core.el b/lisp/ob-core.el
index 8a963fa8e..767586376 100644
--- a/lisp/ob-core.el
+++ b/lisp/ob-core.el
@@ -779,7 +779,9 @@ (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 "at point %d" (nth 5 info)))))
 	    (setq result
 		  (let ((r (funcall cmd body params)))
 		    (if (and (eq (cdr (assq :result-type params)) 'value)
-- 
2.37.1


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information (v2)
  2022-09-23 16:46 ` [PATCH] Babel evaluation: location and timing information (v2) Timothy
@ 2022-09-24  3:11   ` Ihor Radchenko
  2022-09-24  9:12     ` Timothy
  0 siblings, 1 reply; 13+ messages in thread
From: Ihor Radchenko @ 2022-09-24  3:11 UTC (permalink / raw)
  To: Timothy; +Cc: emacs-orgmode

Timothy <orgmode@tec.tecosaur.net> 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


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH] Babel evaluation: location and timing information (v2)
  2022-09-24  3:11   ` Ihor Radchenko
@ 2022-09-24  9:12     ` Timothy
  0 siblings, 0 replies; 13+ messages in thread
From: Timothy @ 2022-09-24  9:12 UTC (permalink / raw)
  To: emacs-orgmode; +Cc: Timothy, emacs-orgmode

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

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

^ permalink raw reply	[flat|nested] 13+ messages in thread

end of thread, other threads:[~2022-09-24  9:15 UTC | newest]

Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-09-18  3:09 [PATCH] Babel evaluation: location and timing information Timothy
2022-09-19 12:28 ` Fraga, Eric
2022-09-19 14:52 ` Max Nikulin
2022-09-22  7:03   ` Timothy
2022-09-22 12:15     ` Max Nikulin
2022-09-23  2:22       ` Ihor Radchenko
2022-09-23 16:21         ` line-number-at-pos performance and cache-long-scans Max Nikulin
2022-09-20  8:29 ` [PATCH] Babel evaluation: location and timing information Ihor Radchenko
2022-09-22  7:05   ` Timothy
2022-09-23  2:27     ` Ihor Radchenko
2022-09-23 16:46 ` [PATCH] Babel evaluation: location and timing information (v2) Timothy
2022-09-24  3:11   ` Ihor Radchenko
2022-09-24  9:12     ` Timothy

Code repositories for project(s) associated with this public inbox

	https://git.savannah.gnu.org/cgit/emacs/org-mode.git

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