Loading...

Type: Bug
Resolution: Duplicate
Priority: Major - P3
Fix Version/s: None
Affects Version/s: 3.2.3
Component/s: Index Maintenance
Labels:
None

Operating System:
ALL

shard2:PRIMARY> version()
3.2.3

shard2:PRIMARY> db.version()
3.2.3

shard2:PRIMARY> db.coll1.count()
129694528

shard2:PRIMARY> db.coll1.getIndexes()
[
	{
		"v" : 1,
		"key" : {
			"_id" : 1
		},
		"name" : "_id_",
		"ns" : "db1.coll1"
	},
	{
		"v" : 1,
		"key" : {
			"field1" : 1,
			"field2" : 1,
			"_id" : 1
		},
		"name" : "field1_1_field2_1__id_1",
		"ns" : "db1.coll1"
	},
	{
		"v" : 1,
		"key" : {
			"field2" : 1,
			"field3" : 1,
			"field1" : 1
		},
		"name" : "field2_1_field3_1_field1_1",
		"ns" : "db1.coll1",
		"background" : true
	}
]

Below message is slow query log from mongodb.log.

2016-03-21T21:09:24.149+0900 I COMMAND  [conn537] command db1.coll1 command: 
find { 
	find: "coll1", 
	filter: { $and: [ 
		{ $or: [ 
			{ field1: 52453027, field2: 95575199643318370 }, 
			{ field1: 52830622, field2: 95574492750870115 }, 
			{ field1: 52453027, field2: 95569183632216466 }, 
			{ field1: 52830622, field2: 95570363249168498 }, 
			{ field1: 73176284, field2: 95569891417110194 }, 
			{ field1: 43687557, field2: 95569419387816370 }, 
			{ field1: 52830622, field2: 95576025413220147 }, 
			{ field1: 65535633, field2: 95570092658348146 }, 
			{ field1: 43687557, field2: 95570716948922003 }, 
			{ field1: 43687557, field2: 95574609828676787 }, 
			{ field1: 52453027, field2: 95570256700958579 }, 
			{ field1: 43687557, field2: 95576733171004387 }, 
			{ field1: 52830622, field2: 95580154159512035 }, 
			{ field1: 52830622, field2: 95571778646775731 }, 
			{ field1: 52453027, field2: 95575938993956994 }, 
			{ field1: 62090613, field2: 95570348393716370 }, 
			{ field1: 65535633, field2: 95575226496465762 }, 
			{ field1: 52453027, field2: 95574697792969411 }, 
			{ field1: 11259631, field2: 95579687975572818 } 
		] }, { field3: 4804010 } 
	] }, 
hint: { $hint: "field2_1_field3_1_field1_1" }, 
shardVersion: [ Timestamp 449000|0, ObjectId('56de9eac877fc817996f60fd') ] } 
planSummary: IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 }, 
	IXSCAN { field2: 1.0, field3: 1.0, field1: 1.0 } 
keysExamined:19632 
docsExamined:19613 
cursorExhausted:1 
keyUpdates:0 
writeConflicts:0 
numYields:153 
nreturned:0 
reslen:214 
locks:{ Global: { acquireCount: { r: 308 } }, Database: { acquireCount: { r: 154 } }, Collection: { acquireCount: { r: 154 } } } 
protocol:op_command 115ms

I think above slow query can fully use index (field2_1_field3_1_field1_1) for where predicate of this query (According to the mongodb manual).

This trace message tell us mongod scanned 19632 index entry and scanned 19613 documents for this query but returned document is 0. What I am wondering is that this query only has field1~3 condition which can be filtered by index fully. I don't understand why mongod scanned so many index entry and even documents.

Is this behavior a bug or designed ?

shard2:PRIMARY> db.coll1.stats()
{
	"ns" : "db1.coll1",
	"count" : 129714725,
	"size" : 14712306529,
	"avgObjSize" : 113,
	"storageSize" : 5810520064,
	"capped" : false,
	"wiredTiger" : {
		"metadata" : {
			"formatVersion" : 1
		},
		"creationString" : "allocation_size=4KB,app_metadata=(formatVersion=1),block_allocation=best,block_compressor=snappy,cache_resident=0,checksum=on,colgroups=,collator=,columns=,dictionary=0,encryption=(keyid=,name=),exclusive=0,extractor=,format=btree,huffman_key=,huffman_value=,immutable=0,internal_item_max=0,internal_key_max=0,internal_key_truncate=,internal_page_max=4KB,key_format=q,key_gap=10,leaf_item_max=0,leaf_key_max=0,leaf_page_max=32KB,leaf_value_max=64MB,log=(enabled=),lsm=(auto_throttle=,bloom=,bloom_bit_count=16,bloom_config=,bloom_hash_count=8,bloom_oldest=0,chunk_count_limit=0,chunk_max=5GB,chunk_size=10MB,merge_max=15,merge_min=0),memory_page_max=10m,os_cache_dirty_max=0,os_cache_max=0,prefix_compression=0,prefix_compression_min=4,source=,split_deepen_min_child=0,split_deepen_per_child=0,split_pct=90,type=file,value_format=u",
		"type" : "file",
		"uri" : "statistics:table:db1/collection-16-7287525874986745644",
		"LSM" : {
			"bloom filters in the LSM tree" : 0,
			"bloom filter false positives" : 0,
			"bloom filter hits" : 0,
			"bloom filter misses" : 0,
			"bloom filter pages evicted from cache" : 0,
			"bloom filter pages read into cache" : 0,
			"total size of bloom filters" : 0,
			"sleep for LSM checkpoint throttle" : 0,
			"chunks in the LSM tree" : 0,
			"highest merge generation in the LSM tree" : 0,
			"queries that could have benefited from a Bloom filter that did not exist" : 0,
			"sleep for LSM merge throttle" : 0
		},
		"block-manager" : {
			"file allocation unit size" : 4096,
			"blocks allocated" : 3008990,
			"checkpoint size" : 5514018816,
			"allocations requiring file extension" : 1994,
			"blocks freed" : 3008872,
			"file magic number" : 120897,
			"file major version number" : 1,
			"minor version number" : 0,
			"file bytes available for reuse" : 336588800,
			"file size in bytes" : 5810520064
		},
		"btree" : {
			"btree checkpoint generation" : 5875,
			"column-store variable-size deleted values" : 0,
			"column-store fixed-size leaf pages" : 0,
			"column-store internal pages" : 0,
			"column-store variable-size RLE encoded values" : 0,
			"column-store variable-size leaf pages" : 0,
			"pages rewritten by compaction" : 0,
			"number of key/value pairs" : 0,
			"fixed-record size" : 0,
			"maximum tree depth" : 5,
			"maximum internal page key size" : 368,
			"maximum internal page size" : 4096,
			"maximum leaf page key size" : 3276,
			"maximum leaf page size" : 32768,
			"maximum leaf page value size" : 67108864,
			"overflow pages" : 0,
			"row-store internal pages" : 0,
			"row-store leaf pages" : 0
		},
		"cache" : {
			"bytes read into cache" : NumberLong("3251702981946"),
			"bytes written from cache" : 68912762057,
			"checkpoint blocked page eviction" : 6,
			"unmodified pages evicted" : 102474954,
			"page split during eviction deepened the tree" : 0,
			"modified pages evicted" : 1341335,
			"data source pages selected for eviction unable to be evicted" : 31373,
			"hazard pointer blocked page eviction" : 21542,
			"internal pages evicted" : 121958,
			"internal pages split during eviction" : 2,
			"leaf pages split during eviction" : 28173,
			"in-memory page splits" : 2,
			"in-memory page passed criteria to be split" : 4,
			"overflow values cached in memory" : 0,
			"pages read into cache" : 103864363,
			"pages read into cache requiring lookaside entries" : 0,
			"overflow pages read into cache" : 0,
			"pages written from cache" : 2997240,
			"page written requiring lookaside records" : 0,
			"pages written requiring in-memory restoration" : 0
		},
		"compression" : {
			"raw compression call failed, no additional data available" : 0,
			"raw compression call failed, additional data available" : 0,
			"raw compression call succeeded" : 0,
			"compressed pages read" : 103589102,
			"compressed pages written" : 2618391,
			"page written failed to compress" : 0,
			"page written was too small to compress" : 378849
		},
		"cursor" : {
			"create calls" : 444221,
			"insert calls" : 7784293,
			"bulk-loaded cursor-insert calls" : 0,
			"cursor-insert key and value bytes inserted" : 920347601,
			"next calls" : 1,
			"prev calls" : 1,
			"remove calls" : 18200317,
			"cursor-remove key bytes removed" : 89707816,
			"reset calls" : 1329808686,
			"restarted searches" : 2039,
			"search calls" : 142024897054,
			"search near calls" : 0,
			"truncate calls" : 0,
			"update calls" : 0,
			"cursor-update value bytes updated" : 0
		},
		"reconciliation" : {
			"dictionary matches" : 0,
			"internal page multi-block writes" : 9646,
			"leaf page multi-block writes" : 28787,
			"maximum blocks required for a page" : 45,
			"internal-page overflow keys" : 0,
			"leaf-page overflow keys" : 0,
			"overflow values written" : 0,
			"pages deleted" : 46458,
			"fast-path pages deleted" : 0,
			"page checksum matches" : 69371,
			"page reconciliation calls" : 2922673,
			"page reconciliation calls for eviction" : 1263695,
			"leaf page key bytes discarded using prefix compression" : 0,
			"internal page key bytes discarded using suffix compression" : 46399
		},
		"session" : {
			"object compaction" : 0,
			"open cursor count" : 341
		},
		"transaction" : {
			"update conflicts" : 0
		}
	},
	"nindexes" : 3,
	"totalIndexSize" : 18573279232,
	"indexSizes" : {
		"_id_" : 6466985984,
		"field1_1_field2_1__id_1" : 4809674752,
		"field2_1_field3_1_field1_1" : 7296618496
	},
	"ok" : 1
}

duplicates

SERVER-13732 Predicates in top-level implicit AND query not considered when generating index access plan for contained OR

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates