emacs-orgmode@gnu.org archives
 help / color / mirror / code / Atom feed
* Clocking in is pretty slow in version 9.6 when the item has a large
@ 2022-12-04 12:12 Eli Qian
  2022-12-04 17:34 ` Mark Barton
  2022-12-04 17:41 ` Ihor Radchenko
  0 siblings, 2 replies; 10+ messages in thread
From: Eli Qian @ 2022-12-04 12:12 UTC (permalink / raw)
  To: emacs-orgmode

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

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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-04 12:12 Clocking in is pretty slow in version 9.6 when the item has a large Eli Qian
@ 2022-12-04 17:34 ` Mark Barton
  2022-12-04 17:41 ` Ihor Radchenko
  1 sibling, 0 replies; 10+ messages in thread
From: Mark Barton @ 2022-12-04 17:34 UTC (permalink / raw)
  To: Eli Qian; +Cc: emacs-orgmode

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

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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-04 12:12 Clocking in is pretty slow in version 9.6 when the item has a large Eli Qian
  2022-12-04 17:34 ` Mark Barton
@ 2022-12-04 17:41 ` Ihor Radchenko
  2022-12-04 17:59   ` [External] : " Daniel Ortmann
  2022-12-04 18:18   ` Ihor Radchenko
  1 sibling, 2 replies; 10+ messages in thread
From: Ihor Radchenko @ 2022-12-04 17:41 UTC (permalink / raw)
  To: Eli Qian; +Cc: emacs-orgmode

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>


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

* Re: [External] : Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-04 17:41 ` Ihor Radchenko
@ 2022-12-04 17:59   ` Daniel Ortmann
  2022-12-04 18:18   ` Ihor Radchenko
  1 sibling, 0 replies; 10+ messages in thread
From: Daniel Ortmann @ 2022-12-04 17:59 UTC (permalink / raw)
  To: Eli Qian; +Cc: emacs-orgmode

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


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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-04 17:41 ` Ihor Radchenko
  2022-12-04 17:59   ` [External] : " Daniel Ortmann
@ 2022-12-04 18:18   ` Ihor Radchenko
  2022-12-04 18:40     ` Mark Barton
  1 sibling, 1 reply; 10+ messages in thread
From: Ihor Radchenko @ 2022-12-04 18:18 UTC (permalink / raw)
  To: Eli Qian; +Cc: emacs-orgmode

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>


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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-04 18:18   ` Ihor Radchenko
@ 2022-12-04 18:40     ` Mark Barton
  2022-12-07 11:53       ` Ihor Radchenko
  0 siblings, 1 reply; 10+ messages in thread
From: Mark Barton @ 2022-12-04 18:40 UTC (permalink / raw)
  To: Ihor Radchenko; +Cc: Eli Qian, emacs-orgmode

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

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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-04 18:40     ` Mark Barton
@ 2022-12-07 11:53       ` Ihor Radchenko
  2022-12-07 18:28         ` Mark Barton
  0 siblings, 1 reply; 10+ messages in thread
From: Ihor Radchenko @ 2022-12-07 11:53 UTC (permalink / raw)
  To: Mark Barton; +Cc: Eli Qian, emacs-orgmode

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>


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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-07 11:53       ` Ihor Radchenko
@ 2022-12-07 18:28         ` Mark Barton
  2022-12-07 18:36           ` Ihor Radchenko
  0 siblings, 1 reply; 10+ messages in thread
From: Mark Barton @ 2022-12-07 18:28 UTC (permalink / raw)
  To: Ihor Radchenko; +Cc: Eli Qian, emacs-orgmode

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

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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-07 18:28         ` Mark Barton
@ 2022-12-07 18:36           ` Ihor Radchenko
  2022-12-07 19:27             ` Mark Barton
  0 siblings, 1 reply; 10+ messages in thread
From: Ihor Radchenko @ 2022-12-07 18:36 UTC (permalink / raw)
  To: Mark Barton; +Cc: Eli Qian, emacs-orgmode

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>


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

* Re: Clocking in is pretty slow in version 9.6 when the item has a large
  2022-12-07 18:36           ` Ihor Radchenko
@ 2022-12-07 19:27             ` Mark Barton
  0 siblings, 0 replies; 10+ messages in thread
From: Mark Barton @ 2022-12-07 19:27 UTC (permalink / raw)
  To: Ihor Radchenko; +Cc: Eli Qian, emacs-orgmode

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

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

end of thread, other threads:[~2022-12-07 19:27 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-12-04 12:12 Clocking in is pretty slow in version 9.6 when the item has a large Eli Qian
2022-12-04 17:34 ` Mark Barton
2022-12-04 17:41 ` Ihor Radchenko
2022-12-04 17:59   ` [External] : " Daniel Ortmann
2022-12-04 18:18   ` Ihor Radchenko
2022-12-04 18:40     ` Mark Barton
2022-12-07 11:53       ` Ihor Radchenko
2022-12-07 18:28         ` Mark Barton
2022-12-07 18:36           ` Ihor Radchenko
2022-12-07 19:27             ` Mark Barton

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