Diagnosing "It's Slow": A Log-Based Troubleshooting Walkthrough

Logging & Log Analysis

Chapter 6 · Diagnosing "It's Slow": A Log-Based Troubleshooting Walkthrough

Every chapter so far has built one piece: severity levels, log locations, access/error log fields, response-time logging, cross-log correlation. This chapter puts all of it to work on one realistic ticket, start to finish — the "Apache running slow" scenario this course has referenced since Chapter 1.

The Ticket

"Customers are reporting the checkout page is taking 10+ seconds to load. Started sometime this morning. Nothing else seems affected."

Step 1

Before anything else: is response time even being logged? Checking the site's Apache config confirms %D was added to the LogFormat months ago — Chapter 4's own prerequisite is already satisfied, so the access log can actually answer a "how slow" question.

Step 2

Filter the access log for the affected path and scan the response-time field:

grep "/checkout" /var/log/apache2/access.log # showing timestamp and %D (microseconds) [08/Aug/2026:07:58:12] 312044 # 0.3s — normal [08/Aug/2026:08:01:47] 298511 # 0.3s — normal [08/Aug/2026:09:02:03] 11402887 # 11.4s — matches the complaint [08/Aug/2026:09:02:19] 10887233 # 10.9s [08/Aug/2026:09:15:41] 287905 # 0.3s — back to normal [08/Aug/2026:10:02:05] 12109442 # 12.1s — slow again

Two real findings already: the slow requests are genuinely confirmed (not just a user's impression), and they're not constant — they cluster into short windows, roughly an hour apart, then return to normal.

Step 3

Checking the error log for the same timestamps — 09:02 through 09:15 — turns up nothing dramatic, but one recurring line stands out precisely because it's routine and repeating in that exact window:

[08/Aug/2026:09:02:15] [warn] [pid 8821] AH01067: Slow database query detected (4.2s): SELECT * FROM cart_items WHERE...

The application layer is confirming the slowness lives somewhere around the database, but not yet why.

Step 4

Checking system-level activity for the same window via journalctl --since "09:00" --until "09:20" turns up the actual trigger:

Aug 08 09:00:01 web01 CRON[9432]: (root) CMD (/usr/local/bin/nightly_backup.sh) Aug 08 09:00:02 web01 kernel: [warn] CPU load average: 8.42, 6.10, 4.88
Step 5 — Correlating the Pattern

Lining the three sources up by timestamp tells a complete, consistent story:

  • A cron job named nightly_backup.sh is starting at 09:00, 10:00, and presumably every hour on the hour — despite its name suggesting it should run once, overnight
  • It drives CPU load sharply upward, visible in the kernel/system log
  • Database queries slow down under that load, visible as the Apache warn-level slow-query notice
  • The checkout page's own response time spikes to match, visible directly in the access log's %D field

No single log source proved this on its own — the access log proved that it was slow, the error log hinted at where, and the system log finally explained why. Correlated by timestamp, the three together point at one specific, fixable cause: a backup script with a misconfigured hourly schedule, not a nightly one.

Don't stop at the first correlated signal
The slow-query warning in Step 3 was tempting to treat as the full answer on its own — "the database is slow, case closed." It's true, but incomplete: without Step 4's system-level check, the actual root cause (a misconfigured cron schedule) would have stayed hidden, and any fix attempted at the database layer alone would likely have missed the real trigger entirely.

Hands-On Exercises

Exercise 1

Explain why Step 1 of this walkthrough checks whether %D is configured before doing anything else, referencing what this course covered in Chapter 4.

📄 View solution
Exercise 2

Explain what each of the three log sources (access log, error log, system/journal log) individually proved in this walkthrough, and why the full picture needed all three rather than any one alone.

📄 View solution
Exercise 3

Explain why this chapter warns against treating the Step 3 slow-query warning as a complete diagnosis on its own, even though it was a real, accurate finding.

📄 View solution

Chapter 6 Quick Reference

  • Confirm response time is actually logged (Chapter 4) before trying to diagnose "slow" from the access log at all
  • The access log's %D/$request_time field confirms and quantifies the symptom — proof, not just a user's impression
  • The error log often hints at where the slowness lives, without fully explaining why
  • System-level logs (journalctl, kernel messages) frequently reveal the actual trigger — resource exhaustion, a misbehaving scheduled job, and similar
  • Correlate all sources by timestamp before concluding a diagnosis is complete — a single confirmed finding can still be an incomplete answer
  • Next chapter: Diagnosing "It's Returning the Wrong Thing" — A Second Troubleshooting Walkthrough