search

Tokutek / mongo

TokuMX is a high-performance, concurrent, compressing, drop-in replacement engine for MongoDB | Issue tracker: https://tokutek.atlassian.net/browse/MX/ |
http://www.tokutek.com/products/tokumx-for-mongodb/
703 stars 97 forks source link

Tokumx Crashes at 98% while building index on large collection #1228

Open adeelahmadch opened 9 years ago

adeelahmadch commented 9 years ago

i have a very large collection :db.catalog_item.count() 112038199

and i am trying to build index on key { newItemExtQuoteId: 1 } , tokumx start the index and crashes at 98% without giving any proper error. if i look into logs it says: Crash Reason: Got signal: 6 (Aborted). Error Logs is at the bottom.below the info for OS, TOKUMX Version and logs

TokumX Version

TokuMX mongod server v2.0.1-mongodb-2.4.10, using TokuKV rev 39fefcc4d2b1421ea09a9e41b130a64b230583b7 Wed Jun 3 23:49:31.430 git version: d4547074dcc9129f2e13ed6b76fd78edb0a2828e

OS Version and Resources r3.large instance where nothing is running and 8GB assigned to TokuMX

cat /etc/os-release

NAME="Amazon Linux AMI" VERSION="2015.03" ID="amzn" ID_LIKE="rhel fedora" VERSION_ID="2015.03" PRETTY_NAME="Amazon Linux AMI 2015.03" ANSI_COLOR="0;33" CPE_NAME="cpe:/o:amazon:linux:2015.03:ga" HOME_URL="http://aws.amazon.com/amazon-linux-ami/"

ulimit -a

core file size (blocks, -c) 0 data seg size (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 122278 max locked memory (kbytes, -l) 64 max memory size (kbytes, -m) unlimited open files (-n) 20000 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 122278 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited

ERROR LOGS

you can see error after 98%

Wed Jun 3 11:07:01.797 [conn10] getmore vroozi.process query: { processState: "SUCCESS" } cursorid:11383450835057017 ntoreturn:0 keyUpdates:0 locks(micros) r:1389 nreturned:660 reslen:243118 1ms Wed Jun 3 11:07:02.007 [conn8] Foreground index build progress (collect phase) for catalog.catalog_item, key { newItemExtQuoteId: 1 }: 110882000/112038199 98% (estimated documents) Wed Jun 3 11:07:03.303
Wed Jun 3 11:07:03.305 ================================================================================ Wed Jun 3 11:07:03.305 Fatal error detected Wed Jun 3 11:07:03.305 ================================================================================ Wed Jun 3 11:07:03.305
Wed Jun 3 11:07:03.305 About to gather debugging information, please include all of the following along Wed Jun 3 11:07:03.305 with logs from other servers in the cluster in a bug report. Wed Jun 3 11:07:03.305
Wed Jun 3 11:07:03.305 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.305 Version info: Wed Jun 3 11:07:03.305
Wed Jun 3 11:07:03.305 tokumxVersion: 2.0.1 Wed Jun 3 11:07:03.305 gitVersion: d4547074dcc9129f2e13ed6b76fd78edb0a2828e Wed Jun 3 11:07:03.305 tokukvVersion: 39fefcc4d2b1421ea09a9e41b130a64b230583b7 Wed Jun 3 11:07:03.305 sysInfo: Linux 9df3ab53d071 3.11.0-26-generic #45-Ubuntu SMP Tue Jul 15 04:02:06 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux BOOST_LIB_VERSION=1_49 Wed Jun 3 11:07:03.305 loaderFlags:
Wed Jun 3 11:07:03.305 compilerFlags: -fPIC -fno-strict-aliasing -ggdb -Wall -Wsign-compare -Wno-unknown-pragmas -Winvalid-pch -pipe -Wnon-virtual-dtor -Woverloaded-virtual -Wno-unused-local-typedefs -fno-builtin-memcmp -O3 Wed Jun 3 11:07:03.305 debug: false Wed Jun 3 11:07:03.305
Wed Jun 3 11:07:03.305 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.305 Simple stacktrace: Wed Jun 3 11:07:03.305
0xc4dfe3 0x951e37 0x9552cb 0x776c77 0x7fb3c9da5640 0x7fb3c9da55c9 0x7fb3c9da6cd8 0x7fb3cb4143f7 0x7fb3cb3f5f63 0x7fb3cb3ffd8b 0x7fb3cb4158ae 0x7fb3cb416bf5 0x7fb3cb416ce0 0x7fb3cb416ce0 0x7fb3cb416ce0 0x7fb3cb418620 0x7fb3cb42eaf4 0x9acfb5 0x9af190 0x9b12d8 /usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x23) [0xc4dfe3] /usr/bin/mongod() [0x951e37] /usr/bin/mongod(_ZN5mongo13dumpCrashInfoERKNS_10StringDataE+0x2b) [0x9552cb] /usr/bin/mongod(_ZN5mongo10abruptQuitEi+0xa7) [0x776c77] /lib64/libc.so.6(+0x35640) [0x7fb3c9da5640] /lib64/libc.so.6(gsignal+0x39) [0x7fb3c9da55c9] /lib64/libc.so.6(abort+0x148) [0x7fb3c9da6cd8] /usr/lib64/tokumx/libtokufractaltree.so(+0x7e3f7) [0x7fb3cb4143f7] /usr/lib64/tokumx/libtokufractaltree.so(+0x5ff63) [0x7fb3cb3f5f63] /usr/lib64/tokumx/libtokufractaltree.so(+0x69d8b) [0x7fb3cb3ffd8b] /usr/lib64/tokumx/libtokufractaltree.so(+0x7f8ae) [0x7fb3cb4158ae] /usr/lib64/tokumx/libtokufractaltree.so(+0x80bf5) [0x7fb3cb416bf5] /usr/lib64/tokumx/libtokufractaltree.so(+0x80ce0) [0x7fb3cb416ce0] /usr/lib64/tokumx/libtokufractaltree.so(+0x80ce0) [0x7fb3cb416ce0] /usr/lib64/tokumx/libtokufractaltree.so(+0x80ce0) [0x7fb3cb416ce0] /usr/lib64/tokumx/libtokufractaltree.so(+0x82620) [0x7fb3cb418620] /usr/lib64/tokumx/libtokufractaltree.so(+0x98af4) [0x7fb3cb42eaf4] /usr/bin/mongod(_ZN5mongo11IndexCursor13fetchMoreRowsEv+0xb5) [0x9acfb5] /usr/bin/mongod(_ZN5mongo11IndexCursor8_advanceEv+0x60) [0x9af190] /usr/bin/mongod(_ZN5mongo11IndexCursor7advanceEv+0x88) [0x9b12d8] Wed Jun 3 11:07:03.384
Wed Jun 3 11:07:03.384 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.384 TokuKV engine backtrace: Wed Jun 3 11:07:03.384
Wed Jun 3 11:07:03.392 Backtrace: (Note: toku_do_assert=0x0x7fb3cb18f860)

Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokuportability.so(_Z27db_env_do_backtraceerrfuncPFvPKviPKczES0+0x1f) [0x7fb3cb19156f] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x1439d) [0x7fb3cb3aa39d] Wed Jun 3 11:07:03.406 /usr/bin/mongod() [0x951f08] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo13dumpCrashInfoERKNS_10StringDataE+0x2b) [0x9552cb] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo10abruptQuitEi+0xa7) [0x776c77] Wed Jun 3 11:07:03.406 /lib64/libc.so.6(+0x35640) [0x7fb3c9da5640] Wed Jun 3 11:07:03.406 /lib64/libc.so.6(gsignal+0x39) [0x7fb3c9da55c9] Wed Jun 3 11:07:03.406 /lib64/libc.so.6(abort+0x148) [0x7fb3c9da6cd8] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x7e3f7) [0x7fb3cb4143f7] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x5ff63) [0x7fb3cb3f5f63] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x69d8b) [0x7fb3cb3ffd8b] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x7f8ae) [0x7fb3cb4158ae] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x80bf5) [0x7fb3cb416bf5] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x80ce0) [0x7fb3cb416ce0] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x80ce0) [0x7fb3cb416ce0] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x80ce0) [0x7fb3cb416ce0] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x82620) [0x7fb3cb418620] Wed Jun 3 11:07:03.406 /usr/lib64/tokumx/libtokufractaltree.so(+0x98af4) [0x7fb3cb42eaf4] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo11IndexCursor13fetchMoreRowsEv+0xb5) [0x9acfb5] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo11IndexCursor8_advanceEv+0x60) [0x9af190] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo11IndexCursor7advanceEv+0x88) [0x9b12d8] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo14CollectionBase11ColdIndexer5buildEv+0x549) [0x948659] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo14CollectionBase11createIndexERKNS_7BSONObjE+0xb2) [0x9cae32] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo14CollectionBase11ensureIndexERKNS_7BSONObjE+0x167) [0x9cc287] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo10Collection11ensureIndexERKNS_7BSONObjE+0xbc) [0x9e6f6c] Wed Jun 3 11:07:03.406 /usr/bin/mongod(_ZN5mongo13insertObjectsEPKcRKSt6vectorINS_7BSONObjESaIS3_EEbmbb+0x3dc) [0x9c89ac] Wed Jun 3 11:07:03.407 /usr/bin/mongod() [0x98b006] Wed Jun 3 11:07:03.407 /usr/bin/mongod(_ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE+0x1315) [0x992545] Wed Jun 3 11:07:03.407 /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0xe8b) [0x99345b] Wed Jun 3 11:07:03.407 /usr/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x8b) [0x78cd0b] Wed Jun 3 11:07:03.407 /usr/bin/mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x3dc) [0x895afc] Wed Jun 3 11:07:03.407 /lib64/libpthread.so.0(+0x7df3) [0x7fb3cad72df3] Wed Jun 3 11:07:03.407 /lib64/libc.so.6(clone+0x6d) [0x7fb3c9e661ad] Wed Jun 3 11:07:03.407 BUILD_ID = 0 Wed Jun 3 11:07:03.409 time of environment creation: Sat Aug 16 23:00:21 2014 Wed Jun 3 11:07:03.409 time of engine startup: Wed Jun 3 10:21:52 2015 Wed Jun 3 11:07:03.409 time now: Wed Jun 3 11:07:03 2015 Wed Jun 3 11:07:03.409 db opens: 304 Wed Jun 3 11:07:03.409 db closes: 163 Wed Jun 3 11:07:03.409 num open dbs now: 141 Wed Jun 3 11:07:03.409 max open dbs: 141 Wed Jun 3 11:07:03.409 period, in ms, that recovery log is automatically fsynced: 100 Wed Jun 3 11:07:03.409 dictionary inserts: 26 Wed Jun 3 11:07:03.410 dictionary inserts fail: 0 Wed Jun 3 11:07:03.410 dictionary deletes: 0 Wed Jun 3 11:07:03.410 dictionary deletes fail: 0 Wed Jun 3 11:07:03.410 dictionary updates: 9 Wed Jun 3 11:07:03.410 dictionary updates fail: 0 Wed Jun 3 11:07:03.410 dictionary broadcast updates: 0 Wed Jun 3 11:07:03.410 dictionary broadcast updates fail: 0 Wed Jun 3 11:07:03.410 dictionary multi inserts: 23 Wed Jun 3 11:07:03.410 dictionary multi inserts fail: 0 Wed Jun 3 11:07:03.410 dictionary multi deletes: 0 Wed Jun 3 11:07:03.410 dictionary multi deletes fail: 0 Wed Jun 3 11:07:03.410 dictionary updates multi: 3 Wed Jun 3 11:07:03.410 dictionary updates multi fail: 0 Wed Jun 3 11:07:03.410 le: max committed xr: 1 Wed Jun 3 11:07:03.410 le: max provisional xr: 2 Wed Jun 3 11:07:03.410 le: expanded: 0 Wed Jun 3 11:07:03.410 le: max memsize: 12556 Wed Jun 3 11:07:03.410 le: size of leafentries before garbage collection (during message application): 187281 Wed Jun 3 11:07:03.410 le: size of leafentries after garbage collection (during message application): 90409 Wed Jun 3 11:07:03.410 le: size of leafentries before garbage collection (outside message application): 0 Wed Jun 3 11:07:03.410 le: size of leafentries after garbage collection (outside message application): 0 Wed Jun 3 11:07:03.410 checkpoint: period: 60 Wed Jun 3 11:07:03.410 checkpoint: footprint: 0 Wed Jun 3 11:07:03.410 checkpoint: last checkpoint began : Wed Jun 3 11:06:52 2015 Wed Jun 3 11:07:03.410 checkpoint: last complete checkpoint began : Wed Jun 3 11:06:52 2015 Wed Jun 3 11:07:03.410 checkpoint: last complete checkpoint ended: Wed Jun 3 11:06:53 2015 Wed Jun 3 11:07:03.410 checkpoint: time spent during checkpoint (begin and end phases): 29 Wed Jun 3 11:07:03.410 checkpoint: time spent during last checkpoint (begin and end phases): 1 Wed Jun 3 11:07:03.410 checkpoint: last complete checkpoint LSN: 820627372 Wed Jun 3 11:07:03.410 checkpoint: checkpoints taken : 46 Wed Jun 3 11:07:03.410 checkpoint: checkpoints failed: 0 Wed Jun 3 11:07:03.410 checkpoint: waiters now: 0 Wed Jun 3 11:07:03.410 checkpoint: waiters max: 0 Wed Jun 3 11:07:03.410 checkpoint: non-checkpoint client wait on mo lock: 0 Wed Jun 3 11:07:03.410 checkpoint: non-checkpoint client wait on cs lock: 0 Wed Jun 3 11:07:03.410 checkpoint: checkpoint begin time: 70300 Wed Jun 3 11:07:03.410 checkpoint: long checkpoint begin time: 0 Wed Jun 3 11:07:03.410 checkpoint: long checkpoint begin count: 0 Wed Jun 3 11:07:03.410 cachetable: miss: 9758 Wed Jun 3 11:07:03.410 cachetable: miss time: 33133243 Wed Jun 3 11:07:03.410 cachetable: prefetches: 50115 Wed Jun 3 11:07:03.410 cachetable: size current: 5486165566 Wed Jun 3 11:07:03.410 cachetable: size limit: 5905580032 Wed Jun 3 11:07:03.410 cachetable: size writing: 0 Wed Jun 3 11:07:03.410 cachetable: size nonleaf: 91252734 Wed Jun 3 11:07:03.410 cachetable: size leaf: 5290051696 Wed Jun 3 11:07:03.410 cachetable: size rollback: 3536 Wed Jun 3 11:07:03.410 cachetable: size cachepressure: 66852458 Wed Jun 3 11:07:03.410 cachetable: size currently cloned data for checkpoint: 0 Wed Jun 3 11:07:03.410 cachetable: evictions: 81 Wed Jun 3 11:07:03.410 cachetable: cleaner executions: 1399 Wed Jun 3 11:07:03.410 cachetable: cleaner period: 2 Wed Jun 3 11:07:03.410 cachetable: cleaner iterations: 5 Wed Jun 3 11:07:03.410 cachetable: number of waits on cache pressure: 0 Wed Jun 3 11:07:03.410 cachetable: time waiting on cache pressure: 0 Wed Jun 3 11:07:03.410 cachetable: number of long waits on cache pressure: 0 Wed Jun 3 11:07:03.410 cachetable: long time waiting on cache pressure: 0 Wed Jun 3 11:07:03.410 locktree: memory size: 516 Wed Jun 3 11:07:03.410 locktree: memory size limit: 536870912 Wed Jun 3 11:07:03.410 locktree: number of times lock escalation ran: 0 Wed Jun 3 11:07:03.410 locktree: time spent running escalation (seconds): 0.000000 Wed Jun 3 11:07:03.410 locktree: latest post-escalation memory size: 0 Wed Jun 3 11:07:03.410 locktree: number of locktrees open now: 143 Wed Jun 3 11:07:03.410 locktree: number of pending lock requests: 0 Wed Jun 3 11:07:03.411 locktree: number of locktrees eligible for the STO: 2 Wed Jun 3 11:07:03.411 locktree: number of times a locktree ended the STO early: 1 Wed Jun 3 11:07:03.411 locktree: time spent ending the STO early (seconds): 0.000017 Wed Jun 3 11:07:03.411 locktree: number of wait locks: 0 Wed Jun 3 11:07:03.411 locktree: time waiting for locks: 0 Wed Jun 3 11:07:03.411 locktree: number of long wait locks: 0 Wed Jun 3 11:07:03.411 locktree: long time waiting for locks: 0 Wed Jun 3 11:07:03.411 locktree: number of lock timeouts: 0 Wed Jun 3 11:07:03.411 locktree: number of waits on lock escalation: 0 Wed Jun 3 11:07:03.411 locktree: time waiting on lock escalation: 0 Wed Jun 3 11:07:03.411 locktree: number of long waits on lock escalation: 0 Wed Jun 3 11:07:03.411 locktree: long time waiting on lock escalation: 0 Wed Jun 3 11:07:03.411 ft: dictionary updates: 350518 Wed Jun 3 11:07:03.411 ft: dictionary broadcast updates: 0 Wed Jun 3 11:07:03.411 ft: descriptor set: 133 Wed Jun 3 11:07:03.411 ft: messages ignored by leaf due to msn: 30672 Wed Jun 3 11:07:03.411 ft: total search retries due to TRY_AGAIN: 12393 Wed Jun 3 11:07:03.411 ft: searches requiring more tries than the height of the tree: 6 Wed Jun 3 11:07:03.411 ft: searches requiring more tries than the height of the tree plus three: 5 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (not for checkpoint): 8 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (not for checkpoint) (bytes): 178688 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (not for checkpoint) (uncompressed bytes): 1491732 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (not for checkpoint) (seconds): 0.000165 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (not for checkpoint): 0 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (not for checkpoint) (bytes): 0 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (not for checkpoint) (uncompressed bytes): 0 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (not for checkpoint) (seconds): 0.000000 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (for checkpoint): 57 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (for checkpoint) (bytes): 13592576 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (for checkpoint) (uncompressed bytes): 71382557 Wed Jun 3 11:07:03.411 ft: leaf nodes flushed to disk (for checkpoint) (seconds): 0.007093 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (for checkpoint): 46 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (for checkpoint) (bytes): 184832 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (for checkpoint) (uncompressed bytes): 1369733 Wed Jun 3 11:07:03.411 ft: nonleaf nodes flushed to disk (for checkpoint) (seconds): 0.011195 Wed Jun 3 11:07:03.411 ft: uncompressed / compressed bytes written (leaf): UNKNOWN STATUS TYPE: 6 Wed Jun 3 11:07:03.411 ft: uncompressed / compressed bytes written (nonleaf): UNKNOWN STATUS TYPE: 6 Wed Jun 3 11:07:03.411 ft: uncompressed / compressed bytes written (overall): UNKNOWN STATUS TYPE: 6 Wed Jun 3 11:07:03.411 ft: nonleaf node partial evictions: 82 Wed Jun 3 11:07:03.411 ft: nonleaf node partial evictions (bytes): 1755376 Wed Jun 3 11:07:03.411 ft: leaf node partial evictions: 2613937 Wed Jun 3 11:07:03.411 ft: leaf node partial evictions (bytes): 174577076805 Wed Jun 3 11:07:03.411 ft: leaf node full evictions: 11 Wed Jun 3 11:07:03.411 ft: leaf node full evictions (bytes): 4390470 Wed Jun 3 11:07:03.411 ft: nonleaf node full evictions: 70 Wed Jun 3 11:07:03.411 ft: nonleaf node full evictions (bytes): 106320195 Wed Jun 3 11:07:03.411 ft: leaf nodes created: 18 Wed Jun 3 11:07:03.411 ft: nonleaf nodes created: 0 Wed Jun 3 11:07:03.411 ft: leaf nodes destroyed: 0 Wed Jun 3 11:07:03.411 ft: nonleaf nodes destroyed: 0 Wed Jun 3 11:07:03.411 ft: bytes of messages injected at root (all trees): 0 Wed Jun 3 11:07:03.411 ft: bytes of messages flushed from h1 nodes to leaves: 104424 Wed Jun 3 11:07:03.411 ft: bytes of messages currently in trees (estimate): 18446744073709447192 Wed Jun 3 11:07:03.411 ft: messages injected at root: 0 Wed Jun 3 11:07:03.411 ft: broadcast messages injected at root: 0 Wed Jun 3 11:07:03.411 ft: basements decompressed as a target of a query: 0 Wed Jun 3 11:07:03.411 ft: basements decompressed for prelocked range: 0 Wed Jun 3 11:07:03.411 ft: basements decompressed for prefetch: 0 Wed Jun 3 11:07:03.411 ft: basements decompressed for write: 0 Wed Jun 3 11:07:03.411 ft: buffers decompressed as a target of a query: 5 Wed Jun 3 11:07:03.411 ft: buffers decompressed for prelocked range: 25 Wed Jun 3 11:07:03.411 ft: buffers decompressed for prefetch: 0 Wed Jun 3 11:07:03.411 ft: buffers decompressed for write: 45 Wed Jun 3 11:07:03.412 ft: pivots fetched for query: 4565 Wed Jun 3 11:07:03.412 ft: pivots fetched for query (bytes): 149541888 Wed Jun 3 11:07:03.412 ft: pivots fetched for query (seconds): 1.895513 Wed Jun 3 11:07:03.412 ft: pivots fetched for prefetch: 50115 Wed Jun 3 11:07:03.412 ft: pivots fetched for prefetch (bytes): 1642138112 Wed Jun 3 11:07:03.412 ft: pivots fetched for prefetch (seconds): 18.704313 Wed Jun 3 11:07:03.412 ft: pivots fetched for write: 1 Wed Jun 3 11:07:03.412 ft: pivots fetched for write (bytes): 512 Wed Jun 3 11:07:03.412 ft: pivots fetched for write (seconds): 0.000001 Wed Jun 3 11:07:03.412 ft: basements fetched as a target of a query: 4812 Wed Jun 3 11:07:03.412 ft: basements fetched as a target of a query (bytes): 24135168 Wed Jun 3 11:07:03.412 ft: basements fetched as a target of a query (seconds): 0.015144 Wed Jun 3 11:07:03.412 ft: basements fetched for prelocked range: 233282 Wed Jun 3 11:07:03.412 ft: basements fetched for prelocked range (bytes): 1120098816 Wed Jun 3 11:07:03.412 ft: basements fetched for prelocked range (seconds): 4.180713 Wed Jun 3 11:07:03.412 ft: basements fetched for prefetch: 2481886 Wed Jun 3 11:07:03.412 ft: basements fetched for prefetch (bytes): 11944488960 Wed Jun 3 11:07:03.412 ft: basements fetched for prefetch (seconds): 40.789658 Wed Jun 3 11:07:03.412 ft: basements fetched for write: 798 Wed Jun 3 11:07:03.412 ft: basements fetched for write (bytes): 10586112 Wed Jun 3 11:07:03.412 ft: basements fetched for write (seconds): 0.003046 Wed Jun 3 11:07:03.412 ft: buffers fetched as a target of a query: 0 Wed Jun 3 11:07:03.412 ft: buffers fetched as a target of a query (bytes): 0 Wed Jun 3 11:07:03.412 ft: buffers fetched as a target of a query (seconds): 0.000000 Wed Jun 3 11:07:03.412 ft: buffers fetched for prelocked range: 0 Wed Jun 3 11:07:03.412 ft: buffers fetched for prelocked range (bytes): 0 Wed Jun 3 11:07:03.412 ft: buffers fetched for prelocked range (seconds): 0.000000 Wed Jun 3 11:07:03.412 ft: buffers fetched for prefetch: 0 Wed Jun 3 11:07:03.412 ft: buffers fetched for prefetch (bytes): 0 Wed Jun 3 11:07:03.412 ft: buffers fetched for prefetch (seconds): 0.000000 Wed Jun 3 11:07:03.412 ft: buffers fetched for write: 21 Wed Jun 3 11:07:03.412 ft: buffers fetched for write (bytes): 43520 Wed Jun 3 11:07:03.412 ft: buffers fetched for write (seconds): 0.000026 Wed Jun 3 11:07:03.412 ft: leaf compression to memory (seconds): 1.512713 Wed Jun 3 11:07:03.412 ft: leaf serialization to memory (seconds): 0.059871 Wed Jun 3 11:07:03.412 ft: leaf decompression to memory (seconds): 307.139583 Wed Jun 3 11:07:03.412 ft: leaf deserialization to memory (seconds): 60.891743 Wed Jun 3 11:07:03.412 ft: nonleaf compression to memory (seconds): 0.073413 Wed Jun 3 11:07:03.412 ft: nonleaf serialization to memory (seconds): 0.001956 Wed Jun 3 11:07:03.412 ft: nonleaf decompression to memory (seconds): 0.449442 Wed Jun 3 11:07:03.412 ft: nonleaf deserialization to memory (seconds): 0.257406 Wed Jun 3 11:07:03.412 ft: promotion: roots split: 0 Wed Jun 3 11:07:03.412 ft: promotion: leaf roots injected into: 56 Wed Jun 3 11:07:03.412 ft: promotion: h1 roots injected into: 0 Wed Jun 3 11:07:03.412 ft: promotion: injections at depth 0: 0 Wed Jun 3 11:07:03.412 ft: promotion: injections at depth 1: 9 Wed Jun 3 11:07:03.412 ft: promotion: injections at depth 2: 2 Wed Jun 3 11:07:03.412 ft: promotion: injections at depth 3: 0 Wed Jun 3 11:07:03.412 ft: promotion: injections lower than depth 3: 0 Wed Jun 3 11:07:03.412 ft: promotion: stopped because of a nonempty buffer: 0 Wed Jun 3 11:07:03.412 ft: promotion: stopped at height 1: 0 Wed Jun 3 11:07:03.412 ft: promotion: stopped because the child was locked or not at all in memory: 0 Wed Jun 3 11:07:03.412 ft: promotion: stopped because the child was not fully in memory: 0 Wed Jun 3 11:07:03.412 ft: promotion: stopped anyway, after locking the child: 0 Wed Jun 3 11:07:03.412 ft: basement nodes deserialized with fixed-keysize: 2720623 Wed Jun 3 11:07:03.412 ft: basement nodes deserialized with variable-keysize: 298 Wed Jun 3 11:07:03.412 ft: promotion: succeeded in using the rightmost leaf shortcut: 0 Wed Jun 3 11:07:03.412 ft: promotion: tried the rightmost leaf shorcut but failed (out-of-bounds): 0 Wed Jun 3 11:07:03.412 ft: promotion: tried the rightmost leaf shorcut but failed (child reactive): 0 Wed Jun 3 11:07:03.412 ft flusher: total nodes potentially flushed by cleaner thread: 44 Wed Jun 3 11:07:03.413 ft flusher: height-one nodes flushed by cleaner thread: 39 Wed Jun 3 11:07:03.413 ft flusher: height-greater-than-one nodes flushed by cleaner thread: 5 Wed Jun 3 11:07:03.413 ft flusher: nodes cleaned which had empty buffers: 0 Wed Jun 3 11:07:03.413 ft flusher: nodes dirtied by cleaner thread: 85 Wed Jun 3 11:07:03.413 ft flusher: max bytes in a buffer flushed by cleaner thread: 205102 Wed Jun 3 11:07:03.413 ft flusher: min bytes in a buffer flushed by cleaner thread: 198 Wed Jun 3 11:07:03.413 ft flusher: total bytes in buffers flushed by cleaner thread: 394922 Wed Jun 3 11:07:03.413 ft flusher: max workdone in a buffer flushed by cleaner thread: 85918 Wed Jun 3 11:07:03.413 ft flusher: min workdone in a buffer flushed by cleaner thread: 0 Wed Jun 3 11:07:03.413 ft flusher: total workdone in buffers flushed by cleaner thread: 373823 Wed Jun 3 11:07:03.413 ft flusher: times cleaner thread tries to merge a leaf: 0 Wed Jun 3 11:07:03.413 ft flusher: cleaner thread leaf merges in progress: 0 Wed Jun 3 11:07:03.413 ft flusher: cleaner thread leaf merges successful: 0 Wed Jun 3 11:07:03.413 ft flusher: nodes dirtied by cleaner thread leaf merges: 0 Wed Jun 3 11:07:03.413 ft flusher: total number of flushes done by flusher threads or cleaner threads: 44 Wed Jun 3 11:07:03.413 ft flusher: number of in memory flushes: 44 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that read something off disk: 0 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that triggered another flush in child: 0 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that triggered 1 cascading flush: 0 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that triggered 2 cascading flushes: 0 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that triggered 3 cascading flushes: 0 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that triggered 4 cascading flushes: 0 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that triggered 5 cascading flushes: 0 Wed Jun 3 11:07:03.413 ft flusher: number of flushes that triggered over 5 cascading flushes: 0 Wed Jun 3 11:07:03.413 ft flusher: leaf node splits: 0 Wed Jun 3 11:07:03.413 ft flusher: nonleaf node splits: 0 Wed Jun 3 11:07:03.413 ft flusher: leaf node merges: 0 Wed Jun 3 11:07:03.413 ft flusher: nonleaf node merges: 0 Wed Jun 3 11:07:03.413 ft flusher: leaf node balances: 0 Wed Jun 3 11:07:03.413 hot: operations ever started: 0 Wed Jun 3 11:07:03.413 hot: operations successfully completed: 0 Wed Jun 3 11:07:03.413 hot: operations aborted: 0 Wed Jun 3 11:07:03.413 hot: max number of flushes from root ever required to optimize a tree: 0 Wed Jun 3 11:07:03.413 txn: begin: 1752 Wed Jun 3 11:07:03.413 txn: begin read only: 3592 Wed Jun 3 11:07:03.413 txn: successful commits: 3971 Wed Jun 3 11:07:03.413 txn: aborts: 1372 Wed Jun 3 11:07:03.413 logger: next LSN: 820627518 Wed Jun 3 11:07:03.413 logger: writes: 230 Wed Jun 3 11:07:03.413 logger: writes (bytes): 588159 Wed Jun 3 11:07:03.413 logger: writes (uncompressed bytes): 588159 Wed Jun 3 11:07:03.413 logger: writes (seconds): 0.004663 Wed Jun 3 11:07:03.413 logger: number of long logger write operations: 0 Wed Jun 3 11:07:03.413 indexer: number of indexers successfully created: 0 Wed Jun 3 11:07:03.413 indexer: number of calls to toku_indexer_create_indexer() that failed: 0 Wed Jun 3 11:07:03.413 indexer: number of calls to indexer->build() succeeded: 0 Wed Jun 3 11:07:03.413 indexer: number of calls to indexer->build() failed: 0 Wed Jun 3 11:07:03.413 indexer: number of calls to indexer->close() that succeeded: 0 Wed Jun 3 11:07:03.413 indexer: number of calls to indexer->close() that failed: 0 Wed Jun 3 11:07:03.413 indexer: number of calls to indexer->abort(): 0 Wed Jun 3 11:07:03.413 indexer: number of indexers currently in existence: 0 Wed Jun 3 11:07:03.413 indexer: max number of indexers that ever existed simultaneously: 0 Wed Jun 3 11:07:03.413 loader: number of loaders successfully created: 7 Wed Jun 3 11:07:03.413 loader: number of calls to toku_loader_create_loader() that failed: 0 Wed Jun 3 11:07:03.413 loader: number of calls to loader->put() succeeded: 111107037 Wed Jun 3 11:07:03.413 loader: number of calls to loader->put() failed: 0 Wed Jun 3 11:07:03.413 loader: number of calls to loader->close() that succeeded: 6 Wed Jun 3 11:07:03.413 loader: number of calls to loader->close() that failed: 0 Wed Jun 3 11:07:03.413 loader: number of calls to loader->abort(): 0 Wed Jun 3 11:07:03.413 loader: number of loaders currently in existence: 1 Wed Jun 3 11:07:03.413 loader: max number of loaders that ever existed simultaneously: 1 Wed Jun 3 11:07:03.413 memory: number of malloc operations: 0 Wed Jun 3 11:07:03.413 memory: number of free operations: 0 Wed Jun 3 11:07:03.413 memory: number of realloc operations: 0 Wed Jun 3 11:07:03.414 memory: number of malloc operations that failed: 0 Wed Jun 3 11:07:03.414 memory: number of realloc operations that failed: 0 Wed Jun 3 11:07:03.414 memory: number of bytes requested: 0 Wed Jun 3 11:07:03.414 memory: number of bytes used (requested + overhead): 0 Wed Jun 3 11:07:03.414 memory: number of bytes freed: 0 Wed Jun 3 11:07:03.414 memory: largest attempted allocation size: 0 Wed Jun 3 11:07:03.414 memory: size of the last failed allocation attempt: 0 Wed Jun 3 11:07:03.414 memory: estimated maximum memory footprint: 0 Wed Jun 3 11:07:03.414 memory: mallocator version: tokumx-2.0.1-0-gd4547074dcc9129f2e13ed6b76fd78edb0a2828e Wed Jun 3 11:07:03.414 memory: mmap threshold: 4194304 Wed Jun 3 11:07:03.414 filesystem: ENOSPC redzone state: 0 Wed Jun 3 11:07:03.414 filesystem: threads currently blocked by full disk: 0 Wed Jun 3 11:07:03.414 filesystem: number of operations rejected by enospc prevention (red zone): 0 Wed Jun 3 11:07:03.414 filesystem: most recent disk full: Wed Dec 31 16:00:00 1969 Wed Jun 3 11:07:03.414 filesystem: number of write operations that returned ENOSPC: 0 Wed Jun 3 11:07:03.414 filesystem: fsync time: 1362438 Wed Jun 3 11:07:03.414 filesystem: fsync count: 724 Wed Jun 3 11:07:03.414 filesystem: long fsync time: 0 Wed Jun 3 11:07:03.414 filesystem: long fsync count: 0 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a full fetch: 0 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a partial fetch: 0 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a full eviction: 0 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a partial eviction: 6 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a message injection: 0 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a message application: 0 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a flush: 0 Wed Jun 3 11:07:03.414 context: tree traversals blocked by a the cleaner thread: 1 Wed Jun 3 11:07:03.414 context: tree traversals blocked by something uninstrumented: 2416 Wed Jun 3 11:07:03.414 context: promotion blocked by a full fetch (should never happen): 0 Wed Jun 3 11:07:03.414 context: promotion blocked by a partial fetch (should never happen): 0 Wed Jun 3 11:07:03.414 context: promotion blocked by a full eviction (should never happen): 0 Wed Jun 3 11:07:03.414 context: promotion blocked by a partial eviction (should never happen): 0 Wed Jun 3 11:07:03.414 context: promotion blocked by a message injection: 0 Wed Jun 3 11:07:03.414 context: promotion blocked by a message application: 0 Wed Jun 3 11:07:03.414 context: promotion blocked by a flush: 0 Wed Jun 3 11:07:03.414 context: promotion blocked by the cleaner thread: 0 Wed Jun 3 11:07:03.414 context: promotion blocked by something uninstrumented: 0 Wed Jun 3 11:07:03.414 context: something uninstrumented blocked by something uninstrumented: 0 Wed Jun 3 11:07:03.414 Memory usage:

Wed Jun 3 11:07:03.421
Wed Jun 3 11:07:03.421 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.421 Crash reason: Wed Jun 3 11:07:03.421
Wed Jun 3 11:07:03.421 Got signal: 6 (Aborted). Wed Jun 3 11:07:03.421
Wed Jun 3 11:07:03.421 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.421 Process info: Wed Jun 3 11:07:03.421
Wed Jun 3 11:07:03.424 OS: Linux Amazon Linux AMI release 2015.03 Kernel 3.14.33-26.47.amzn1.x86_64 x86_64 Wed Jun 3 11:07:03.424 NCPU: 2 Wed Jun 3 11:07:03.431 VIRT: 7107 MB Wed Jun 3 11:07:03.431 RES: 7107 MB Wed Jun 3 11:07:03.431 PHYS: 15302 MB Wed Jun 3 11:07:03.431 RLIMIT_CORE: 0 (soft), unlimited (hard) Wed Jun 3 11:07:03.431 RLIMIT_CPU: unlimited (soft), unlimited (hard) Wed Jun 3 11:07:03.431 RLIMIT_DATA: unlimited (soft), unlimited (hard) Wed Jun 3 11:07:03.431 RLIMIT_FSIZE: unlimited (soft), unlimited (hard) Wed Jun 3 11:07:03.431 RLIMIT_NOFILE: 1024 (soft), 4096 (hard) Wed Jun 3 11:07:03.431 RLIMIT_STACK: 8388608 (soft), unlimited (hard) Wed Jun 3 11:07:03.431 RLIMIT_AS: unlimited (soft), unlimited (hard) Wed Jun 3 11:07:03.431 _SC_OPEN_MAX: 1024 Wed Jun 3 11:07:03.431 _SC_PAGESIZE: 4096 Wed Jun 3 11:07:03.431 _SC_PHYS_PAGES: 3917503 Wed Jun 3 11:07:03.431 _SC_AVPHYS_PAGES: 39159 Wed Jun 3 11:07:03.431 _SC_NPROCESSORS_CONF: 2 Wed Jun 3 11:07:03.431 _SC_NPROCESSORS_ONLN: 2 Wed Jun 3 11:07:03.431
Wed Jun 3 11:07:03.431 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.431 Parsed server options: Wed Jun 3 11:07:03.431
Wed Jun 3 11:07:03.434 cacheSize: 5368709120 Wed Jun 3 11:07:03.435 command: [ "run" ] Wed Jun 3 11:07:03.435 config: "/etc/tokumx.conf" Wed Jun 3 11:07:03.435 dbpath: "/var/lib/tokumx-fresh" Wed Jun 3 11:07:03.435 fork: "true" Wed Jun 3 11:07:03.435 logappend: "true" Wed Jun 3 11:07:03.435 logpath: "/var/log/tokumx/tokumx.log" Wed Jun 3 11:07:03.435 pidfilepath: "/var/run/tokumx/tokumx.pid" Wed Jun 3 11:07:03.435 pluginsDir: "/usr/lib64/tokumx/plugins" Wed Jun 3 11:07:03.435 quiet: true Wed Jun 3 11:07:03.435 verbose: "true" Wed Jun 3 11:07:03.435
Wed Jun 3 11:07:03.435 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.435 Filesystem information: Wed Jun 3 11:07:03.435
Wed Jun 3 11:07:03.437 Information for dbpath "/var/lib/tokumx-fresh": Wed Jun 3 11:07:03.437
Wed Jun 3 11:07:03.437 type magic: 0x0000EF53 Wed Jun 3 11:07:03.437 type: ext2/3/4 Wed Jun 3 11:07:03.437 bsize: 4096 Wed Jun 3 11:07:03.437 blocks: 64474460 Wed Jun 3 11:07:03.437 bfree: 32729415 Wed Jun 3 11:07:03.437 bavail: 32704353 Wed Jun 3 11:07:03.437
Wed Jun 3 11:07:03.437 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.437 Current operations in progress: Wed Jun 3 11:07:03.437
Wed Jun 3 11:07:03.446 { opid: 6517, active: false, op: "query", ns: "", query: { createdOn: { $lte: new Date(1433354115108) } }, client: "127.0.0.1:37381", desc: "conn50", threadId: "0x7fb249bfb700", connectionId: 50, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.446 { opid: 6516, active: false, op: "query", ns: "", query: { processState: "SUCCESS" }, client: "127.0.0.1:37383", desc: "conn51", threadId: "0x7fb249afa700", connectionId: 51, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.446 { opid: 5692, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:37194", desc: "conn43", threadId: "0x7fb253fff700", connectionId: 43, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 1260, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.446 { opid: 2795, active: false, op: "query", ns: "vroozi.shopper_lists", query: { userId: "2", unitId: "2", listType: { $nin: [ "LIST_SHOPPING_CART", "LIST_FAVORITES", "LIST_COMPARE" ] } }, client: "127.0.0.1:36818", desc: "conn34", threadId: "0x7fb38a2fe700", connectionId: 34, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 164152, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.446 { opid: 2782, active: false, op: "query", ns: "vroozi.announcements", query: { query: { unitId: 2, filterUsers: { $nin: [ "2" ] }, mailingList: { $in: [ "144" ] } }, orderby: { date: -1 } }, client: "127.0.0.1:36538", desc: "conn26", threadId: "0x7fb393dfc700", connectionId: 26, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 1152, w: 0 }, timeAcquiringMicros: { r: 4, w: 0 } } } Wed Jun 3 11:07:03.446 { opid: 7128, active: false, op: "query", ns: "content.process", query: { processState: "SUCCESS" }, client: "127.0.0.1:36398", desc: "conn12", threadId: "0x7fb3b1bfc700", connectionId: 12, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 280, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.446 { opid: 5585, active: false, op: "query", ns: "vroozi.profile_group", query: { unitId: "2", token: "null", active: true }, client: "127.0.0.1:37155", desc: "conn42", threadId: "0x7fb3849f9700", connectionId: 42, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 2051, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.446 { opid: 5481, active: false, op: "query", ns: "vroozi.user", query: { userId: "2", deleted: false }, client: "127.0.0.1:36429", desc: "conn15", threadId: "0x7fb3b0ffb700", connectionId: 15, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 10576, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.446 { opid: 1506, active: false, op: "getmore", ns: "vroozi.user", query: {}, client: "127.0.0.1:36462", desc: "conn22", threadId: "0x7fb395afd700", connectionId: 22, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 8323, w: 0 }, timeAcquiringMicros: { r: 2, w: 0 } } } Wed Jun 3 11:07:03.447 { opid: 2818, active: false, op: "query", ns: "vroozi.supplier", query: { _id: { $in: [ "98", "763", "773", "79", "127", "132", "114", "128", "133", "115", "751", "113", "139", "124", "129", "2", "0", "885", "131", "141" ] }, active: true, includeSupplierCard: true }, client: "127.0.0.1:36811", desc: "conn29", threadId: "0x7fb38d9fc700", connectionId: 29, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 905, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.447 { opid: 2386, active: false, op: "killcursors", ns: "", query: {}, client: "127.0.0.1:36459", desc: "conn20", threadId: "0x7fb3af1fc700", connectionId: 20, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.447 { opid: 5573, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:36560", desc: "conn27", threadId: "0x7fb38dbfe700", connectionId: 27, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 431, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.447 { opid: 2794, active: false, op: "query", ns: "vroozi.saved_searches", query: { userId: "2", unitId: "2" }, client: "127.0.0.1:36819", desc: "conn35", threadId: "0x7fb38a1fd700", connectionId: 35, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 1324, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.447 { opid: 6062, active: false, op: "query", ns: "", query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 }, client: "127.0.0.1:37316", desc: "conn46", threadId: "0x7fb249fff700", connectionId: 46, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.448 { opid: 161, active: false, op: "query", ns: "vroozi.company_settings", query: { userName: null, password: null }, client: "127.0.0.1:36390", desc: "conn7", threadId: "0x7fb3b52f2700", connectionId: 7, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 1338, w: 0 }, timeAcquiringMicros: { r: 2, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 7125, active: false, op: "getmore", ns: "vroozi.process", query: {}, client: "127.0.0.1:36395", desc: "conn9", threadId: "0x7fb3b3bfe700", connectionId: 9, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 1414, w: 0 }, timeAcquiringMicros: { r: 3, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 5744, active: false, op: "query", ns: "vroozi.seq_collection", query: { name: "seq_document_flow_2" }, client: "127.0.0.1:37075", desc: "conn39", threadId: "0x7fb384cfc700", connectionId: 39, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 109, w: 0 }, timeAcquiringMicros: { r: 3, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 5732, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:37245", desc: "conn44", threadId: "0x7fb253efe700", connectionId: 44, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 430, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 6968, active: false, op: "query", ns: "", query: { createdOn: { $lte: new Date(1433354415212) } }, client: "127.0.0.1:37453", desc: "conn52", threadId: "0x7fb2499f9700", connectionId: 52, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.448 { opid: 2783, active: false, op: "query", ns: "vroozi.profile", query: { unitId: "2", active: true, isSupplierAssociated: false }, client: "127.0.0.1:36813", desc: "conn31", threadId: "0x7fb38c6fe700", connectionId: 31, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 2296, w: 0 }, timeAcquiringMicros: { r: 4, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 5568, active: false, op: "query", ns: "vroozi.user", query: { userId: "2", deleted: false }, client: "127.0.0.1:36526", desc: "conn23", threadId: "0x7fb3959fc700", connectionId: 23, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 15654, w: 0 }, timeAcquiringMicros: { r: 8, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 6063, active: false, op: "query", ns: "", query: { createdOn: { $lte: new Date(1433353795904) } }, client: "127.0.0.1:37319", desc: "conn49", threadId: "0x7fb249cfc700", connectionId: 49, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.448 { opid: 1101, active: false, op: "query", ns: "vroozi.user", query: { findandmodify: "user", query: { username: "shaz.khan+tester@vroozi.com", unitId: "2", active: true, deleted: false }, update: { $set: { userStatus: "Active" } } }, client: "127.0.0.1:36427", desc: "conn14", threadId: "0x7fb3b19fa700", connectionId: 14, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 219, w: 0 }, timeAcquiringMicros: { r: 2, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 5425, active: false, op: "query", ns: "vroozi.user", query: { findandmodify: "user", query: { username: "shaz.khan+tester@vroozi.com", unitId: "2", active: true, deleted: false }, update: { $set: { userStatus: "Active" } } }, client: "127.0.0.1:37005", desc: "conn36", threadId: "0x7fb384fff700", connectionId: 36, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 225, w: 0 }, timeAcquiringMicros: { r: 3, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 1266, active: false, op: "query", ns: "vroozi.user_session_data", query: { _id: ObjectId('556f3979e4b0616b50c825a5') }, client: "127.0.0.1:36460", desc: "conn21", threadId: "0x7fb395bfe700", connectionId: 21, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 76, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 5572, active: false, op: "query", ns: "vroozi.shopping_items", query: { query: { listId: "216", checkedOut: { $ne: true } }, orderby: { bundleNumber: 1, supplierId: -1 } }, client: "127.0.0.1:36800", desc: "conn28", threadId: "0x7fb38dafd700", connectionId: 28, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 391, w: 0 }, timeAcquiringMicros: { r: 3, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 5646, active: false, op: "query", ns: "", query: { expireAfterSeconds: { $exists: true } }, client: "0.0.0.0:0", desc: "TTLMonitor", threadId: "0x7fb3b17fc700", rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.448 { opid: 5733, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:36458", desc: "conn19", threadId: "0x7fb3af2fd700", connectionId: 19, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 351, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 7127, active: false, op: "getmore", ns: "vroozi.messages", query: {}, client: "127.0.0.1:36384", desc: "conn6", threadId: "0x7fb3b53f3700", connectionId: 6, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 329709, w: 0 }, timeAcquiringMicros: { r: 3, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 266, active: false, op: "query", ns: "content.iso_currencies", query: { count: "iso_currencies", query: {} }, client: "127.0.0.1:36397", desc: "conn11", threadId: "0x7fb3b39fc700", connectionId: 11, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 216, w: 0 }, timeAcquiringMicros: { r: 2, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 1690, active: false, op: "query", ns: "vroozi.profile", query: { unitId: "2", active: true, isSupplierAssociated: false }, client: "127.0.0.1:36536", desc: "conn25", threadId: "0x7fb393efd700", connectionId: 25, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 4434, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.448 { opid: 2824, active: false, op: "query", ns: "", query: { getlasterror: 1, w: 1, wtimeout: 0, fsync: true }, client: "127.0.0.1:36817", desc: "conn33", threadId: "0x7fb38a3ff700", connectionId: 33, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 5577, active: false, op: "query", ns: "vroozi.shopper_lists", query: { userId: "2", unitId: "2", listType: { $nin: [ "LIST_SHOPPING_CART", "LIST_FAVORITES", "LIST_COMPARE" ] } }, client: "127.0.0.1:37133", desc: "conn41", threadId: "0x7fb384afa700", connectionId: 41, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 35786, w: 0 }, timeAcquiringMicros: { r: 4, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 0, active: false, op: "none", ns: "", query: {}, desc: "clientcursormon", threadId: "0x7fb3b2bfe700", rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 119, active: false, op: "query", ns: "vroozi.company_settings", query: { userName: null, password: null }, client: "127.0.0.1:36383", desc: "conn5", threadId: "0x7fb3c25d6700", connectionId: 5, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 1500, w: 0 }, timeAcquiringMicros: { r: 23, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 6061, active: false, op: "query", ns: "", query: { processState: "SUCCESS" }, client: "127.0.0.1:37318", desc: "conn48", threadId: "0x7fb249dfd700", connectionId: 48, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 6969, active: false, op: "query", ns: "", query: { processState: "SUCCESS" }, client: "127.0.0.1:37454", desc: "conn53", threadId: "0x7fb20f7ff700", connectionId: 53, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 7134, active: false, op: "getmore", ns: "vroozi.process", query: {}, client: "127.0.0.1:36396", desc: "conn10", threadId: "0x7fb3b3afd700", connectionId: 10, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 1389, w: 0 }, timeAcquiringMicros: { r: 2, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 5569, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:37108", desc: "conn40", threadId: "0x7fb384bfb700", connectionId: 40, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 481, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 2790, active: false, op: "query", ns: "", query: { getlasterror: 1, w: 1, wtimeout: 0 }, client: "127.0.0.1:36814", desc: "conn32", threadId: "0x7fb38c5fd700", connectionId: 32, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 5485, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:36448", desc: "conn18", threadId: "0x7fb3af3fe700", connectionId: 18, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 365, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 1458, active: false, op: "query", ns: "", query: { getlasterror: 1, w: 1, wtimeout: 0 }, client: "127.0.0.1:36530", desc: "conn24", threadId: "0x7fb393ffe700", connectionId: 24, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 0, active: false, op: "none", ns: "", query: {}, desc: "snapshotthread", threadId: "0x7fb3b33ff700", rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 6060, active: false, op: "query", ns: "", query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 }, client: "127.0.0.1:36380", desc: "conn4", threadId: "0x7fb3c26d7700", connectionId: 4, rootTxnid: 1030250306, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 1114, active: false, op: "query", ns: "vroozi.user_session_data", query: { _id: ObjectId('556f3979e4b0616b50c825a5') }, client: "127.0.0.1:36432", desc: "conn17", threadId: "0x7fb3b0df9700", connectionId: 17, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 97, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 7131, active: false, op: "query", ns: "", query: { buildinfo: 1 }, client: "127.0.0.1:36379", desc: "conn3", threadId: "0x7fb3c9d6f700", connectionId: 3, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 5734, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:37049", desc: "conn38", threadId: "0x7fb384dfd700", connectionId: 38, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 356, w: 0 }, timeAcquiringMicros: { r: 6, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 5582, active: true, secs_running: 1008, op: "insert", ns: "catalog.system.indexes", insert: {}, client: "127.0.0.1:36394", desc: "conn8", threadId: "0x7fb3b51f1700", connectionId: 8, rootTxnid: 1030250420, locks: { ^: "w", ^catalog: "W" }, context: "insert (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/instance.cpp:997)", waitingForLock: false, msg: "Foreground index build progress (collect phase) for catalog.catalog_item, key { newItemExtQuoteId: 1 }: 110882000/112038199 98% (estimated documents) ", lockStats: { timeLockedMicros: { r: 101, w: 0 }, timeAcquiringMicros: { r: 9, w: 3 } } } Wed Jun 3 11:07:03.449 { opid: 2817, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:36812", desc: "conn30", threadId: "0x7fb38c7ff700", connectionId: 30, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 418, w: 0 }, timeAcquiringMicros: { r: 8, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 1256, active: false, op: "query", ns: "vroozi.user", query: { findandmodify: "user", query: { username: "shaz.khan+tester@vroozi.com", unitId: "2", active: true, deleted: false }, update: { $set: { userStatus: "Active" } } }, client: "127.0.0.1:36430", desc: "conn16", threadId: "0x7fb3b0efa700", connectionId: 16, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 231, w: 0 }, timeAcquiringMicros: { r: 2, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 7132, active: false, op: "query", ns: "", query: { buildinfo: 1 }, client: "127.0.0.1:36376", desc: "conn2", threadId: "0x7fb3cbaa8700", connectionId: 2, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 5735, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:37007", desc: "conn37", threadId: "0x7fb384efe700", connectionId: 37, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 355, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 6064, active: false, op: "query", ns: "", query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 }, client: "127.0.0.1:37317", desc: "conn47", threadId: "0x7fb249efe700", connectionId: 47, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 5486, active: false, op: "query", ns: "vroozi.company_settings", query: { unitId: "2" }, client: "127.0.0.1:36419", desc: "conn13", threadId: "0x7fb3b1afb700", connectionId: 13, rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 386, w: 0 }, timeAcquiringMicros: { r: 7, w: 0 } } } Wed Jun 3 11:07:03.449 { opid: 6065, active: false, op: "query", ns: "", query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 }, client: "127.0.0.1:37315", desc: "conn45", threadId: "0x7fb253dfd700", connectionId: 45, rootTxnid: 0, locks: { ^catalog: "R" }, context: "query (/data/package-rpm-el6/build/BUILD/tokumx-2.0.1/src/mongo/db/ops/query.cpp:1003)", waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449 { opid: 0, active: false, op: "insert", ns: "local.startup_log", insert: {}, client: "0.0.0.0:0", desc: "initandlisten", threadId: "0x7fb3cbab1840", rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: { r: 85, w: 5368 }, timeAcquiringMicros: { r: 4, w: 1 } } } Wed Jun 3 11:07:03.449 { opid: 0, active: false, op: "none", ns: "", query: {}, desc: "websvr", threadId: "0x7fb3afbff700", rootTxnid: 0, waitingForLock: false, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } Wed Jun 3 11:07:03.449
Wed Jun 3 11:07:03.449 -------------------------------------------------------------------------------- Wed Jun 3 11:07:03.449 OpDebug info: Wed Jun 3 11:07:03.450
Wed Jun 3 11:07:03.450 query catalog.item_tracker query: { createdOn: { $lte: new Date(1433354115108) } } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 query catalog.process query: { processState: "SUCCESS" } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:1260 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:164152 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:1152 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:280 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:2051 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:10576 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:8323 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:905 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:431 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:1324 0ms Wed Jun 3 11:07:03.450 query catalog.catalog_item query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:1338 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:1414 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:109 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:430 0ms Wed Jun 3 11:07:03.450 query catalog.item_tracker query: { createdOn: { $lte: new Date(1433354415212) } } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:2296 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:15654 0ms Wed Jun 3 11:07:03.450 query catalog.item_tracker query: { createdOn: { $lte: new Date(1433353795904) } } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:219 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:225 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:76 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:391 0ms Wed Jun 3 11:07:03.450 query catalog.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:351 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:329709 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:216 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:4434 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:35786 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:1500 0ms Wed Jun 3 11:07:03.450 query catalog.process query: { processState: "SUCCESS" } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 query catalog.process query: { processState: "SUCCESS" } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:1389 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:481 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:365 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 query catalog.catalog_item query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:97 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:356 0ms Wed Jun 3 11:07:03.450 insert catalog.system.indexes keyUpdates:0 locks(micros) r:101 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:418 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:231 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 0ms Wed Jun 3 11:07:03.450 none keyUpdates:0 locks(micros) r:355 0ms Wed Jun 3 11:07:03.451 query catalog.catalog_item query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.451 none keyUpdates:0 locks(micros) r:386 0ms Wed Jun 3 11:07:03.451 query catalog.catalog_item query: { _id: { $in: [ ObjectId('5562ff58e4b067544fb8ada2') ] }, deleted: 0 } ntoreturn:0 keyUpdates:0 0ms Wed Jun 3 11:07:03.451 none keyUpdates:0 locks(micros) r:85 w:5368 0ms Wed Jun 3 11:07:03.451 none keyUpdates:0 0ms Wed Jun 3 11:07:03.451
Wed Jun 3 11:26:36.789 nssize is a deprecated parameter forked process: 7514 all output going to: /var/log/tokumx/tokumx.log

adeelahmadch commented 9 years ago

Found the same issue here: https://github.com/Tokutek/mongo/issues/1219

adeelahmadch commented 9 years ago

i tested it further and its a bug in tokumx. now i use Server with 120GB RAM and 500GB HDD. i didn't specify cache size which means that line is comment in tokumx.conf. i tried to build the index and it crashed.

what i found is:

  1. if i try to build index in foreground on large collection, no matter what OS, what size of RAM and ulimits are set , tokumx crashes. db.catalog_item.createIndex( { newItemExtQuoteId : 1 } , { sparse: true })
  2. if we build index in background on large collection(95190736 items) it worked fine and consume less resources. in my case i was able to that on a server with 15GB RAM and 5GB cache size assigned to tokumx. db.catalog_item.createIndex( { newItemExtQuoteId : 1 } , { sparse: true, background: true })

i am expecting more from tokumx, crashing is not an option, it should throw some kind of error instead of crashing.

esmet commented 9 years ago

What does the servers log say?

Sent from my iPhone

On Jun 4, 2015, at 4:41 PM, Adeel Ahmad notifications@github.com wrote:

i tested it further and its a bug in tokumx. now i use Server with 120GB RAM and 500GB HDD. i didn't specify cache size which means that line is comment in tokumx.conf. i tried to build the index and it crashed.

what i found is:

if i try to build index in foreground on large collection, no matter what OS, what size of RAM and ulimits are set , tokumx crashes. db.catalog_item.createIndex( { newItemExtQuoteId : 1 } , { sparse: true })

if we build index in background on large collection(95190736 items) it worked fine and consume less resources. in my case i was able to that on a server with 15GB RAM and 5GB cache size assigned to tokumx. db.catalog_item.createIndex( { newItemExtQuoteId : 1 } , { sparse: true, background: true })

i am expecting more from tokumx, crashing is not an option, it should throw some kind of error instead of crashing.

— Reply to this email directly or view it on GitHub.

sdeusch commented 9 years ago

Server log throughout crash is above.

adeelahmadch commented 9 years ago

Server logs are attached above. TokuMx 2.0.1 is not stable with indexing.

now i tried to build the index in background which works previously when i did not perform any other operation. This time it crashed again when i am building the same index. it was on 19% and i performed another operation on some other DB and it crashed.

esmet commented 9 years ago

Looks like the source data may be bad, as the previous issue you linked showed "Checksum failure when reading data from disk"

Surviving a corrupted data read is not really that important, since you cannot continue if you can't trust the data on disk. This replica set member needs to be wiped and resyncd.

adeelahmadch commented 9 years ago

yes, that's was some other user issue, in my case data it not corrupted.

i was able to build my indexes one by one using background: true options. it appears to me that tokumx doesn't handle index in foreground. if you try to build multiple large index in foreground it crash.