During a fifty minute incident in June, four of us sat in a call watching a spinner. Every search we ran against our log store took between six and eight minutes to come back. We were not short of data. We had the request ids, the error signatures and the customer references, and we could not ask about any of them faster than once every few minutes, which meant that in fifty minutes we asked our logs about seven questions between us.
Everything from forty services went into one index per day, thirty days of them kept on the same hot nodes, with no routing and no separation. A search for a request id with no service filter, over the default thirty day range that our saved view opened on, scanned roughly one point four terabytes. People widened ranges out of habit, because narrowing one means already knowing when the trouble started, which during an incident is precisely the thing you do not know.
We changed the storage shape and the questions. Logs route by service into per service indices, three days on fast local disk, twenty five days on cheaper nodes, then a searchable snapshot. The saved view for a service opens on one hour and carries the service filter already applied. And the five things we ask in every single incident, error counts by endpoint, failures for one customer id, slowest endpoints, the last ten deploys and a count per error signature, are now five buttons that run bounded queries rather than five expressions somebody types badly under pressure.
The request id lookup that took six minutes returns in about four seconds. The median query in our last three incidents was under ten seconds. We also record query latency now, and time to first answer goes into the incident review next to time to detect.
Two years of work had gone into making our telemetry complete and none into making it answerable. Your tooling has a latency and it is spent inside the outage, at the moment when a person is holding a hypothesis they cannot check. Correct and slow is a strange thing to be proud of.
– Sergey Shinder
