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