chaos-demo responses are taking 8 seconds
Correct.
The injected fault was slow-query: one route runs an unindexed scan.
Incident report
confidence high · started 11:20:40
Root cause
Unindexed scan on /reports. The route filters orders on customer_note with ILIKE, which runs a sequential scan of the whole table on every request.
category · slow_query
Symptom
Requests to /reports take about 8 seconds from 11:20. Health probes still pass, no 5xx, other routes are fast.
Proposed fix
Add an index that serves the /reports filter (a trigram index on orders.customer_note), or change the query to filter on an indexed column.
6tool calls
3m 02sfault to report
56,780tokens in
$0.0071costhaiku-5-5
haiku-5-5model
How it got there
01 get_health 0.4s up · 3 of 3 probes passing · latency 8.2s, was 0.08s before 11:20
Checking whether the app is up and how slow the probe is.
get_health(app="chaos-demo", since="30m")
probe chaos-demo.xodhiambo.com
10:51–11:20 up p50 0.08s
11:20–now up p50 8.2s
query · probe_success{job="blackbox", instance=~".*chaos-demo.xodhiambo.com.*"}
probe_duration_seconds{job="blackbox", instance=~".*chaos-demo.xodhiambo.com.*"}
02 get_error_rate 0.8s no 5xx in the last 30m
Up but slow. If requests were timing out there would be 5xx, so checking errors.
get_error_rate(app="chaos-demo", since="30m")
0 lines matched status >= 500
query · sum by (status) (count_over_time({job="nginx", app="chaos-demo"} | json | status >= 500 [1m]))
03 get_container_stats 0.6s 1 process · 0 restarts · memory 38% · no deploy in window
No errors. Ruling out a starved or restarting container.
get_container_stats(app="chaos-demo")
web up memory 195 MiB of 512 MiB (38%) CPU 9% restarts 0
last start 1 Nov 09:12 (before the window)
query · max by (process_type) (container_memory_working_set_bytes{job="cadvisor", app="chaos-demo"}) / max by (process_type) (container_spec_memory_limit_bytes{job="cadvisor", app="chaos-demo"})
sum by (process_type) (rate(container_cpu_usage_seconds_total{job="cadvisor", app="chaos-demo"}[5m]))
max by (process_type) (container_start_time_seconds{job="cadvisor", app="chaos-demo"})
changes(container_start_time_seconds{job="cadvisor", app="chaos-demo"}[30m])
04 get_slow_traces 1.2s 5 traces over 2s · all GET /reports · 97% in one SELECT
Container is healthy and idle, so the time is spent inside requests. Traces will show which route and which span.
get_slow_traces(app="chaos-demo", since="15m", min_duration="2s")
8.31s GET /reports slowest span SELECT orders 8.07s (97%)
8.24s GET /reports slowest span SELECT orders 8.01s (97%)
8.22s GET /reports slowest span SELECT orders 7.99s (97%)
8.19s GET /reports slowest span SELECT orders 7.96s (97%)
8.15s GET /reports slowest span SELECT orders 7.92s (97%)
query · {resource.service.name="chaos-demo"} | duration > 2s
05 get_app_logs 0.5s 2 distinct messages · 128 lines
One query on one route. The logs may show the statement itself.
get_app_logs(app="chaos-demo", since="15m", contains="reports")
64× slow query 8.1s: SELECT * FROM orders WHERE customer_note ILIKE $1
64× GET /reports 200 8.2s
query · {job="docker", app="chaos-demo"} |= "reports"
06 get_host_stats 0.5s disk 62% free · memory 3.1 GiB available · load 0.4 · all normal
Making sure the host is not the reason the query is slow.
get_host_stats(app="chaos-demo")
disk / 62% free ok
memory 3.1 GiB available ok
load (5m) 0.4 on 4 cores ok
query · node_filesystem_avail_bytes{job="node", mountpoint="/"} / node_filesystem_size_bytes{job="node", mountpoint="/"}
node_memory_MemAvailable_bytes{job="node"}
node_load5{job="node"}
07 submit_report Report recorded.
The slow route, the query and a clean host point to one unindexed scan.
submit_report(cause_category="slow_query", confidence="high")
Queries are shown on each step. Logs, metrics and traces come from the server's own Prometheus, Loki and Tempo.