update using $cmd query is slow when document is bigger than ~500 bytes

[Tomaz Beltram]

I am using mongodb 3.2 with Poco:MongoDB client. I noticed strange delay of ~40ms with the update command of bigger documents. I was not able to reproduce this behaviour with the mongoshell. Below are the systemLog.verbosity:2 traces for the update command. The delay is after the third line, before actual execution of the update. Any ideas why and how to avoid it?

2016-11-25T15:55:54.423+0100 D QUERY    [conn1] Running query: query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D) } sort: {} projection: {} ntoreturn=1
2016-11-25T15:55:54.423+0100 D QUERY    [conn1] Using idhack: query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D) } sort: {} projection: {} ntoreturn=1
2016-11-25T15:55:54.424+0100 I COMMAND  [conn1] query eds_ng.Object query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D) } planSummary: IDHACK ntoreturn:1 ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:964 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms
2016-11-25T15:55:54.463+0100 D COMMAND  [conn1] run command eds_ng.$cmd { update: "Object", updates: [ { q: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D), rev: 4 }, u: { consistency: { checksum: "CRC-32", value: "c131a171" }, domain: { meta: "000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000..." }, internal: { container_id: BinData(4, 308E9D96EEEC4BCA907A946C6341CBF9), has_binary_meta: false, state: "transferred", state_updated: new Date(1480085754424), uploaded_size: 9 }, static: { content_type: "", created: new Date(1480085753994), name: "testfile", size: 9, tenant: "eds_ng", uploaded: new Date(1480085754424) }, processing: { data: [], meta: [] }, rev: 5 } } ] }
2016-11-25T15:55:54.463+0100 D QUERY    [conn1] Relevant index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 1, key: { _id: 1 }, name: "_id_", ns: "eds_ng.Object" }
2016-11-25T15:55:54.463+0100 D QUERY    [conn1] Relevant index 1 is kp: { rev: 1.0 } name: 'rev_1' io: { v: 1, key: { rev: 1.0 }, name: "rev_1", ns: "eds_ng.Object" }
2016-11-25T15:55:54.463+0100 D QUERY    [conn1] Only one plan is available; it will be run but will not be cached. query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D), rev: 4 } sort: {} projection: {}, planSummary: IXSCAN { _id: 1 }
2016-11-25T15:55:54.464+0100 I WRITE    [conn1] update eds_ng.Object query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D), rev: 4 } update: { consistency: { checksum: "CRC-32", value: "c131a171" }, domain: { meta: "000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000..." }, internal: { container_id: BinData(4, 308E9D96EEEC4BCA907A946C6341CBF9), has_binary_meta: false, state: "transferred", state_updated: new Date(1480085754424), uploaded_size: 9 }, static: { content_type: "", created: new Date(1480085753994), name: "testfile", size: 9, tenant: "eds_ng", uploaded: new Date(1480085754424) }, processing: { data: [], meta: [] }, rev: 5 } keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keyUpdates:1 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-11-25T15:55:54.464+0100 I COMMAND  [conn1] command eds_ng.$cmd command: update { update: "Object", updates: [ { q: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D), rev: 4 }, u: { consistency: { checksum: "CRC-32", value: "c131a171" }, domain: { meta: "000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000..." }, internal: { container_id: BinData(4, 308E9D96EEEC4BCA907A946C6341CBF9), has_binary_meta: false, state: "transferred", state_updated: new Date(1480085754424), uploaded_size: 9 }, static: { content_type: "", created: new Date(1480085753994), name: "testfile", size: 9, tenant: "eds_ng", uploaded: new Date(1480085754424) }, processing: { data: [], meta: [] }, rev: 5 } } ] } keyUpdates:0 writeConflicts:0 numYields:0 reslen:55 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms

[Tomaz Beltram]

On Saturday, November 26, 2016 at 12:24:25 AM UTC+1, Tomaz Beltram wrote:

I am using mongodb 3.2 with Poco:MongoDB client. I noticed strange delay of ~40ms with the update command of bigger documents. I was not able to reproduce this behaviour with the mongoshell. Below are the systemLog.verbosity:2 traces for the update command. The delay is after the third line, before actual execution of the update. Any ideas why and how to avoid it?

2016-11-25T15:55:54.423+0100 D QUERY    [conn1] Running query: query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D) } sort: {} projection: {} ntoreturn=1
2016-11-25T15:55:54.423+0100 D QUERY    [conn1] Using idhack: query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D) } sort: {} projection: {} ntoreturn=1
2016-11-25T15:55:54.424+0100 I COMMAND  [conn1] query eds_ng.Object query: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D) } planSummary: IDHACK ntoreturn:1 ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:964 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms
2016-11-25T15:55:54.463+0100 D COMMAND  [conn1] run command eds_ng.$cmd { update: "Object", updates: [ { q: { _id: BinData(4, 28F23E211D9B48BF8EABA8322F04CA7D), rev: 4 }, u: { consistency: { checksum: "CRC-32", value: "c131a171" }, domain: { meta: "000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000..." }, internal: { container_id: BinData(4, 308E9D96EEEC4BCA907A946C6341CBF9), has_binary_meta: false, state: "transferred", state_updated: new Date(1480085754424), uploaded_size: 9 }, static: { content_type: "", created: new Date(1480085753994), name: "testfile", size: 9, tenant: "eds_ng", uploaded: new Date(1480085754424) }, processing: { data: [], meta: [] }, rev: 5 } } ] }

FYI: I figured it out. The update command starts at the third line and has to wait for the previous update of the same document to finish. I was able to avoid the delay by selectively updating just the changed elements with $set.