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

Queries/getmores generate write lock stats in system.profile

    XMLWordPrintable

Details

    • ALL

    Description

      After investigating this more, and discussing this with others, here is what I've found:

      • The entries (lock time specifically) in the profile collection include the time taken to write to the system.profile collection, in addition to the orig. op
      • We do not separate the user operation from the system logging/profiling.
      • This is confusing for read-only operations like queries and getmores, since they never need a write lock
      • It would be good if we can get trace or separate levels of reporting for the various stages of the whole operation so it is clear what the cost of the user operation would be without profiling

      Originally I had expected, as did the users who noticed this, that "lockStats.timeAcquiringMicros.w" should be zero since it was a read-only operation.

      {
      	"ts" : ISODate("2012-09-21T18:50:05.301Z"),
      	"op" : "query",
      	"ns" : "l.c",
      	"query" : {
      		
      	},
      	"cursorid" : NumberLong("168104220735197301"),
      	"ntoreturn" : 0,
      	"ntoskip" : 0,
      	"nscanned" : 102,
      	"keyUpdates" : 0,
      	"numYield" : 0,
      	"lockStats" : {
      		"timeLockedMicros" : {
      			"r" : NumberLong(73),
      			"w" : NumberLong(0)
      		},
      		"timeAcquiringMicros" : {
      			"r" : NumberLong(3),
      			"w" : NumberLong(2)
      		}
      	},
      	"nreturned" : 101,
      	"responseLength" : 17815,
      	"millis" : 0,
      	"client" : "127.0.0.1",
      	"user" : ""
      }
      {
      	"ts" : ISODate("2012-09-21T18:50:05.425Z"),
      	"op" : "getmore",
      	"ns" : "l.c",
      	"cursorid" : NumberLong("168104220735197301"),
      	"ntoreturn" : 0,
      	"keyUpdates" : 0,
      	"numYield" : 0,
      	"lockStats" : {
      		"timeLockedMicros" : {
      			"r" : NumberLong(8781),
      			"w" : NumberLong(0)
      		},
      		"timeAcquiringMicros" : {
      			"r" : NumberLong(11),
      			"w" : NumberLong(5)
      		}
      	},
      	"nreturned" : 865,
      	"responseLength" : 150008,
      	"millis" : 8,
      	"client" : "127.0.0.1",
      	"user" : ""
      }
      
      

      Attachments

        Issue Links

          Activity

            People

              backlog-server-query Backlog - Query Team (Inactive)
              scotthernandez Scott Hernandez
              Votes:
              3 Vote for this issue
              Watchers:
              10 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: