[SERVER-48385] Streamable isMaster generates slow query log Created: 21/May/20  Updated: 27/Oct/23  Resolved: 22/May/20

Status: Closed
Project: Core Server
Component/s: Diagnostics
Affects Version/s: 4.4.0-rc6
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: Jeffrey Yemin Assignee: Unassigned
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File mongodb.log    
Participants:

 Description   

When using the new streamable isMaster protocol, the server generates a "Slow query" log entry for each response, like this:

{"t":{"$date":"2020-05-21T19:38:09.257-04:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn1313",
"msg":"Slow query",
"attr":{"type":"command","ns":"admin.$cmd","command":{"ismaster":1,
"topologyVersion":{"processId":{"$oid":"5ec6a8fc391637b919d6d8ca"},"counter":0}," maxAwaitTimeMS":10000,"$db":"admin"},"numYields":0,"reslen":304,"locks":{},"protocol":"op_msg","durationMillis":9999}}

Is this expected, and if so, is it desirable?



 Comments   
Comment by Bruce Lucas (Inactive) [ 22/May/20 ]

No problem; I learned something too.

Comment by Jeffrey Yemin [ 22/May/20 ]

OK, feel free to close then. Thank you for the explanation.

Comment by Bruce Lucas (Inactive) [ 22/May/20 ]

So the message "Slow query" maybe is somewhat misleading: it really means "an operation completed, and here is some information about it, including how long it took". Depending on settings like slowms and verbosity it may actually not be "slow", and it may not actually be a query as such. I think I would expect that under conditions where every operation is logged that these would also be logged.

Comment by Jeffrey Yemin [ 22/May/20 ]

No messages at the default log file. But still, I think it's misleading to identify this as a slow query at any log level.

Comment by Bruce Lucas (Inactive) [ 22/May/20 ]

Thanks. I noticed that you're running at high verbosity level. Do the slow query logs for isMaster also show at normal verbosity?

{
    "t": {
        "$date": "2020-05-22T11:50:07.560Z"
    },
    "s": "I",
    "c": "CONTROL",
    "id": 21951,
    "ctx": "initandlisten",
    "msg": "Options set by command line",
    "attr": {
        "options": {
            "config": "/Users/jeff/mongo/mongod-42-inMemory.conf",
            "net": {
                "compression": {
                    "compressors": "zlib,snappy,noop"
                },
                "ipv6": true
            },
            "setParameter": {
                "enableTestCommands": "1"
            },
            "storage": {
                "dbPath": "/tmp/data/db42-inMemory",
                "engine": "inMemory"
            },
            "systemLog": {
                "component": {
                    "command": {
                        "verbosity": 4
                    },
                    "query": {
                        "verbosity": 4
                    }
                },
                "destination": "file",
                "path": "/tmp/log/db42-inMemory/mongodb.log",
                "verbosity": 2
            }
        }
    }
}

Comment by Jeffrey Yemin [ 22/May/20 ]

Uploaded log file.

I double checked the server version. The messages appear continuous.

One thing to note is that I'm testing with a standalone. I haven't checked replica set or mongos.

Comment by Bruce Lucas (Inactive) [ 22/May/20 ]

I believe this should have been fixed by SERVER-47267. Are these messages being generated continuously every 10 seconds or only sporadically? Can you double check the server version?

cc: jesse

Generated at Thu Feb 08 05:16:58 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.