| name | human-readable-timestamp-logging |
| description | Add human-readable timestamped logging with per-function timing breakdowns to identify latency bottlenecks. Use when instrumenting code, adding observability, profiling request flows (API routes, dependencies, DB calls), or when the user asks to measure latency, performance, or bottlenecks. |
Human-Readable Timestamp Logging & Latency Breakdown
Goal: produce logs that are easy for humans to read and show detailed timing breakdowns per function/step so bottlenecks are obvious.
Do not add noisy logs everywhere—log structured spans around meaningful steps.
What “Good” Looks Like
Log requirements
- Human-readable timestamp (local time) at the start of each main log line.
- A correlation id per request/operation (e.g., short hex) to connect all lines.
- A scope label (e.g.,
[categories:d4914999]) for route/module context.
- Per-step durations in ms with consistent alignment.
- Indented sub-spans for nested steps (dependencies, DB, external calls).
- Total time for the whole operation + route total.
- Optional metadata:
rows=, status=, cache=hit/miss, db=pool, etc.
Example output style (format target)
This is a format target; actual code can differ.
INFO: 127.0.0.1:52715 - "OPTIONS /api/v1/categories/{id}/exam/status HTTP/1.1" 200 OK
├─ dependency.db.acquire: 0.1ms
├─ dependency.auth.validate: 0.0ms
INFO: [categories:d4914999] db.connection 99.04 ms
⚠️ [15464d1a] repo.category.get_all_active 69.50 ms
INFO: [categories:d4914999] repo.get_all_active 69.66 ms | rows=16
INFO: [categories:d4914999] repo.get_all_category_progress 2.09 ms | rows=17
INFO: [categories:d4914999] repo.get_card_counts_batch 1.80 ms | rows=16
INFO: [categories:d4914999] python.build_response 0.48 ms | rows=16
INFO: [categories:d4914999] total 173.87 ms
📍 [15464d1a] route.categories.list 175.60 ms
