Priority: Urgent
Current State: Closed
Released In: n/a
Target Release: n/a
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:
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