moin icon indicating copy to clipboard operation
moin copied to clipboard

Slow performance: up to 10s per page

Open sebix opened this issue 1 year ago • 7 comments

The load time of one of our wikis has significantly decreased over time as more and more pages were added. The wiki still has only 69 pages, but the load times vary between 2s and 10s, which significantly reduces the user experience.

On the same server, we have an even smaller wiki with the same code base and only 13 pages, with load times of 0.7-1.7s.

Because of this correlation, we guess that the performance degradation is related to the number of pages.

Are there any performance-related things to improve in the settings? Are the any logging/debugging options to investigate the cause?

We are currently on version 5d33343dc617c706fd5d9d9fe398f2493f53e286

sebix avatar Aug 13 '24 13:08 sebix

Can you try to run a 'moin index-optimize' command when nobody is updating the wiki? In #1310 this fixed a performance issue.

Before and after running that command you can list the index files with 'ls -l wiki/index' to compare the size and number of index files.

UlrichB22 avatar Aug 13 '24 14:08 UlrichB22

Thank you for the tip.

The number of files decreased from 20 to 6 and the total size of the directory from 62M to 56M. The load times are now indeed below 2s, which isn't great but a big relief.

I guess we need to run that command on a regular basis.

sebix avatar Aug 13 '24 14:08 sebix

@sebix but you hopefully don't run moin as cgi?

With a persistent python/moin2 wsgi process, 2s sounds way too much for a normal/simple page.

Of course, on special pages and pages with expensive macros, load time depends very much on what is actually done there.

ThomasWaldmann avatar Aug 13 '24 15:08 ThomasWaldmann

@sebix but you hopefully don't run moin as cgi?

With a persistent python/moin2 wsgi process, 2s sounds way too much for a normal/simple page.

The setup uses apache2 with WSGI.

Of course, on special pages and pages with expensive macros, load time depends very much on what is actually done there.

The mentioned load times were all for simple pages with markdown or text only, without macros. /+index/ and /+history/ actually have the same load times (1.5s-2s). Markdown seems to have a very little effect of about 0.2s or so. Calling non-existent pages is quicker by about 1s: 0.8s. Calling, for example, /Home or /+index/Home directly from localhost to exclude any possible delays of TLS, reverse proxies, etc., the load time is consistently 1.7s.

sebix avatar Aug 13 '24 15:08 sebix

try to run a 'moin index-optimize' command when nobody is updating the wiki?

Is there an easy way to disable that people can update the wiki? Or: What happens if somebody updates it while the command runs?

bernhardreiter avatar Aug 13 '24 16:08 bernhardreiter

Is there an easy way to disable that people can update the wiki? Or: What happens if somebody updates it while the command runs?

No, I don't know of any other way to disable updates other than stopping the web server. In the case of optimize-index, this shouldn't really require an offline state, but I would always recommend running it at off-peak times.

UlrichB22 avatar Aug 15 '24 17:08 UlrichB22

@sebix, can you please test again with the latest update? In the last few days, some improvements have been made to speed up simple items. Perhaps we can close this issue for the moment?

Do not forget to clear the browser cache before testing with the latest version.

UlrichB22 avatar Oct 22 '24 20:10 UlrichB22

@sebix, are you using the discussion feature:

image

If not, you can deactivate the feature with following additional setting in wikiconfig.py:

    # deactivate discussion feature
    supplementation_item_names = []

This will save some additional index queries.

UlrichB22 avatar Nov 01 '24 20:11 UlrichB22

@sebix, can you please test again with the latest update? In the last few days, some improvements have been made to speed up simple items. Perhaps we can close this issue for the moment?

Yes, the performance is slightly better: 1.8s -> 1.7s.

@sebix, are you using the discussion feature: If not, you can deactivate the feature with following additional setting in wikiconfig.py:

    # deactivate discussion feature
    supplementation_item_names = []

This will save some additional index queries.

yes, that brings another small improvement of 1.7s -> 1.6s

sebix avatar Nov 29 '24 20:11 sebix

Note, even that is a slow system 1.6 seconds is still too slow for a tiny production wiki. If there is a linear dependency on the number of pages, it will only grow. Just from the technical structure, there shouldn't be an increasing effort for accessing one page depending on the total number of pages.

bernhardreiter avatar Dec 02 '24 10:12 bernhardreiter

We have successfully converted our moin wiki to moin2 and in total we have about 10.000 pages. We experience this slow performance as well and we have tried the above tips with moin index-optimize with just some minimal difference. Problem seem to come in bursts, sometimes it takes multiple minutes before a page is shown and sometime it comes quite quick, do not know if this is related to cache. If we look at the load of the system it never seems to use more than one core (100%) even if the server has 12 cores available. Any further tips would be appreciated.

xmarcux avatar Feb 27 '25 10:02 xmarcux

@xmarcux, which version are you using? The current Git version or version 2.0.0b1 from pip/Pypi?

Is the performance related to the pages, i.e. pages with a fast response are always fast, pages with a poor performance are always poor?

UlrichB22 avatar Feb 27 '25 11:02 UlrichB22

@UlrichB22, yes we are running 2.0.0b1 from pip. No, the loading time is really random, the same page can be fast sometimes and really slow sometimes. Have not been able to find any pattern yet and as said, do not know if it is related to cache. We will do some more testing during next week to see if we can see some pattern in the loading time and in that case we will report back.

xmarcux avatar Feb 27 '25 16:02 xmarcux

Since 2.0.0b1 we have made several performance improvements. If possible, can you check the current Git version? We recommend clearing the browser cache before testing with the newer version.

UlrichB22 avatar Feb 28 '25 13:02 UlrichB22

We recommend clearing the browser cache before testing with the newer version.

And also delete the cookies, as that has a major impact how the backend processes stuff (as proven by #1801)

sebix avatar Feb 28 '25 13:02 sebix

Please test the above mentioned PR in a test environment. I would be happy to get your feedback.

After updating to this version the indexes need to be dropped and rebuild:

moin index-destroy
moin index-create
moin index-build

Documentation updates and some test modules will follow.

UlrichB22 avatar Mar 21 '25 19:03 UlrichB22

Thank you, will do so!

sebix avatar Mar 21 '25 19:03 sebix

In my local test env the speed increases by about 40%, but the sample size is low. When I test the code on the prod environment: All I need to do to switch back, is re-creating the index the same way, right?

sebix avatar Mar 23 '25 16:03 sebix

Problem seem to come in bursts, sometimes it takes multiple minutes before a page is shown and sometime it comes quite quick, do not know if this is related to cache.

@xmarcux, moin 2.0 does not have an item cache. There is a draft version to improve response times (s. above). If you still encounter these extreme response times you can enable DEBUG logging and look for the timer messages in the log, e.g.

DEBUG 2025-03-23 22:03:49,124 moin.utils.clock:48 timer init(0): 3.95ms 
DEBUG 2025-03-23 22:03:49,700 moin.utils.clock:48 timer conv_in_dom(0): 16.92ms 
DEBUG 2025-03-23 22:03:49,701 moin.utils.clock:48 timer nowiki(0): 0.42ms 
DEBUG 2025-03-23 22:03:49,701 moin.utils.clock:48 timer conv_include(0): 0.72ms 
DEBUG 2025-03-23 22:03:49,775 moin.utils.clock:48 timer conv_macro(0): 73.27ms 
DEBUG 2025-03-23 22:03:50,468 moin.utils.clock:48 timer conv_link(0): 693.36ms 
DEBUG 2025-03-23 22:03:50,480 moin.utils.clock:48 timer conv_dom_html(0): 10.97ms 
DEBUG 2025-03-23 22:03:50,896 moin.utils.clock:48 timer navibar(0): 0.69ms 
DEBUG 2025-03-23 22:03:50,898 moin.utils.clock:48 timer total(0): 1778.40ms /Home

In this example the item /Home has a lot of links and checking the existence of the link targets takes approx. 700ms in the conv_link method.

UlrichB22 avatar Mar 23 '25 21:03 UlrichB22

can enable DEBUG logging

How to do that? I wasn't able to find information on logging levels in the documentation.

sebix avatar Mar 24 '25 07:03 sebix

Please see the comments in src/moin/log.py.

In a development environment, the simplest method is to temporarily update log.level = “DEBUG” in the above file.

I also added an issue to update the docs.

UlrichB22 avatar Mar 24 '25 08:03 UlrichB22

On one of our instances, 1.4s is spent within timer total(0), the second most 0.3s in conv_link(0):

timer init(0): 53.83ms 
timer conv_in_dom(0): 2.52ms 
timer nowiki(0): 1.05ms 
timer conv_include(0): 2.43ms 
timer conv_macro(0): 2.98ms 
timer conv_link(0): 333.54ms 
timer conv_dom_html(0): 4.75ms 
timer navibar(0): 0.30ms 
timer total(0): 1456.41ms /Home
timer init(0): 61.32ms 
timer total(0): 63.45ms /_themes/focus/js/main.js
timer init(0): 34.56ms 
timer total(0): 37.33ms /_themes/focus/icons/magnifying-glass-solid.svg
timer init(0): 21.82ms 
timer total(0): 23.58ms /_themes/focus/icons/globe-rotate-left-solid.svg

sebix avatar Mar 24 '25 09:03 sebix

On one of our instances, 1.4s is spent within timer total(0), the second most 0.3s in conv_link(0):

@sebix can you please test again with today's changes to the focus theme in #1528?

Some performance improvements from October 2024 were not included in this theme.

UlrichB22 avatar Apr 22 '25 19:04 UlrichB22

I had used a merged branch that included all commits up to 1b072a1f0d22c595b4a93ed34361e7a1dcc88d27 (March 2025).

This is now on de8631a614639a66043ed2dc0f13c7a0771aff7a with the same page as with the timer output above:

timer init(0): 17.88ms 
timer conv_in_dom(0): 2.50ms 
timer nowiki(0): 0.99ms 
timer conv_include(0): 2.15ms 
timer conv_macro(0): 2.73ms 
timer conv_link(0): 325.47ms 
timer conv_dom_html(0): 4.39ms 
timer navibar(0): 0.28ms 
timer total(0): 663.89ms /Home
timer init(0): 20.96ms 
timer total(0): 22.63ms /_themes/focus/js/main.js
timer init(0): 34.28ms 
timer total(0): 36.10ms /_themes/focus/icons/magnifying-glass-solid.svg
timer init(0): 34.34ms 
timer total(0): 35.93ms /_themes/focus/icons/globe-rotate-left-solid.svg

This is another page:

timer init(0): 18.06ms 
timer conv_in_dom(0): 2.48ms 
timer nowiki(0): 0.97ms 
timer conv_include(0): 2.10ms 
timer conv_macro(0): 2.66ms 
timer conv_link(0): 563.61ms 
timer conv_dom_html(0): 3.38ms 
timer navibar(0): 0.28ms 
timer total(0): 906.09ms /Meetings
timer init(0): 22.21ms 
timer total(0): 29.96ms /_themes/focus/js/main.js
timer init(0): 117.69ms 
timer total(0): 119.44ms /_themes/focus/icons/globe-rotate-left-solid.svg
timer init(0): 121.46ms 
timer total(0): 122.99ms /_themes/focus/icons/magnifying-glass-solid.svg

sebix avatar Apr 23 '25 06:04 sebix

Performance fix #1877 is merged. This issue is closed now.

For new performance issues, please provide some details about your environment, such as

  • Theme used

  • Number of items, as specified in the header of +index/all

  • Size of the index files. Example from a Linux system:

    $ du -sm wiki/index/*.seg
    53	wiki/index/all_revs_p5a0b8htea6grjke.seg
    10	wiki/index/latest_idx_sdoyws8715tzm069.seg
    123	wiki/index/latest_revs_q5rl3r47mk54uds3.seg
    

UlrichB22 avatar May 19 '25 19:05 UlrichB22

The performance improvement of #1877 is significant, in the range of about 10-50% per page, depending on the page size/complexity.

sebix avatar May 20 '25 06:05 sebix