Item11088: MongoDB much slower when SEARCH outputs 'formfield()'

I get a severe speed slowdown on a newly installed server when the SEARCH has a $formfield in the "format=" part. This is not the case on a server installed back in June.

I see the mongo web now are named differently also so I guess it is MongoDBPlugin related. From what I can see, trying db.current.find() in mongo CLI, the data seem to have been imported. So, meta info seem to be very fast but not formfields. I have no clue if it's just missing indexes or just not looking in mongodb when looking up formfield.

-- LarsEik - 28 Aug 2011

mmm, interesting! I'll take a look soonish - I'm still snowed under by child duties atm.

-- SvenDowideit - 29 Aug 2011

I stopped apache/mongod and deleted all mongodb files and then reimported. Using mongodb-10gen version. I get the same slowness when values from formfield has to be looked up. Tried to run https://gist.github.com/941875 but it doesn't run (mongo ensureIndexOnDBs.js from CLI). I assume I should try to svn out some older version of mongodbplugin but I'm mostly a svn co guy

-- LarsEik - 05 Sep 2011

For reference, we're using:

• MongoDBPlugin:74d537b5ca54 MongoDBPlugin
• distro:43d73c8445c3 core
• MongoDB 2.0.0-rc0 (nightly 2.0.0-rcX series can be obtained from http://www.mongodb.org/downloads )
• CPAN:MongoDB 0.43
• On 4GB Foswiki + 8GB MongoDB (single-core amd64 Ubuntu 10.04.3 LTS) VMs
• Feel free to hit our public site, Eg. http://wiki.trin.org.au/Lauries/ (JQGridPlugin SEARCH over ~25k topics) for comparison

This seems to work fine for us.

I think we need more information to proceed.

Can you please detail:

• How many topics in the web being searched
• What the SEARCH roughly looks like
• How many topics are in the results
• Are you using paging, or trying to display thousands of hits in a single page
• Etc

-- PaulHarvey - 05 Sep 2011

It's 2049 topics in this web, no subweb stuff.

I just add/remove the dollar in front of formfield to get the effect. No paging, 27 hits.
%SEARCH{
    "form.name = 'ServerForm' AND Os =~ 'SLES'"
     type="query"
     nonoise="on"
    web="Doku"
    format="   * [[$web.$topic][$topic]] -> $wikiname -> $parent -> formfield(Ip)"
}%

I'll check the other version numbers.

-- LarsEik - 05 Sep 2011

core: svn 12414 MongoDBPlugin: 12414 mongod --version: db version v1.8.3, pdfile version 4.5

-- LarsEik - 05 Sep 2011

I checked out the same revision of core and MongoDBPlugin but still have issues. I have deleted, re-imported, ensuredIndex etc. The test search I had in Sandbox to Doku web (above) is now much faster. But when I view some topics from within in the Doku web it's very slow. There's a view template and a form. Here I find that disabling SEARCH and RENDERFORDISPLAY in the view template makes thing fly as expected. Using QUERY and FORMFIELD seem ok.

I don't know how to troubleshoot other than removing MACROs and stuff to see what happens. I don't find much logging in /var/lob/mongodb/mongodb.log either. I logs nothing when I do the test search (above) but when I open a topic in the Doku web, from the search, then it logs two lines:

Wed Sep  7 13:57:51 [conn22] command web_83e2905dd4b6958a4f9c183739faa5d9.$cmd command: { count: "current", query: { _history: { $exists: 0 }, $where: " ( (foswiki_getField(this, 'FORM.name') == 'RutineForm') )  &&  ( ( ( /3dom02/.test(foswiki_toLowerCase(foswiki_getField(this, 'FIELD.all.value'))) ) ...", _ACLProfile_DENYTOPICVIEW: { $nin: {} }, _ACLProfile_ALLOWTOPICVIEW: { $in: [ "UNDEFINED" ] } } } ntoreturn:1 reslen:48 104ms
Wed Sep  7 13:57:51 [conn22] query web_83e2905dd4b6958a4f9c183739faa5d9.current nscanned:2051 reslen:20 112ms

-- LarsEik - 07 Sep 2011

27 hits and you get 'massive slowdown' ? that is mad. The main change that i was expecting to be a problem is that we're no longer trying to cache the form definition (and failing badly in some odd places)

but that should not make a massive difference

do you have actual figures? and more significantly, can you send me your dataset? thats so few topics that its more likely to e a weird corner case.

as you can see from the log lines you have, the in-mongodb portion is taking ~100ms - which hopefully is not the slowdown you're talking about.

-- SvenDowideit - 07 Sep 2011

Note that the org problem with formfield and format is gone now. I see so far that it is just some topics or types of topics that are affected. I'll have to analyze a bit more.

-- LarsEik - 07 Sep 2011

The slowness is variable but goes from 2 secs til 9 secs, sometimes more. The reason why some topics are slower seems to be that the SEARCH on the view template actually gets any results back and then has to render the formfield. No result is quick. That means the original problem is still there, I just got confused before I had time to dig more.

Now I took the SEARCH out of the view template to test it alone on a single topic and instead of BASETOPIC as criteria I hardcoded one specific topic. It is easy to see the effect then. The puzzling thing is that when I put the slow SEARCH in a TestTopic in the Sanbox web it's blazin fast, but it is slow when in the same web!? This symptom I can also see on the other test server.

-- LarsEik - 07 Sep 2011

And you've tried re-loading? Can you report what indexes are set:

use web_83e2905dd4b6958a4f9c183739faa5d9
db.current.getIndexes()

-- PaulHarvey - 08 Sep 2011

Also: are you brave enough to try mongodb-10gen-unstable ? They're almost ready to release MongoDB 2.0, so it shouldn't be too unstable... (you should probably delete /var/lib/mongodb/* and start again).

It's the only thing I can think of that might be substantially different :/

-- PaulHarvey - 08 Sep 2011

I'm on unstable already. About indexes I get a few screens of this:

{
      "v" : 1,
      "key" : {
         "FIELD.Merke.value" : NumberLong(1)
      },
      "ns" : "web_83e2905dd4b6958a4f9c183739faa5d9.current",
      "name" : "FIELD.Merke",
      "background" : true
   },

-- LarsEik - 08 Sep 2011

And WHY is the search so much faster when executed from a topic in Sandbox??

-- LarsEik - 08 Sep 2011

Sometimes I get these, plain visible at the top of the topic:

%META:TOPICINFO{_authorWikiName="Lek" author="lek" comment="save topic" date="1315481475" format="1.1" reprev="83" version="1"}%

Don't know if it was after import or after an edit.

-- LarsEik - 08 Sep 2011

About TOPICINFO: yeah, that's a bug I'm still seeing too. I've been meaning to write a test case so sven can fix ... doing that now.

As for the search executing faster from Sandbox... wow, that's one for Sven I think :/

Perhaps you can go through all the .pm files shipped with MongoDBPlugin and change all the lines use constant MONITOR       => 0; to =use constant MONITOR => 1;

Also, do you have DebugLogPlugin installed? It should give some timing stats in the HTTP header of any Foswiki response (watch with Firebug's net panel)

-- PaulHarvey - 08 Sep 2011

Also: does changing $Foswiki::cfg{Plugins}{MongoDBPlugin}{ExperimentalCode} make any difference?

-- PaulHarvey - 08 Sep 2011

I can't understand if I'm the only one to see this, but anyways. First this slowness shows only on data sets where the data form has several field definitions where a SEARCH get the data for values. That's why some of my data if performing well and other not. But I don't understand why looking up a value in a result set should re-read the form definition, because that's what it looks like from my user perspective. It might be something else completely in the code, of course.

Secondly I tested the slow SEARCH and then I changed the $formfield(Someting) to $percntQUERY{'$item'/Someting}$percnt. And it flies like 1.3 sec against 5 sec with formfield. How can this be on my system only?

Also as mentioned before, something works differently from within the same web (slow with formfield) and from another web (fast) using the exact same search. I've tried to nuke the WebPreferences and LdapContrib for permissions, nothing seems to affect other than this formfield thing. I can't think of anything else it can be but a core/MongoDB issue.

-- LarsEik - 11 Sep 2011

Excellent. It sounds like you've nailed the issue. Indeed, I think SvenDowideit removed some code to cache DataForm definitions, but the way that was done, was causing problems.

QUERY extracts the field verbatim, from the topic meta.

Whereas $formfield uses $field->renderForDisplay(), and that requires parsing of the DataForm definition to determine the field type.

-- PaulHarvey - 12 Sep 2011

You might be able to confirm this by reverting MongoDBPlugin:7caaf0cdcb58 - but then you might see some problems noted in Item10987

-- PaulHarvey - 12 Sep 2011

Tested a couple of other versions of Listener.pm but it did not help. I think it has to do with some other code because the exact same search is much faster in rendering the formfield from another web.

-- LarsEik - 12 Sep 2011

This is all mostly because a $formfield() will prompt a call to getRevisionInfo(), which means an RCS call, which on our VMs is ~100ms per call. So on a page with 100-200 results on it, that's.... a really long time.

• Add a getRevisionInfo store listener, a counterpart to load() and getRevisionHistory().
• Fix MetaCache so that it's multi-user safe, see Item10344, and re-enable its usage in Foswiki::Meta.
• Review Mongo's store listener behaviour, when the MetaCache has a copy, currently the mongo listener aborts.

-- PaulHarvey - 24 Oct 2011

This can be close by my part now. I have changed most of the formfields so they don't do the search there.

-- LarsEik - 23 Nov 2011

This problem has a few different facets to it; in this task, I have added a store listener which avoids unnecessary chattiness with RCS when Mongo has all the revs in its DB.

For the more fundamental issue that MongoDBPlugin can only transmit entire topic objects, and not just the parts actually needed by a formatted SEARCH or so, that is continued over at Item11697.

Closing.

-- PaulHarvey - 27 Mar 2012

Commenting is disabled while not logged in