Skip to content

Commit

Permalink
[mongo] Slow query log parsing should be timezone aware (#19057)
Browse files Browse the repository at this point in the history 
* parse log entry with timezone awareness

* update test

* update changelog
  • Loading branch information
@lu-zhengda
lu-zhengda authored Nov 14, 2024
1 parent b891675 commit b8de861
Show file tree
Hide file tree
Showing 3 changed files with 15 additions and 4 deletions.
1 change: 1 addition & 0 deletions mongo/changelog.d/19057.fixed
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Fixes timezone parsing bug in slow query log, preventing incorrect timestamp conversions on non-UTC servers.
16 changes: 13 additions & 3 deletions mongo/datadog_checks/mongo/dbm/slow_operations.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,8 @@ def __init__(self, check):

self._last_collection_timestamp = None

self._log_json_opts = json_util.JSONOptions(tz_aware=True)

def run_job(self):
self.collect_slow_operations()

Expand Down Expand Up @@ -157,18 +159,24 @@ def _collect_slow_operations_from_profiler(self, db_name, last_ts):
yield self._obfuscate_slow_operation(profile, db_name)

def _collect_slow_operations_from_logs(self, db_names, last_ts):
self._check.log.debug(
"Collecting slow operations from logs for databases %s with lookback ts %s", db_names, last_ts
)
logs = self._check.api_client.get_log_data()
log_entries = logs.get("log", [])
self._check.log.debug("Found %d log entries", len(log_entries))
start_index = self._binary_search(log_entries, last_ts)
self._check.log.debug("Starting log search from index: %d", start_index)
for i in range(start_index, len(log_entries)):
parsed_log = log_entries[i]
if isinstance(parsed_log, str):
try:
parsed_log = json_util.loads(parsed_log)
parsed_log = json_util.loads(parsed_log, json_options=self._log_json_opts)
except Exception as e:
self._check.log.error("Failed to parse log line: %s", e)
continue
if parsed_log.get("msg", "").lower() == 'slow query':
log_msg = parsed_log.get("msg", "")
if log_msg.lower() == 'slow query':
ts = parsed_log["t"].timestamp()
if ts <= last_ts:
# This check is still needed when binary search fails to parse a log line
Expand All @@ -182,6 +190,8 @@ def _collect_slow_operations_from_logs(self, db_names, last_ts):
continue
log_attr["ts"] = ts
yield self._obfuscate_slow_operation(log_attr, db_name)
else:
self._check.log.debug("Skipping non-slow query log entry: %s", log_msg)

def _collect_slow_operation_explain_plan(self, slow_operation, dbname):
try:
Expand Down Expand Up @@ -232,7 +242,7 @@ def _binary_search(self, logs, ts):
while left <= right:
mid = (left + right) // 2
try:
parsed_log = json_util.loads(logs[mid])
parsed_log = json_util.loads(logs[mid], json_options=self._log_json_opts)
except Exception as e:
self._check.log.debug("Failed to parse log line: %s", e)
# If we can't parse the log, skip binary search and linearly search the rest of the logs
Expand Down
2 changes: 1 addition & 1 deletion mongo/tests/fixtures/getLog-standalone
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@
"{\"t\":{\"$date\":\"2023-04-01T18:45:41.386+00:00\"},\"s\":\"I\", \"c\":\"WRITE\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"update\",\"ns\":\"test.customers\",\"command\":{\"q\":{\"age\":{\"$gt\":35}},\"u\":{\"$set\":{\"subscribed\":true}},\"multi\":true,\"upsert\":false,\"comment\":\"update customers subscription status by age\"},\"planSummary\":\"IXSCAN { age: -1 }\",\"keysExamined\":487,\"docsExamined\":487,\"nMatched\":487,\"nModified\":487,\"nUpserted\":0,\"keysInserted\":487,\"keysDeleted\":487,\"numYields\":0,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":1}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"w\":1}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":1}},\"Global\":{\"acquireCount\":{\"w\":1}},\"Database\":{\"acquireCount\":{\"w\":1}},\"Collection\":{\"acquireCount\":{\"w\":1}}},\"flowControl\":{\"acquireCount\":1},\"storage\":{},\"cpuNanos\":11530375,\"remote\":\"192.168.65.1:58133\",\"durationMillis\":11,\"workingMillis\":10}}\n",
"{\"t\":{\"$date\":\"2024-04-01T18:45:41.387+00:00\"},\"s\":\"I\", \"c\":\"COMMAND\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"command\",\"ns\":\"test.$cmd\",\"command\":{\"update\":\"customers\",\"ordered\":true,\"comment\":\"update customers subscription status by age\",\"$db\":\"test\"},\"numYields\":0,\"reslen\":60,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":2}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":1}},\"Global\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"Database\":{\"acquireCount\":{\"w\":2}},\"Collection\":{\"acquireCount\":{\"w\":2}}},\"flowControl\":{\"acquireCount\":1},\"storage\":{},\"cpuNanos\":11746542,\"remote\":\"192.168.65.1:58133\",\"protocol\":\"op_msg\",\"durationMillis\":11}}\n",
"{\"t\":{\"$date\":\"2024-04-01T18:45:41.387+00:00\"},\"s\":\"I\", \"c\":\"COMMAND\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"command\",\"ns\":\"test.$cmd\",\"command\":{\"update\":\"customers\",\"ordered\":true,\"comment\":\"update customers subscription status by age\",\"$db\":\"test\"},\"numYields\":0,\"reslen\":60,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":2}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":1}},\"Global\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"Database\":{\"acquireCount\":{\"w\":2}},\"Collection\":{\"acquireCount\":{\"w\":2}}},\"flowControl\":{\"acquireCount\":1},\"storage\":{},\"cpuNanos\":11746542,\"remote\":\"192.168.65.1:58133\",\"protocol\":\"op_msg\",\"durationMillis\":11}}\n",
"{\"t\":{\"$date\":\"2024-04-01T18:45:41.387+00:00\"},\"s\":\"I\", \"c\":\"COMMAND\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"command\",\"ns\":\"test.$cmd\",\"command\":{\"update\":\"customers\",\"ordered\":true,\"comment\":\"update customers subscription status by age\",\"$db\":\"test\"},\"numYields\":0,\"reslen\":60,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":2}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":1}},\"Global\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"Database\":{\"acquireCount\":{\"w\":2}},\"Collection\":{\"acquireCount\":{\"w\":2}}},\"flowControl\":{\"acquireCount\":1},\"storage\":{},\"cpuNanos\":11746542,\"remote\":\"192.168.65.1:58133\",\"protocol\":\"op_msg\",\"durationMillis\":11}}\n",
"{\"t\":{\"$date\":\"2024-04-01T19:45:41.387+01:00\"},\"s\":\"I\", \"c\":\"COMMAND\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"command\",\"ns\":\"test.$cmd\",\"command\":{\"update\":\"customers\",\"ordered\":true,\"comment\":\"update customers subscription status by age\",\"$db\":\"test\"},\"numYields\":0,\"reslen\":60,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":2}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":1}},\"Global\":{\"acquireCount\":{\"r\":1,\"w\":2}},\"Database\":{\"acquireCount\":{\"w\":2}},\"Collection\":{\"acquireCount\":{\"w\":2}}},\"flowControl\":{\"acquireCount\":1},\"storage\":{},\"cpuNanos\":11746542,\"remote\":\"192.168.65.1:58133\",\"protocol\":\"op_msg\",\"durationMillis\":11}}\n",
"{\"t\":{\"$date\":\"2999-04-01T18:45:43.991+00:00\"},\"s\":\"I\", \"c\":\"WRITE\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"update\",\"ns\":\"test.customers\",\"command\":{\"q\":{\"age\":{\"$gt\":18}},\"u\":{\"$set\":{\"subscribed\":false}},\"multi\":true,\"upsert\":false,\"comment\":\"update customers subscription status by age\"},\"planSummary\":\"IXSCAN { age: -1 }\",\"keysExamined\":608,\"docsExamined\":608,\"nMatched\":608,\"nModified\":441,\"nUpserted\":0,\"keysInserted\":441,\"keysDeleted\":441,\"numYields\":4,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":5}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"w\":5}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":5}},\"Global\":{\"acquireCount\":{\"w\":5}},\"Database\":{\"acquireCount\":{\"w\":5}},\"Collection\":{\"acquireCount\":{\"w\":5}}},\"flowControl\":{\"acquireCount\":5},\"storage\":{},\"cpuNanos\":74500749,\"remote\":\"192.168.65.1:58133\",\"durationMillis\":74,\"queues\":{\"ingress\":{\"admissions\":7,\"totalTimeQueuedMicros\":0},\"execution\":{\"admissions\":328,\"totalTimeQueuedMicros\":2109}}}}\n",
"{\"t\":{\"$date\":\"2999-04-01T18:45:43.991+00:00\"},\"s\":\"I\", \"c\":\"COMMAND\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"command\",\"ns\":\"test.$cmd\",\"command\":{\"update\":\"customers\",\"ordered\":true,\"comment\":\"update customers subscription status by age\",\"$db\":\"test\"},\"numYields\":4,\"reslen\":60,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":6}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"r\":1,\"w\":6}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":5}},\"Global\":{\"acquireCount\":{\"r\":1,\"w\":6}},\"Database\":{\"acquireCount\":{\"w\":6}},\"Collection\":{\"acquireCount\":{\"w\":6}}},\"flowControl\":{\"acquireCount\":5},\"storage\":{},\"cpuNanos\":74715957,\"remote\":\"192.168.65.1:58133\",\"protocol\":\"op_msg\",\"durationMillis\":74}}\n",
"{\"t\":{\"$date\":\"2999-04-01T18:45:45.007+00:00\"},\"s\":\"I\", \"c\":\"WRITE\", \"id\":51803, \"ctx\":\"conn50\",\"msg\":\"Slow query\",\"attr\":{\"type\":\"update\",\"ns\":\"test.customers\",\"command\":{\"q\":{\"age\":{\"$gt\":35}},\"u\":{\"$set\":{\"subscribed\":true}},\"multi\":true,\"upsert\":false,\"comment\":\"update customers subscription status by age\"},\"planSummary\":\"IXSCAN { age: -1 }\",\"keysExamined\":495,\"docsExamined\":495,\"nMatched\":495,\"nModified\":495,\"nUpserted\":0,\"keysInserted\":495,\"keysDeleted\":495,\"numYields\":2,\"locks\":{\"ParallelBatchWriterMode\":{\"acquireCount\":{\"r\":3}},\"FeatureCompatibilityVersion\":{\"acquireCount\":{\"w\":3}},\"ReplicationStateTransition\":{\"acquireCount\":{\"w\":3}},\"Global\":{\"acquireCount\":{\"w\":3}},\"Database\":{\"acquireCount\":{\"w\":3}},\"Collection\":{\"acquireCount\":{\"w\":3}}},\"flowControl\":{\"acquireCount\":3},\"storage\":{},\"cpuNanos\":27416375,\"remote\":\"192.168.65.1:58133\",\"durationMillis\":27,\"workingMillis\":20,\"queues\":{\"ingress\":{\"admissions\":7,\"totalTimeQueuedMicros\":0},\"execution\":{\"admissions\":328,\"totalTimeQueuedMicros\":2109}}}}\n",
Expand Down

0 comments on commit b8de861

Please sign in to comment.