Clocking in is pretty slow in version 9.6 when the item has a large

Clocking in is pretty slow in version 9.6 when the item has a large

[Eli Qian]

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

I use the following method to get the time taken for `org-clocl-in`:
(benchmark 1 '(org-clock-sum (org-clock-get-sum-start)))

In my case, the item has 1400+ entries in its logbook,  clocking in will
cost
1-2s to finish(benchmark results: "Elapsed time: 1.689801s (0.527506s in 7
GCs)"). That's abnormal because it is done very quickly in version
9.5.5.(benchmark result: "Elapsed time: 0.057270s")

After investigation by using profiler, I found the problem is caused by
`org-element-at-point`, which was added to `org-clock-sum` in version 9.6.

Any idea about speeding up clocking in?

[-- Attachment #2: Type: text/html, Size: 676 bytes --]

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Mark Barton]

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



> On Dec 4, 2022, at 4:12 AM, Eli Qian <eli.q.qian@gmail.com> wrote:
> 
> After investigation by using profiler, I found the problem is caused by
> `org-element-at-point`

I'm also seeing this slowdown after compliling from Emacs master around the time of the 29.1 cutoff. I use the org version in Emacs master. I use clocktable reports that scope a two week period to calculate the time spent on tasks. Normally the update to the table takes maybe 10s-30s, but lately it takes over 3 minutes to run.

Emacs 30.0.50 (Build 21G115) of 2022-12-02
Org mode version release_9.6-3-ga4d38e @ /Applications/Emacs.app/Contents/Resources/lisp/org/
Emacs  -Q
Open org file with clocking data and find the clocktable line as shown below. C-c C-c to update the clocktable report.

#+BEGIN: clocktable :scope file :maxlevel 6 :link nil :tstart "[2022-11-19 Sat 00:00]" :tend "[2022-12-03 Sat 11:00]" :formula % :step day :stepskip0 t

This took over 3 minutes to run.

If I use an older build I have as my "stable" version for testing...
Emacs 29.0.50 (Build 21F79) of 2022-08-05
Org mode version 9.5.4-17-g6e991f 
then the same clocktable line takes 11s to update.

Mark

[-- Attachment #2: Type: text/html, Size: 3102 bytes --]

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Ihor Radchenko]

Eli Qian <eli.q.qian@gmail.com> writes:

> Any idea about speeding up clocking in?

Try reducing `org-element--cache-self-verify-frequency' to a smaller
number.

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

Re: [External] : Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Daniel Ortmann]

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

Eli,
I also had performance issues after the logbook was switched to true 
parsing instead of regular expressions.  In my case, I had logbook 
entries going back to 2012!

After I cleared out the excess entries the performance jumped back up.

https://git.savannah.gnu.org/cgit/emacs/org-mode.git/commit/?id=3790bf8ea1d070055a989f0b9587948e07877977

On 12/4/22 11:41, Ihor Radchenko wrote:
> Eli Qian <eli.q.qian@gmail.com> writes:
>
>> Any idea about speeding up clocking in?
> Try reducing `org-element--cache-self-verify-frequency' to a smaller
> number.
>

[-- Attachment #2: [External] : Re: [BUG] recent slow down in agenda's clock table report (and with first clock-in) [9.6-pre (release_9.5.5-995-g4b9aef @ /home/dortmann/src/git-org-mode/lisp/)].eml --]
[-- Type: message/rfc822, Size: 1473 bytes --]

From: Daniel Ortmann <daniel.ortmann@oracle.com>
To: Ihor Radchenko <yantar92@posteo.net>
Cc: emacs-orgmode@gnu.org
Subject: Re: [External] : Re: [BUG] recent slow down in agenda's clock table report (and with first clock-in) [9.6-pre (release_9.5.5-995-g4b9aef @ /home/dortmann/src/git-org-mode/lisp/)]
Date: Thu, 20 Oct 2022 11:21:19 -0500
Message-ID: <c07b9f70-d80a-377f-e9ce-c2e32373bc8d@oracle.com>

Works perfectly after cleaning out old time log entries going back to 
2013.  :-)

On 10/20/22 00:37, Ihor Radchenko wrote:
> Daniel Ortmann <daniel.ortmann@oracle.com> writes:
>
>> (The performance drop was sudden and steep, by the way.)
> It is because clocking now calls Org parser API.
> https://urldefense.com/v3/__https://git.savannah.gnu.org/cgit/emacs/org-mode.git/commit/?id=3790bf8ea1d070055a989f0b9587948e07877977__;!!ACWV5N9M2RV99hQ!KgwLbNpmmeNRH40ZJBT24H5ehmytyzRmS_wXhRSXlz7b-jzilorwtWKuAF0iQwTkP4UT779uIe4jNXhYh7W-$
>

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Ihor Radchenko]

Ihor Radchenko <yantar92@posteo.net> writes:

> Eli Qian <eli.q.qian@gmail.com> writes:
>
>> Any idea about speeding up clocking in?
>
> Try reducing `org-element--cache-self-verify-frequency' to a smaller
> number.

For some context, self-verify staff will only be enabled during pretest.
It is an equivalent of ./configure --enable-checking in Emacs. We do it,
because we absolutely need to catch all issues with org-element cache
ASAP, before the code goes into Emacs release.

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

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Mark Barton]

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



> On Dec 4, 2022, at 10:18 AM, Ihor Radchenko <yantar92@posteo.net> wrote:
> 
> Ihor Radchenko <yantar92@posteo.net <mailto:yantar92@posteo.net>> writes:
> 
>> Eli Qian <eli.q.qian@gmail.com <mailto:eli.q.qian@gmail.com>> writes:
>> 
>>> Any idea about speeding up clocking in?
>> 
>> Try reducing `org-element--cache-self-verify-frequency' to a smaller
>> number.
> 
> For some context, self-verify staff will only be enabled during pretest.
> It is an equivalent of ./configure --enable-checking in Emacs. We do it,
> because we absolutely need to catch all issues with org-element cache
> ASAP, before the code goes into Emacs release.

FYI here is how reducing that number helped with my clocktable updates in the order I tested each value.
*** org-element--cache-self-verify-frequency 0.01 
update takes 1:18 (minutes : seconds)
*** org-element--cache-self-verify-frequency 0.005
update takes 0:48
*** org-element--cache-self-verify-frequency 0.002
update takes 0:28
*** org-element--cache-self-verify-frequency 0.001
update takes 0:19
*** org-element--cache-self-verify-frequency 0.0005
update takes 0:20
*** org-element--cache-self-verify-frequency 0.03 (default value)
update takes 3:29


[-- Attachment #2: Type: text/html, Size: 7074 bytes --]

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Ihor Radchenko]

Mark Barton <mbarton98@gmail.com> writes:

> FYI here is how reducing that number helped with my clocktable updates in the order I tested each value.
> *** org-element--cache-self-verify-frequency 0.01 
> update takes 1:18 (minutes : seconds)
> *** org-element--cache-self-verify-frequency 0.005
> update takes 0:48
> *** org-element--cache-self-verify-frequency 0.002
> update takes 0:28
> *** org-element--cache-self-verify-frequency 0.001
> update takes 0:19
> *** org-element--cache-self-verify-frequency 0.0005
> update takes 0:20
> *** org-element--cache-self-verify-frequency 0.03 (default value)
> update takes 3:29

Thanks for the data!
What about setting org-element--cache-self-verify to nil?
That's what we will do once we finish the test.


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

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Mark Barton]

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



> On Dec 7, 2022, at 3:53 AM, Ihor Radchenko <yantar92@posteo.net> wrote:
> 
> What about setting org-element--cache-self-verify to nil?

(setq org-element--cache-self-verify-frequency nil)
Update clocktable
Wrong type argument: number-or-marker-p, nil

Try again but use zero instead of nil...
(setq org-element--cache-self-verify-frequency 0)
Updates in 11s.

Mark

[-- Attachment #2: Type: text/html, Size: 1372 bytes --]

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Ihor Radchenko]

Mark Barton <mbarton98@gmail.com> writes:

>> On Dec 7, 2022, at 3:53 AM, Ihor Radchenko <yantar92@posteo.net> wrote:
>> 
>> What about setting org-element--cache-self-verify to nil?
>
> (setq org-element--cache-self-verify-frequency nil)
> Update clocktable
> Wrong type argument: number-or-marker-p, nil
>
> Try again but use zero instead of nil...
> (setq org-element--cache-self-verify-frequency 0)
> Updates in 11s.

Sorry, I meant (setq org-element--cache-self-verify nil).
In any case, the time is back to previous, which should be good enough
considering that no optimizations have been made to the clock table
calculation.

If you need it, you may run M-x profiler-start <RET> cpu <RET>, run
clocktable, M-x profiler-report M-x profiler-report-write-profile, and
share the resulting profile.

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

Re: Clocking in is pretty slow in version 9.6 when the item has a large

[Mark Barton]

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



> On Dec 7, 2022, at 10:36 AM, Ihor Radchenko <yantar92@posteo.net> wrote:
> 
> Sorry, I meant (setq org-element--cache-self-verify nil).
> In any case, the time is back to previous, which should be good enough
> considering that no optimizations have been made to the clock table
> calculation.

I just realized my mistake on the variable. I'm good. It was very acceptable for me at 20s considering how many clocking lines I have to parse going back to 2019. I will keep the self-verify as is if that will help capture errors before the release branch.

Mark

[-- Attachment #2: Type: text/html, Size: 3571 bytes --]