Item11983: prevent excessive calls into the revision system

A simple view is iterating over ALL revisions of a topic.

Despite the common believe that META:TOPICINFO is used to cache the latest revision information, this cache isn't used in most of the cases.

There's one simple operation of the RCS subsystem requested most frequently ... and implemented most expensively: getting the latest revision ID. This ID is used to build up a revision history iterator, which basically is a numbered list.

This last rev ID is computed by calling _numRevisions in the store handlers RcsWrapHandler and RcsLightHandler. The _numRevisions function is rather expensive in both implementations forking an external process in the first and reading all of the ,v file into memory in the second case.

_numRevisions is called 62 times on a normal topic (System.WebHome). These are 23 calls _numRevisions to different topics and 39 are repetitions.

_numRevisions in turn calls _readTo 1059 times(RcsLiteHandler).

All of these calls are only done to get the last rev ID, also available in the META:TOPICINFO.

All but one code path doesn't care about META:TOPICINFO. These then trigger a full RCS read.

It seems the RcsLite code was trying to only read up to a required point: _readTo ... (only read up to the next char required). However _readTo is wrapped into a while(1) loop in _ensureProcess() which crawls the ,v exhaustively.

_ensureProcessed seems to be invented to make sure all history data has been gathered in case it is required...

_ensureProcessed is called pretty much all over RcsLite in different places. It is a kind of "hit him on the head" just to make sure he is dead: a classic overkill.

Looking at Foswiki::UI::View, there are two direct calls into the revision system.

$revIt = $topicObject->getRevisionHistory();

and the undocumented pseudo-macro %REVISIONS%

     # Show revisions around the one being displayed.
    $tmpl =~ s/%REVISIONS%/
      revisionsAround(
          $session, $topicObject, $requestedRev, $showRev, $maxRev)/e;

(REVINFOS only works in templates, not in the topic)

The revIt isn't used in most of the cases, or only to get the last rev ID, or when a revision was explicitly requested. When a revision was explicitly requested, revIt is traveled down one revision at a time up to the number the revision ID was found in the history.

The pseudo-macro %REVISIONS is used by PatternSkin to display a fragment of the most recent revision history IDs (like r126 < r125 < r124 < r123 for my SitePreferences topic). This is implemented by a view-only private method called Foswiki::UI::View::revisionsAround() also used in Foswiki::UI::RDiff which again does a call to getRevisionsHistory() on its own (not reusing the one already computed)

and then does a

my @revs = $revIt->all();

Besides %REVISIONS being a bit of a usability problem, it yet again triggers a full read of the history.

The entry point for this kind of slowness is _numRevisions being called on various code paths:

1. while establishing the preference cache, all revisions of all involved topics are read triggered by a getInfo(), part of a readTopic(), starting with System.DefaultPreferences, all topic preferences, site preferences, etc.
2. readTopic() and thus getInfo() is also triggered by plugins reading parameters from topics, like AutoViewTemplate, SmiliesPlugin, InterwikiPlugin and so on
3. then comes getRevisionHistory() part of view
4. then comes %REVISIONS part of view
5. then comes a series of calls to %REVINFO part of the templates, that too trigger a revision system interaction
6. then come all %INCLUDEs (WebLeftBar, WebLeftBarLogin, WebLeftBarWebList, WebLeftBarExample, WebTopBarExample, LanguageSelector

As far as I see META:TOPICINFO is completely ignored by all of these calls resulting in an expensive RCS lookup.

-- MichaelDaum - 05 Jul 2012

Is there any reason at all to have the revision id's ( r126 < r125 < r124 < r123 ) ever refer back to the actual revisions in rcs, rather than just list current, -1, -2, -3? I think it is safe to assume that revisions are always sequential, esp. for this simple list of links. There is not any tooltip or any other information rendered beyond the numbers that I can find anyway.

-- GeorgeClark - 05 Jul 2012

Well I always found these numbers and links to be a sever problem for people to use. Imho, they have to go out all together and should be replaced with something like this

available via the "More" drop menu.

-- MichaelDaum - 05 Jul 2012

[08:38] <MichaelDaum> pharvey said: TOPICINFO line can't be trusted on the .txt
[08:39] <MichaelDaum> you have to. it caches the information deeply buried inside an rcs coffin ... expensive to dig out 
[08:40] <MichaelDaum> ie. as this is done on a massive scale on pages like WebIndex or WebChanges
[08:46] <pharvey> When Foswiki decides the .txt has been externally modified, it doesn't trust the TOPICINFO. That's the current behaviour
[08:56] <MichaelDaum> I had to disable this logic in readTopic
[08:57] <MichaelDaum> the overall logic isnt straight 
[08:58] <MichaelDaum> some code reads TOPICINFO first, some compares it to the "$truth" and tries to rewrite TOPICINFO, a lot of other code paths go the middle way by using the file timestamp to decid
[09:00] <MichaelDaum> IMHO, the last-rev-info should only be read from RCS in some very _very_ pathological cases
[09:00] <MichaelDaum> e.g. when there is no TOPICINFO in the txt file
[09:01] <MichaelDaum> everything else simply is too expensive
[09:02] <MichaelDaum> while comparing file mod time is cheap, the consequences are a significant drop of performance with users not being able to do much about it 
[09:03] <MichaelDaum> the choice is between "cant trust txt" vs "dont touch RCS with a ten foot pole"
[09:04] <MichaelDaum> first means: correctness 4ever, second means performance rulez over correctness
[09:05] <MichaelDaum> the situation immediately changes as soon as reading the last-rev-info record from the revision control system becomes as cheap as opening up the txt file
[09:06] <MichaelDaum> like cahce it in a memcached
[09:07] <MichaelDaum> or just plain memory for modperlers or fastcgieans

-- MichaelDaum - 08 Jul 2012

Here's a hotfix for foswiki-1.1.5 to get it back to performance

-- MichaelDaum - 12 Jul 2012

just a quick note - I think this change is broken. see http://trunk.foswiki.org/System/WebChanges

-- SvenDowideit - 15 Jul 2012

The fixes on this task item only opened a can of a lot more bugs.

It is triggered by topics with an invalid version string in META:TOPICINFO. Stuff like $Rev ...$. Foswiki::Store::cleanUpRevID returns zero in that case ... which triggers the assert ... a hidden error being there for about 2 years, maybe even longer.

cleanUpRevID must always return a valid rev id, which is a positive integer or a float 1.1, 1.2, ... 1.n.

It must never return even zero which it does right now. There are only a few code paths that are zero-aware. These triggerd the bug.

There are other points where a { ... version => 0 ...} hash is constructed in memory. That's wrong as well.

-- MichaelDaum - 27 Jul 2012

We desperately need to clarify the way META:TOPICINFO and the revision system interact with each other when:

1. using $meta->get('TOPICINFO')
2. using $store->getVersionInfo()
3. using $store->getNextRevision()
4. using $store->getRevisionHistory()

with the goal to make META:TOPICINFO act as a proper cache, that is we have to rely as much as possible on it to be consistent. That's not been the case before and therefore the performance problems turned up.

All except get('TOPICINFO') should try to read META:TOPICINFO first and only back down to deeper inspection when (a) there's a checkin pending or (b) the revision tag is invalid.

Calling get('TOPICINFO') will always return the raw data as stored in the txt file and won't try to be too intelligent with regards to cache consistency.

Only save() will fix the META:TOPICINFO bringing it in line with the revision history as stored in a ,v file.

I am currently struggling with the VCStoreTests to reshape the changed semantics as well as make sure we still improve on performance compared to before.

-- MichaelDaum - 07 Aug 2012

I think I've fixed the code and the unit tests now.

-- MichaelDaum - 08 Aug 2012

Re-opening to correct a flaw.

-- CrawfordCurrie - 14 Aug 2012

Lots of broken unit tests:

# Following  broken by Foswikirev:15268 - Item11963
# ../bin/TestRunner.pl -clean ViewScriptTests::test_render_raw QueryTests::verify_string_uops_BruteForceQuery SaveScriptTests::test_1897 MetaTests::test_validateMetaTagsInText CommentPluginTests::test_rev1_template_redirectto  Fn_SEARCH::test_groupby_none_using_subwebs  StoreImplementationTests::verify_delRev_StoreImplementationTests_RcsLite StoreImplementationTests::verify_delRev_StoreImplementationTests_RcsWrap StoreImplementationTests::verify_getRevisionDiff_StoreImplementationTests_RcsLite StoreImplementationTests::verify_getRevisionDiff_StoreImplementationTests_RcsWrap StoreImplementationTests::verify_getRevisionInfo_StoreImplementationTests_RcsLite StoreImplementationTests::verify_getRevisionInfo_StoreImplementationTests_RcsWrap ManageDotPmTests::test_DoubleAddToNewGroupCreate ManageDotPmTests::test_RemoveFromNonExistantGroup ManageDotPmTests::test_RemoveNoUserFromExistantGroup ManageDotPmTests::test_SingleAddToNewGroupCreate ManageDotPmTests::test_TwiceAddToNewGroupCreate ManageDotPmTests::verify_deleteUser_AllowLoginName_HtPasswdManager_TopicUserMapping ManageDotPmTests::verify_deleteUser_DontAllowLoginName_HtPasswdManager_TopicUserMapping ManageDotPmTests::verify_resetEmailOkay_AllowLoginName_HtPasswdManager_TopicUserMapping ManageDotPmTests::verify_resetEmailOkay_DontAllowLoginName_HtPasswdManager_TopicUserMapping 

# Following tests all broken by Foswikirev:15108 - Item11983
#../bin/TestRunner.pl -clean  Fn_SEARCH::test_groupby_none_using_subwebs MailerContribSuite::test_changeSubscription_and_isSubScribedTo_API  TWikiFuncTests::test_checkAccessPermission TWikiFuncTests::test_checkAccessPermission_421 FuncTests::test_checkWebAccessPermission FuncTests::test_createWeb_permissions FuncTests::test_saveTopicRoundTrip    

-- GeorgeClark - 23 Aug 2012

Fixed the ViewScriptTests

-- MichaelDaum - 27 Aug 2012

Results from hours of git bisect:

Following broken by distro:a28ee4428568 - Item15268 - MichaelDaum

• QueryTests::verify_string_uops_BruteForceQuery
• Fn_SEARCH::test_groupby_none_using_subwebs
• MetaTests::test_validateMetaTagsInText - seems to be missing a \n at the end of the topic text
• SaveScriptTests::test_1897 -

Fixed the two latter ... -- MD - 18 Sep 2012

• StoreImplementationTests::verify_delRev
• StoreImplementationTests::verify_eachChange
• StoreImplementationTests::verify_getRevisionDiff
• StoreImplementationTests::verify_getRevisionInfo
• StoreImplementationTests::verify_saveTopic $

The above showed some more nasty bugs in the core -- MD - 19 Sep 2012

Following broken by distro:2b941c92afa3 - Item11945 - MichaelDaum

• HTMLValidationTests::verify_switchboard_function_edit_default
• HTMLValidationTests::verify_switchboard_function_edit_pattern
• HTMLValidationTests::verify_switchboard_function_edit_plain
• HTMLValidationTests::verify_switchboard_function_edit_print

This is unrelated to this bug item. Fixed as part of Item12079. ... -- MD - 18 Sep 2012

Following tests all broken by distro:f9263416b90d - Item15268 - MichaelDaum

• Fn_SEARCH::test_groupby_none_using_subwebs

Not related to this bug item. Just an error in the unit test when sorting+limitting SEARCH results. Works as expected - test was f*ed up. ... -- MD - 18 Sep 2012

• MailerContribSuite::test_changeSubscription_and_isSubScribedTo_API
• FuncTests::test_saveTopicRoundTrip

Fixed these two ... Item12079. ... -- MD - 18 Sep 2012

These never worked - Item11860 - SvenDowideit. "fixed" using an expect_failure() call.

• Fn_SEARCH::test_paging_three_webs_second_page_zeroresultsset
• Fn_SEARCH::test_paging_three_webs_third_page_zeroresultsset

• FuncTests::test_checkWebAccessPermission
• FuncTests::test_createWeb_permissions

Following tests all broken by distro:ec7bbced9e73 - Item11571 - ArthurClemens

• SemiAutomaticTestCaseTests::test_TestCaseAutoFormattedSearchDetails

This test could not be bisected. The store changes seem to mask the failing commit.

• SemiAutomaticTestCaseTests::test_TestCaseAutoFormattedSearch

• Fixed by Babar afaics ... MD

-- GeorgeClark - 12 Sep 2012

New test failures:

• RCSHandlerTests fixed again.

-- MichaelDaum - 19 Sep 2012

These two TWikiFunc tests appear to reveal some breakage. They set an access permission in the Meta, and then a conflicting access permission in the text. The Meta should override the text, however in this case, the text appears to rule. Bisect points to distro:f9263416b90d

• TWikiFuncTests::test_checkAccessPermission
• TWikiFuncTests::test_checkAccessPermission_421

• These two have been yet another serious bug in Foswiki::Func::checkAccessPermission, besides the tests being plain wrong. See distro:6ea19d14fada ... MD - 24 Sep 2012

The corresponding Func tests are a bit different, and don't reveal the issue.

-- GeorgeClark - 21 Sep 2012

The difference is that after the Store changes, Meta->new( ... some topic ) returns loads the topic from store, even though it's not supposed to. I've added debug print statements to Func.pm.

Rev = HEAD	Rev = 11507
checkAccessPermission entered VIEW, WikiGuest TEXT supplied * Set ALLOWTOPICVIEW = NotASoul TEXT * Set ALLOWTOPICVIEW = NotASoul and META->text() * Set DENYTOPICVIEW = WikiGuest HAVE ACCESS RETURNS 0 *** META failed to override at TWikiCompatibilityPlugin//TWikiFuncTests.pm line 591	checkAccessPermission entered VIEW, WikiGuest TEXT supplied * Set ALLOWTOPICVIEW = NotASoul TEXT * Set ALLOWTOPICVIEW = NotASoul and META->text() HAVE ACCESS RETURNS 1

(Although the failure says meta failed to override, This is the pre-test, to confirm that the topic without meta->text() should be allowed. Since there is unexpected text in the topic object, the test fails. )

-- GeorgeClark - 21 Sep 2012

I've tried to create a test to duplicate the unloaded object. I've failed. Foswiki appears to always load the topic, so I have no idea where this is going or why the test fails.

Noted one other subtle difference. On Foswiki 1.1.5, an unloaded Meta object returns null from $meta->text(), Trunk returns an empty string.

-- GeorgeClark - 24 Sep 2012

Fixed in distro:6ea19d14fada

-- MichaelDaum - 24 Sep 2012

distro:a28ee4428568 breaks MongoDBPlugin quite horribly, according to git bisect. I think we broke store listeners. Consider the following code in AccessControlTests:

sub test_SetInText {
    my $this = shift;

    my $text = <<'THIS';
    * Set ALLOWTOPICVIEW = %USERSWEB%.MrGreen
THIS
    my ($topicObject) =
      Foswiki::Func::readTopic( $this->{test_web}, $this->{test_topic} );
    print '1' . $topicObject->text();
    $topicObject->text($text);
    print '2' . $topicObject->text();
    $topicObject->save();
    print '3' . $topicObject->text();
    $topicObject->finish();
    $this->createNewFoswikiSession();

    ($topicObject) =
      Foswiki::Func::readTopic( $this->{test_web}, $this->{test_topic} );
    print '4' . $topicObject->text();
    $this->_checkSettings($topicObject);
    $topicObject->finish();

    return;
}

Expected output with Mongo listener enabled seen with distro:669229528dee:

1BLEEGLE
2   * Set ALLOWTOPICVIEW = %USERSWEB%.MrGreen
3   * Set ALLOWTOPICVIEW = %USERSWEB%.MrGreen
4   * Set ALLOWTOPICVIEW = %USERSWEB%.MrGreen

Actual output with Mongo listener enabled seen with distro:a28ee4428568:

1BLEEGLE
2   * Set ALLOWTOPICVIEW = %USERSWEB%.MrGreen
3BLEEGLE
4BLEEGLE

So I need to understand if the tests that we "fixed" were actually fixed to pass with the current broken behaviour, or if this is additional breakage that's really not captured by any existing tests.

-- PaulHarvey - 16 Oct 2012

On a traditional foswiki the tests pass. The print output is as expected. So mongo seemed to have expected the previous broken behaviour. As far as I see there is no way to test the listeners without a mongo db setup. There are some hard-coded checks to skip some tests when there's no such setup. I guess these should better go into the mongo db extension rather than being part of the core unit tests. But anyway. Other than that there's barely any test on the "listener" stuff. As far as I remember Sven planned to re-engineer the listener concept, last but not least to fix the weird ask-listener pattern in the design (listeners listen, you can't ask them, they are passive, better use the normal "handler" pattern).

-- MichaelDaum - 16 Oct 2012

I think it's best to defer this task for the 1.2.0 release. The fix is very extensive, and fairly high risk for a patch release. Due to store differences, the back-port to 1.1.6 will be more complex than I want to handle.

-- GeorgeClark - 22 Oct 2012

See Extensions/Testing/PatchItem11983Contrib for an easy to install patch to Foswiki 1.1.5 and 1.1.6.

-- GeorgeClark - 06 Dec 2012

More so getting revision infos on attachments: each call to getAttachmentRevisionInfo results in two forks, ignoring any info cached in META::FILEATTACHMENT. Nasty.

Instead, the thing should first read META::FILEATTACHMENT and fall back to extracting rev info the hard way using an external helper program being forked.

-- MichaelDaum - 05 Aug 2013

Re-released PatchItem11983Contrib, but didn't bump the version. Only changed the comments to say it applies to 1.1.5-1.1.9 instead of 1.1.5-1.1.6. No reason to trigger anyone to re-install if it's already installed.

-- GeorgeClark - 14 Nov 2013

Commenting is disabled while not logged in