[SERVER-13121] ninserted is one too few, for write command batch inserts Created: 10/Mar/14  Updated: 10/Dec/14  Resolved: 20/Mar/14

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

Type: Bug Priority: Major - P3
Reporter: Peter Garafano (Inactive) Assignee: Eric Milkie
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive BulkLoadTest.r3.zip     JPEG File ninserted.capture.jpg    
Issue Links:
Duplicate
duplicates SERVER-13163 WriteBatchExecutor doesn't handle Pag... Closed
Operating System: ALL
Participants:

 Description   

When using bulk insert on 2.6.0-rc1, the log shows "ninserted:999" when the driver reports 1000 documents inserted during the operation. I have verified that 1000 documents were inserted into the collection by doing a .count() on the collection pre and post insert.

I can supply a sample Java program if needed.



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

A fix for this was committed last night to the 2.6 branch, as part of SERVER-13165. We were starting out with -1 inserts, which is why the log message was off by one.

Comment by Eric Milkie [ 10/Mar/14 ]

The behavior of inserts changed with a commit made this morning (SERVER-12762), so the insertion counting may be working better after that change is visible in the latest server build. The new behavior will be that each insert of a batch will be profiled independently (with ninserted=1), and then you will see a final profile of the command (where numYields might be greater than 0, and where the lock hold time will be accrued, but where ninserted will be 0 since they were already counted individually). This behavior will more closely match the behavior for batch updates and deletes, where each one is profiled individually.

Comment by Jeffrey Yemin [ 10/Mar/14 ]

I moved this issue out of the SERVER project prematurely. Stepping through the Java driver code, I can see that the splitting is happening correctly and the insert command is correctly returning { n : 1000 }. Furthermore, if I dial the batch size in the test program down to 1, I see this in the server logs:

2014-03-10T16:33:54.980-0400 [conn6] run command BulkLoadTestDb.$cmd { insert: "BulkLoadTestCol", ordered: false, documents: [ { _id: { PR: -1561771309, LO: 415607983, t: 475714156 }, msrs: { D: 842132154, T: 0.6500416099177782, U: 0.6286249120742459, V: 1246672358 } } ] }
2014-03-10T16:33:54.981-0400 [conn6] insert BulkLoadTestDb.BulkLoadTestCol ninserted:0 keyUpdates:0 numYields:0 locks(micros) w:28 0ms

My conclusion is that the server is logging incorrectly.

Comment by Jeffrey Yemin [ 10/Mar/14 ]

Thanks, I'll step through and see what's going on.

Comment by Peter Garafano (Inactive) [ 10/Mar/14 ]

Latest output from mongod:

2014-03-10T16:12:42.064-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:67380 110ms
2014-03-10T16:12:42.065-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 112ms
2014-03-10T16:12:44.274-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:57072 111ms
2014-03-10T16:12:44.275-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 114ms
2014-03-10T16:12:44.769-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:103976 111ms
2014-03-10T16:12:44.769-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 113ms
2014-03-10T16:12:46.068-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:51939 114ms
2014-03-10T16:12:46.069-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 116ms
2014-03-10T16:12:46.884-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:54197 111ms
2014-03-10T16:12:46.885-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 112ms
2014-03-10T16:12:47.377-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:98924 103ms
2014-03-10T16:12:47.378-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 105ms
2014-03-10T16:12:47.748-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:99686 101ms
2014-03-10T16:12:47.749-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 102ms
2014-03-10T16:12:47.934-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:61922 116ms
2014-03-10T16:12:47.935-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 118ms
2014-03-10T16:12:48.834-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:63028 141ms
2014-03-10T16:12:48.835-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 143ms
2014-03-10T16:12:49.888-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:55265 115ms
2014-03-10T16:12:49.889-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 117ms
2014-03-10T16:12:50.796-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:83946 155ms
2014-03-10T16:12:50.799-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 159ms
2014-03-10T16:12:50.933-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:107697 109ms
2014-03-10T16:12:50.933-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 111ms
2014-03-10T16:12:51.422-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:99769 101ms
2014-03-10T16:12:51.423-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 103ms
2014-03-10T16:12:51.769-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:55171 106ms
2014-03-10T16:12:51.769-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 108ms
2014-03-10T16:12:52.493-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:103295 104ms
2014-03-10T16:12:52.494-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 106ms
2014-03-10T16:12:52.681-0400 [conn2] insert BulkLoadTestDb.BulkLoadTestCol ninserted:999 keyUpdates:0 numYields:0 locks(micros) w:54654 116ms
2014-03-10T16:12:52.682-0400 [conn2] command BulkLoadTestDb.$cmd command:

{ $msg: "query not recording (too large)" }

keyUpdates:0 numYields:0 reslen:40 118ms

Using Java driver 2.12.0-rc1

Calls to getInsertedCount() return 1000.

Comment by Jeffrey Yemin [ 10/Mar/14 ]

This looks to be a duplicate of JAVA-1119, which has been fixed and released in 2.12.0-rc1. Would you mind re-testing with that version (assuming you're not already using it.)?

Comment by Jeffrey Yemin [ 10/Mar/14 ]

Moving this issue to the JAVA driver.

Comment by Peter Garafano (Inactive) [ 10/Mar/14 ]

milkie I was under the impression the driver wouldn't split as long as the batch size is <= 1000. It is possible that the driver is splitting into 999 and 1. Any ideas on how to confirm this?

I attached both a screenshot of the output I see, and a program to generate it.

Comment by Eric Milkie [ 10/Mar/14 ]

Sorry, that ticket I realize is for the shell. Java driver may have a similar issue. When you say "the log shows", are you seeing just the slowms logging? If the java driver splits the batch into 999 and 1, the batch of 1 may be too fast to show up in the log.

Comment by Eric Milkie [ 10/Mar/14 ]

See linked ticket.

Comment by Eric Milkie [ 10/Mar/14 ]

I believe you are hitting this bug that was just fixed in the shell in master.

Comment by J Rassi [ 10/Mar/14 ]

peter.garafano: yes, could you please attach to this ticket the source file of the program that reproduces this issue? Thanks.

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