[SERVER-13054] Statistics from write commands Created: 05/Mar/14  Updated: 10/Dec/14  Resolved: 07/Mar/14

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 2.6.0-rc0
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: Alexander Komyagin Assignee: Eric Milkie
Resolution: Duplicate Votes: 3
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-12762 Batch inserts should be counted and p... Closed
Related
related to SERVER-12858 Return detailed stats from write comm... Backlog
is related to SERVER-12926 Insert write commands on documents >=... Closed
Operating System: ALL
Participants:

 Description   

With the new write commands API, logged operations do not carry a lot of useful statistics at all:

2014-02-26T17:42:02.664-0500 [conn1] command test.$cmd command: { insert: "foo", documents: [ { _id: ObjectId('530e6dbaed9a16e31683ccce'), foo: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa..." } ], ordered: true } keyUpdates:0 numYields:0  reslen:40 0ms

In order for these log messages to be useful (comparable to 2.4), we need to consider adding at least the following:

  • time under write lock
  • number of operations in the batch
  • number of inserted/updated/removed docs


 Comments   
Comment by Eric Milkie [ 07/Mar/14 ]

Please file a new ticket to discuss further stats changes. For the work being done to profile individual batch inserts, follow SERVER-12762

Comment by Eric Milkie [ 07/Mar/14 ]

I forgot that numYield has been around for a while so we can't change it now since it's in everyone's profile collections.

Comment by Eliot Horowitz (Inactive) [ 07/Mar/14 ]

Can't change.

Comment by Eric Milkie [ 07/Mar/14 ]

I will fix the "numYield"; that is a typo.
Changing the historic fields' casing is a decision for eliot; while it does look sloppy now, I am concerned about breaking scripts that scraping this data.

Comment by Thomas Rueckstiess [ 07/Mar/14 ]

I found a couple more issues with the formatting.

Camel casing of n-counters in log file

nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 keyUpdates:0

The "nMatched", "nModified" are in camel case, but nscanned, nreturned, ninserted, ndeleted, ntoreturn ... are all lowercase. Should this be made consistent?

Camel casing of n-counters in system.profile

Same applies to profiling output:

    "nscanned" : 1,
    "nscannedObjects" : 1,
    "nMatched" : 1,
    "nModified" : 1,
    "keyUpdates" : 3,
    "numYield" : 0,

Whatever we decide for log files should be consistent with profiling output.

numYield inconsistent between log and profiler

"numYield" in profiling, but "numYields" (with s) in log file. Can we make that consistent too?

If all this should be a separate ticket, let me know.

Comment by Eric Milkie [ 06/Mar/14 ]

Also, for inserts, this will be a bit more complicated, as each insert in a batch will be profiled but the write lock will be held throughout the entire batch, unlike updates or deletes. So the total write lock hold time and the yield count will need to be added to the profile of the entire insert batch command.

Comment by Eric Milkie [ 06/Mar/14 ]

For updates and deletes, I think you still get everything that was present in 2.4:

> db.foo.update({a:1}, {a:2})
WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 1 })

Server log:

2014-03-06T09:37:17.928-0500 [conn3] update test.foo query: { a: 1.0 } update: { a: 2.0 } nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 keyUpdates:0 numYields:0 locks(micros) w:95 0ms
2014-03-06T09:37:17.928-0500 [conn3] command test.$cmd command: update { update: "foo", updates: [ { q: { a: 1.0 }, u: { a: 2.0 }, multi: false, upsert: false } ], ordered: true } keyUpdates:0 numYields:0  reslen:55 0ms

Note that each individual write can be shown as well as the write command itself (this will not contain very much useful data).

For inserts, the code currently doesn't show the individual inserts, but it will as soon as SERVER-12762 is complete.

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