1"""Chapter 30: Observability. Tested with Python 3, standard library only.
2
3Running example: the bookstore's checkout during the Big Book Sale. Something is slow.
4What do the logs, metrics and traces tell us, and when should someone be woken up?
5"""
6import bisect
7import json
8import random
9from collections import Counter, defaultdict
10
11
12# ---------- 30.2.1 structured logs ----------
13
14def log_line(level, msg, **fields):
15 return json.dumps({"level": level, "msg": msg, **fields}, sort_keys=True)
16
17
18def query_logs(lines, **match):
19 out = []
20 for line in lines:
21 rec = json.loads(line)
22 if all(rec.get(k) == v for k, v in match.items()):
23 out.append(rec)
24 return out
25
26
27# ---------- 30.2.2 metrics: counters and histograms ----------
28
29BUCKETS = [25, 50, 100, 250, 500, 1000, 2500, 5000, 10000] # ms upper bounds
30
31
32class Histogram:
33 def __init__(self):
34 self.counts = [0] * (len(BUCKETS) + 1)
35 self.total = 0
36
37 def observe(self, ms):
38 self.counts[bisect.bisect_left(BUCKETS, ms)] += 1
39 self.total += 1
40
41 def merge(self, other):
42 out = Histogram()
43 out.counts = [a + b for a, b in zip(self.counts, other.counts)]
44 out.total = self.total + other.total
45 return out
46
47 def quantile(self, q):
48 """Upper bound of the bucket containing the q-th observation (Prometheus-style, roughly)."""
49 target, seen = q * self.total, 0
50 for i, c in enumerate(self.counts):
51 seen += c
52 if seen >= target:
53 return BUCKETS[i] if i < len(BUCKETS) else float("inf")
54
55
56def exact_quantile(xs, q):
57 s = sorted(xs)
58 return s[min(len(s) - 1, int(q * len(s)))]
59
60
61def series_count(label_values):
62 """How many time series a metric creates: the product of distinct values per label."""
63 n = 1
64 for values in label_values.values():
65 n *= values
66 return n
67
68
69# ---------- 30.2.3 traces ----------
70
71def build_trace():
72 """One checkout request: spans (name, parent, start_ms, end_ms)."""
73 return [
74 ("POST /checkout", None, 0, 1840),
75 ("auth", "POST /checkout", 5, 25),
76 ("cart.load", "POST /checkout", 25, 70),
77 ("pricing.quote", "POST /checkout", 70, 160),
78 ("inventory.reserve", "POST /checkout", 160, 230),
79 ("payment.charge", "POST /checkout", 230, 1790),
80 ("gateway.http", "payment.charge", 240, 1780),
81 ("db.insert_order", "POST /checkout", 1790, 1830),
82 ]
83
84
85def self_time(spans):
86 """Time in each span not covered by its children."""
87 children = defaultdict(list)
88 for name, parent, s, e in spans:
89 if parent:
90 children[parent].append((s, e))
91 out = {}
92 for name, parent, s, e in spans:
93 covered = sum(ce - cs for cs, ce in children[name])
94 out[name] = (e - s) - covered
95 return out
96
97
98# ---------- 30.4 / 30.5 SLOs and error budgets ----------
99
100def sli(good, total):
101 return good / total
102
103
104def error_budget(slo, total_requests):
105 return (1 - slo) * total_requests
106
107
108def burn_rate(error_ratio, slo):
109 return error_ratio / (1 - slo)
110
111
112def should_page(err_1h, err_5m, slo, threshold=14.4):
113 """Multiwindow burn-rate alert: both the long and short window must be burning fast."""
114 return burn_rate(err_1h, slo) >= threshold and burn_rate(err_5m, slo) >= threshold
115
116
117# ---------- 30.8 debugging: break errors down by dimension ----------
118
119def breakdown(requests, dim):
120 total, errs = Counter(), Counter()
121 for r in requests:
122 total[r[dim]] += 1
123 errs[r[dim]] += r["status"] >= 500
124 return {k: round(errs[k] / total[k], 3) for k in total}
125
126
127# ---------- checks ----------
128
129def run_checks():
130 rnd = random.Random(30)
131
132 # structured logs with a trace id are queryable
133 logs = [log_line("info", "checkout started", trace_id="t-881", user="asha"),
134 log_line("error", "payment timeout", trace_id="t-881", gateway="pg-a", ms=3000),
135 log_line("info", "checkout started", trace_id="t-882", user="ravi")]
136 assert [r["msg"] for r in query_logs(logs, trace_id="t-881")] == ["checkout started", "payment timeout"]
137 assert query_logs(logs, level="error")[0]["gateway"] == "pg-a"
138
139 # averages hide the tail: 98% of requests are fast, 2% very slow
140 lat = [rnd.uniform(80, 200) for _ in range(9_800)] + [rnd.uniform(3_000, 6_000) for _ in range(200)]
141 mean = sum(lat) / len(lat)
142 p50, p99 = exact_quantile(lat, 0.5), exact_quantile(lat, 0.99)
143 assert mean < 250 and p50 < 200 and p99 > 3_000 # the mean looks fine
144
145 # histograms: merge, don't average percentiles
146 a, b = Histogram(), Histogram()
147 for _ in range(9_000):
148 a.observe(rnd.uniform(40, 90)) # server A: healthy, busy
149 for _ in range(1_000):
150 b.observe(rnd.uniform(2_600, 4_800)) # server B: sick, less traffic
151 avg_of_p99 = (a.quantile(0.99) + b.quantile(0.99)) / 2
152 true_p99 = a.merge(b).quantile(0.99)
153 assert a.quantile(0.99) == 100 and b.quantile(0.99) == 5_000
154 assert avg_of_p99 == 2_550 and true_p99 == 5_000 # averaging understates it
155 assert a.merge(b).quantile(0.5) == 100
156
157 # cardinality
158 assert series_count({"endpoint": 20, "status": 5, "region": 3}) == 300
159 assert series_count({"endpoint": 20, "status": 5, "region": 3, "user_id": 1_000_000}) == 300_000_000
160
161 # traces: where did 1,840 ms go?
162 st = self_time(build_trace())
163 slowest = max(st, key=st.get)
164 assert slowest == "gateway.http" and st["gateway.http"] == 1_540
165 assert st["payment.charge"] == 20 # its own code was quick
166
167 # SLOs and error budgets: 99.9% of checkouts succeed, 30 days, 20M checkouts
168 assert round(error_budget(0.999, 20_000_000)) == 20_000
169 assert round(sli(19_985_000, 20_000_000), 5) == 0.99925 # within SLO
170 assert round(burn_rate(0.0144, 0.999), 1) == 14.4 # 1.44% errors burns 14.4x
171 assert round(30 * 24 / 14.4) == 50 # whole month's budget gone in ~50 h
172 assert should_page(0.02, 0.03, 0.999) # real incident
173 assert not should_page(0.02, 0.0005, 0.999) # already recovered: don't page
174 assert not should_page(0.003, 0.004, 0.999) # slow burn: ticket, not page
175
176 # debugging: errors concentrate in one version
177 reqs = []
178 for i in range(10_000):
179 version = "v42" if i % 4 == 0 else "v41"
180 region = ["mumbai", "delhi", "chennai"][i % 3]
181 bad = version == "v42" and rnd.random() < 0.2
182 reqs.append({"version": version, "region": region, "status": 500 if bad else 200})
183 by_version, by_region = breakdown(reqs, "version"), breakdown(reqs, "region")
184 assert by_version["v41"] == 0 and by_version["v42"] > 0.15
185 assert max(by_region.values()) - min(by_region.values()) < 0.03 # region isn't the cause
186
187 return {"mean_p50_p99": (round(mean), round(p50), round(p99)), "avg_p99_vs_true": (avg_of_p99, true_p99),
188 "slowest_span": (slowest, st[slowest]), "by_version": by_version}
189
190
191if __name__ == "__main__":
192 print("All checks pass.", run_checks())