Performance of property drawers in Org cache

Performance of property drawers in Org cache

[Michael Brand]

Hi all

Hello again, it's been a long time since I last followed this list
regularly or posted regularly (until 2019, code contributions until
2016).

Now I would like to report issues with the performance of property
drawers in Org cache. The time it takes to open an Org file with a
useful amount of property drawers like in test_1.org has increased too
much for me to update from Org mode 9.5, see the table below.

Org loading performance has also degraded a bit but I assume and hope
that the amount is not more than necessary for the convenience of
having more Org features preloaded.

To do some homework I looked in Org news, the mailing list, the
Commentary of org-element-ast.el and an overview of
org-element-ast.el. The beginning of the result of
~(org-element-cache-map #'car :granularity 'element)~ (as found in
test-org-element.el) and its length of 3003 for test_1.org look
completely reasonable to me. ~org-element--cache-map-statistic t~ does
not reveal where the by far large rest of the total time goes: "Total
time: 10.668449 sec. Pre-process time: 0.000000 sec. Predicate time:
0.014772 sec. Re-search time: 0.000000 sec.". I am surprised that a
repeated use of ~org-element-cache-map~ is still quite slow: 2.0 s
without statistic for iterating over 3003 cached AST nodes to collect
their ~car~?. Obviously I am a bit overchallenged with the Org cache
and hope that someone can look into this.

Out of curiosity: What consumes time during killing an Org buffer that
seems to scale with the buffer/cache size? What has to be done more
than just garbage collection that can be deferred to after killing has
finished?

Michael

* Test procedure
----------------

Benchmarking started do get complicated because of the different time
sinks, so I automated the following steps 3) to 5) with
~benchmark-elapse~ etc. See the source block with the Emacs Lisp code
below.

1) Change Org version and ~$ make cleanall uncompiled~
2) ~$ emacs -Q --eval '(add-to-list (quote load-path)
"~/path/to/org-mode/lisp")'~
3) First just load Org by opening an empty Org file and kill the
buffer (table column "Load Org")
4) Then open test_1.org and kill the buffer (table column "test_1.org")
5) Then open test_2.org and kill the buffer (table column "test_2.org")

The times in seconds [s] are for opening the file and in parenthesis
for killing the buffer, rows in reverse chronological order:

| Org version |  Load Org | test_1.org | test_2.org |
|             |       [s] | size: 1000 |  size: 400 |
|             |           |        [s] |        [s] |
|             |       <r> |        <r> |        <r> |
|-------------+-----------+------------+------------|
| eebc9be7ca  | 3.3 (0.0) | 13.3 (5.4) |  1.7 (0.7) |
| ...         |           |            |            |
| 924a64da39  | 3.1 (0.0) | 10.7 (0.2) |  1.3 (0.1) |
| 924a64da39^ | 2.6 (0.0) |  5.4 (0.2) |  0.7 (0.1) |
| ...         |           |            |            |
| release_9.6 | 2.9 (0.0) |  6.9 (0.0) |  1.8 (0.0) |
| ...         |           |            |            |
| release_9.5 | 2.3 (0.0) |  0.2 (0.0) | 12.1 (0.0) |

Commit eebc9be7ca: The main branch as of [2024-12-16 Mon].

Commit 924a64da39:
- Author: Ihor Radchenko <yantar92@posteo.net>
- Date:   Sat May 20 13:29:04 2023 +0200
- Title:  org-element: Use the new org-element-ast library

All with Emacs 29.4 on macOS.

* Minimal working examples
--------------------------

test_1.org depends on ~overview~ and drawers that may be property
drawers or just drawers and may be empty. Shell command for size 1000:
: $ (echo '#+startup: overview' && for ((i = 1; i <= 1000; i++)); do
printf '* %d\n:PROPERTIES:\n:END:\n' $i; done ; ) > test_1.org

test_2.org depends on ~overview~, the drawers may be empty. Shell
command for different size 400:
: $ (echo '#+startup: overview' && for ((i = 1; i <= 400; i++)); do
printf ':MY_DRAWER_%d:\n:END:\n' $i; done ; ) > test_2.org

* Test automation
-----------------

#+begin_src emacs-lisp :eval no
(let ((test-0-open-file -1.0) (test-0-kill-buffer -1.0)
      (test-1-open-file -1.0) (test-1-kill-buffer -1.0)
      (test-2-open-file -1.0) (test-2-kill-buffer -1.0))
  (require 'benchmark)

  ;; ,test_0.org
  (when t
    (setq test-0-open-file (benchmark-elapse (find-file "~/z/,test_0.org")))
    (switch-to-buffer "*Messages*")
    (message (concat "INF: test-0-open-file = "
                     (number-to-string test-0-open-file))))
  (when t
    (setq test-0-kill-buffer (benchmark-elapse (kill-buffer ",test_0.org")))
    (switch-to-buffer "*Messages*")
    (message (concat "INF: test-0-kill-buffer = "
                     (number-to-string test-0-kill-buffer))))

  ;; ,test_1.org
  (when t
    (setq test-1-open-file (benchmark-elapse (find-file "~/z/,test_1.org")))
    (switch-to-buffer "*Messages*")
    (message (concat "INF: test-1-open-file = "
                     (number-to-string test-1-open-file))))
  (when t
    (setq test-1-kill-buffer (benchmark-elapse (kill-buffer ",test_1.org")))
    (switch-to-buffer "*Messages*")
    (message (concat "INF: test-1-kill-buffer = "
                     (number-to-string test-1-kill-buffer))))

  ;; ,test_2.org
  (when t
    (setq test-2-open-file (benchmark-elapse (find-file "~/z/,test_2.org")))
    (switch-to-buffer "*Messages*")
    (message (concat "INF: test-2-open-file = "
                     (number-to-string test-2-open-file))))
  (when t
    (setq test-2-kill-buffer (benchmark-elapse (kill-buffer ",test_2.org")))
    (switch-to-buffer "*Messages*")
    (message (concat "INF: test-2-kill-buffer = "
                     (number-to-string test-2-kill-buffer))))

  (kill-new (concat " " (format "%.1f" test-0-open-file)
                    " (" (format "%.1f" test-0-kill-buffer) ") |"
                    " " (format "%.1f" test-1-open-file)
                    " (" (format "%.1f" test-1-kill-buffer) ") |"
                    " " (format "%.1f" test-2-open-file)
                    " (" (format "%.1f" test-2-kill-buffer) ") |")))
#+end_src

Re: Performance of property drawers in Org cache

[Ihor Radchenko]

Michael Brand <michael.ch.brand@gmail.com> writes:

> Now I would like to report issues with the performance of property
> drawers in Org cache. The time it takes to open an Org file with a
> useful amount of property drawers like in test_1.org has increased too
> much for me to update from Org mode 9.5, see the table below.

This is because of new `org-cycle-hide-drawer-startup' that is set to t
by default. Previously, drawers were not folded on startup. Instead, they
were folded every time you unfold a heading, via `org-cycle-hook' (it no
longer contains `org-cycle-hide-drawers' entry by default).

This change was a tradeoff. Folding many drawers can be expensive, and we
increased the time for opening an Org buffer in exchange for faster
folding later.

> Org loading performance has also degraded a bit but I assume and hope
> that the amount is not more than necessary for the convenience of
> having more Org features preloaded.

This is hard to control, unfortunately. Org libraries are so much
entangled together that almost everything has to be loaded every time
you load Org. I hope to address this, but it is not a trivial task.

> To do some homework I looked in Org news, the mailing list, the
> Commentary of org-element-ast.el and an overview of
> org-element-ast.el. The beginning of the result of
> ~(org-element-cache-map #'car :granularity 'element)~ (as found in
> test-org-element.el) and its length of 3003 for test_1.org look
> completely reasonable to me. ~org-element--cache-map-statistic t~ does
> not reveal where the by far large rest of the total time goes: "Total
> time: 10.668449 sec. Pre-process time: 0.000000 sec. Predicate time:
> 0.014772 sec. Re-search time: 0.000000 sec.". I am surprised that a
> repeated use of ~org-element-cache-map~ is still quite slow: 2.0 s
> without statistic for iterating over 3003 cached AST nodes to collect
> their ~car~?. Obviously I am a bit overchallenged with the Org cache
> and hope that someone can look into this.

This is what I am getting on your test_1.org:

Mapped over elements in #<buffer test_1.org>. 3006/3006 predicate matches. Total time: 0.275971 sec. Pre-process time: 0.000000 sec. Predicate time: 0.002361 sec. Re-search time: 0.000000 sec.

In this case, it is very important that Org mode should be compiled.

> Out of curiosity: What consumes time during killing an Org buffer that
> seems to scale with the buffer/cache size? What has to be done more
> than just garbage collection that can be deferred to after killing has
> finished?

org-element-cache-persistent: writing parser cache to disk.
May it be deferred? It might, I think. But Emacs will be blocked at some
point anyway while doing so.

You can disable writing cache, if it is what you prefer.

-- 
Ihor Radchenko // yantar92,
Org mode maintainer,
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>