Logs say what happened; traces say where the time went

The previous course ended with structured, correlated logs. They answer what happened, in what order, to whom. Here is what they do not answer.

A user reports that the Mastery page is slow. Your log has one line:

{"message":"request.completed","path":"/enrollment/mastery","status":200,"duration_ms":3840}

Three point eight seconds. The line is correct, complete, and useless: it tells you the request was slow and nothing about which part of it was slow. The timings in this lesson are invented to show the shape; the real calls are not this slow.

Open Enrollment::UserGamificationQuery in this repository and the ambiguity becomes concrete. One call to .call does, at minimum:

• ExperiencePoint.total_for(user.id): a sum
• Level.ordered.to_a: a load
• SkillRadarQuery.call(user:): another query object, with its own queries
• LeaderboardSnapshot.current_for("all_time"): a lookup of the current snapshot
• snapshot.entries.find_by(user_id:): the learner's entry in it
• snapshot.entries.count: a count over every ranked learner

That is six database round trips, plus whatever SkillRadarQuery does inside itself, behind one method call and one log line. Which of them took three seconds? The log cannot say. A count over a large entries table and whatever SkillRadarQuery runs inside itself are both plausible, and guessing between them is how an afternoon disappears.

What a trace is

A trace is the same request, broken into nested timed intervals called spans:

flowchart TB
  R["GET /enrollment/mastery — 3840ms"] --> C["MasteryController#show — 3800ms"]
  C --> Q["UserGamificationQuery.call — 3700ms"]
  Q --> S1["ExperiencePoint.total_for — 120ms"]
  Q --> S2["Level.ordered — 40ms"]
  Q --> S3["SkillRadarQuery.call — 300ms"]
  Q --> S4["LeaderboardSnapshot.current_for — 30ms"]
  Q --> S5["entries.find_by — 50ms"]
  Q --> S6["entries.count — 3100ms"]

Laid out on a timeline, the same trace is a waterfall: each bar starts where its caller allows and lasts as long as it took.

GET /enrollment/mastery        |=========================================| 3840ms
  MasteryController#show       | ========================================| 3800ms
    UserGamificationQuery.call |  =======================================| 3700ms
      ExperiencePoint.total_for|  ==                                     |  120ms
      Level.ordered            |     =                                   |   40ms
      SkillRadarQuery.call     |      ====                               |  300ms
      Snapshot.current_for     |          =                              |   30ms
      entries.find_by          |           =                             |   50ms
      entries.count            |            ============================ | 3100ms

The answer is visible: entries.count took three point one seconds. No hypothesis, no bisecting, no adding timing logs and waiting for it to happen again.

That is the whole proposition. A trace turns the request was slow into this call was slow, and it does so for a request that already happened.

Why the distributed part

A trace within one process is useful. It becomes necessary when the work crosses a boundary: an HTTP call to another service, a job handed to a worker, a call to a payment provider. Each of those is a black box in your own timing, and a distributed trace makes them spans like any other, with a shared identifier passed across.

This application is a modular monolith, so the boundaries it crosses are the database, background jobs and outbound HTTP. That is enough to make tracing worth having and to teach every concept. The same concepts transfer directly to a system with twelve services, which is where you will meet them again.

The three signals

They complement each other, and none substitutes for another. The pattern that emerges, which lesson 6 develops, is: a metric alerts, a trace localizes, a log explains. Losing any one of them makes the other two work harder.

What this costs

Weigh these before you commit to it:

• Instrumentation overhead: small with automatic instrumentation, but every span is an allocation and a timestamp.
• Volume: every request produces many spans. At scale you must sample, which is lesson 4.
• A backend: Jaeger, Tempo, or a vendor. Another system to run, or another bill.
• Attention: a tracing system nobody opens is a cost with no return. Teams that install one without deciding what question it answers often end up there.

What this course covers

1. Logs say what happened; traces say where the time went (you are here).
2. Spans, traces, and context.
3. Instrumenting a Rails application.
4. Sampling, and what it costs.
5. Reading a trace.
6. The three signals together.
7. Putting it together: tracing this application.

Key takeaways

• A log line reports that a request took 3.8 seconds; it cannot say which of its ten operations did.
• A trace is one request as a tree of timed spans, which localizes slowness without reproducing it.
• Distribution matters at process boundaries (services, jobs, outbound calls), where your own timing goes blind.
• Metrics alert, traces localize, logs explain; the three complement each other.
• Tracing costs overhead, volume, a backend, and the attention to use it.