[SERVER-29393] system.profile 'timeAcquiringMicros' value is much higher than the actual time spent Created: 27/May/17  Updated: 27/Oct/23  Resolved: 02/Jun/17

Status: Closed
Project: Core Server
Component/s: Concurrency
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: rocky Assignee: Mark Agarunov
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

hi all:
My mongo version is '3.2.10' and use WT engine, My server is slow load. The collection only 14 document, but query spent "millis" : 1632. Developer confirm response only spent 298ms .
This probleem is similer https://jira.mongodb.org/browse/SERVER-20386 https://jira.mongodb.org/browse/SERVER-21305

Pleace see below slow sql example,

{
	"op" : "query",
	"ns" : "XXX.XXX",
	"query" : {
		"find" : "XXX",
		"filter" : {
			"articleType" : 2,
			"issueTime" : {
				"$lte" : 1495817044
			},
			"status" : {
				"$lt" : 3
			}
		},
		"batchSize" : NumberLong(0),
		"projection" : {
			"_id" : 1
		},
		"sort" : {
			"time" : -1
		}
	},
	"keysExamined" : 7,
	"docsExamined" : 7,
	"hasSortStage" : true,
	"cursorExhausted" : true,
	"keyUpdates" : 0,
	"writeConflicts" : 0,
	"numYield" : 0,
	"locks" : {
		"Global" : {
			"acquireCount" : {
				"r" : NumberLong(2)
			},
			"acquireWaitCount" : {
				"r" : NumberLong(1)
			},
			{color:red}"timeAcquiringMicros" : {
				"r" : NumberLong(1632495)
			}{color}
		},
		"Database" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		},
		"Collection" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		}
	},
	"nreturned" : 0,
	"responseLength" : 138,
	"protocol" : "op_query",
	{color:red}"millis" : 1632,{color}
	"execStats" : {
		"stage" : "CACHED_PLAN",
		"nReturned" : 0,
		{color:red}"executionTimeMillisEstimate" : 0,{color}
		"works" : 0,
		"advanced" : 0,
		"needTime" : 0,
		"needYield" : 0,
		"saveState" : 0,
		"restoreState" : 0,
		"isEOF" : 1,
		"invalidates" : 0,
		"inputStage" : {
			"stage" : "PROJECTION",
			"nReturned" : 0,
			"executionTimeMillisEstimate" : 0,
			"works" : 10,
			"advanced" : 0,
			"needTime" : 9,
			"needYield" : 0,
			"saveState" : 0,
			"restoreState" : 0,
			"isEOF" : 1,
			"invalidates" : 0,
			"transformBy" : {
				"_id" : 1
			},
			"inputStage" : {
				"stage" : "SORT",
				"nReturned" : 0,
				"{color:red}executionTimeMillisEstimate" : 0,{color}
				"works" : 10,
				"advanced" : 0,
				"needTime" : 9,
				"needYield" : 0,
				"saveState" : 0,
				"restoreState" : 0,
				"isEOF" : 1,
				"invalidates" : 0,
				"sortPattern" : {
					"time" : -1
				},
				"memUsage" : 0,
				"memLimit" : 33554432,
				"inputStage" : {
					"stage" : "SORT_KEY_GENERATOR",
					"nReturned" : 0,
					{color:red}"executionTimeMillisEstimate" : 0,{color}
					"works" : 9,
					"advanced" : 0,
					"needTime" : 8,
					"needYield" : 0,
					"saveState" : 0,
					"restoreState" : 0,
					"isEOF" : 1,
					"invalidates" : 0,
					"inputStage" : {
						"stage" : "FETCH",
						"filter" : {
							"$and" : [
								{
									"articleType" : {
										"$eq" : 2
									}
								},
								{
									"issueTime" : {
										"$lte" : 1495817044
									}
								}
							]
						},
						"nReturned" : 0,
						"executionTimeMillisEstimate" : 0,
						"works" : 8,
						"advanced" : 0,
						"needTime" : 7,
						"needYield" : 0,
						"saveState" : 0,
						"restoreState" : 0,
						"isEOF" : 1,
						"invalidates" : 0,
						"docsExamined" : 7,
						"alreadyHasObj" : 0,
						"inputStage" : {
							"stage" : "IXSCAN",
							"nReturned" : 7,
							"executionTimeMillisEstimate" : 0,
							"works" : 8,
							"advanced" : 7,
							"needTime" : 0,
							"needYield" : 0,
							"saveState" : 0,
							"restoreState" : 0,
							"isEOF" : 1,
							"invalidates" : 0,
							"keyPattern" : {
								"status" : 1
							},
							"indexName" : "status_1",
							"isMultiKey" : false,
							"isUnique" : false,
							"isSparse" : false,
							"isPartial" : false,
							"indexVersion" : 1,
							"direction" : "forward",
							"indexBounds" : {
								"status" : [
									"[-inf.0, 3)"
								]
							},
							"keysExamined" : 7,
							"dupsTested" : 0,
							"dupsDropped" : 0,
							"seenInvalidated" : 0
						}
					}
				}
			}
		}
	},
	"ts" : ISODate("2017-05-26T16:44:06.370Z"),
	"client" : "XXXX",
	"allUsers" : [
		{
			"user" : "XX",
			"db" : "XX"
		}
	],
	"user" : "XXXX"



 Comments   
Comment by rocky [ 03/Jun/17 ]

Hi, Mark
The following is slow sql log:
2017-06-03T21:15:53.966+0800 I COMMAND [conn8273928] command liveplatform.guild_article_issue command: find { find: "guild_article_issue", filter: { articleType: 1, issueTime:

{ $lte: 1496495750 }

, status:

{ $lt: 3 }

}, batchSize: 0, projection:

{ _id: 1 }

, sort:

{ time: -1 }

} planSummary: IXSCAN

{ status: 1.0 }

cursorid:635957131090 keysExamined:7 docsExamined:7 hasSortStage:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:138 locks:{ Global: { acquireCount:

{ r: 2 }

, acquireWaitCount:

{ r: 1 }

, timeAcquiringMicros:

{ r: 3928866 }

}, Database: { acquireCount:

{ r: 1 }

}, Collection: { acquireCount:

{ r: 1 }

} } protocol:op_query 3929ms
My questions:
1.Just a small collection that include 14 documents ,unexpectedly, a query spent 3929ms
2.Developer confirm that the query the actual time spent below 3929ms.

Thanks,
Rocky

Comment by Mark Agarunov [ 02/Jun/17 ]

Hello 514154167@qq.com,

Thank you for providing the files. Looking over the data and logs, it appears that there may be a miscommunication as to the metric values. The timeAcquiringMicros value is in microseconds, while the millis metric is in milliseconds.

From your initial example, the values are

"millis" : 1632,
"timeAcquiringMicros" : {"r" : NumberLong(1632495)}

If you convert the timeAcquiringMicros to milliseconds:

 1632495 / 1000 = 1632.495

the values match as expected.

Thanks,
Mark

Comment by rocky [ 02/Jun/17 ]

hi,Mark
I have finished uploading the files.
Thanks,
Rocky

Comment by Mark Agarunov [ 01/Jun/17 ]

Hello 514154167@qq.com,

Thank you for providing this information. Unfortunately, without the diagnostic data and complete log files (Including the startup of mongod), the behavior is difficult to diagnose. I've created a secure upload portal so that you can upload these files privately. Any files uploaded to the portal can only be accessed by you or a MongoDB employee.

To reitterate, please upload the following:

  • The complete and entire log files from mongod
  • Please archive and upload the complete $dbPath/diagnostic.data directory.

Additionally, I'd like to clarify what the 268ms response you mentioned is related to. Is this from the application or from MongoDB?

Thanks,
Mark

Comment by rocky [ 01/Jun/17 ]

hi Mark,
Thank you for your attention.
Now, I can provide following:
1.One detailed document , It is similer other 13 documents.
2.The complete logs from mongod when this issue is present.

Thanks & Best regards,
Rocky

1.one document:

{
"_id" : ObjectId("591ed735a9218d2f32167fe3"), 
"articleType" : 1,
"applyCount" : 0, 
"guildMobi" : 0, 
"starLevel" : 0, 
"failType" : 0, 
"failTime" : NumberLong("4638873600"), 
"canDiscuss" : 0, 
"discussMobi" : { "min" : 0, "max" : 0 },
"issueType" : 1, 
"issueTime" : 1495193700, 
"isTop" : 1, 
"title" : "新公会成长指南", 
"content" : "<p class=\"MsoListParagraph\" style=\"margin-left: 48px; text-align: left;\"><span style=\"font-size: 20px; color: rgb(255, 0, 0);\">一、获取官方一手信息<br/></span></p><p class=\"MsoListParagraph\" style=\"margin-left: 48px; text-align: left;\"><span style=\"font-size: 16px;\">&nbsp; &nbsp; 新公会入驻成功后,请移步加入官方新公会XXX,可向群管理咨询公会的专属对</span></p><p class=\"MsoListParagraph\" style=\"margin-left: 48px; text-align: left;\"><span style=\"font-size: 16px;\">&nbsp; &nbsp; 接运营。</span><br/></p><p style=\"text-align:left\"><span style=\"font-size: 19px\">&nbsp;</span></p><p class=\"MsoListParagraph\" style=\"margin-left:48px;text-align:left\"><span style=\"font-size:20px;color:red\">二、<span style=\"font-variant-numeric: normal;font-stretch: normal;font-size: 9px;line-height: normal;font-family: &#39;Times New Roman&#39;\">&nbsp;&nbsp; </span>熟悉基础业务信息</span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left\"><span style=\"font-size: 16px;\"><strong>1)<span style=\"font-variant-numeric: normal; font-weight: normal; font-stretch: normal; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span></strong><strong>主播加入公会操作流程</strong></span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left\"><span style=\"font-size: 16px;\"><strong><a href=\"sssss/1kVqkgtx\" target=\"_self\">如何成为公会XXX</a></strong></span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left\"><span style=\"font-size: 16px;\"><strong>2)<span style=\"font-variant-numeric: normal; font-weight: normal; font-stretch: normal; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span></strong><strong>公会主播问题</strong></span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left\"><span style=\"font-size: 16px;\"><strong>&nbsp;</strong><strong><a href=\"https://aaaaa/s/1cLAAD4\" target=\"_self\">公会主播XXXX)</a></strong></span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left\"><span style=\"font-size: 16px;\"><strong>3)<span style=\"font-variant-numeric: normal; font-weight: normal; font-stretch: normal; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span></strong><strong>经纪人转公司及公司对公业务</strong></span></p><p style=\"margin-left:80px;text-align:left\"><span style=\"font-size: 16px;\"><strong>A.</strong>经纪人转公司业务请联系(summer:XXXX)</span></p><p style=\"margin-left:32px;text-indent:47px\"><span style=\"font-size: 16px;\"><strong><span style=\"font-family: DengXian; color: black;\">B.</span></strong><span style=\"font-family: DengXian; color: black;\">对公要求:对公结结算申请要求改为:&nbsp;1、流水达标一</span></span><span style=\"font-family: DengXian;\">个月达标&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;2、能提供20份播主身份&nbsp;</span></p><p style=\"margin-left:32px;text-indent:47px\"><span style=\"font-family: DengXian;\">&nbsp; &nbsp;证扫描件(XXX验证播主确实XXX,且等非4级以下播主)+手持身份证片&nbsp;&nbsp;&nbsp;&nbsp;3、</span></p><p style=\"margin-left:32px;text-indent:47px\"><span style=\"font-family: DengXian;\">&nbsp; &nbsp;提供20份线下合同&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;4、提供以上最少XXXX在工作场地的合照</span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left\"><strong><span style=\"font-size: 19px\">4)<span style=\"font-variant-numeric: normal;font-weight: normal;font-stretch: normal;font-size: 9px;line-height: normal;font-family: &#39;Times New Roman&#39;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span></span></strong><strong><span style=\"font-size: 19px\">OBS</span></strong><strong><span style=\"font-size: 19px\">电脑直播问题</span></strong></p><p style=\"margin-left:48px;text-align:left\"><span style=\"font-size:14px;font-family:&#39;MS Mincho&#39;;color:#343434;background:white\">&nbsp;&nbsp;</span><span style=\"font-size: 16px;\"><span style=\"font-family: &quot;MS Mincho&quot;; color: rgb(52, 52, 52); background: white;\">&nbsp; &nbsp; &nbsp; XX官方</span><span style=\"font-family: &quot;Helvetica Neue&quot;; color: rgb(52, 52, 52); background: white;\">OBS</span><span style=\"font-family: &quot;MS Mincho&quot;; color: rgb(52, 52, 52); background: white;\">教程:</span><span style=\"font-family: &quot;Times New Roman&quot;;\"><a href=\"http://aaaaaaa/h5/help/home/obshelp\" target=\"_blank\"><span style=\"font-family: &quot;Helvetica Neue&quot;; color: blue; background: white;\">http://aaaaaaa/h5/help/home/obshelp</span></a></span></span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left\"><strong><span style=\"font-size: 19px\">5)<span style=\"font-variant-numeric: normal;font-weight: normal;font-stretch: normal;font-size: 9px;line-height: normal;font-family: &#39;Times New Roman&#39;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span></span></strong><strong><span style=\"font-size: 19px\">常见技术问题</span></strong></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left;text-indent:0\"><span style=\"font-size: 16px;\">&nbsp;<a href=\"https://aaaaaa/a/1dESFL4H\" target=\"_self\">常见技术问题XXX)</a></span></p><p class=\"MsoListParagraph\" style=\"margin-left:80px;text-align:left;text-indent:0\"><br/></p><p class=\"MsoListParagraph\" style=\"margin-left:48px;text-align:left\"><span style=\"font-size:19px;color:red\">三、<span style=\"font-variant-numeric: normal;font-stretch: normal;font-size: 9px;line-height: normal;font-family: &#39;Times New Roman&#39;\">&nbsp;&nbsp;&nbsp; </span>主动争取推荐资源</span></p><p class=\"MsoListParagraph\" style=\"margin-left:48px;text-align:left;text-indent:0\"><span style=\"color: red; font-size: 16px;\">&nbsp; &nbsp; &nbsp;&nbsp;<a href=\"https://aaaaaa/s/1eS7psMQ\" target=\"_self\">在XXX如何获取推荐资源(密码: XXXX)</a></span></p><p class=\"MsoListParagraph\" style=\"margin-left:48px;text-align:left;text-indent:0\"><br/></p><p class=\"MsoListParagraph\" style=\"margin-left:48px;text-align:left\"><span style=\"font-size:19px;color:red\">四、<span style=\"font-variant-numeric: normal;font-stretch: normal;font-size: 9px;line-height: normal;font-family: &#39;Times New Roman&#39;\">&nbsp;&nbsp;&nbsp; </span>促进播主长线发展</span></p><p><span style=\"font-size:19px;font-family:DengXian;color:black\">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp;<span style=\"font-family: DengXian; color: black; font-size: 16px;\"> 王牌XX项目</span></span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\">&nbsp; &nbsp; &nbsp;1.<span style=\"color: black; font-variant-numeric: normal; font-stretch: normal; font-size: 9px; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span>王牌XXXX优质主播开放的项目,播主和平台签订长期合约,可每</span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; 日获取较强的流量扶持,并且可优先享受XX平台的推荐曝光资源,促进播主</span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; 在XX平台拥有更大的成长空间。</span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\"><br/></span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\">&nbsp; &nbsp; 2.<span style=\"color: black; font-variant-numeric: normal; font-stretch: normal; font-size: 9px; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span>报名XX: </span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; a)<span style=\"color: black; font-variant-numeric: normal; font-stretch: normal; font-size: 9px; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span>公会上月总流水XXX币</span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; b)<span style=\"color: black; font-variant-numeric: normal; font-stretch: normal; font-size: 9px; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span>公会播主达到XXX万</span></p><p style=\"margin-left:32px\"><span style=\"font-family: DengXian; color: black; font-size: 16px;\">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; c)<span style=\"color: black; font-variant-numeric: normal; font-stretch: normal; font-size: 9px; line-height: normal; font-family: &quot;Times New Roman&quot;;\">&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; </span>公会播主XXX违规行为</span></p><p class=\"MsoListParagraph\" style=\"margin-left:48px;text-align:left;text-indent:0\"><span style=\"color: red; font-size: 16px;\">&nbsp;</span></p><p class=\"MsoListParagraph\" style=\"margin-left:48px;text-indent:0\"><span style=\"font-size: 19px\">&nbsp;</span></p><p><br/></p>",
"status" : 2 
}

2.The complete logs

2017-06-01T16:17:04.099+0800 I ACCESS   [conn8082555] Successfully authenticated as principal XXXXX on XXXXX
2017-06-01T16:17:05.667+0800 I NETWORK  [initandlisten] connection accepted from XXXXX:12955 #8082560 (363 connections now open)
2017-06-01T16:17:05.681+0800 I ACCESS   [conn8082560] Successfully authenticated as principal XXXXX on XXXXX
2017-06-01T16:17:05.684+0800 I NETWORK  [conn8082560] end connection XXXXX:12955 (362 connections now open)
2017-06-01T16:17:09.348+0800 I COMMAND  [conn8074181] command XXXXX.guild_article_issue command: find { find: "guild_article_issue", filter: { articleType: 1, issueTime: { $lte: 1496305028 }, status: { $lt: 3 } }, batchSize: 0, projection: { _id: 1 }, sort: { time: -1 } } planSummary: IXSCAN { status: 1.0 } cursorid:636860039020 keysExamined:7 docsExamined:7 hasSortStage:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:138 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 980260 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 980ms
2017-06-01T16:17:09.348+0800 I COMMAND  [conn8073242] command XXXX.guild_article_issue command: find { find: "guild_article_issue", filter: { articleType: 1, issueTime: { $lte: 1496305028 }, status: { $lt: 3 } }, batchSize: 0, projection: { _id: 1 }, sort: { time: -1 } } planSummary: IXSCAN { status: 1.0 } cursorid:636190499097 keysExamined:7 docsExamined:7 hasSortStage:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:138 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1078971 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1079ms
2017-06-01T16:17:09.348+0800 I COMMAND  [conn8073205] command XXX.guild_article_issue command: find { find: "guild_article_issue", filter: { articleType: 1, issueTime: { $lte: 1496305028 }, status: { $lt: 3 } }, batchSize: 0, projection: { _id: 1 }, sort: { time: -1 } } planSummary: IXSCAN { status: 1.0 } cursorid:637044849933 keysExamined:7 docsExamined:7 hasSortStage:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:138 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 761201 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 761ms
2017-06-01T16:17:10.870+0800 I NETWORK  [initandlisten] connection accepted from XXXXX:41181 #8082561 (363 connections now open)
2017-06-01T16:17:10.872+0800 I NETWORK  [initandlisten] connection accepted from XXXXX:41185 #8082562 (364 connections now open)
2017-06-01T16:17:10.873+0800 I NETWORK  [conn8082561] end connection XXXXX:41181 (363 connections now open)

Comment by Mark Agarunov [ 30/May/17 ]

Hello 514154167@qq.com,

Thank you for the report. To better investigate the behavior you've described, I'd like to request some additional information. Could you please provide the following:

  • The complete logs from mongod when this issue is present,
  • An archive (tar or zip) of the $dbpath/diagnostic.data directory,
  • If possible, the dataset you are using when you experience this problem.

Thanks,
Mark

Generated at Thu Feb 08 04:20:44 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.