Item10674: large MongoDBPlugin rest updateWebs crash after import

so while rendering the output it does something wrong .. not urgent, but annoying.

[Sat Apr 23 18:10:37 2011] [error] [client 192.168.1.30] File does not exist: /var/www/favicon.ico
[Sat Apr 23 19:55:55 2011] [error] [client 192.168.1.30] start web: System/MigrationScriptsInsectsDemo (74588)
[Sat Apr 23 19:56:18 2011] [error] [client 192.168.1.30] imported 1000
[Sat Apr 23 19:56:44 2011] [error] [client 192.168.1.30] imported 2000
[Sat Apr 23 19:57:14 2011] [error] [client 192.168.1.30] imported 3000
[Sat Apr 23 19:57:45 2011] [error] [client 192.168.1.30] imported 4000
[Sat Apr 23 19:58:16 2011] [error] [client 192.168.1.30] imported 5000
[Sat Apr 23 19:58:47 2011] [error] [client 192.168.1.30] imported 6000
[Sat Apr 23 19:59:18 2011] [error] [client 192.168.1.30] imported 7000
[Sat Apr 23 19:59:48 2011] [error] [client 192.168.1.30] imported 8000
[Sat Apr 23 20:00:19 2011] [error] [client 192.168.1.30] imported 9000
[Sat Apr 23 20:00:49 2011] [error] [client 192.168.1.30] imported 10000
[Sat Apr 23 20:01:20 2011] [error] [client 192.168.1.30] imported 11000
[Sat Apr 23 20:01:50 2011] [error] [client 192.168.1.30] imported 12000
[Sat Apr 23 20:02:20 2011] [error] [client 192.168.1.30] imported 13000
[Sat Apr 23 20:02:52 2011] [error] [client 192.168.1.30] imported 14000
[Sat Apr 23 20:03:24 2011] [error] [client 192.168.1.30] imported 15000
[Sat Apr 23 20:04:00 2011] [error] [client 192.168.1.30] imported 16000
[Sat Apr 23 20:04:40 2011] [error] [client 192.168.1.30] imported 17000
[Sat Apr 23 20:05:21 2011] [error] [client 192.168.1.30] imported 18000
[Sat Apr 23 20:06:04 2011] [error] [client 192.168.1.30] imported 19000
[Sat Apr 23 20:06:50 2011] [error] [client 192.168.1.30] imported 20000
[Sat Apr 23 20:07:39 2011] [error] [client 192.168.1.30] imported 21000
[Sat Apr 23 20:08:29 2011] [error] [client 192.168.1.30] imported 22000
[Sat Apr 23 20:09:21 2011] [error] [client 192.168.1.30] imported 23000
[Sat Apr 23 20:10:16 2011] [error] [client 192.168.1.30] imported 24000
[Sat Apr 23 20:11:13 2011] [error] [client 192.168.1.30] imported 25000
[Sat Apr 23 20:12:12 2011] [error] [client 192.168.1.30] imported 26000
[Sat Apr 23 20:13:14 2011] [error] [client 192.168.1.30] imported 27000
[Sat Apr 23 20:14:17 2011] [error] [client 192.168.1.30] imported 28000
[Sat Apr 23 20:15:22 2011] [error] [client 192.168.1.30] imported 29000
[Sat Apr 23 20:16:29 2011] [error] [client 192.168.1.30] imported 30000
[Sat Apr 23 20:17:38 2011] [error] [client 192.168.1.30] imported 31000
[Sat Apr 23 20:18:51 2011] [error] [client 192.168.1.30] imported 32000
[Sat Apr 23 20:20:06 2011] [error] [client 192.168.1.30] imported 33000
[Sat Apr 23 20:21:23 2011] [error] [client 192.168.1.30] imported 34000
[Sat Apr 23 20:22:42 2011] [error] [client 192.168.1.30] imported 35000
[Sat Apr 23 20:24:04 2011] [error] [client 192.168.1.30] imported 36000
[Sat Apr 23 20:25:27 2011] [error] [client 192.168.1.30] imported 37000
[Sat Apr 23 20:26:54 2011] [error] [client 192.168.1.30] imported 38000
[Sat Apr 23 20:28:22 2011] [error] [client 192.168.1.30] imported 39000
[Sat Apr 23 20:29:52 2011] [error] [client 192.168.1.30] imported 40000
[Sat Apr 23 20:31:25 2011] [error] [client 192.168.1.30] imported 41000
[Sat Apr 23 20:32:59 2011] [error] [client 192.168.1.30] imported 42000
[Sat Apr 23 20:34:37 2011] [error] [client 192.168.1.30] imported 43000
[Sat Apr 23 20:36:16 2011] [error] [client 192.168.1.30] imported 44000
[Sat Apr 23 20:37:57 2011] [error] [client 192.168.1.30] imported 45000
[Sat Apr 23 20:39:40 2011] [error] [client 192.168.1.30] imported 46000
[Sat Apr 23 20:41:24 2011] [error] [client 192.168.1.30] imported 47000
[Sat Apr 23 20:43:11 2011] [error] [client 192.168.1.30] imported 48000
[Sat Apr 23 20:44:59 2011] [error] [client 192.168.1.30] imported 49000
[Sat Apr 23 20:46:50 2011] [error] [client 192.168.1.30] imported 50000
[Sat Apr 23 20:48:42 2011] [error] [client 192.168.1.30] imported 51000
[Sat Apr 23 20:50:36 2011] [error] [client 192.168.1.30] imported 52000
[Sat Apr 23 20:52:33 2011] [error] [client 192.168.1.30] imported 53000
[Sat Apr 23 20:54:32 2011] [error] [client 192.168.1.30] imported 54000
[Sat Apr 23 20:56:33 2011] [error] [client 192.168.1.30] imported 55000
[Sat Apr 23 20:58:36 2011] [error] [client 192.168.1.30] imported 56000
[Sat Apr 23 21:00:41 2011] [error] [client 192.168.1.30] imported 57000
[Sat Apr 23 21:02:48 2011] [error] [client 192.168.1.30] imported 58000
[Sat Apr 23 21:04:58 2011] [error] [client 192.168.1.30] imported 59000
[Sat Apr 23 21:07:10 2011] [error] [client 192.168.1.30] imported 60000
[Sat Apr 23 21:09:23 2011] [error] [client 192.168.1.30] imported 61000
[Sat Apr 23 21:11:40 2011] [error] [client 192.168.1.30] imported 62000
[Sat Apr 23 21:13:57 2011] [error] [client 192.168.1.30] imported 63000
[Sat Apr 23 21:16:19 2011] [error] [client 192.168.1.30] imported 64000
[Sat Apr 23 21:18:40 2011] [error] [client 192.168.1.30] imported 65000
[Sat Apr 23 21:21:04 2011] [error] [client 192.168.1.30] imported 66000
[Sat Apr 23 21:23:31 2011] [error] [client 192.168.1.30] imported 67000
[Sat Apr 23 21:26:02 2011] [error] [client 192.168.1.30] imported 68000
[Sat Apr 23 21:28:34 2011] [error] [client 192.168.1.30] imported 69000
[Sat Apr 23 21:31:07 2011] [error] [client 192.168.1.30] imported 70000
[Sat Apr 23 21:33:43 2011] [error] [client 192.168.1.30] imported 71000
[Sat Apr 23 21:36:21 2011] [error] [client 192.168.1.30] imported 72000
[Sat Apr 23 21:39:00 2011] [error] [client 192.168.1.30] imported 73000
[Sat Apr 23 21:41:43 2011] [error] [client 192.168.1.30] imported 74000
[Sat Apr 23 21:43:19 2011] [error] [client 192.168.1.30] imported 74589
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] recv timed out (30000 ms) at /usr/local/lib/perl/5.10.1/MongoDB/Cursor.pm line 233.
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30]  at /usr/local/lib/perl/5.10.1/MongoDB/Cursor.pm line 233
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tMongoDB::Cursor::_do_query('MongoDB::Cursor=HASH(0xb753d758)') called at /home/sven/foswiki/core/lib/Foswiki/Plugins/MongoDBPlugin/Meta.pm line 90
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Plugins::MongoDBPlugin::Meta::reload('Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm line 192
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Plugins::MongoDBPlugin::Listener::loadTopic('Foswiki::Plugins::MongoDBPlugin::Listener=HASH(0xbd4b068)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki/Store.pm line 183
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Store::askListeners('Foswiki::Store::RcsWrap=HASH(0xa2d9658)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki/Store/VC/Store.pm line 82
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Store::VC::Store::readTopic('Foswiki::Store::RcsWrap=HASH(0xa2d9658)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)', undef) called at /home/sven/foswiki/core/lib/Foswiki/Meta.pm line 1020
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Meta::loadVersion('Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)', undef) called at /home/sven/foswiki/core/lib/Foswiki/Meta.pm line 455
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Meta::load('Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki/Macros/QUERY.pm line 31
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::QUERY('Foswiki=HASH(0xa2aa2b0)', 'Foswiki::Attrs=HASH(0xb753c048)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki.pm line 3038
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::_expandMacroOnTopicRendering('Foswiki=HASH(0xa2aa2b0)', 'QUERY', '"{NameFilter}"', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki.pm line 2917
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::_processMacros('Foswiki=HASH(0xa2aa2b0)', '%QUERY{"{NameFilter}"}%', 'CODE(0xa2388a0)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)', 15) called at /home/sven/foswiki/core/lib/Foswiki.pm line 2935
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::_processMacros('Foswiki=HASH(0xa2aa2b0)', '<meta name="foswiki.TWISTYANIMATIONSPEED" content="fast" /><!...', 'CODE(0xa2388a0)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)', 16) called at /home/sven/foswiki/core/lib/Foswiki.pm line 2714
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::innerExpandMacros('Foswiki=HASH(0xa2aa2b0)', 'SCALAR(0xa241fc8)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki.pm line 3215
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::expandMacros('Foswiki=HASH(0xa2aa2b0)', '<meta name="foswiki.TWISTYANIMATIONSPEED" content="fast" /><!...', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)') called at /home/sven/foswiki/core/lib/Foswiki/Meta.pm line 3189
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Meta::expandMacros('Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0xb7539dd8)', '<meta name="foswiki.TWISTYANIMATIONSPEED" content="fast" /><!...') called at /home/sven/foswiki/core/lib/Foswiki.pm line 3462
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::_renderZone('Foswiki=HASH(0xa2aa2b0)', 'head', 'HASH(0xac2df50)') called at /home/sven/foswiki/core/lib/Foswiki.pm line 3529
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::_renderZones('Foswiki=HASH(0xa2aa2b0)', '\\x{a} importing: \\x{a}System/MigrationScriptsInsectsDemo: 74589\\x{a}\\x{a}\\x{a}') called at /home/sven/foswiki/core/lib/Foswiki.pm line 762
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::writeCompletePage('Foswiki=HASH(0xa2aa2b0)', '\\x{a} importing: \\x{a}System/MigrationScriptsInsectsDemo: 74589\\x{a}\\x{a}\\x{a}') called at /home/sven/foswiki/core/lib/Foswiki/UI/Rest.pm line 255
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::UI::Rest::rest('Foswiki=HASH(0xa2aa2b0)') called at /home/sven/foswiki/core/lib/Foswiki/UI.pm line 316
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::UI::__ANON__() called at /usr/share/perl5/Error.pm line 416
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \teval {...} called at /usr/share/perl5/Error.pm line 408
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tError::subs::try('CODE(0x9d09948)', 'HASH(0xa2a9fd0)') called at /home/sven/foswiki/core/lib/Foswiki/UI.pm line 435
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::UI::_execute('Foswiki::Request=HASH(0xa285db0)', 'CODE(0xa285b40)', 'rest', 1) called at /home/sven/foswiki/core/lib/Foswiki/UI.pm line 274
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::UI::handleRequest('Foswiki::Request=HASH(0xa285db0)') called at /home/sven/foswiki/core/lib/Foswiki/Engine/CGI.pm line 37
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] \tFoswiki::Engine::CGI::run('Foswiki::Engine::CGI=HASH(0x9f18e18)') called at rest line 29.
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] 
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] 
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] | Event  | Delta | Abs | Mem |
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] 
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] | Foswiki object created | 0.00291395811807805% | 0.00291395811807805% | 20246528 |
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] 
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] | END | 99.9970655781506% | 100% | 83283968 |
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] Total time: 6474.87 wallclock secs (579.81 usr + 15.53 sys = 595.34 CPU)
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] 
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] | Count  |  Time (Min/Max) | Memory(Min/Max) | Total                                                       | Method        |
[Sat Apr 23 21:43:49 2011] [error] [client 192.168.1.30] File does not exist: /var/www/favicon.ico

-- SvenDowideit - 24 Apr 2011

And here's mine (slightly different)

imported 162000
can't get db response, not connected at /usr/local/lib/perl/5.10.1/MongoDB/Collection.pm line 383.
 at /usr/local/lib/perl/5.10.1/MongoDB/Collection.pm line 383
        MongoDB::Collection::update('MongoDB::Collection=HASH(0x115384e0)', 'HASH(0x11531b68)', 'HASH(0x11538720)', 'HASH(0x115312e0)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/Plugins/MongoDBPlugin/DB.pm line 151
        Foswiki::Plugins::MongoDBPlugin::DB::update('Foswiki::Plugins::MongoDBPlugin::DB=HASH(0x21aa570)', 'System/MigrationScriptsInsectsDemo', 'versions', 'System/MigrationScriptsInsectsDemo.Insect162833@1', 'HASH(0x11531988)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/Plugins/MongoDBPlugin.pm line 373
        Foswiki::Plugins::MongoDBPlugin::_updateTopic('System/MigrationScriptsInsectsDemo', 'Insect162833', 'Foswiki::Meta=HASH(0x11510850)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/Plugins/MongoDBPlugin.pm line 222
        Foswiki::Plugins::MongoDBPlugin::updateWebCache('System/MigrationScriptsInsectsDemo') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/Plugins/MongoDBPlugin.pm line 195
        Foswiki::Plugins::MongoDBPlugin::_update('Foswiki=HASH(0x1c20fd8)', 'MongoDBPlugin', 'update', 'Foswiki::Response=HASH(0x1c05d00)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/Func.pm line 665
        Foswiki::Func::__ANON__('Foswiki=HASH(0x1c20fd8)', 'MongoDBPlugin', 'update', 'Foswiki::Response=HASH(0x1c05d00)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/UI/Rest.pm line 242
        Foswiki::UI::Rest::rest('Foswiki=HASH(0x1c20fd8)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/UI.pm line 316
        Foswiki::UI::__ANON__() called at /usr/local/share/perl/5.10.1/Error.pm line 415
        eval {...} called at /usr/local/share/perl/5.10.1/Error.pm line 407
        Error::subs::try('CODE(0x1bc1ba8)', 'HASH(0x1c26940)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/UI.pm line 435
        Foswiki::UI::_execute('Foswiki::Request=HASH(0x1b5def8)', 'CODE(0x1b5db50)', 'rest', 1, 'command_line', 1) called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/UI.pm line 274
        Foswiki::UI::handleRequest('Foswiki::Request=HASH(0x1b5def8)') called at /usr/local/src/git.trin.org.au/core/lib/Foswiki/Engine/CLI.pm line 53
        Foswiki::Engine::CLI::run('Foswiki::Engine::CLI=HASH(0x15dc318)') called at bin/rest line 29.
Foswiki detected an internal error - please check your Foswiki logs and webserver logs for more information.

can't get db response, not connected1709.25user 203.78system 12:07:23elapsed 4%CPU (0avgtext+0avgdata 1124240maxresident)k
395208inputs+347288outputs (3338major+87972146minor)pagefaults 0swaps

-- PaulHarvey - 24 Apr 2011

Ah... looking at my nohup.out timestamp, this is roughly the same time as when I tried to sort the insecta web. While it was still being loaded. I thought a restart of all my mongod would help (it did!) but evidently the way I rebooted all three nodes in quick succession somehow made the driver fall over.

-- PaulHarvey - 24 Apr 2011

ok, so I should probly add a 'don't use flag to a database while its being loaded :/

or maybe something more brutal - like load only works if the foswiki is offline.

-- SvenDowideit - 25 Apr 2011

In a perfect world, we could run queries on the secondaries, while the master is busy being written at. I'd rather keep the existing behaviour, re-trying the webs that haven't loaded yet, rather than take the whole site down for an import. So if you add an "only if foswiki is offline" mode, please make it optional.

-- PaulHarvey - 25 Apr 2011

I protected the few "very large" (> 20,000) webs we had to AdminGroup, and the load completed successfully. I guess there's some contention going on when you're updating 60 topics/sec and it's trying to maintain indexes and then you've got these queries scanning over large sets of topics. I suspect the queries that are making it sad are those that are converted to db.eval (javascript) code executed inside mongo.

-- PaulHarvey - 29 Apr 2011

yes, write lock contention is 'bad' - essentially, when we resourt to the db.eval stuff, we're implementing a JOIN, which is outside the design spec

-- SvenDowideit - 29 Apr 2011

It would be interesting, in our copious amounts of spare time, to see if the import is more reliable with indexes disabled, and then do the ensureIndex steps after loading is completed

-- PaulHarvey - 29 Apr 2011

This doesn't affect us very often. Lowering to 'low'.

-- PaulHarvey - 23 May 2011

I imported Marine/SeaSlug/Messages (36k-ish topics) and at the end of it, there were no FIELD indexes set, so we couldn't order="formfield(Foo)" anything. Dropped & re-import seemd to get the indexes set. I did try updateDatabase, but that didn't help

-- PaulHarvey - 07 Jul 2011

I haven't seen this problem in a long time; I think this might be an artifact of struggling VMs or network, or both. Closing.

-- PaulHarvey - 15 Mar 2012

Commenting is disabled while not logged in