[SERVER-76799] executor log line isn't useful Created: 03/May/23  Updated: 29/Oct/23  Resolved: 01/Jun/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 6.3.1
Fix Version/s: 7.1.0-rc0, 7.0.0-rc4

Type: Bug Priority: Major - P3
Reporter: Eric Milkie Assignee: Jason Chan
Resolution: Fixed Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Assigned Teams:
Service Arch
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v7.0
Sprint: Service Arch 2023-05-29, Service Arch 2023-06-12
Participants:

 Description   

With the upgrade to 6.3, the "Client's executor exceed time limit" log line is appearing as a large percentage of log lines in all Serverless MTM logs. The units in the variables aren't useful to compare, so all the log lines look the same:

{"t":{"$date":"2023-04-18T20:14:45.328+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn132","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:15:17.288+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn132","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:15:49.584+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn126","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:16:30.991+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn130","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:16:57.926+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn129","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:23:53.518+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn129","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:25:07.888+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn128","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:26:04.580+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn129","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:29:08.836+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn129","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:33:53.093+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn130","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:36:54.710+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn128","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:38:48.453+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn127","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:39:01.341+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn130","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:39:16.014+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn130","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:40:41.788+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn131","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:40:44.824+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn130","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:41:46.159+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn131","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:44:04.368+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn131","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:45:24.320+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn132","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:47:06.455+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn131","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:47:14.312+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn128","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:48:57.930+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn128","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:53:09.731+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn128","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:54:52.420+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn99","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}
{"t":{"$date":"2023-04-18T20:56:19.113+00:00"},"s":"I",  "c":"-",        "id":4651401, "ctx":"conn130","msg":"Client's executor exceeded time limit","attr":{"elapsedMillis":1,"limitMicros":30}}

We should either suppress these log lines, or make them more useful by changing how we measure the executor time.



 Comments   
Comment by Githook User [ 13/Jun/23 ]

Author:

{'name': 'Jason Chan', 'email': 'jason.chan@mongodb.com', 'username': 'jasonjhchan'}

Message: SERVER-76799 Update precision of ClientOutOfLineExecutor timer

(cherry picked from commit 397c8da541940b3fbe6257243f97a342fe7e0d3b)
Branch: v7.0
https://github.com/mongodb/mongo/commit/fedc01fad54b22a43147eb366b28c9cc3227db69

Comment by Githook User [ 01/Jun/23 ]

Author:

{'name': 'Jason Chan', 'email': 'jason.chan@mongodb.com', 'username': 'jasonjhchan'}

Message: SERVER-76799 Update precision of ClientOutOfLineExecutor timer
Branch: master
https://github.com/mongodb/mongo/commit/397c8da541940b3fbe6257243f97a342fe7e0d3b

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