[SERVER-12926] Insert write commands on documents >=512 bytes not logged with partial doc display Created: 26/Feb/14  Updated: 11/Jul/16  Resolved: 10/Mar/14

Status: Closed
Project: Core Server
Component/s: Diagnostics, Write Ops
Affects Version/s: 2.6.0-rc0
Fix Version/s: 2.6.0-rc2

Type: Bug Priority: Major - P3
Reporter: J Rassi Assignee: Eric Milkie
Resolution: Done Votes: 0
Labels: 26qa
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
depends on SERVER-12762 Batch inserts should be counted and p... Closed
Related
related to SERVER-13054 Statistics from write commands Closed
related to SERVER-13053 createIndexes command should be expli... Closed
Operating System: ALL
Participants:

 Description   

A slow insert of a 512-byte document is logged simply as a "query not recording (too large)" command, containing no information about what kind of write op was slow.

> db.setProfilingLevel(2,-1)
{ "was" : 2, "slowms" : -1, "ok" : 1 }
> var s512 = 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa';
> print(s512.length)
512
> db.foo.insert({foo: s512})
WriteResult({ "nInserted" : 1 })

2014-02-26T17:42:09.055-0500 [conn1] command test.$cmd command: { $msg: "query not recording (too large)" } keyUpdates:0 numYields:0  reslen:40 0ms

To the contrary, a slow insert of a 256-byte document is logged with the truncated document, such that it is clear that the slow operation is an insert:

> db.setProfilingLevel(2,-1)
{ "was" : 2, "slowms" : -1, "ok" : 1 }
> var s256 = 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa';
> print(s256.length)
256
> db.foo.insert({foo: s256})
WriteResult({ "nInserted" : 1 })

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



 Comments   
Comment by Githook User [ 10/Mar/14 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-12926 identify command name explicity in profile text
Branch: master
https://github.com/mongodb/mongo/commit/8b73e5c944903f2ec4c1ae62f0118759e1119da3

Comment by Eric Milkie [ 04/Mar/14 ]

This is related to, and due to, the fact that we're not profiling (nor counting) each individual insert, unlike the update/remove write command paths. If we profiled each individual insert, you could see which one was slow and it would be labeled as an insert.

Comment by Eric Milkie [ 26/Feb/14 ]

Might be related to the way we are managing nested CurOp's for inserts.

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