[SERVER-78835] MongoDB truncates currentOP when it shouldn't Created: 10/Jul/23  Updated: 27/Oct/23  Resolved: 02/Oct/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 6.0.6, 5.0.18
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jean da Silva Assignee: Bernard Gorman
Resolution: Works as Designed Votes: 3
Labels: query-director-triage
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Assigned Teams:
Query Execution
Operating System: ALL
Steps To Reproduce:

I followed the same steps for 4.4.22,  5.0.18, and 6.0.6.

 

1. Deploy a standard sharded cluster:

  • 3 shards, with 3 nodes each.
  • Config Server with 3 nodes.
  • 1 mongoS.

2.  Enabled sharding on the following database and collection:

 

[direct: mongos] admin> sh.enableSharding("foo")
{
  ok: 1,
  '$clusterTime': {
    clusterTime: Timestamp({ t: 1689002196, i: 2 }),
    signature: {
      hash: Binary(Buffer.from("cf0525d509f7a3e09de5e41618bee63d5aa05ae7", "hex"), 0),
      keyId: Long("7252848566232678424")
    }
  },
  operationTime: Timestamp({ t: 1689002196, i: 1 })
}

 

 

[direct: mongos] admin> sh.shardCollection("foo.guests", { "_id": 1} )
{
  collectionsharded: 'foo.guests',
  ok: 1,
  '$clusterTime': {
    clusterTime: Timestamp({ t: 1689002207, i: 14 }),
    signature: {
      hash: Binary(Buffer.from("f75203a5e0be5ebe7ffe2f62c9876cc6721aea37", "hex"), 0),
      keyId: Long("7252848566232678424")
    }
  },
  operationTime: Timestamp({ t: 1689002207, i: 10 })
}

 

 

3. Started to insert dummy data with mgeneratejs as follows:

 

$ mgeneratejs '{"name": "$name", "age": "$age", "emails": {"$array": {"of": "$email", "number": 3}}, "even_numbers": {"$inc": {"start": 0, "step": 2}}, "code": {"$join": {"array": ["foo", "bar", "baz"], "sep": "-"}},"badgeId": {"$numberLong": {"min": 100000}},"created": "$now"}' -n 209980000 | mongoimport --uri mongodb://admin:sekret@localhost:6065/foo?authSource=admin --collection guests --mode insert -vvvvvv

 

Observation:

  • Without lowering the profiling level, no truncated messages were generated, likely because they were running below 100ms.
  • But, reducing the profiling level threshold on shards, helped to track those operations and thus display the message:

shard01 [direct: primary] foo> db.setProfilingLevel(1, {slowms: 0})
{
  was: 0,
  slowms: 0,
  ratelimit: 1,
  sampleRate: 1,
  ok: 1,
  lastCommittedOpTime: Timestamp({ t: 1689002603, i: 3000 }),
  '$clusterTime': {
    clusterTime: Timestamp({ t: 1689002603, i: 3000 }),
    signature: {
      hash: Binary(Buffer.from("63498806c7c9e86c8fdf453128b68ac2d4edff64", "hex"), 0),
      keyId: Long("7252848566232678424")
    }
  },
  operationTime: Timestamp({ t: 1689002603, i: 3000 })
}

[...]
{"t":{"$date":"2023-07-10T13:04:31.491-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254487,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:31.556-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":255127,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:31.619-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254441,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:31.690-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254682,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:31.751-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254688,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:31.817-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254798,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:31.891-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254848,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:31.967-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254746,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.031-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254557,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.092-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254712,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.155-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254519,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.222-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254656,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.286-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254613,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.354-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254958,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.418-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254862,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.486-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254983,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.549-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254639,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.611-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":255108,"limit":51200}}

Again, this only happens on 5.0 and 6.0

Following the same steps on 4.4 did not rise such messages.

 

Participants:

 Description   

While running a batch insert on a Sharded Cluster environment, we noticed a shard getting flooded with the following messages:

 

{"t":{"$date":"2023-07-10T13:04:32.092-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254712,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.155-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254519,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.222-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254656,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.286-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254613,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.354-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254958,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.418-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254862,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.486-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254983,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.549-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":254639,"limit":51200}}
{"t":{"$date":"2023-07-10T13:04:32.611-03:00"},"s":"I",  "c":"-",        "id":4760300, "ctx":"conn202","msg":"Gathering currentOp information, operation of size {size} exceeds the size limit of {limit} and will be truncated.","attr":{"size":255108,"limit":51200}}

 

 

However, while analyzing the problem, we saw that since 5.0, mongo changed how currentOP would work, as documented here and{} here.

 

Alongside that, the message itself is not very clear on the limits; Is that on bytes or kilobytes?

I'm assuming it's reporting in bytes, following the reference here from the source code.

 

    // When the currentOp command is run, it returns a single response object containing all current
    // operations; this request will fail if the response exceeds the 16MB document limit. By
    // contrast, the $currentOp aggregation stage does not have this restriction. If 'truncateOps'
    // is true, limit the size of each op to 1000 bytes. Otherwise, do not truncate.
    const boost::optional<size_t> maxQuerySize{truncateOps, 1000};

 

 

If that's correct.

  • Why is it limiting on such a lower threshold, should it be at least 16MB? 1000bytes per the code or  51200bytes per my tests.
    • Also wondering why such divergence. 
  • Additionally, after 5.0; the currentOP() is now built around the $currentOp via aggregation pipeline, which removes the above limitation on the max size of 16MB BSON.
    • Then, the operation itself should not fall into that condition.

 

I've tested that on 4.4.22,  5.0.18, and 6.0.6.

But got those messages only on 5.0.18 and 6.0.6.



 Comments   
Comment by Bernard Gorman [ 02/Oct/23 ]

Hi jean_nsilva@hotmail.com - I hope I've addressed all your questions above, in particular how using the $currentOp aggregation stage directly can avoid these truncation issues. Since the currentOp command is intended to truncate operations - even when internally implemented as an aggregation - and the log messages are only expected on 5.0 and later, I'll close this ticket as Works As Designed.

Comment by Bernard Gorman [ 08/Sep/23 ]

Hi jean_nsilva@hotmail.com,

Thank you for raising this issue. I'll try to address your questions below.

Why is it limiting on such a lower threshold, should it be at least 16MB? 1000bytes per the code or 51200bytes per my tests.

The currentOp command reports all events on the cluster in a single BSON document; the sum total of all operations in the system must therefore be less than 16MB, since that is the maximum permitted BSON document size. To reduce the chances of hitting this limit, each individual operation is limited to 1000 bytes.

Additionally, after 5.0; the currentOP() is now built around the $currentOp via aggregation pipeline, which removes the above limitation on the max size of 16MB BSON. Then, the operation itself should not fall into that condition.

When we added the $currentOp aggregation stage, we retained the currentOp command for backward compatibility. This means that it must still report all events on the system in a single BSON document. If a client issues a currentOp command, we will convert it into a $currentOp aggregation internally, but we configure the aggregation to perform the same truncation as the original currentOp command, and at the end of the aggregation we combine all results into a single document.

If you want to avoid these truncation issues, the best way is to run a $currentOp aggregation directly rather than using the currentOp command.

I've tested that on 4.4.22, 5.0.18, and 6.0.6. But got those messages only on 5.0.18 and 6.0.6.

The log message in question did not exist in 4.4 (compare to 5.0, 6.0, master); it was added in SERVER-47603. It's very likely that v4.4 was performing exactly the same truncation of the operations in currentOp as 5.0 and 6.0, but simply wasn't logging a message to inform you of that fact.

Comment by Chris Kelly [ 18/Jul/23 ]

Hi jean_nsilva@hotmail.com,

Thank you for your report, and your attention to detail in presenting your questions! I am going to pass this ticket to the relevant team to look into these questions.

Generated at Thu Feb 08 06:39:24 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.