Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-29393

system.profile 'timeAcquiringMicros' value is much higher than the actual time spent

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Works as Designed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Concurrency
    • Labels:
      None
    • Operating System:
      ALL

      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"
      

        Attachments

          Activity

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: