Item5238: eachGroupMember seems to be re-processing the same groups multiple times.

I also found user mapping to be very slow in my test installation of 4.2.0 RC2. I've got only a few hundred user entries in several groups, but this is enough to slow down accesses very, very significantly. Access speed is OK if the logged-in user is found in one of the first user groups, but if all group topics have to be searched, a simple click on the "Edit" button takes 10-20 seconds.

I traced calls to _expandUserList and eachGroupMember in TWikiUserMapping.pm, and found that for a simple view access, each of my group topics is expanded multiple times. One of the group topics is apparently opened 100 times for one view access! I cannot exclude the possibility that something is severely wrong with the group definitions, and I'll double-check everything now, but if this is the kind of performance I'll get in 4.2, I won't be able to upgrade :(

-- TWiki:Main.ClausBrod - 10 Jan 2008

Claus, thanks for the report - I'll take a hard look at that today. Is this something you're seeing on pages visible to everyone? or on a restricted access one?

-- TWiki:Main.SvenDowideit - 10 Jan 2008

I think it's for pretty much any page (I've tried TWikiTemplates), but I'll have to double-check.

I just added a simple "caching" hack ( eachGroupMember only reads and expands a group topic if it hasn't expanded it before), and that seems to fix my performance problem. Need to experiment with this a little more, though. More on this hopefully tomorrow.

-- TWiki:Main.ClausBrod - 10 Jan 2008

looking into it in the mean time. There is definatly a bug in that its not cacheing, but if what you say is righ, there is a more serious problem that TWiki is evaluating groups even when it should not.

This might be peculiar to the LocalSite.cfg settings you have, or something in one of the topics in the render. (WebLeftBar, or even having a non-public web?)

-- TWiki:Main/SvenDowideit - 11 Jan 2008

ah. Looking back on 4.1.2 - this is where the removal of the user and group objects breaks down completely. I'm essentially bringing it back by using the cache hack that I'll commit in a moment.

-- TWiki:Main.SvenDowideit - 11 Jan 2008

I'm using

inotifywait -mr --timefmt "%T" --format "%T: %w%f - %e" data

to give me an idea of what is happening.

-- TWiki:Main.SvenDowideit - 11 Jan 2008

now, for a simple topic, edited by TWikiGuest, with no access permissions to get in the way, this is the file access log. I'm not sure yet why the viewed topic is read from disk twice.

17:37:49: data/TWiki/TWikiPreferences.txt - OPEN
17:37:49: data/TWiki/TWikiPreferences.txt - ACCESS
17:37:49: data/TWiki/TWikiPreferences.txt - ACCESS
17:37:49: data/TWiki/TWikiPreferences.txt - ACCESS
17:37:49: data/TWiki/TWikiPreferences.txt - ACCESS
17:37:49: data/TWiki/TWikiPreferences.txt - ACCESS
17:37:49: data/TWiki/TWikiPreferences.txt - ACCESS
17:37:49: data/TWiki/TWikiPreferences.txt - CLOSE_NOWRITE,CLOSE
17:37:49: data/Main/TWikiPreferences.txt - OPEN
17:37:49: data/Main/TWikiPreferences.txt - ACCESS
17:37:49: data/Main/TWikiPreferences.txt - CLOSE_NOWRITE,CLOSE
17:37:49: data/Main/TWikiGuest.txt - OPEN
17:37:49: data/Main/TWikiGuest.txt - ACCESS
17:37:49: data/Main/TWikiGuest.txt - CLOSE_NOWRITE,CLOSE
17:37:49: data/Sandbox/WebPreferences.txt - OPEN
17:37:50: data/Sandbox/WebPreferences.txt - ACCESS
17:37:50: data/Sandbox/WebPreferences.txt - CLOSE_NOWRITE,CLOSE
17:37:50: data/Sandbox/TestTopic5.txt - OPEN
17:37:50: data/Sandbox/TestTopic5.txt - ACCESS
17:37:50: data/Sandbox/TestTopic5.txt - CLOSE_NOWRITE,CLOSE
17:37:50: data/Sandbox/TestTopic5.txt - OPEN
17:37:50: data/Sandbox/TestTopic5.txt - ACCESS
17:37:50: data/Sandbox/TestTopic5.txt - CLOSE_NOWRITE,CLOSE
17:37:50: data/Sandbox/WebPreferences.txt - OPEN
17:37:50: data/Sandbox/WebPreferences.txt - ACCESS
17:37:50: data/Sandbox/WebPreferences.txt - CLOSE_NOWRITE,CLOSE
17:37:50: data/Sandbox/TestTopic5.txt - OPEN
17:37:50: data/Sandbox/TestTopic5.txt - ACCESS
17:37:50: data/Sandbox/TestTopic5.txt - CLOSE_NOWRITE,CLOSE
17:37:50: data/log200801.txt - OPEN
17:37:50: data/log200801.txt - MODIFY
17:37:50: data/log200801.txt - CLOSE_WRITE,CLOSE

-- SvenDowideit - 11 Jan 2008

Sven, this is brilliant!

I cannot merge in all your changes right away, since apparently there were a number of changes in this area since RC2, but I'm using the same caching approach which you introduced into eachGroupMember in TWikirev:16190 (without the changes in Users.pm), and it takes care of most of the performance problem already for me.

I'm not familiar with the TWiki release process - what needs to be done to integrate these performance changes into the upcoming 4.2.0 release?

Thanks a million!

-- TWiki:Main.ClausBrod - 11 Jan 2008

The changes you see are (now) in 4.2.0 - I'm pretty much working on nothing but 4.2.0 (and presumably 4.2.1). Please, feel free to report any other issues you may see (or even think you see) - sometimes its hard to see the trees for the forest - and this has been a year long forest.

-- TWiki:Main.SvenDowideit - 11 Jan 2008