Correct usage of options array on executeBulkWrite

[gmsantos]

Description

Before version 1.4 I used to execute a bulk write for a heavy process with write concern 0. This process is chunked in some parts to avoid memory size exhaust in big MongoDB\Driver\BulkWrite objects.

$manager = new MongoDB\Driver\Manager();

for ($j = 0; $j <= 40; $j++) {
    $bulkWrite = new MongoDB\Driver\BulkWrite(['ordered' => false]);

    for ($i=0; $i < 90000; $i++) {
        $bulkWrite->update(
            [
                '_id' => rand(88888888, 99999999)
            ],
            [
                '$set' => [
                    'name' => 'GMSantos', 
                    'rand' => rand(0, 100000)
                ]
            ],
            [
                'upsert' => true
            ]
        );
    }

    $manager->executeBulkWrite(
        'db.some_collection',
        $bulkWrite,
        new MongoDB\Driver\WriteConcern(0)
    );
}

After upgrade to 1.4 driver, I noticed that chunks started to have a big delay in almost an hour, like writeConcern(0) was ignored. Even using the new options array this delay persisted:

$manager->executeBulkWrite(
    'db.some_collection',
    $this->getChunkedBulkWrite(),
    ['writeConcern' => new MongoDB\Driver\WriteConcern(0)]
);

But skipping the third argument or using a non associative array eliminated that delay:

$manager->executeBulkWrite(
    'db.some_collection',
    $this->getChunkedBulkWrite(),
    [new MongoDB\Driver\WriteConcern(0)] 
);

// or 

$manager->executeBulkWrite(
    'db.some_collection',
    $this->getChunkedBulkWrite()
);

What is the correct usage of $options argument? Is write concern 0 the default for executeBulkWrite on Manager?

Environment

mongodb -> 1.4.1
libbson bundled version => 1.9.2
libmongoc bundled version => 1.9.2
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => disabled
libmongoc SASL => disabled
libmongoc compression => enabled
libmongoc compression snappy => disabled
libmongoc compression zlib => enabled

[jmikola]

Would you mind registering a CommandSubscriber (following the steps in the APM tutorial) and sharing information from the CommandStartedEvent objects? If you may have multiple commands running in the process, you can use CommandStartedEvent::getCommandName() to check for "insert" before dumping the getCommand() output to share. That should show us the command document being sent by the driver from your script. Feel free to collect this output for all three options variations to compare.

As an aside, if you can capture trace logs (using the mongodb.debug INI setting) output for some of these bulk write operations, that'd be helpful as well. That output may end up being quite large, so feel free to attach compressed archives with those logs. Again, one log per options variation would be helpful to compare.

For all variations, it'd be best if you used the same insertion data/payload.

[gmsantos]

Sorry for the delay. I changed how to generate the insertion payload with the variations and pushed all code to https://github.com/gmsantos/bulkwrite

Also added the query listener and tried to dump into a file, but the generated output for getCommand() is really large (more than 170gb of a serialized json until my disk is full). Is there something smaller than getCommand() for debugging purposes?

[gmsantos]

I disabled the listener in a test and the output of mongodb.debug is smaller. Is that enough for comparison between variations?

[jmikola]

Before I get into an explanation, I'd like to address your previous question:

What is the correct usage of $options argument? Is write concern 0 the default for executeBulkWrite on Manager?

The documentation on MongoDB\Driver\Manager::executeBulkWrite() is accurate. In PHP driver 1.3.x and earlier, the third argument was an optional WriteConcern object. In 1.4.0+, the third argument is now an options array that accepts a "writeConcern" option. For backwards compatibility, a WriteConcern object is still accepted.

When you were passing [new MongoDB\Driver\WriteConcern(0)] as the third argument, the driver ignored the array key 0, found nothing in a "writeConcern" key, and defaulted to the Manager object's write concern. Since your connection string does not specify a custom write concern, the driver defaults to { w: 1 } (i.e. acknowledged).

---

Thanks very much for the repository and bundled example scripts. Noting that you were using MongoDB 3.4, I can offer the following explanation:

PHP driver 1.3.x uses libmongoc 1.8, which is compatible with server versions up to 3.4. The code path for executing a bulk write is _mongoc_write_command() in mongoc-write-command.c. This function can execute writes in one of two ways:

• Write commands: MongoDB 2.6 introduced insert, update, and delete commands, which allow one or more writes of the same type to be executed in the same command. At the wire protocol layer (i.e. network level), these commands are executed using the OP_QUERY message.
• Historically, MongoDB has supported OP_INSERT, OP_UPDATE, and OP_DELETE wire protocol messages. Since all commands in MongoDB return a response, most drivers still use these legacy message formats for issuing unacknowledged writes. OP_INSERT is also the only message that allows multiple documents to be specified in the same message.

The above is also discussed in the server manual's documentation for request opcodes.

As it relates to your application, you're executing a bulk write (i.e. one or more write operations) with an unacknowledged write concern. This instructs libmongoc to use the legacy wire protocol messages. Instead of batching your 9,000 updates into 9 update commands (according to maxWriteBatchSize for MongoDB 3.4), the driver issues 9,000 separate OP_UPDATE messages. Each of those is its own network message. While the individual "commands" themselves are shorter in duration (see: CommandSucceededEvent::getDurationMicros()), the sum of their durations greatly exceeds the sum of 9 update commands with an acknowledged write concern.

Given that, any time savings you might have expected with an unacknowledged write concern are forfeited. Note that this is specific to bulk updates and deletes. If you were benchmarking bulk inserts, I expect you'd find that unacknowledged inserts may be faster. Batching between OP_INSERT and the insert command would be comparable, and OP_INSERT would not require acknowledgement.

All of that said, MongoDB 3.6 introduced a new OP_MSG wire protocol message, which the driver can use to execute write commands (i.e. insert, update, delete) with unacknowledged write concerns. If you look at the new code path for _mongoc_write_command_execute() in mongoc-write-command.c in libmongoc 1.9 (PHP driver 1.4.x), you can see that OP_MSG takes priority over the old logic that decided between commands or legacy messages for 3.4 and earlier servers.

In summary, you can do one of two things:

• Upgrade to MongoDB 3.6 to take advantage of OP_MSG and continue using unacknowledged write concerns
• Continue using MongoDB 3.4 and revert to using an acknowledged write concern (the default)

---

While running your scripts with APM logging, I noticed that each update operation was reporting the full command document (with 9000 update statements) as its own. This effectively produced 9000 times more output than would normally be expected. The bug is a result of libmongoc failing to produce the appropriate synthetic command document when upconverting the legacy OP_UPDATE message. I opened CDRIVER-2573 to track that issue in libmongoc.

Without that bug, APM should have produced less log output than mongodb.debug, as the latter ends up tracing many functional calls and logs the full command payload multiple times across various layers (e.g. command serialization, socket communication).

[gmsantos]

Thank you for the explanation. Since mLab doesn't offer mongodb 3.6 yet, I changed the code to use an acknowledged write concern.