OPERATIONAL DEFECT DATABASE
...
...
> db.serverStatus() { "host" : "rinmato-MacBook-Pro.local", "version" : "3.4.4", "process" : "mongod", "pid" : NumberLong(4087), "uptime" : 278, "uptimeMillis" : NumberLong(277065), "uptimeEstimate" : NumberLong(277), "localTime" : ISODate("2017-04-25T06:30:29.040Z"), "asserts" : { "regular" : 0, "warning" : 0, "msg" : 0, "user" : 0, "rollovers" : 0 }, "connections" : { "current" : 2, "available" : 202, "totalCreated" : 2 }, "extra_info" : { "note" : "fields vary by platform", "page_faults" : 0 }, "globalLock" : { "totalTime" : NumberLong(277064000), "currentQueue" : { "total" : 0, "readers" : 0, "writers" : 0 }, "activeClients" : { "total" : 8, "readers" : 0, "writers" : 0 } }, "locks" : { "Global" : { "acquireCount" : { "r" : NumberLong(8148), "w" : NumberLong(61), "W" : NumberLong(5) } }, "Database" : { "acquireCount" : { "r" : NumberLong(4027), "R" : NumberLong(12), "W" : NumberLong(61) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(4011) } }, "Metadata" : { "acquireCount" : { "w" : NumberLong(1) } } }, "network" : { "bytesIn" : NumberLong(3132), "bytesOut" : NumberLong(12707), "physicalBytesIn" : NumberLong(3132), "physicalBytesOut" : NumberLong(12707), "numRequests" : NumberLong(67) }, "opLatencies" : { "reads" : { "latency" : NumberLong(1306), "ops" : NumberLong(2) }, "writes" : { "latency" : NumberLong(0), "ops" : NumberLong(0) }, "commands" : { "latency" : NumberLong(12199), "ops" : NumberLong(31) } }, "opcounters" : { "insert" : 0, "query" : 1, "update" : 0, "delete" : 0, "getmore" : 0, "command" : 34 }, "opcountersRepl" : { "insert" : 0, "query" : 0, "update" : 0, "delete" : 0, "getmore" : 0, "command" : 0 }, "storageEngine" : { "name" : "wiredTiger", "supportsCommittedReads" : true, "readOnly" : false, "persistent" : true }, "wiredTiger" : { "uri" : "statistics:", "LSM" : { "application work units currently queued" : 0, "merge work units currently queued" : 0, "rows merged in an LSM tree" : 0, "sleep for LSM checkpoint throttle" : 0, "sleep for LSM merge throttle" : 0, "switch work units currently queued" : 0, "tree maintenance operations discarded" : 0, "tree maintenance operations executed" : 0, "tree maintenance operations scheduled" : 0, "tree queue hit maximum" : 0 }, "async" : { "current work queue length" : 0, "maximum work queue length" : 0, "number of allocation state races" : 0, "number of flush calls" : 0, "number of operation slots viewed for allocation" : 0, "number of times operation allocation failed" : 0, "number of times worker found no work" : 0, "total allocations" : 0, "total compact calls" : 0, "total insert calls" : 0, "total remove calls" : 0, "total search calls" : 0, "total update calls" : 0 }, "block-manager" : { "blocks pre-loaded" : 1609, "blocks read" : 191, "blocks written" : 42, "bytes read" : 1314816, "bytes written" : 421888, "bytes written for checkpoint" : 421888, "mapped blocks read" : 0, "mapped bytes read" : 0 }, "cache" : { "application threads page read from disk to cache count" : 79, "application threads page read from disk to cache time (usecs)" : 2267, "application threads page write from cache to disk count" : 0, "application threads page write from cache to disk time (usecs)" : 0, "bytes belonging to page images in the cache" : 2110375, "bytes currently in the cache" : 2423646, "bytes not belonging to page images in the cache" : 313271, "bytes read into cache" : 1954246, "bytes written from cache" : 301882, "checkpoint blocked page eviction" : 0, "eviction calls to get a page" : 19, "eviction calls to get a page found queue empty" : 19, "eviction calls to get a page found queue empty after locking" : 0, "eviction currently operating in aggressive mode" : 0, "eviction empty score" : 0, "eviction server candidate queue empty when topping up" : 0, "eviction server candidate queue not empty when topping up" : 0, "eviction server evicting pages" : 0, "eviction server slept, because we did not make progress with eviction" : 0, "eviction server unable to reach eviction goal" : 0, "eviction state" : 16, "eviction walks abandoned" : 0, "eviction worker thread active" : 4, "eviction worker thread created" : 0, "eviction worker thread evicting pages" : 0, "eviction worker thread removed" : 12, "eviction worker thread stable number" : 0, "failed eviction of pages that exceeded the in-memory maximum" : 0, "files with active eviction walks" : 0, "files with new eviction walks started" : 0, "force re-tuning of eviction workers once in a while" : 2, "hazard pointer blocked page eviction" : 0, "hazard pointer check calls" : 0, "hazard pointer check entries walked" : 0, "hazard pointer maximum array length" : 0, "in-memory page passed criteria to be split" : 0, "in-memory page splits" : 0, "internal pages evicted" : 0, "internal pages split during eviction" : 0, "leaf pages split during eviction" : 0, "lookaside table insert calls" : 0, "lookaside table remove calls" : 0, "maximum bytes configured" : 8053063680, "maximum page size at eviction" : 0, "modified pages evicted" : 0, "modified pages evicted by application threads" : 0, "overflow pages read into cache" : 0, "overflow values cached in memory" : 0, "page split during eviction deepened the tree" : 0, "page written requiring lookaside records" : 0, "pages currently held in the cache" : 153, "pages evicted because they exceeded the in-memory maximum" : 0, "pages evicted because they had chains of deleted items" : 0, "pages evicted by application threads" : 0, "pages queued for eviction" : 0, "pages queued for urgent eviction" : 0, "pages queued for urgent eviction during walk" : 0, "pages read into cache" : 151, "pages read into cache requiring lookaside entries" : 0, "pages requested from the cache" : 3925, "pages seen by eviction walk" : 0, "pages selected for eviction unable to be evicted" : 0, "pages walked for eviction" : 0, "pages written from cache" : 24, "pages written requiring in-memory restoration" : 0, "percentage overhead" : 8, "tracked bytes belonging to internal pages in the cache" : 251400, "tracked bytes belonging to leaf pages in the cache" : 2172246, "tracked dirty bytes in the cache" : 69914, "tracked dirty pages in the cache" : 2, "unmodified pages evicted" : 0 }, "connection" : { "auto adjusting condition resets" : 29, "auto adjusting condition wait calls" : 1712, "files currently open" : 67, "memory allocations" : 24297, "memory frees" : 15981, "memory re-allocations" : 1026, "pthread mutex condition wait calls" : 4448, "pthread mutex shared lock read-lock calls" : 2818, "pthread mutex shared lock write-lock calls" : 524, "total fsync I/Os" : 41, "total read I/Os" : 1210, "total write I/Os" : 63 }, "cursor" : { "cursor create calls" : 159, "cursor insert calls" : 69, "cursor next calls" : 1117, "cursor prev calls" : 60, "cursor remove calls" : 4, "cursor reset calls" : 3291, "cursor restarted searches" : 0, "cursor search calls" : 3751, "cursor search near calls" : 4, "cursor update calls" : 0, "truncate calls" : 0 }, "data-handle" : { "connection data handles currently active" : 65, "connection sweep candidate became referenced" : 0, "connection sweep dhandles closed" : 1, "connection sweep dhandles removed from hash list" : 5, "connection sweep time-of-death sets" : 67, "connection sweeps" : 27, "session dhandles swept" : 1, "session sweep attempts" : 19 }, "lock" : { "checkpoint lock acquisitions" : 4, "checkpoint lock application thread wait time (usecs)" : 0, "checkpoint lock internal thread wait time (usecs)" : 2, "handle-list lock eviction thread wait time (usecs)" : 836, "metadata lock acquisitions" : 4, "metadata lock application thread wait time (usecs)" : 0, "metadata lock internal thread wait time (usecs)" : 2, "schema lock acquisitions" : 72, "schema lock application thread wait time (usecs)" : 5, "schema lock internal thread wait time (usecs)" : 3, "table lock acquisitions" : 0, "table lock application thread time waiting for the table lock (usecs)" : 0, "table lock internal thread time waiting for the table lock (usecs)" : 0 }, "log" : { "busy returns attempting to switch slots" : 0, "consolidated slot closures" : 13, "consolidated slot join active slot closed" : 0, "consolidated slot join races" : 0, "consolidated slot join transitions" : 13, "consolidated slot joins" : 18, "consolidated slot transitions unable to find free slot" : 0, "consolidated slot unbuffered writes" : 0, "log bytes of payload data" : 6073, "log bytes written" : 7808, "log files manually zero-filled" : 0, "log flush operations" : 2675, "log force write operations" : 2973, "log force write operations skipped" : 2967, "log records compressed" : 5, "log records not compressed" : 1, "log records too small to compress" : 12, "log release advances write LSN" : 7, "log scan operations" : 5, "log scan records requiring two reads" : 0, "log server thread advances write LSN" : 6, "log server thread write LSN walk skipped" : 1215, "log sync operations" : 13, "log sync time duration (usecs)" : 439765, "log sync_dir operations" : 1, "log sync_dir time duration (usecs)" : 27040, "log write operations" : 18, "logging bytes consolidated" : 7424, "maximum log file size" : 104857600, "number of pre-allocated log files to create" : 2, "pre-allocated log files not ready and missed" : 1, "pre-allocated log files prepared" : 2, "pre-allocated log files used" : 0, "records processed by log scan" : 10, "total in-memory size of compressed records" : 12198, "total log buffer size" : 33554432, "total size of compressed records" : 5262, "written slots coalesced" : 0, "yields waiting for previous log file close" : 0 }, "reconciliation" : { "fast-path pages deleted" : 0, "page reconciliation calls" : 24, "page reconciliation calls for eviction" : 0, "pages deleted" : 0, "split bytes currently awaiting free" : 0, "split objects currently awaiting free" : 0 }, "session" : { "open cursor count" : 17, "open session count" : 16, "table alter failed calls" : 0, "table alter successful calls" : 0, "table alter unchanged and skipped" : 0, "table compact failed calls" : 0, "table compact successful calls" : 0, "table create failed calls" : 0, "table create successful calls" : 0, "table drop failed calls" : 1, "table drop successful calls" : 1, "table rebalance failed calls" : 0, "table rebalance successful calls" : 0, "table rename failed calls" : 0, "table rename successful calls" : 0, "table salvage failed calls" : 0, "table salvage successful calls" : 0, "table truncate failed calls" : 0, "table truncate successful calls" : 0, "table verify failed calls" : 0, "table verify successful calls" : 0 }, "thread-state" : { "active filesystem fsync calls" : 0, "active filesystem read calls" : 0, "active filesystem write calls" : 0 }, "thread-yield" : { "application thread time evicting (usecs)" : 0, "application thread time waiting for cache (usecs)" : 0, "page acquire busy blocked" : 0, "page acquire eviction blocked" : 0, "page acquire locked blocked" : 0, "page acquire read blocked" : 0, "page acquire time sleeping (usecs)" : 0 }, "transaction" : { "number of named snapshots created" : 0, "number of named snapshots dropped" : 0, "transaction begins" : 30, "transaction checkpoint currently running" : 0, "transaction checkpoint generation" : 4, "transaction checkpoint max time (msecs)" : 223, "transaction checkpoint min time (msecs)" : 51, "transaction checkpoint most recent time (msecs)" : 53, "transaction checkpoint scrub dirty target" : 0, "transaction checkpoint scrub time (msecs)" : 0, "transaction checkpoint total time (msecs)" : 394, "transaction checkpoints" : 4, "transaction checkpoints skipped because database was clean" : 1, "transaction failures due to cache overflow" : 0, "transaction fsync calls for checkpoint after allocating the transaction ID" : 4, "transaction fsync duration for checkpoint after allocating the transaction ID (usecs)" : 21078, "transaction range of IDs currently pinned" : 0, "transaction range of IDs currently pinned by a checkpoint" : 0, "transaction range of IDs currently pinned by named snapshots" : 0, "transaction sync calls" : 0, "transactions committed" : 4, "transactions rolled back" : 26 }, "concurrentTransactions" : { "write" : { "out" : 0, "available" : 128, "totalTickets" : 128 }, "read" : { "out" : 0, "available" : 128, "totalTickets" : 128 } } }, "mem" : { "bits" : 64, "resident" : 32, "virtual" : 2580, "supported" : true, "mapped" : 0, "mappedWithJournal" : 0 }, "metrics" : { "commands" : { "buildInfo" : { "failed" : NumberLong(0), "total" : NumberLong(4) }, "distinct" : { "failed" : NumberLong(0), "total" : NumberLong(2) }, "dropIndexes" : { "failed" : NumberLong(0), "total" : NumberLong(1) }, "getLog" : { "failed" : NumberLong(0), "total" : NumberLong(2) }, "isMaster" : { "failed" : NumberLong(0), "total" : NumberLong(14) }, "listCollections" : { "failed" : NumberLong(0), "total" : NumberLong(4) }, "listDatabases" : { "failed" : NumberLong(0), "total" : NumberLong(2) }, "replSetGetStatus" : { "failed" : NumberLong(2), "total" : NumberLong(2) }, "serverStatus" : { "failed" : NumberLong(0), "total" : NumberLong(1) }, "whatsmyuri" : { "failed" : NumberLong(0), "total" : NumberLong(2) } }, "cursor" : { "timedOut" : NumberLong(0), "open" : { "noTimeout" : NumberLong(0), "pinned" : NumberLong(0), "total" : NumberLong(0) } }, "document" : { "deleted" : NumberLong(0), "inserted" : NumberLong(0), "returned" : NumberLong(0), "updated" : NumberLong(0) }, "getLastError" : { "wtime" : { "num" : 0, "totalMillis" : 0 }, "wtimeouts" : NumberLong(0) }, "operation" : { "scanAndOrder" : NumberLong(0), "writeConflicts" : NumberLong(0) }, "queryExecutor" : { "scanned" : NumberLong(2), "scannedObjects" : NumberLong(6) }, "record" : { "moves" : NumberLong(0) }, "repl" : { "executor" : { "counters" : { "eventCreated" : 0, "eventWait" : 0, "cancels" : 0, "waits" : 0, "scheduledNetCmd" : 0, "scheduledDBWork" : 0, "scheduledXclWork" : 0, "scheduledWorkAt" : 0, "scheduledWork" : 0, "schedulingFailures" : 0 }, "queues" : { "networkInProgress" : 0, "dbWorkInProgress" : 0, "exclusiveInProgress" : 0, "sleepers" : 0, "ready" : 0, "free" : 0 }, "unsignaledEvents" : 0, "eventWaiters" : 0, "shuttingDown" : false, "networkInterface" : "\nNetworkInterfaceASIO Operations' Diagnostic:\nOperation: Count: \nConnecting 0 \nIn Progress 0 \nSucceeded 0 \nCanceled 0 \nFailed 0 \nTimed Out 0 \n\n" }, "apply" : { "attemptsToBecomeSecondary" : NumberLong(0), "batches" : { "num" : 0, "totalMillis" : 0 }, "ops" : NumberLong(0) }, "buffer" : { "count" : NumberLong(0), "maxSizeBytes" : NumberLong(0), "sizeBytes" : NumberLong(0) }, "initialSync" : { "completed" : NumberLong(0), "failedAttempts" : NumberLong(0), "failures" : NumberLong(0) }, "network" : { "bytes" : NumberLong(0), "getmores" : { "num" : 0, "totalMillis" : 0 }, "ops" : NumberLong(0), "readersCreated" : NumberLong(0) }, "preload" : { "docs" : { "num" : 0, "totalMillis" : 0 }, "indexes" : { "num" : 0, "totalMillis" : 0 } } }, "storage" : { "freelist" : { "search" : { "bucketExhausted" : NumberLong(0), "requests" : NumberLong(0), "scanned" : NumberLong(0) } } }, "ttl" : { "deletedDocuments" : NumberLong(0), "passes" : NumberLong(4) } }, "ok" : 1 }
xgen-internal-githook commented on Fri, 5 May 2017 20:40:04 +0000: Author: {u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'} Message: SERVER-28952 Update test for absence of covered plans over multikey indices in 3.4.x versions. Branch: v3.4 https://github.com/mongodb/mongo/commit/02728d11d54f6bd43276ff3c76dea6d2484b4134 xgen-internal-githook commented on Fri, 5 May 2017 20:40:03 +0000: Author: {u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'} Message: SERVER-28952 fix distinct planning for multikey indices (cherry picked from commit 566694eb312d7eaaf9e6e756e42cf863ad7f0f58) Branch: v3.4 https://github.com/mongodb/mongo/commit/9b1f1f9d1225711aa049725174e6ca88ea24e9c8 xgen-internal-githook commented on Thu, 4 May 2017 18:38:14 +0000: Author: {u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'} Message: SERVER-28952 fix distinct planning for multikey indices Branch: master https://github.com/mongodb/mongo/commit/566694eb312d7eaaf9e6e756e42cf863ad7f0f58 david.storch commented on Wed, 3 May 2017 19:12:23 +0000: I believe this regression was first introduced in version 3.3.12 due to the changes in SERVER-24401. This change allowed the DISTINCT_SCAN to be used for non-covered plans, so long as there are no additional filters that need to be applied. However, plans using multikey indexes are not covered, so this had the unintentional side affect of generating incorrect DISTINCT_SCAN plans in the multikey case. kyle.suarez commented on Tue, 25 Apr 2017 15:54:52 +0000: I can reproduce this even with only one field, where the distinct key is an array and a query exists. > db.coll.find() { "_id" : ObjectId("58ff6a2c2541d2cfe75f1cc7"), "a" : [ 1, 2, 3 ] } { "_id" : ObjectId("58ff6a312541d2cfe75f1cc8"), "a" : [ 2, 3, 4 ] } { "_id" : ObjectId("58ff6a362541d2cfe75f1cc9"), "a" : [ 3, 4, 5 ] } > db.coll.getIndexes() [ { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_", "ns" : "test.coll" }, { "v" : 2, "key" : { "a" : 1 }, "name" : "a_1", "ns" : "test.coll" } ] > db.coll.distinct("a", {a: 3}) [ 1, 2, 3 ] > db.coll.explain().distinct("a", {a: 3}) { "queryPlanner" : { "plannerVersion" : 1, "namespace" : "test.coll", "indexFilterSet" : false, "parsedQuery" : { "a" : { "$eq" : 3 } }, "winningPlan" : { "stage" : "FETCH", "inputStage" : { "stage" : "DISTINCT_SCAN", "keyPattern" : { "a" : 1 }, "indexName" : "a_1", "isMultiKey" : true, "multiKeyPaths" : { "a" : [ "a" ] }, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 2, "direction" : "forward", "indexBounds" : { "a" : [ "[3.0, 3.0]" ] } } }, "rejectedPlans" : [ ] }, "serverInfo" : { "host" : "celadon", "port" : 27017, "version" : "0.0.0", "gitVersion" : "unknown" }, "ok" : 1 } If the index is multikey, we cannot do the DISTINCT_SCAN optimization if the distinct key is the array component. turnIxscanIntoDistinctIxscan() should not consider such indexes eligible for the optimization. I've tested this on version 3.2.12, and can confirm that it is not affected by this issue, as the IXSCAN is not converted into a DISTINCT_SCAN: ksuarz@celadon:~/code/mongo $ ./mongo MongoDB shell version: 3.2.12 connecting to: test > db.coll.insert( { a: [3, 4, 5] } ) WriteResult({ "nInserted" : 1 }) > db.coll.insert( { a: [2, 3, 4] } ) WriteResult({ "nInserted" : 1 }) > db.coll.insert( { a: [1, 2, 3] } ) WriteResult({ "nInserted" : 1 }) > db.coll.createIndex({a: 1}) { "createdCollectionAutomatically" : false, "numIndexesBefore" : 1, "numIndexesAfter" : 2, "ok" : 1 } > db.coll.distinct("a", {a: 3}) [ 3, 4, 5, 2, 1 ] > db.coll.explain().distinct("a", {a: 3}) { "queryPlanner" : { "plannerVersion" : 1, "namespace" : "test.coll", "indexFilterSet" : false, "parsedQuery" : { "a" : { "$eq" : 3 } }, "winningPlan" : { "stage" : "FETCH", "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "a" : 1 }, "indexName" : "a_1", "isMultiKey" : true, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 1, "direction" : "forward", "indexBounds" : { "a" : [ "[3.0, 3.0]" ] } } }, "rejectedPlans" : [ ] }, "serverInfo" : { "host" : "celadon", "port" : 27017, "version" : "3.2.12", "gitVersion" : "ef3e1bc78e997f0d9f22f45aeb1d8e3b6ac14a14" }, "ok" : 1 } kyle.suarez commented on Tue, 25 Apr 2017 14:10:14 +0000: Hello hotdog929, Thanks for your report and the detailed reproduction steps. I can reproduce this bug on 3.4.4, and I've sent this ticket to the Query Team for triage. Best, Kyle
> use test_distinct switched to db test_distinct > db.Item.insert({label:"L1",content:["A","B","C"]}) WriteResult({ "nInserted" : 1 }) > db.Item.insert({label:"L1",content:["B","C","D"]}) WriteResult({ "nInserted" : 1 }) > db.Item.insert({label:"L1",content:["C","D","E"]}) WriteResult({ "nInserted" : 1 }) > db.Item.insert({label:"L2",content:["a","b","c"]}) WriteResult({ "nInserted" : 1 }) > db.Item.insert({label:"L2",content:["b","c","d"]}) WriteResult({ "nInserted" : 1 }) > db.Item.distinct("content") [ "A", "B", "C", "D", "E", "a", "b", "c", "d" ] > db.Item.distinct("content",{label:"L1"}) [ "A", "B", "C", "D", "E" ] > db.Item.distinct("content",{label:"L1",content:"C"}) [ "A", "B", "C", "D", "E" ] > db.Item.createIndex({label:1,content:1}) { "createdCollectionAutomatically" : false, "numIndexesBefore" : 1, "numIndexesAfter" : 2, "ok" : 1 } // Incorrect > db.Item.distinct("content",{label:"L1",content:"C"}) [ "A", "B", "C" ] > db.Item.dropIndex({label:1,content:1}) { "nIndexesWas" : 2, "ok" : 1 } > db.Item.distinct("content",{label:"L1",content:"C"}) [ "A", "B", "C", "D", "E" ]
MongoDB Integration
Learn more about where this data comes from
Bug Scrub Advisor
Streamline upgrades with automated vendor bug scrubs
BugZero Enterprise
Wish you caught this bug sooner? Get proactive today.
