Property search takes too long, a long LOGBOOK is the "problem"?

Question

I have just one headline and do a simple property search (prop1="blah1") for the 'org-agenda', but this takes about 10 seconds!

* empty item but with a long logbook
  :PROPERTIES:
  :prop1: blah1
  :END:
:LOGBOOK:
CLOCK: [2022-03-12 Sat 06:38]--[2022-03-12 Sat 06:50] =>  0:12
CLOCK: [2022-03-11 Fri 15:05]--[2022-03-11 Fri 17:24] =>  2:19
CLOCK: [2022-03-11 Fri 20:50]--[2022-03-11 Fri 21:20] =>  0:30

-- " about 300 CLOCK lines " --
:END:

• Without the long LOGBOOK (about 300 lines) the search is as expected fast. But this shouldn't be a problem at all. Emacs doesn't need to know the LOGBOOK drawer for the search(?).
• A tag search isn't slow.
• I've tested it with the latest org-version (9.5) and emacs-version (27.2), and with a clean 'init.el'.

Any ideas? Can someone confirm the problem?

Answer 1

As I mentioned in a comment, you really should report this with M-x org-submit-bug-report. In the meantime, you might be interested in how to determine where the time goes in an Emacs Lisp program through profiling.

You can instrument a package (or a function) for profiling - see Profiling in the Emacs Lisp manual.

Since the problem is reproducible and we know that it's an Org mode function, we can use the elp profiler to instrument the whole package: M-x elp-instrument-package RET org RET. Then we redo the search and after 35 seconds on my ancient desktop, the agenda is refreshed. We can then get the profile with M-x elp-results. This is what I get:

Function Name                           Call Count  Elapsed Time  Average Time
org-agenda-redo                         1           36.496303302  36.496303302
org-tags-view                           1           36.495485895  36.495485895
org-scan-tags                           1           33.558405685  33.558405685
org-entry-properties                    2           33.557729633  16.778864816
org-cached-entry-get                    1           33.557712313  33.557712313
org-element-context                     624         33.473615970  0.0536436153
org-element-at-point                    624         33.463912935  0.0536280656
org-element--parse-to                   624         33.439052122  0.0535882245
org-element--current-element            98904       30.069014025  0.0003040222
org-element-clock-parser                97656       24.182288182  0.0002476272
org-element-timestamp-parser            97656       19.247151592  0.0001970913
org-parse-time-string                   195312      9.7605813210  4.997...e-05
org-make-tags-matcher                   1           2.863862144   2.863862144
org-get-limited-outline-regexp          100780      1.0370951569  1.029...e-05
org-at-heading-p                        99528       0.6671784279  6.703...e-06
org-element--cache-put                  98904       0.4657518790  4.709...e-06
...

You can see that the parser is parsing all the clock entries: I added 312 clock entries, so org-element-context is called twice for each entry (presumably once for the beginning time and once for the ending time) and accounts for 33.5 secs out of the 36.5 secs total. It in turn calls org-element-at-point which calls org-element--current-element repeatedly (about 98904/624 ~= 160 times per call) and almost each one (all but two) of those calls results in a call to org-element-clock-parser and org-element-timestamp-parser. This last one calls org-parse-time-string twice, again probably because of the beginning and ending time.

Almost 200000 calls to org-parse-time-string amount to almost 10 seconds of the elapsed time. Most of the rest is parsing overhead in org-element--parse-to and its descendants.

The main question is why isn't the LOGBOOK drawer skipped altogether in org-entry-properties.

There have been attempts to introduce a cache in order to speed up the parser, but there have been cache corruption problems in the past (a lot of which have been resolved through the heroic efforts of Ihor Radchenko primarily), but in this case, even when I turned the cache on, the needle did not move.

So not an answer to solving the problem, but maybe the explanation and the methodology might be interesting to some.

EDIT: [The conclusions here are probably wrong and my fault - see the next EDIT for more recent and accurate information]

As the OP mentions in a comment, he submitted a bug report to the Org mode mailing list and Ihor Radchenko replied that this particular bug has been fixed in the upstream version of Org mode (not released yet - it's a set of major changes, so they will be available when Org 9.6 gets released). Unfortunately, I cannot confirm that result: I updated to latest Org mode version 9.5.2 (release_9.5.2-401-g91681f), compiled everything from scratch (N.B. I am not using native compilation), turned on org-element--cache (it was nil to begin with) and I still get 30-second rebuilds of the agenda with numbers similar to what I got before (a 17% improvement perhaps but certainly not a 35x or bigger improvement as Ihor seems to claim). I'll follow up on the ML.

EDIT: Actually, I just tried it again on a different (and more modern) machine, but it is likely that I goofed the update previously. I updated Org mode to the latest upstream: Org mode version 9.5.2 (release_9.5.2-403-gc2c122),so just a couple more updates than the one above it's exactly the same update as the one above; I just have two extra private commits that I carry in my own fork of Org mode on this machine.

The agenda update is indeed instant (1.9 secs) as Ihor claimed. The elp profile looks completely different from before:

Function Name                        Call Count  Elapsed Time  Average Time
org-agenda-redo                      1           1.894974809   1.894974809
org-tags-view                        1           1.882400592   1.882400592
org-make-tags-matcher                1           1.277559932   1.277559932
org-element-cache-map                32          0.597807413   0.0186814816
org-scan-tags                        8           0.5946565140  0.0743320642
org-entry-properties                 568         0.2964548949  0.0005219276
org-cached-entry-get                 284         0.2824113799  0.0009944062
org-element-at-point                 3200        0.2052949870  6.415...e-05
org-element--parse-to                2368        0.1557959290  6.579...e-05
org-element--cache-verify-element    3280        0.1545616289  4.712...e-05
org-element-context                  797         0.1469199920  0.0001843412
org-element--current-element         2487        0.1004897320  4.040...e-05
org-element-clock-parser             2327        0.0565625379  2.430...e-05
org-before-first-heading-p           1148        0.0444745280  3.874...e-05
org-element-timestamp-parser         2561        0.0405111339  1.581...e-05
org-get-category                     283         0.0320344579  0.0001131959
org-entry-get-with-inheritance       567         0.0315457040  5.563...e-05
org-get-tags                         856         0.0311058959  3.633...e-05
org-entry-blocked-p                  284         0.0307554069  0.0001082936
org-entry-get                        601         0.0280415809  4.665...e-05
org-back-to-heading-or-point-min     570         0.0253977600  4.455...e-05
org--property-local-values           2180        0.0223472170  1.025...e-05
org-get-limited-outline-regexp       2614        0.0217447480  8.318...e-06
org-parse-time-string                4893        0.0136911819  2.798...e-06
org-get-property-block               284         0.0129505220  4.560...e-05
org-element-headline-parser          171         0.0128519330  7.515...e-05
...

The org-element-timestamp-parser which was called about 100K times previously is now down to 2.5K calls. There are no calls to org-parse-time-string. It's all good!