Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-79891

Inconsistent profiling output for inserts

    • Type: Icon: Bug Bug
    • Resolution: Unresolved
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • Query Execution
    • ALL

      For the insert operation, the profiling output is currently inconsistent in some ways:

      1) Inconsistency between inserts initiates from mongod v.s. inserts sent from mongos

      When we do an insert directly from monogd, the profile entry in the <db>.system.profile collection will contain and entry with a field "command" like this:

          "command" : {
              "insert" : "coll",
              "lsid" : { ... },
              "$clusterTime" : { ... },
              "$db" : "test",

               }

      Note that this does not include the actual documents inserted (which seems not desired), however if the insert command is sent from mongos, "command" field will include a subField "documents" that is an array of all the inserted documents. Additionally the missing "documents" subField is also a problem for 'slow query' logs as it prints the command using the same way described below.

      The reason of the difference is two-folded:

      a) For the similar reason described in SERVER-79442, for requests initiated from mongod, any field that are marked as 'supports_doc_sequence' (such as the "documents" field in the insert command, the "updates" field in the update command and the "deletes" field in the delete command) will only be present in the OpMsg::sequences vector, but not in OpMsg::body, while for requests sent from mongos, requests are serialized in a way such that all fields are in OpMsg::body.

      b) For every command handled by mongod, curOpCommandSetup() will first be called to set basic command info in CurOp,  where it calls setOpDescription_inlock() to set opDescription using OpMsg::body, and this is basically what's printed in the "command" field of the profile entry. However, the problem is that unlike update and delete command where they unroll each update/delete op and overwrite the opDescription with the individual update/delete op, insert does not do that. Combined with a), inserts initiated from mongod will lose the "documents" field in the profile entry.

      2) Inconsistency between inserts v.s. updates/deletes

      From the above example profile output, we can see that insert command includes some request-level fields like $clusterTime, $db, txnNumber, etc. However due to aforementioned reason b), update and delete commands will overwrite the opDescription with individual update/delete op and so will not include those request-level fields. And we seem to be relying on this to for JS tests because when I did a one-line change to make inserts also overwrite opDescription with the inserted documents, I saw a bunch of tests failed because they expect the request level fields being present in the insert command profile output. I think ultimately insert/update/delete should have consistent profile entry format, but I'm not sure whether we want to fix insert or fix update/delete. If I have to guess, we probably want to have the request-level fields to be present in update/delete as well.

       

      (Just to add on a bit, currently an update/delete command creates nested CurOp and so would call CurOp::completeAndLogOperation() and profile() for the parent CurOp, in addition to the calls for each individual update/delete entry. Usually the result is correct, but under certain profile/logging configurations, the profile output and/or slow query logs might be slightly weird, and this is a bit confusing to developer even when the result is correct which feels like a tech debt.)

       

            Assignee:
            backlog-query-execution [DO NOT USE] Backlog - Query Execution
            Reporter:
            wenbin.zhu@mongodb.com Wenbin Zhu
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated: