Indexing.py: Item init is called several times with the same query values when viewing an item

[UlrichB22]

While running performance tests on an imported wiki I found that the Item init method

moin/src/moin/storage/middleware/indexing.py

Line 1064 in 807bfe1

class Item(PropertiesMixin):

is called several times with the same query values. Each Query causes a whoosh index query. Because of the index size for a wiki with 2400 items and about 12000 revisions each index query lasts about 120 ms. The following server output was produced with additional clock timers, see commit 26bd5dc.

For the test I created a simple MoinWiki item called 'TestItem' with a header only.

DEBUG 2024-10-11 23:08:20,354 moin.utils.clock:48 timer init(0): 3.29ms 
DEBUG 2024-10-11 23:08:20,530 moin.utils.clock:48 timer Item init(0): 174.80ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:20,664 moin.utils.clock:48 timer Item init(0): 133.91ms name: None query: {'itemid': 'cb33ee84eb3a4a54a31e2f4c5132ee5c'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:20,665 moin.utils.clock:48 timer Revision init(0): 0.02ms name: ['TestItem'] revid: 308f87c48ab044058631c7007b7a5030
DEBUG 2024-10-11 23:08:20,665 moin.utils.clock:48 timer show item create(0): 310.24ms TestItem rev_id=current

DEBUG 2024-10-11 23:08:20,668 moin.utils.clock:48 timer conv_in_dom(0): 2.10ms 
DEBUG 2024-10-11 23:08:20,669 moin.utils.clock:48 timer nowiki(0): 0.05ms 
DEBUG 2024-10-11 23:08:20,669 moin.utils.clock:48 timer conv_include(0): 0.10ms 
DEBUG 2024-10-11 23:08:20,669 moin.utils.clock:48 timer conv_macro(0): 0.08ms 
DEBUG 2024-10-11 23:08:20,670 moin.utils.clock:48 timer conv_link(0): 0.05ms 
DEBUG 2024-10-11 23:08:20,672 moin.utils.clock:48 timer conv_dom_html(0): 1.98ms 

DEBUG 2024-10-11 23:08:21,024 moin.utils.clock:48 timer Item init(0): 112.57ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:21,143 moin.utils.clock:48 timer Item init(0): 118.20ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:21,143 moin.utils.clock:48 timer protecting may(0): 118.49ms TestItem
DEBUG 2024-10-11 23:08:21,266 moin.utils.clock:48 timer Item init(0): 121.99ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:21,266 moin.utils.clock:48 timer protecting may(0): 122.24ms TestItem
DEBUG 2024-10-11 23:08:21,391 moin.utils.clock:48 timer Item init(0): 124.47ms name: /TestItem/Discussion query: {'name_exact': '/TestItem/Discussion', 'namespace': ''} itemid: undefined latest_doc: False
DEBUG 2024-10-11 23:08:21,510 moin.utils.clock:48 timer Item init(0): 118.51ms name: /TestItem/Discussion query: {'namespace': '', 'name_exact': '/TestItem/Discussion'} itemid: undefined latest_doc: False
DEBUG 2024-10-11 23:08:21,628 moin.utils.clock:48 timer Item init(0): 118.26ms name: /TestItem/Discussion query: {'namespace': '', 'name_exact': '/TestItem/Discussion'} itemid: undefined latest_doc: False
DEBUG 2024-10-11 23:08:21,628 moin.utils.clock:48 timer protecting may(0): 237.18ms /TestItem/Discussion
DEBUG 2024-10-11 23:08:21,768 moin.utils.clock:48 timer Item init(0): 139.43ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:21,768 moin.utils.clock:48 timer protecting may(0): 139.65ms TestItem
DEBUG 2024-10-11 23:08:21,905 moin.utils.clock:48 timer Item init(0): 136.24ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:21,906 moin.utils.clock:48 timer protecting may(0): 137.39ms TestItem
DEBUG 2024-10-11 23:08:22,038 moin.utils.clock:48 timer Item init(0): 130.20ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:22,039 moin.utils.clock:48 timer protecting may(0): 131.00ms TestItem
DEBUG 2024-10-11 23:08:22,194 moin.utils.clock:48 timer Item init(0): 122.39ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:22,194 moin.utils.clock:48 timer protecting may(0): 122.63ms TestItem
DEBUG 2024-10-11 23:08:22,196 moin.utils.clock:48 timer navibar(0): 0.15ms 
DEBUG 2024-10-11 23:08:22,323 moin.utils.clock:48 timer Item init(0): 126.49ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:22,442 moin.utils.clock:48 timer Item init(0): 118.78ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:22,559 moin.utils.clock:48 timer Item init(0): 116.36ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:22,677 moin.utils.clock:48 timer Item init(0): 118.09ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:08:22,678 moin.utils.clock:48 timer protecting may(0): 118.39ms TestItem
DEBUG 2024-10-11 23:08:22,678 moin.utils.clock:48 timer show item do_show(0): 2012.44ms TestItem rev_id=current

DEBUG 2024-10-11 23:08:22,679 moin.utils.clock:48 timer total(0): 2329.05ms /TestItem

Viewing the meta data of this item afterwards takes nearly the same time (2.5 secs).

[UlrichB22]

To prove the impact of the redundant queries I wrote a short cache function in commit 3e933ed.
This is experimental and should not be the solution. The result is looking like this

DEBUG 2024-10-11 23:24:28,422 moin.utils.clock:48 timer init(0): 4.27ms 
DEBUG 2024-10-11 23:24:28,589 moin.utils.clock:48 timer Item init(0): 164.12ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:28,722 moin.utils.clock:48 timer Item init(0): 133.30ms name: None query: {'itemid': 'cb33ee84eb3a4a54a31e2f4c5132ee5c'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:28,723 moin.utils.clock:48 timer Revision init(0): 0.02ms name: ['TestItem'] revid: 308f87c48ab044058631c7007b7a5030
DEBUG 2024-10-11 23:24:28,723 moin.utils.clock:48 timer show item create(0): 298.86ms TestItem rev_id=current

DEBUG 2024-10-11 23:24:28,725 moin.utils.clock:48 timer conv_in_dom(0): 1.25ms 
DEBUG 2024-10-11 23:24:28,725 moin.utils.clock:48 timer nowiki(0): 0.03ms 
DEBUG 2024-10-11 23:24:28,725 moin.utils.clock:48 timer conv_include(0): 0.12ms 
DEBUG 2024-10-11 23:24:28,725 moin.utils.clock:48 timer conv_macro(0): 0.07ms 
DEBUG 2024-10-11 23:24:28,726 moin.utils.clock:48 timer conv_link(0): 0.05ms 
DEBUG 2024-10-11 23:24:28,728 moin.utils.clock:48 timer conv_dom_html(0): 2.13ms 

DEBUG 2024-10-11 23:24:29,017 moin.utils.clock:48 timer Item init(0): 0.02ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,018 moin.utils.clock:48 timer Item init(0): 0.04ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,019 moin.utils.clock:48 timer protecting may(0): 0.62ms TestItem
DEBUG 2024-10-11 23:24:29,021 moin.utils.clock:48 timer Item init(0): 0.05ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,022 moin.utils.clock:48 timer protecting may(0): 0.68ms TestItem
DEBUG 2024-10-11 23:24:29,161 moin.utils.clock:48 timer Item init(0): 138.64ms name: /TestItem/Discussion query: {'name_exact': '/TestItem/Discussion', 'namespace': ''} itemid: undefined latest_doc: False
DEBUG 2024-10-11 23:24:29,289 moin.utils.clock:48 timer Item init(0): 126.96ms name: /TestItem/Discussion query: {'namespace': '', 'name_exact': '/TestItem/Discussion'} itemid: undefined latest_doc: False
DEBUG 2024-10-11 23:24:29,289 moin.utils.clock:48 timer Item init(0): 0.02ms name: /TestItem/Discussion query: {'namespace': '', 'name_exact': '/TestItem/Discussion'} itemid: undefined latest_doc: False
DEBUG 2024-10-11 23:24:29,289 moin.utils.clock:48 timer protecting may(0): 127.35ms /TestItem/Discussion
DEBUG 2024-10-11 23:24:29,289 moin.utils.clock:48 timer Item init(0): 0.01ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,289 moin.utils.clock:48 timer protecting may(0): 0.13ms TestItem
DEBUG 2024-10-11 23:24:29,290 moin.utils.clock:48 timer Item init(0): 0.03ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,291 moin.utils.clock:48 timer protecting may(0): 0.41ms TestItem
DEBUG 2024-10-11 23:24:29,291 moin.utils.clock:48 timer Item init(0): 0.03ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,291 moin.utils.clock:48 timer protecting may(0): 0.37ms TestItem
DEBUG 2024-10-11 23:24:29,320 moin.utils.clock:48 timer Item init(0): 0.02ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,320 moin.utils.clock:48 timer protecting may(0): 0.24ms TestItem
DEBUG 2024-10-11 23:24:29,322 moin.utils.clock:48 timer navibar(0): 0.25ms 
DEBUG 2024-10-11 23:24:29,325 moin.utils.clock:48 timer Item init(0): 0.09ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,325 moin.utils.clock:48 timer Item init(0): 0.02ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,325 moin.utils.clock:48 timer Item init(0): 0.01ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,326 moin.utils.clock:48 timer Item init(0): 0.02ms name: TestItem query: {'namespace': '', 'name_exact': 'TestItem'} itemid: cb33ee84eb3a4a54a31e2f4c5132ee5c latest_doc: False
DEBUG 2024-10-11 23:24:29,326 moin.utils.clock:48 timer protecting may(0): 0.24ms TestItem
DEBUG 2024-10-11 23:24:29,327 moin.utils.clock:48 timer show item do_show(0): 603.51ms TestItem rev_id=current

DEBUG 2024-10-11 23:24:29,329 moin.utils.clock:48 timer total(0): 911.13ms /TestItem

The response time dropped to 900 ms, and the display of the metadata immediately afterwards takes around 100 ms.

I need help and support on this issue. I did not see any call to the Items init function where latest_doc was used. This parameter should avoid running the same query repeatedly.

[UlrichB22]

Several of those queries are caused by user.may.write(fqname) in templates/itemviews.html. IMO it is the best solution to move this function call into apps/frontend/views.py and pass the result to the context of the template (same as item_is_deleted). Please advise.

I wonder what this line is intended for:

moin/src/moin/templates/itemviews.html

Line 10 in 807bfe1

{% set exists = fqname and storage.get_item(**fqname.query) %}

Is there any use case where the template is called for a non-existent element?

[RogerHaase]

Good catch; I cannot think of a case where the template is called for a non-existent element.

Agree with your suggestion to move user.may.write to views.py and pass into context.

[UlrichB22]

The above fix reduces the response time in the above example to about 1500 ms - that is a reduction of 30 %. For smaller wikis, the reduction is only around 10 to 15 %.

[UlrichB22]

Running a diff from an item history gives following traceback:

File "/mypath/moin/src/moin/templates/diff.html", line 6, in top-level template code
    {% extends theme("show.html") %}
    ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/mypath/moin/src/moin/templates/show.html", line 5, in top-level template code
    {% import "itemviews.html" as itemviews with context %}
    ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/mypath/moin-venv-python3/lib/python3.12/site-packages/jinja2/environment.py", line 1408, in make_module
    return TemplateModule(self, ctx)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/mypath/moin-venv-python3/lib/python3.12/site-packages/jinja2/environment.py", line 1540, in __init__
    body_stream = list(template.root_render_func(context))
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/mypath/moin/src/moin/templates/itemviews.html", line 54, in top-level template code
    {%- if endpoint == 'frontend.modify_item' and may.write and not_trash %}
    ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/mypath/moin-venv-python3/lib/python3.12/site-packages/jinja2/environment.py", line 487, in getattr
    return getattr(obj, attribute)
           ^^^^^^^^^^^^^^^^^^^^^^^
jinja2.exceptions.UndefinedError: 'may' is undefined
ERROR moin Exception on /+diff/MoinMoinWiki [GET]

[UlrichB22]

The index queries for /TestItem/Discussion above can be ommited if the Discussion feature is not used.
The feature can be deactived by following setting in wikiconfig.py:

    # deactivate discussion feature
    supplementation_item_names = []

I will add comments in wikiconfig.py .