[SERVER-15104] Why me execute the same command but get different result? Created: 01/Sep/14  Updated: 23/Apr/15  Resolved: 23/Apr/15

Status: Closed
Project: Core Server
Component/s: Index Maintenance, Querying
Affects Version/s: 2.4.10
Fix Version/s: None

Type: Question Priority: Major - P3
Reporter: angus.aqlu Assignee: Ramon Fernandez Marina
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Participants:

 Description   

I used mongodb 2.4.10 to collect some app logs, sometimes when i statistics and analysis, i execute a same command, but give me different result:

    logReplSet:PRIMARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}})
    86
    logReplSet:PRIMARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}})
    47
    logReplSet:PRIMARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}})
    47
    logReplSet:PRIMARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}})
    47
    logReplSet:PRIMARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}})
    47

the current db and collection status:

    logReplSet:PRIMARY> db.stats()
    {
    "db" : "logs",
    "collections" : 45,
    "objects" : 2108341434,
    "avgObjSize" : 747.0257969857837,
    "dataSize" : NumberLong("1574985440052"),
    "storageSize" : NumberLong("1634846926048"),
    "numExtents" : 1303,
    "indexes" : 230,
    "indexSize" : 661429905136,
    "fileSize" : NumberLong("2365305389056"),
    "nsSizeMB" : 16,
    "dataFileVersion" : {
        "major" : 4,
        "minor" : 5
    },
    "ok" : 1
    }
 
    logReplSet:PRIMARY> db.ofapi_inf_record_20140825.stats()
    {
    "ns" : "logs.ofapi_inf_record_20140825",
    "count" : 45681275,
    "size" : 45292806320,
    "avgObjSize" : 991.496106884057,
    "storageSize" : 47941103312,
    "numExtents" : 43,
    "nindexes" : 6,
    "lastExtentSize" : 2146426864,
    "paddingFactor" : 1,
    "systemFlags" : 1,
    "userFlags" : 0,
    "totalIndexSize" : 18175558688,
    "indexSizes" : {
        "_id_" : 1482316976,
        "invokeTime_-1.0_methodName_1.0" : 7287988288,
        "uuId_1.0" : 3596499760,
        "paramValues.userCode_1.0" : 1950908064,
        "costTime_-1.0" : 2296245952,
        "exceptionMsg_1.0" : 1561599648
    },
    "ok" : 1
    }
 

Mongodb Logs: (first cost 51952ms )

Mon Sep  1 08:59:27.659 [conn5901521] command logs.$cmd command: { count: "ofapi_inf_record_20140825", query: { invokeTime: { $gte: "2014-08-29 19:30:52", $lte: "2014-08-29 19:41:52" }, exceptionMsg: { $ne: null } }, fields: {} } ntoreturn:1 keyUpdates:0 numYields: 1494 locks(micros) r:101254026 reslen:48 51952ms
Mon Sep  1 08:59:55.252 [conn5901521] command logs.$cmd command: { count: "ofapi_inf_record_20140825", query: { invokeTime: { $gte: "2014-08-29 19:30:52", $lte: "2014-08-29 19:41:52" }, exceptionMsg: { $ne: null } }, fields: {} } ntoreturn:1 keyUpdates:0 numYields: 1 locks(micros) r:317472 reslen:48 169ms
Mon Sep  1 09:03:27.404 [conn5901521] command logs.$cmd command: { count: "ofapi_inf_record_20140825", query: { invokeTime: { $gte: "2014-08-29 19:30:52", $lte: "2014-08-29 19:41:52" }, exceptionMsg: { $ne: null } }, fields: {} } ntoreturn:1 keyUpdates:0 numYields: 2 locks(micros) r:292434 reslen:48 169ms
Mon Sep  1 09:03:29.201 [conn5901521] command logs.$cmd command: { count: "ofapi_inf_record_20140825", query: { invokeTime: { $gte: "2014-08-29 19:30:52", $lte: "2014-08-29 19:41:52" }, exceptionMsg: { $ne: null } }, fields: {} } ntoreturn:1 keyUpdates:0 locks(micros) r:162235 reslen:48 162ms
Mon Sep  1 09:22:09.624 [conn5901521] command logs.$cmd command: { count: "ofapi_inf_record_20140825", query: { invokeTime: { $gte: "2014-08-29 19:30:52", $lte: "2014-08-29 19:41:52" }, exceptionMsg: { $ne: null } }, fields: {} } ntoreturn:1 keyUpdates:0 numYields: 281 locks(micros) r:373800 reslen:48 380ms



 Comments   
Comment by Ramon Fernandez Marina [ 01/Apr/15 ]

angus.aqlu apologies for the late follow up. It seems your exceptionMsg field is an array, so the query will match documents that contain the text you're searching for in any of the array elements. Consider the following collection:

db.foo.find()
{ "_id" : ObjectId("551c38d7f43827417cce1a68"), "x" : 0 }
{ "_id" : ObjectId("551c38ddf43827417cce1a69"), "x" : 1, "y" : [ ] }
{ "_id" : ObjectId("551c3809f43827417cce1a63"), "x" : 2, "y" : [  "aaa" ] }
{ "_id" : ObjectId("551c3810f43827417cce1a64"), "x" : 3, "y" : [  "aaa",  "bbb" ] }
{ "_id" : ObjectId("551c381cf43827417cce1a65"), "x" : 4, "y" : [  "bbb",  "ccc" ] }
{ "_id" : ObjectId("551c3984f43827417cce1a6b"), "x" : 5, "y" : [ ] }

And the following operations:

> db.foo.count({y:{$ne:null}})
5 // An empty array is not null
> db.foo.count({y:/aaa/})
2 // Two documents contain the string "aaa"
> db.foo.count({y:/bbb/})
2 // 2 + 2 /= 5

So this part is expected. In order to determine if there's a bug, could you please run the count() query hinting on two different indexes (you may need to adjust index names if I didn't get them right):

db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}}).hint({errorMsg : 1})
db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}}).hint("invokeTime_-1.0_methodName_1.0")

Alternatively, if you could share your data set with us that would help investigating; please let me know if this is an option and I can provide instructions for uploading privately and securely.

Thanks,
Ramón.

Comment by angus.aqlu [ 10/Sep/14 ]

Hi Thomas,
Is this a bug or need I rebuild indexes?

Comment by angus.aqlu [ 03/Sep/14 ]

Hi Thomas,

yes, i used a replica, not sharded cluster.

this is my replica set status:

    {
        "set" : "logReplSet",
        "date" : ISODate("2014-09-03T00:52:03Z"),
        "myState" : 1,
        "members" : [
            {
                "_id" : 0,
                "name" : "192.168.65.180:27000",
                "health" : 1,
                "state" : 7,
                "stateStr" : "ARBITER",
                "uptime" : 5257476,
                "lastHeartbeat" : ISODate("2014-09-03T00:52:02Z"),
                "lastHeartbeatRecv" : ISODate("2014-09-03T00:52:03Z"),
                "pingMs" : 1
            },
            {
                "_id" : 1,
                "name" : "192.168.65.181:27000",
                "health" : 1,
                "state" : 1,
                "stateStr" : "PRIMARY",
                "uptime" : 5257476,
                "optime" : Timestamp(1409705523, 1577),
                "optimeDate" : ISODate("2014-09-03T00:52:03Z"),
                "self" : true
            },
            {
                "_id" : 2,
                "name" : "192.168.65.182:27000",
                "health" : 1,
                "state" : 2,
                "stateStr" : "SECONDARY",
                "uptime" : 5257474,
                "optime" : Timestamp(1409705523, 416),
                "optimeDate" : ISODate("2014-09-03T00:52:03Z"),
                "lastHeartbeat" : ISODate("2014-09-03T00:52:03Z"),
                "lastHeartbeatRecv" : ISODate("2014-09-03T00:52:02Z"),
                "pingMs" : 0,
                "syncingTo" : "192.168.65.181:27000"
            }
        ],
        "ok" : 1
    }

Here is my explains:

    logReplSet:PRIMARY> db.ofapi_inf_record_20140825.find({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}}).explain(true)
    
    {
        "cursor" : "BtreeCursor exceptionMsg_1.0 multi",
        "isMultiKey" : false,
        "n" : 86,
        "nscannedObjects" : 36318,
        "nscanned" : 36319,
        "nscannedObjectsAllPlans" : 108958,
        "nscannedAllPlans" : 108959,
        "scanAndOrder" : false,
        "indexOnly" : false,
        "nYields" : 2,
        "nChunkSkips" : 0,
        "millis" : 1517,
        "indexBounds" : {
            "exceptionMsg" : [
                [
                    {
                        "$minElement" : 1
                    },
                    null
                ],
                [
                    null,
                    {
                        "$maxElement" : 1
                    }
                ]
            ]
        },
        "allPlans" : [
            {
                "cursor" : "BtreeCursor invokeTime_-1.0_methodName_1.0",
                "n" : 52,
                "nscannedObjects" : 36320,
                "nscanned" : 36320,
                "indexBounds" : {
                    "invokeTime" : [
                        [
                            "2014-08-29 19:41:52",
                            "2014-08-29 19:30:52"
                        ]
                    ],
                    "methodName" : [
                        [
                            {
                                "$minElement" : 1
                            },
                            {
                                "$maxElement" : 1
                            }
                        ]
                    ]
                }
            },
            {
                "cursor" : "BtreeCursor exceptionMsg_1.0 multi",
                "n" : 47,
                "nscannedObjects" : 36318,
                "nscanned" : 36319,
                "indexBounds" : {
                    "exceptionMsg" : [
                        [
                            {
                                "$minElement" : 1
                            },
                            null
                        ],
                        [
                            null,
                            {
                                "$maxElement" : 1
                            }
                        ]
                    ]
                }
            },
            {
                "cursor" : "BasicCursor",
                "n" : 0,
                "nscannedObjects" : 36320,
                "nscanned" : 36320,
                "indexBounds" : {
                }
            }
        ],
        "oldPlan" : {
            "cursor" : "BtreeCursor exceptionMsg_1.0 multi",
            "indexBounds" : {
                "exceptionMsg" : [
                    [
                        {
                            "$minElement" : 1
                        },
                        null
                    ],
                    [
                        null,
                        {
                            "$maxElement" : 1
                        }
                    ]
                ]
            }
        },
        "server" : "lin-mongo-65-181:27000"
    }

Comment by Thomas Rueckstiess [ 02/Sep/14 ]

Hi Angus,

Is this a replica set or a sharded cluster?

Can you repeat the commands but replace .count with .find and add .explain(true) to the end of the commands? Can you paste the output of the explains below?

Thanks,
Thomas

Comment by angus.aqlu [ 01/Sep/14 ]

Additional:

Data is only collected, not deleted;

begin 2014-08-29 19:30:52 to 2014-08-29 19:41:52, no data change.

first i want count field("exceptionMsg") is not null, it return 47;second i count field("exceptionMsg") with regExp /Invoke remote method/, it return 37; third i count field ("exceptionMsg") with regExp /余额不足/, it return 46;

but 37 + 46 > 47, why ?

logReplSet:SECONDARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":{"$ne":null}})
47
logReplSet:SECONDARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":/Invoke remote method/})
37
logReplSet:SECONDARY> db.ofapi_inf_record_20140825.count({"invokeTime":{"$gte":"2014-08-29 19:30:52","$lte":"2014-08-29 19:41:52"},"exceptionMsg":/余额不足/})
46

Generated at Thu Feb 08 03:36:57 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.