Log Analysis · By · 7 min read

Your logs spiked. Which service actually caused it?

Every log tool draws the spike. The expensive question is which source caused it. The Trends view ranks contributors against their own baseline so you start with a name.

A log volume chart with a spike in it is one of the least useful pictures in operations. You already knew something happened, because that is why you opened the chart. What you need is the name of the thing that did it, and the chart will not tell you.

So you start narrowing. Filter to errors, and the spike is still there because most of the extra volume was info. Filter by service, one at a time, and you find one that went up, except three others also went up and you cannot tell which of them is cause and which is consequence. Twenty minutes in you have a suspect and no real confidence, and the thing has usually stopped by now anyway.

The reason this is hard is that “went up” is meaningless without knowing what normal looked like for that specific source. A service that emits 400 lines a minute jumping to 3,000 is an incident. A service that emits 40,000 lines a minute jumping to 43,000 is Tuesday. Eyeballing a stacked chart cannot distinguish those, because the second one is drawn much bigger.

Every source gets measured against itself

The Trends view does the comparison for you, and states its terms on screen.

The What Drove It panel showing a bucket at 03:32 PM with 70,174 logs against 7,644 expected. Eleven contributors are ranked by change from their own median: Other at plus 35,288, session-broker at plus 3,396, user-service at plus 3,338, down through shipping-daemon at plus 1,284 and lynxtrac-api at minus 1,444.
The line under the heading is doing the work: 70,174 logs against 7,644 expected, with contributors ranked by change from their own median rather than by volume. Note the bottom row, lynxtrac-api, went down by 1,444 during the same window.

Two numbers frame the window: what arrived, and what was expected. Underneath, every source is ranked by how far it moved from its own median, so a small service having a very bad minute outranks a large service having an ordinary one.

The bottom row is the part that convinced me this was built by someone who has done the job. lynxtrac-api is listed with a negative number. It went down by 1,444 lines while everything else went up. That is not noise to be filtered out of a “top contributors” list, it is a clue: a service that goes quiet during a surge is often the one that stopped accepting work, and if you only ever rank by increase you never see it.

The spikes become a worklist

Beside the contributor breakdown, the same analysis runs across the window and lists what it found.

The Detected Anomalies panel listing five timestamped entries, each with the source that drove it and a multiplier: 03:32 PM driven by Other at 9.2 times, 04:06 PM driven by lynxtrac-api at 5.5 times, 04:05 PM at 5.5 times, 04:10 PM at 5.4 times and 04:08 PM at 5.4 times.
Each entry carries a timestamp, a multiplier against expected volume, and the source that drove it. Clicking one moves the breakdown on the left to that window, so the list is a set of starting points rather than a set of notifications.

Each row is a time, a multiplier against what was expected, and the source held responsible. The 9.2x at the top of this list is the same 03:32 PM bucket broken down in the previous screenshot.

It is worth separating the two steps, because they work differently. Finding the anomaly is a comparison against a seasonal profile: the selected range is folded into a per-time-of-day expected volume, and a bucket is flagged when total volume runs above the top of that band. The multiplier is simply observed over expected. Attribution is the second step and the per-source one, comparing each individual source against its own median across the surrounding buckets.

So the spike is detected on the total, and blamed on the sources. That distinction matters if you are reading the numbers closely: a source can be the top contributor to a bucket that was flagged for reasons it only partly caused.

No model is being trained here and nothing is predicted. It is arithmetic against a baseline, and we would rather describe it accurately than call it something it is not.

When the biggest contributor is seventy things

Look again at the contributor list and the largest bar is Other (70), at plus 35,288. It accounts for more of the spike than every named service combined.

That is because the chart shows the top ten sources by volume and buckets the remaining seventy into one row. When a spike is broad, hitting many small services at once, most of the change lands in that bucket and the ranking tells you less than it looks like it does.

This is a real limitation and it points at a real conclusion. A broad spike across seventy low-volume sources is usually not seventy independent problems. It is one shared dependency having a bad time, and the sources are all logging their reaction to it. When Other tops the list, that is the finding: stop looking at services and start looking at what they have in common.

Silence fails differently

Volume spikes are the loud failure. The quiet one is a source that stops producing anything, and no threshold catches it because thresholds fire on too much rather than on nothing.

The Health view showing an 11 percent health score with 1 of 9 applications reporting normally, split into 3 critical, 5 warning, 1 healthy and 0 silent. A silent-after selector offers 6h, 24h, 48h and 7d. Below, an application roster sorted by error rate lists nine applications with their log counts, error counts and error percentages.
The silent-after selector, left of centre, sets how long a source can produce nothing before it is called silent rather than quiet. A batch job that runs nightly and a request path that should never stop need very different answers, which is why it is a control and not a constant.

Silent is a state alongside critical, warning and healthy, and how long counts as silent is something you set. That selector carries a lot of weight for its size. A nightly batch job is silent for twenty-three hours a day by design; an API request path that goes silent for six minutes is an outage. One threshold cannot serve both, so it is adjustable and you pick per situation.

The roster sorts by error rate rather than by error count, which is the same principle as ranking contributors by change rather than volume. The application with the most errors is usually just the application with the most traffic.

A name and a timestamp is the whole output

None of this diagnoses anything, and it is not trying to.

What it removes is the twenty minutes of filtering that used to happen before you had a suspect. You open Trends, read which source moved furthest from its own normal, and go there. If the answer is Other, you have learned that the problem is shared rather than local, which is also worth knowing before you start.

The rest of the investigation is the same work it always was: the error tracker for grouped exceptions, live tail for what is happening right now, and the surrounding context for the window in question. We wrote up the broader approach in log aggregation and analysis for faster root-cause analysis. Consider this the step that came before it and used to be done by hand.


More on how this works in practice: the log analysis overview, or email [email protected] with questions.

Related posts