[SERVER-23266] Add profiling for the batch update/remove summary Created: 21/Mar/16  Updated: 06/Dec/22

Status: Backlog
Project: Core Server
Component/s: Diagnostics, Querying
Affects Version/s: None
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: James Wahlin Assignee: Backlog - Query Optimization
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
is depended on by SERVER-45693 Testing of RWC default application to... Closed
Assigned Teams:
Query Optimization
Participants:

 Description   

We currently write batch update and batch remove summary to the slow diagnostic log. We should write batch summaries to the profiler as well to make consistent.



 Comments   
Comment by James Wahlin [ 16/May/16 ]

Example of bulk write logging post SERVER-23128:
Bulk Insert of 2 Documents

2016-05-16T12:30:00.106-0400 I COMMAND  [conn1] command test.test command: insert { insert: "test", documents: 2, ordered: true } ninserted:2 keysInserted:2 numYields:0 reslen:29 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_command 1ms

Bulk Update of 2 Documents

2016-05-16T12:31:46.388-0400 I WRITE    [conn1] update test.test query: { a: 1.0 } planSummary: COLLSCAN update: { $inc: { c: 3.0 } } keysExamined:0 docsExamined:2 nMatched:1 nModified:1 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 2ms
2016-05-16T12:31:46.388-0400 I WRITE    [conn1] update test.test query: { a: 2.0 } planSummary: COLLSCAN update: { $inc: { c: 1.0 } } keysExamined:0 docsExamined:3 nMatched:0 nModified:0 numYields:0 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } 0ms
2016-05-16T12:31:46.388-0400 I COMMAND  [conn1] command test.$cmd command: update { update: "test", updates: 2, ordered: true } numYields:0 reslen:44 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_command 3ms

Bulk Removal of 2 Documents

2016-05-16T12:35:24.989-0400 I WRITE    [conn1] remove test.test query: { a: 1.0 } planSummary: COLLSCAN keysExamined:0 docsExamined:2 ndeleted:1 keysDeleted:1 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 1ms
2016-05-16T12:35:24.989-0400 I WRITE    [conn1] remove test.test query: { a: 1.0 } planSummary: COLLSCAN keysExamined:0 docsExamined:2 ndeleted:1 keysDeleted:1 numYields:0 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } 0ms
2016-05-16T12:35:24.989-0400 I COMMAND  [conn1] command test.$cmd command: delete { delete: "test", deletes: 2, ordered: true } numYields:0 reslen:29 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_command 2ms

Review of log, profiler and currentOp() output for the above shows:

Operation Individual Logged Batch Logged Individual in Profiler Batch in Profiler Individual in CurrentOp Batch in CurrentOp
Insert No Yes No Yes No Yes
Update Yes Yes Yes No Yes No
Remove Yes Yes Yes No Yes No
Generated at Thu Feb 08 04:02:52 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.