Incident: Slow Products Category Query — Zava API (PostgreSQL Cold Cache Recurrence)

[wilkinshum]

Incident Report: Slow Products Category Query (Recurrence)

• Incident ID: 70f877d1-2427-8c7c-5ccd-efa31e920033
• Service: AKS — aks-Zava-auf6gw / PostgreSQL — zava-pg-auf6gw (rg: rg-zava-aks-postgres)
• Subscription: f627598e-05c5-4093-8667-5730c4026ea3
• FQDN: zava-pg-auf6gw.postgres.database.azure.com
• AKS Status: provisioningState: Succeeded, k8s v1.34
• Previous Incident: Incident: Slow Products Category Query — Zava API (PostgreSQL Cold Cache) dm-chelupati/grubify#310 (2026-06-22 — same root cause, filed in dm-chelupati/grubify)

Summary

The Zava-products-query-slow alert fired at 2026-06-23T00:31:07Z (Sev2) indicating that /api/products/category/<X> endpoints averaged well above the 30ms threshold (healthy baseline ~3ms). Category queries (Running, Cycling, Yoga, Swimming, Outdoor, Recovery, Training, Accessories) averaged 850–1050ms — a ~300x degradation from baseline. PostgreSQL buffer cache hit ratio was 0% with CPU at 92.3%, confirming all queries were hitting disk. This is a recurrence of the cold-cache pattern from the previous incident (dm-chelupati#310, 2026-06-22) — the recommended remediation actions were not implemented.

Impact

• All /api/products/category/* endpoints degraded to 850–1050ms avg latency (baseline ~3ms)
• Probe endpoint (__probe) latency spiked from ~2ms to 131ms
• PostgreSQL CPU saturated at 92.3% due to cold-cache disk I/O
• No HTTP 5xx errors observed — degradation was latency-only (no data loss)
• Affected all product category browsing for end users during the incident window

Timeline (UTC)

• 23:30–00:20: Baseline normal — probe at ~2ms, SELECT queries ~1.5ms, only health/products/probe traffic
• ~00:25: Category-specific queries (Running, Cycling, etc.) begin arriving; SELECT latency jumps to 345ms avg; pg.connect latency 530ms (7 new connections)
• ~00:30: SELECT latency escalates to 662ms avg; category endpoints at 850–1050ms; probe at 131ms
• 00:31:07: Zava-products-query-slow alert fires (Sev2)
• Ongoing: Cache hit ratio remains at 0%; CPU at 92.3%

Evidence

AppRequests — Category Query Latency (00:25–00:30 UTC)

Category	Avg Latency (ms) @ 00:25	Avg Latency (ms) @ 00:30	Max (ms)	Request Count
Training	1048.7	986.3	1560.4	139
Recovery	973.5	936.3	1447.4	153
Outdoor	945.5	909.3	1822.3	143
Swimming	895.7	930.0	1414.0	154
Yoga	865.9	952.6	1625.8	137
Cycling	863.2	850.4	1402.0	158
Running	861.4	921.3	1486.4	142
Accessories	285.0	297.2	449.8	148

Probe Endpoint Latency Timeline

Time (UTC)	Avg Latency (ms)	Status
23:30–00:20	~2.0–2.3	Normal baseline
00:25	41.3	Degraded
00:30	131.4	Severely degraded

PostgreSQL Dependency Latency (AppDependencies)

Time (UTC)	pg.query:SELECT Avg (ms)	pg.query:SELECT Count	pg.connect Avg (ms)
23:30–00:20	~1.5	~1,050/5min	N/A (pool warm)
00:25	345.3	1,348	530.3 (7 connects)
00:30	662.3	815	N/A

PostgreSQL Server Metrics (at incident time)

Metric	Value	Status
CPU	92.3%	CRITICAL
Memory	20.3%	OK
Cache Hit Ratio	0%	CRITICAL
Active Connections	22/859	OK
Disk IOPS	42.1%	Elevated
Disk Bandwidth	35.2%	Elevated
Temp File Usage	52 MB	Elevated
Storage	128 GB	OK

PostgreSQL Logs

• Regular 10-minute checkpoints — no shutdown/startup messages detected
• Only internal azuresu management connections in recent logs
• No application errors in PostgreSQL logs

Infrastructure Status

Resource	State	Notes
PostgreSQL zava-pg-auf6gw	Ready	v16, Standard_D2ds_v5, Sweden Central
AKS aks-Zava-auf6gw	Succeeded	k8s v1.34, 3 nodes
Resource Health	Available	No platform events
Activity Log (stop/start)	Empty	No manual stop/start detected

Root Cause

PostgreSQL cold buffer cache (cache hit ratio = 0%) causing all product-category queries to hit disk instead of shared_buffers, resulting in ~300x latency degradation. When category-specific traffic began at ~00:25 UTC, the buffer cache did not have the required data pages cached. Every SELECT had to read from disk, causing elevated disk I/O (42% IOPS, 35% bandwidth) and CPU saturation (92.3%).

This is a recurrence of the same cold-cache pattern from 2026-06-22 (issue dm-chelupati#310 in dm-chelupati/grubify). The recommended remediation actions from that incident were not implemented:

1. Index on products(category) was not created — queries likely use sequential scans
2. pg_prewarm was not configured for post-restart cache warming
3. log_min_duration_statement remains disabled (-1) — slow queries invisible
4. metrics.collector_database_activity remains OFF — limited observability

Contributing factors:

• No server restart detected (regular checkpoints, no startup logs), but cache hit ratio has been persistently at 0%
• Missing index forces full table scans for category filtering
• Temp file usage (52MB) indicates queries spilling to disk due to insufficient work_mem

Remediation

• Database: Create index: CREATE INDEX CONCURRENTLY idx_products_category ON products(category) to eliminate sequential scans for category queries
• Cache Warming: Configure pg_prewarm extension to pre-load critical tables into shared_buffers after restarts
• Observability: Enable slow query logging: set log_min_duration_statement = 100 (ms) to capture slow queries
• Observability: Enable enhanced metrics: set metrics.collector_database_activity = ON for per-database activity metrics
• Performance: Consider increasing work_mem from 4MB to 16MB to reduce temp file spills
• Platform: Enable High Availability on PostgreSQL Flexible Server to reduce cold-cache risk from failovers

Action Items

#	Action	Priority
1	Create index on products(category) column	High
2	Enable log_min_duration_statement = 100	High
3	Enable metrics.collector_database_activity = ON	High
4	Configure pg_prewarm for critical tables	Medium
5	Increase work_mem to 16MB	Medium
6	Investigate persistent 0% cache hit ratio	Medium
7	Enable High Availability on PostgreSQL	Low
8	Add cache warm-up script to post-deployment/restart pipeline	Low

References

• PostgreSQL Server: /subscriptions/f627598e-05c5-4093-8667-5730c4026ea3/resourceGroups/rg-zava-aks-postgres/providers/Microsoft.DBforPostgreSQL/flexibleServers/zava-pg-auf6gw
• AKS Cluster: /subscriptions/f627598e-05c5-4093-8667-5730c4026ea3/resourceGroups/rg-zava-aks-postgres/providers/Microsoft.ContainerService/managedClusters/aks-Zava-auf6gw
• Log Analytics Workspace ID: 69f6cc9c-c59f-4624-8b95-e12b93220ece
• Log Analytics ARM ID: /subscriptions/f627598e-05c5-4093-8667-5730c4026ea3/resourceGroups/rg-zava-aks-postgres/providers/Microsoft.OperationalInsights/workspaces/law-Zava-auf6gw
• App Insights: /subscriptions/f627598e-05c5-4093-8667-5730c4026ea3/resourceGroups/rg-zava-aks-postgres/providers/Microsoft.Insights/components/ai-Zava-auf6gw
• App Insights App ID: 397041f5-0122-4b79-bb80-59b181c42270
• Alert Rule: /subscriptions/f627598e-05c5-4093-8667-5730c4026ea3/resourceGroups/rg-zava-aks-postgres/providers/microsoft.insights/scheduledqueryrules/Zava-products-query-slow
• SRE Agent Thread: https://sre.azure.com/agents/subscriptions/f627598e-05c5-4093-8667-5730c4026ea3/resourceGroups/rg-sre-lab/providers/Microsoft.App/agents/sre-agent-jkazytu5kl5py/views/thread/d62560e1-fd83-4998-a9f2-7aab5981f309

---

This issue was created by sre-agent-jkazytu5kl5py--70975bf6
Tracked by the SRE agent here