[SERVER-13583] mongostat shows queued inserts as readers Created: 14/Apr/14  Updated: 14/Mar/17  Resolved: 18/Apr/14

Status: Closed
Project: Core Server
Component/s: Diagnostics, Tools
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Alexander Komyagin Assignee: Unassigned
Resolution: Won't Fix Votes: 0
Labels: locking, metrics
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Documented
is documented by DOCS-9002 mongostat shows queued inserts as rea... Closed
Related
related to SERVER-13655 Report queued operations by type (ins... Closed
Backwards Compatibility: Major Change
Operating System: ALL
Participants:

 Description   

While running an insert-only test, I noticed that mongostat shows queued readers, while I do not read anything.

Sample mongostat output:

insert  query update delete getmore command flushes mapped  vsize    res faults   locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
  6120     *0     *0     *0       0     2|0       0    16g  32.3g  1.97g      0  test:68.3%          0      19|0     0|1     6m     3k    23   19:33:03
  6061     *0     *0     *0       0     2|0       0    18g  36.3g  1.99g      1  test:76.4%          0      19|0     0|1     6m     8k    23   19:33:04
  5966     *0     *0     *0       0     1|0       0    18g  36.3g  2.02g      0  test:63.3%          0      19|0     0|1     6m     3k    23   19:33:05
  6110     *0     *0     *0       0     1|0       0    18g  36.3g  2.04g      0  test:68.4%          0      19|0     0|1     6m     3k    23   19:33:06

db.currentOp output for the same time:

> db.currentOp()
{
	"inprog" : [
		{
			"opid" : 824735,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60486",
			"desc" : "conn62",
			"threadId" : "0x7f37873b4700",
			"connectionId" : 62,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824726,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60494",
			"desc" : "conn72",
			"threadId" : "0x7f37871b2700",
			"connectionId" : 72,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824740,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60484",
			"desc" : "conn63",
			"threadId" : "0x7f3f851a3700",
			"connectionId" : 63,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824743,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60493",
			"desc" : "conn71",
			"threadId" : "0x7f3f855a7700",
			"connectionId" : 71,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824739,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60489",
			"desc" : "conn67",
			"threadId" : "0x7f3f850a2700",
			"connectionId" : 67,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824741,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60499",
			"desc" : "conn77",
			"threadId" : "0x7f3f859ab700",
			"connectionId" : 77,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824733,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60497",
			"desc" : "conn75",
			"threadId" : "0x7f3f854a6700",
			"connectionId" : 75,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824725,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60495",
			"desc" : "conn73",
			"threadId" : "0x7f3786dae700",
			"connectionId" : 73,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824727,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60501",
			"desc" : "conn79",
			"threadId" : "0x7f3f853a5700",
			"connectionId" : 79,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824728,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60483",
			"desc" : "conn65",
			"threadId" : "0x7f3786eaf700",
			"connectionId" : 65,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824736,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60496",
			"desc" : "conn74",
			"threadId" : "0x7f3786fb0700",
			"connectionId" : 74,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824738,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60490",
			"desc" : "conn68",
			"threadId" : "0x7f37870b1700",
			"connectionId" : 68,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824742,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60488",
			"desc" : "conn66",
			"threadId" : "0x7f37872b3700",
			"connectionId" : 66,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824732,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60498",
			"desc" : "conn76",
			"threadId" : "0x7f3f85cae700",
			"connectionId" : 76,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824730,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60491",
			"desc" : "conn69",
			"threadId" : "0x7f3f85aac700",
			"connectionId" : 69,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824729,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60487",
			"desc" : "conn64",
			"threadId" : "0x7f3f85daf700",
			"connectionId" : 64,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824734,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60500",
			"desc" : "conn78",
			"threadId" : "0x7f3f856a8700",
			"connectionId" : 78,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824731,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60502",
			"desc" : "conn80",
			"threadId" : "0x7f3f852a4700",
			"connectionId" : 80,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 824737,
			"active" : false,
			"op" : "insert",
			"ns" : "",
			"insert" : {
 
			},
			"client" : "10.61.157.244:60503",
			"desc" : "conn81",
			"threadId" : "0x7f3f857a9700",
			"connectionId" : 81,
			"locks" : {
				"^test" : "W"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		}
	]
}



 Comments   
Comment by Daniel Pasette (Inactive) [ 18/Apr/14 ]

This is going to change a lot in the next release, so I don't think we're going to put work into it now, though it's confusing.

Comment by Scott Hernandez (Inactive) [ 18/Apr/14 ]

TLTR: The LockState doesn't have the desired locking state when it is pending, so non-yielded writes show up as queued reads (no matter the lock state they desire).

The issue is due to the fact the internal lock state doesn't set the thread local until after the lock transitions into the active state (not pending) so it reports as not-a-write via suggestYieldMicros, which is what the GlobalLockServerStatusSection uses to report the queue numbers. An easy fix would be to change the reporting to use a new function other than suggstYieldMicros to count the desired lock state which we will have to store in the LockState – we don't currently have the desired state when it is pending.

I'm inclined to re-write this issue as an improvement but really I think users want to report operation locking (based on the operation, like an insert/update/remove), not the underlying lock states (which we report now).

Changing these current metrics could negatively affect monitoring, alerts and people's current understanding of their system behavior.

This is not a regression, nor 2.6 only, as 2.4 behaved the same way, and still does.

Comment by Alexander Komyagin [ 16/Apr/14 ]

I can repro it with 10 bulk threads easily both on 2.6 and 2.4.5 shells, for bulk and non-bulk inserts:

for i in `seq 1 10`; do echo "arr=[]; for(i=0;i<1000;i++) {arr.push({x:i,val:Math.ceil( Math.random()*1000000)})}; while(true) {db.test.insert(arr)}" | mongo & done

for i in `seq 1 10`; do echo "while(true) {db.test.insert({x:1,val:Math.ceil( Math.random()*1000000)})}" | mongo & done

Comment by Alexander Komyagin [ 16/Apr/14 ]

I was performing single inserts of docs (in 20 threads), docs were like {foo:1,bar:2}. Should be trivial to repro

Comment by Greg Studer [ 16/Apr/14 ]

Hmm... I assume this is because inserts are coming in as commands, which are basically queries.

EDIT: Discussed with milkie, we'd like to dig deeper - what kind of inserts are you performing (batch size, what they contain) and what indexes exist? Think this could also be a side-effect of the new optimistic index key generation.

Or alternately a .js test would be great if this is nontrivial.

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