DevOps NetworkDevOpsNetwork
Join Free
Practical infra coding

Pair START and END lines to find slow and stuck requests

mediumLog parsing and aggregation

Problem statement

A service logs a START line when a request begins and an END line when it finishes. Requests run concurrently, so lines from different requests are interleaved. Each line has a timestamp HH:MM:SS.mmm, the event, and key=value fields including req, the request ID.

Report:

  1. The 3 slowest completed requests: ID, path and duration in milliseconds, slowest first.
  2. Requests that started but never finished (stuck, or the process died).
  3. END lines whose START is not in the file (it was in the previous log file).

trace.log

TEXT
10:00:00.100 START req=a1 path=/api/users
10:00:00.150 START req=b2 path=/api/orders
10:00:00.180 END req=a1 status=200
10:00:00.400 START req=c3 path=/api/login
10:00:01.020 END req=b2 status=500
10:00:01.100 END req=zz status=200
10:00:01.300 START req=d4 path=/api/users
10:00:01.450 END req=d4 status=200

Examples

Example 1

Input: python solution.py trace.log

Output: b2 /api/orders 870 ms d4 /api/users 150 ms a1 /api/users 80 ms never finished: c3 end without start: zz

Explanation: b2 starts at 00.150 and ends at 01.020: 870 ms. c3 has no END. zz has an END but no START.

Hints

Approach

Optimal

This is a matching problem with a hash map.

  1. Convert the timestamp to milliseconds since midnight. Pad the fraction to 3 digits so .1 means 100 ms, not 1 ms.
  2. On START, store open_reqs[req] = (ms, path).
  3. On END, pop the ID. If it is not there, record an orphan END. Otherwise compute the duration and push it into a min-heap that never grows past k: heappushpop adds the new item and removes the smallest in one step.
  4. At the end, the heap holds the k slowest requests and open_reqs holds the unfinished ones.

Memory is the number of requests in flight at once plus k, not the total number of requests. That is what makes this workable on a day of traffic.

ComplexityTime O(n log k)Space O(open + k)
Python
import heapq
import sys
def to_ms(ts):
"""'10:00:01.020' -> milliseconds since midnight."""
hms, _, frac = ts.partition(".")
h, m, s = (int(x) for x in hms.split(":"))
return ((h * 60 + m) * 60 + s) * 1000 + int(frac.ljust(3, "0")[:3])
def pair_requests(lines, k=3):
open_reqs = {} # req id -> (start_ms, path); only in-flight requests live here
slowest = [] # min-heap of (duration, req, path), never larger than k
orphans_end = []
bad = 0
for line in lines:
parts = line.split()
if len(parts) < 3:
if parts:
bad += 1
continue
fields = dict(p.split("=", 1) for p in parts[2:] if "=" in p)
req = fields.get("req")
try:
ms = to_ms(parts[0])
except ValueError:
bad += 1
continue
if req is None or parts[1] not in ("START", "END"):
bad += 1
continue
if parts[1] == "START":
open_reqs[req] = (ms, fields.get("path", "?"))
continue
if req not in open_reqs:
orphans_end.append(req)
continue
start, path = open_reqs.pop(req)
item = (ms - start, req, path)
if len(slowest) < k:
heapq.heappush(slowest, item)
else:
heapq.heappushpop(slowest, item) # drops the fastest of the k+1
return sorted(slowest, reverse=True), list(open_reqs), orphans_end, bad
def main(path):
with open(path, encoding="utf-8", errors="replace") as f:
slowest, unfinished, orphans, bad = pair_requests(f)
for dur, req, p in slowest:
print(f"{req} {p} {dur} ms")
print("never finished:", ", ".join(unfinished) or "-")
print("end without start:", ", ".join(orphans) or "-")
if bad:
print(f"skipped {bad} malformed line(s)", file=sys.stderr)
if __name__ == "__main__":
main(sys.argv[1] if len(sys.argv) > 1 else "trace.log")

Follow-up questions

  • Requests stuck for more than 30 seconds should be reported while the log is still being read, not only at the end.
  • The START and END for one request are in different files from different hosts. How do you join them?
  • Report p95 duration per path instead of the top 3 overall.

Frequently asked questions

This version overwrites the first START, so the first attempt disappears. Depending on the system, a repeated ID could be a retry, a bug, or IDs being reused. In an interview, say which you assume. A safer option is to report the earlier START as unfinished before replacing it.

Correlating events by request ID is how you debug distributed systems without a tracing product: find the slow requests and find the ones that never returned. It also tests whether you notice that memory should depend on concurrency, not on total volume.

With time-of-day stamps, an END at 00:00:00.100 looks earlier than a START at 23:59:59.900. If the duration comes out negative, add 24 hours, or better, log full ISO-8601 timestamps so the problem cannot arise.