[wdmmg-dev] MongoDB crash during openspending import

Tue Sep 20 05:24:35 UTC 2011

Hi, I decided to try to install OpenSpending devel branch today to
work out why my dataset doesn't finish importing on the sandbox site.
Unfortunately, it seems to be due to MongoDB crashing or stalling in a
mapreduce job. One time when it didn't crash, it was just stuck at
"16499/218870" but those lines in the file don't seem very different
to any other.

Platform
Fedora 15 x86-64 under VMWare
MongoDB 2.0
Python 2.7.1
Solr 3.40 under Tomcat 6

Trying to import
http://ckan.net/dataset/australian_federal_government_contract_spending
a dataset with 218270 lines but some lines can be very long because of
HTML pasted in description free text field.

ETL output:
[...]
2011-09-20 15:16:40 INFO: Imported 215000 lines
2011-09-20 15:16:42 INFO: Imported 216000 lines
2011-09-20 15:16:44 INFO: Imported 217000 lines
2011-09-20 15:16:46 INFO: Imported 218000 lines

MongoDB output (I tried to turn up the debugging as much as I could)
Tue Sep 20 15:16:31 [conn6] update openspending_dev.entity  query: {
name: "taylor-thomson-whitting-act-pty-ltd-trustee-for-taylor-thomson-whittin..."
} 147ms
Tue Sep 20 15:16:33 [conn6] insert openspending_dev.entry 127ms
Tue Sep 20 15:16:49 [conn6] update openspending_dev.classifier  query:
{ taxonomy: "unspsc" } 122ms
Tue Sep 20 15:16:49 [conn6] building new index on { _id: 1 } for
openspending_dev.distincts__australian_federal_government_contract_spending
Tue Sep 20 15:16:49 [conn6] done for 0 records 0secs
Tue Sep 20 15:16:49 [conn6] info: creating collection
openspending_dev.distincts__australian_federal_government_contract_spending
on add index
Tue Sep 20 15:16:49 [conn6] building new index on { value.keys: 1.0 }
for openspending_dev.distincts__australian_federal_government_contract_spending
Tue Sep 20 15:16:49 [conn6] done for 0 records 0secs
Tue Sep 20 15:16:49 [conn6] CMD: drop
openspending_dev.tmp.mr.entry_distincts__australian_federal_government_contract_spending_0
Tue Sep 20 15:16:49 [conn6] CMD: drop
openspending_dev.tmp.mr.entry_distincts__australian_federal_government_contract_spending_0_inc
Tue Sep 20 15:16:49 [conn6] building new index on { 0: 1 } for
openspending_dev.tmp.mr.entry_distincts__australian_federal_government_contract_spending_0_inc
Tue Sep 20 15:16:49 [conn6] done for 0 records 0secs
Tue Sep 20 15:16:49 [conn6] warning: ClientCursor::yield can't unlock
b/c of recursive lock ns: openspending_dev.entry
[the line above repeated many times]
Tue Sep 20 15:16:49 [conn6] warning: ClientCursor::yield can't unlock
b/c of recursive lock ns: openspending_dev.entry
		5600/218870	2%
		11900/218870	5%
Tue Sep 20 15:16:56 Got signal: 11 (Segmentation fault).

Tue Sep 20 15:16:56 Backtrace:
0x7c9e8f 0x7c2bec 0x7f2ebbe73350 0x36a2356c9b 0x36a22f688a
0x36a22c14b9 0x36a22d3ae5 0x36a22d409e 0x36a225ce77 0x36a22ca8ea
0x36a22d3ae5 0x36a22d409e 0x36a22d4e9e 0x36a224d803 0x5f5dd5 0x757dc2
0x758a56 0x75b473 0x75b73d 0x760717
 mongod(_ZN5mongo15printStackTraceERSo+0x1f) [0x7c9e8f]
 mongod(_ZN5mongo10abruptQuitEi+0x34c) [0x7c2bec]
 /lib64/libc.so.6(+0x35350) [0x7f2ebbe73350]
 /usr/lib64/libmozjs185.so.1.0() [0x36a2356c9b]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22f688a]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22c14b9]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22d3ae5]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22d409e]
 /usr/lib64/libmozjs185.so.1.0() [0x36a225ce77]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22ca8ea]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22d3ae5]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22d409e]
 /usr/lib64/libmozjs185.so.1.0() [0x36a22d4e9e]
 /usr/lib64/libmozjs185.so.1.0(JS_CallFunction+0x43) [0x36a224d803]
 mongod(_ZN5mongo7SMScope6invokeEP10JSFunctionRKNS_7BSONObjEib+0x225) [0x5f5dd5]
 mongod(_ZN5mongo2mr9JSReducer7_reduceERKSt6vectorINS_7BSONObjESaIS3_EERS3_Ri+0x6d2)
[0x757dc2]
 mongod(_ZN5mongo2mr9JSReducer6reduceERKSt6vectorINS_7BSONObjESaIS3_EE+0x76)
[0x758a56]
 mongod(_ZN5mongo2mr5State14reduceInMemoryEv+0xa3) [0x75b473]
 mongod(_ZN5mongo2mr5State9checkSizeEv+0x2d) [0x75b73d]
 mongod(_ZN5mongo2mr16MapReduceCommand3runERKSsRNS_7BSONObjERSsRNS_14BSONObjBuilderEb+0x647)
[0x760717]

Tue Sep 20 15:16:56 dbexit:
Tue Sep 20 15:16:56 [conn6] shutdown: going to close listening sockets...
Tue Sep 20 15:16:56 [conn6] closing listening socket: 5
Tue Sep 20 15:16:56 [conn6] closing listening socket: 6
Tue Sep 20 15:16:56 [conn6] closing listening socket: 7
Tue Sep 20 15:16:56 [conn6] closing listening socket: 8
Tue Sep 20 15:16:56 [conn6] removing socket file: /tmp/mongodb-27017.sock
Tue Sep 20 15:16:56 [conn6] removing socket file: /tmp/mongodb-28017.sock
Tue Sep 20 15:16:56 [conn6] shutdown: going to flush diaglog...
Tue Sep 20 15:16:56 [conn6] shutdown: going to close sockets...
Tue Sep 20 15:16:56 [conn6] shutdown: waiting for fs preallocator...
Tue Sep 20 15:16:56 [conn6] shutdown: closing all files...
Tue Sep 20 15:16:56 [conn2] end connection 127.0.0.1:42349
Tue Sep 20 15:16:56 closeAllFiles() finished
Tue Sep 20 15:16:56 [conn6] shutdown: removing fs lock...
Tue Sep 20 15:16:56 dbexit: really exiting now
Tue Sep 20 15:16:56 [conn6] ERROR: Client::~Client _context should be
null but is not; client:conn