While running ./mongostat, from one day to another, my document update-count decreased a lot (from 1000 docs/secs to only +-50)
Then I realized there's a waterfall of exceptions in mongo.log
This occured without doing any administration task, within months of server uptime
Our collection are pretty small (20k and 100k docs), sumarizing less than 1Gb of db files
- I had 1.6.5 version, and to trust db.coll.validate() process I migrated to 1.8.1, results are still "valid: true"
- I still didnt run any repairDatabase(), there's no sign of corruption...
After migrating, the error persists.
I'd appreciate any clue to this issue....
(Change it to Question if you feel this aint a bug)
------------ THESE ARE COMMON UPSERT OPERATIONS USING JAVA DRIVER (these upserts doesnt look to be updating anything)
DEBUG [scheduler-1] 30 May 2011 21:33:01 (BaseMongoPersister.java:302) - Upsert to dayByCountry Obj: { "$set" : { "day" :
{ "$date" : "2011-05-30T00:00:00Z"}, "client" : "myclient" , "country" : "ke"} , "$inc" : { "counters.120.h" : 2 , "counters.301.h" : 1 , "counters.281.h" : 2 , "counters.139.h" : 2 , "counters.119.h" : 2 , "counters.508.h" : 2 , "counters.303.h" : 2 , "counters.299.h" : 1 , "counters.147.h" : 2 , "counters.432.h" : 2 , "counters.81.h" : 2 , "counters.285.h" : 1 , "urlCounters.461.h" : 2 , "domainCounters.d1*openx*org.h" : 2 , "hitCount" : 2}} USING Query: { "day" :
{ "$date" : "2011-05-30T00:00:00Z"} , "country" : "ke" , "client" : "myclient"}
DEBUG [scheduler-1] 30 May 2011 21:33:01 (BaseMongoPersister.java:314) - Upsert to monthByCountry Obj: { "$set" : { "country" : "ke" , "client" : "myclient" , "month" : { "$date" : "2011-05-01T00:00:00Z"}} , "$inc" : { "counters.120.h" : 2 , "counters.301.h" : 1 , "counters.281.h" : 2 , "counters.139.h" : 2 , "counters.119.h" : 2 , "counters.508.h" : 2 , "counters.303.h" : 2 , "counters.299.h" : 1 , "counters.147.h" : 2 , "counters.432.h" : 2 , "counters.81.h" : 2 , "counters.285.h" : 1 , "urlCounters.461.h" : 2 , "domainCounters.d1*openx*org.h" : 2 , "hitCount" : 2}} USING Query: { "country" : "ke" , "client" : "myclient" , "month" : { "$date" : "2011-05-01T00:00:00Z"}}
INFO [scheduler-1] 30 May 2011 21:33:01 (BaseMongoPersister.java:207) - Logged OK - Country: ke Client: myclient Hits: 2
-------------- VERIFYING EXISTANCE OF DOCUMENTS
To verify documents that should be reached by upserts, which instead are failing (see errors below)
> db.dayByCountry.find({"country":"gb", "client":"myclient", "day": {"$gte": new Date(2011, 4, 30, 0), "$lte": new Date(2011, 4, 30, 0)}},
{"hitCount": 1, "day":1})
{ "_id" : ObjectId("4de2de3a79d39014de0ac86a"), "day" : ISODate("2011-05-30T00:00:00Z"), "hitCount" : 1384761 }So document exists...
-------------- EXTRACT OF MONGO-LOG
Mon May 30 21:25:36 [conn5] update pixserverHits.dayByCountry query:
{ day: new Date(1306713600000), country: "gb", client: "myclient" } exception 0 assertion db/update.cpp:686 24ms
Mon May 30 21:25:36 [conn6] pixserverHits.dayByCountry Assertion failure 0 db/update.cpp 686
0x54e8de 0x55f971 0x67a9f8 0x67abaf 0x6656a6 0x667f28 0x66aed0 0x75632f 0x758cc1 0x8a3b3e 0x8b6a40 0x7f38704c39ca 0x7f386fa7270d
/home/mongo/mongodb/bin/mongod(_ZN5mongo12sayDbContextEPKc+0xae) [0x54e8de]
/home/mongo/mongodb/bin/mongod(_ZN5mongo8assertedEPKcS1_j+0x111) [0x55f971]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsINS_14BSONObjBuilderEEEvRKSsRT_RKNS_7BSONObjE+0xb18) [0x67a9f8]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsINS_14BSONObjBuilderEEEvRKSsRT_RKNS_7BSONObjE+0xccf) [0x67abaf]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsEv+0x66) [0x6656a6]
/home/mongo/mongodb/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0xc48) [0x667f28]
/home/mongo/mongodb/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x130) [0x66aed0]
/home/mongo/mongodb/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x47f) [0x75632f]
/home/mongo/mongodb/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1941) [0x758cc1]
/home/mongo/mongodb/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a3b3e]
/home/mongo/mongodb/bin/mongod(thread_proxy+0x80) [0x8b6a40]
/lib/libpthread.so.0(+0x69ca) [0x7f38704c39ca]
/lib/libc.so.6(clone+0x6d) [0x7f386fa7270d]
Mon May 30 21:25:36 [conn6] update pixserverHits.dayByCountry query:
exception 0 assertion db/update.cpp:686 25ms
Mon May 30 21:25:36 [conn4] pixserverHits.monthByCountry Assertion failure 0 db/update.cpp 686
0x54e8de 0x55f971 0x67a9f8 0x67abaf 0x6656a6 0x667f28 0x66aed0 0x75632f 0x758cc1 0x8a3b3e 0x8b6a40 0x7f38704c39ca 0x7f386fa7270d
/home/mongo/mongodb/bin/mongod(_ZN5mongo12sayDbContextEPKc+0xae) [0x54e8de]
/home/mongo/mongodb/bin/mongod(_ZN5mongo8assertedEPKcS1_j+0x111) [0x55f971]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsINS_14BSONObjBuilderEEEvRKSsRT_RKNS_7BSONObjE+0xb18) [0x67a9f8]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsINS_14BSONObjBuilderEEEvRKSsRT_RKNS_7BSONObjE+0xccf) [0x67abaf]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsEv+0x66) [0x6656a6]
/home/mongo/mongodb/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0xc48) [0x667f28]
/home/mongo/mongodb/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x130) [0x66aed0]
/home/mongo/mongodb/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x47f) [0x75632f]
/home/mongo/mongodb/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1941) [0x758cc1]
/home/mongo/mongodb/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a3b3e]
/home/mongo/mongodb/bin/mongod(thread_proxy+0x80) [0x8b6a40]
/lib/libpthread.so.0(+0x69ca) [0x7f38704c39ca]
/lib/libc.so.6(clone+0x6d) [0x7f386fa7270d]
Mon May 30 21:25:36 [conn4] update pixserverHits.monthByCountry query:
exception 0 assertion db/update.cpp:686 49ms
Mon May 30 21:25:36 [conn5] pixserverHits.monthByCountry Assertion failure 0 db/update.cpp 686
0x54e8de 0x55f971 0x67a9f8 0x67abaf 0x6656a6 0x667f28 0x66aed0 0x75632f 0x758cc1 0x8a3b3e 0x8b6a40 0x7f38704c39ca 0x7f386fa7270d
/home/mongo/mongodb/bin/mongod(_ZN5mongo12sayDbContextEPKc+0xae) [0x54e8de]
/home/mongo/mongodb/bin/mongod(_ZN5mongo8assertedEPKcS1_j+0x111) [0x55f971]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsINS_14BSONObjBuilderEEEvRKSsRT_RKNS_7BSONObjE+0xb18) [0x67a9f8]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsINS_14BSONObjBuilderEEEvRKSsRT_RKNS_7BSONObjE+0xccf) [0x67abaf]
/home/mongo/mongodb/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsEv+0x66) [0x6656a6]
/home/mongo/mongodb/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0xc48) [0x667f28]
/home/mongo/mongodb/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x130) [0x66aed0]
/home/mongo/mongodb/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x47f) [0x75632f]
/home/mongo/mongodb/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1941) [0x758cc1]
/home/mongo/mongodb/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a3b3e]
/home/mongo/mongodb/bin/mongod(thread_proxy+0x80) [0x8b6a40]
/lib/libpthread.so.0(+0x69ca) [0x7f38704c39ca]
/lib/libc.so.6(clone+0x6d) [0x7f386fa7270d]
------------- RESULTS WHEN DOING VALIDATION
> db.dayByCountry.validate()
{
"ns" : "pixserverHits.dayByCountry",
"result" : "\nvalidate\n firstExtent:0:3d00 ns:pixserverHits.dayByCountry\n lastExtent:3:1378f500 ns:pixserverHits.dayByCountry\n # extents:22\n datasize?:748977412 nrecords?:137782 lastExtentSize:155085824\n padding:1.01\n first extent:\n loc:0:3d00 xnext:0:5d00 xprev:null\n nsdiag:pixserverHits.dayByCountry\n size:8192 firstRecord:0:3db0 lastRecord:0:5c94\n 137782 objects found, nobj:137782\n 751181924 bytes data w/headers\n 748977412 bytes data wout/headers\n deletedList: 0110111111111100001\n deleted: n: 131 size: 140185724\n nIndexes:3\n pixserverHits.dayByCountry.$id keys:137782\n pixserverHits.dayByCountry.$dayByCountry2 keys:137782\n pixserverHits.dayByCountry.$dayByCountry keys:137782\n",
"ok" : 1,
"valid" : true,
"lastExtentSize" : 155085824
}
> db.monthByCountry.validate()
{
"ns" : "pixserverHits.monthByCountry",
"result" : "\nvalidate\n firstExtent:3:1d617300 ns:pixserverHits.monthByCountry\n lastExtent:4:4b73700 ns:pixserverHits.monthByCountry\n # extents:12\n datasize?:82677816 nrecords?:13072 lastExtentSize:25047552\n padding:1.01\n first extent:\n loc:3:1d617300 xnext:3:1d619300 xprev:null\n nsdiag:pixserverHits.monthByCountry\n size:8192 firstRecord:3:1d6173b0 lastRecord:3:1d6191e8\n 13072 objects found, nobj:13072\n 82886968 bytes data w/headers\n 82677816 bytes data wout/headers\n deletedList: 0010001111111111001\n deleted: n: 115 size: 28248456\n nIndexes:3\n pixserverHits.monthByCountry.$id keys:13072\n pixserverHits.monthByCountry.$monthByCountry keys:13072\n pixserverHits.monthByCountry.$monthByCountry2 keys:13072\n",
"ok" : 1,
"valid" : true,
"lastExtentSize" : 25047552
}