[wdmmg-dev] MongoDB crash during openspending import

Thu Sep 22 22:01:28 UTC 2011

Hi Alex,

I haven't had a chance to look into this yet, but will attempt to do
so in the next few days. It looks a little like Mongo's failing when
trying to build an index -- it's not beyond comprehension that this is
because we're building an index for a field on which we really don't
want to be doing so.

-N

On Tue, Sep 20, 2011 at 06:24, Alex (Maxious) Sadleir <maxious at gmail.com> wrote:
> 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
>
> _______________________________________________
> wdmmg-dev mailing list
> wdmmg-dev at lists.okfn.org
> http://lists.okfn.org/mailman/listinfo/wdmmg-dev
>