[SERVER-71480] Reduce logging frequency of "Slow session workflow loop" Created: 18/Nov/22  Updated: 23/Nov/22  Resolved: 23/Nov/22

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

Type: Improvement Priority: Major - P3
Reporter: Louis Williams Assignee: Blake Oler
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-71029 Update slow SessionWorkflow log criteria Closed
Sprint: Service Arch 2022-11-28
Participants:

 Description   

On a completely idle mongod, this log message is reported every 10 seconds:

{"t":{"$date":"2022-11-18T15:01:48.159+01:00"},"s":"I",  "c":"EXECUTOR", "id":6983000, "ctx":"conn1","msg":"Slow SessionWorkflow loop","attr":{"elapsed":{"totalMillis":10010,"activeMillis":10010,"receiveWorkMillis":0,"processWorkMillis":10007,"sendResponseMillis":3,"finalizeMillis":0}}}

It seems like the intention of this log message is to indicate an abnormality, but it is actually being logged in the steady state of the system. We should avoid logging it so frequently.



 Comments   
Comment by Blake Oler [ 23/Nov/22 ]

Seeing this log message every ten seconds on a connection that lasts ten seconds makes sense – the threshold is 100ms to make a slow operation (and its underlying connection!).

I'd actually say that the log isn't the issue here – why do we have an operation that sits around for ten seconds? Should such an operation be excluded from the slow SessionWorkflow log catcher?

I'm interested in seeing the logs for this.

This is all mainly a moot point, though – SERVER-71029 will restrict this log to only emit when the sendResponse (read: networking) phase is over 100ms, and even then we'll only emit a log at most once every five seconds. We should only run into this saturation point on a severely overloaded system.

I'm closing this as resolved by/a duplicate of SERVER-71029.

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