From 3b10d3859e4cb76a871fb6cef671c8ef4be1dbc3 Mon Sep 17 00:00:00 2001 From: Jeff Luo Date: Fri, 28 Aug 2026 15:36:42 -0400 Subject: [PATCH 1/2] docs: add symptom-first troubleshooting guides The metric registry says what each instrument measures, and the observability guide says how telemetry is collected, but neither takes an operator from a symptom to a cause. A user reporting a slow request or a 503 had no path through the data. These three guides each start at a symptom and end at a component. Every step gives a query, says how to read the result, and names the next step or the guide to switch to. The shared index holds what all three need: the two spellings of the instrument names and which ingest path produces each, the four reasons a query returns nothing, and the pointer to the subsystems that emit no metrics at all. Every query was run against a live cluster, and the readings drove the text: the resume label is only meaningful next to the outcome, a fleet gauge that every replica reports needs max rather than sum, and a phase histogram has to exclude failures before its quantile means anything. --- README.md | 1 + docs/observability.md | 4 + docs/troubleshooting/README.md | 116 ++++++ docs/troubleshooting/capacity-is-full.md | 281 +++++++++++++++ docs/troubleshooting/requests-are-slow.md | 216 ++++++++++++ docs/troubleshooting/resumes-are-slow.md | 410 ++++++++++++++++++++++ 6 files changed, 1028 insertions(+) create mode 100644 docs/troubleshooting/README.md create mode 100644 docs/troubleshooting/capacity-is-full.md create mode 100644 docs/troubleshooting/requests-are-slow.md create mode 100644 docs/troubleshooting/resumes-are-slow.md diff --git a/README.md b/README.md index f3f110a6dd..e488e5acdf 100644 --- a/README.md +++ b/README.md @@ -219,6 +219,7 @@ We provide several sample applications demonstrating Agent Substrate's capabilit * [Glossary](docs/glossary.md): Core terms (Actor, Atespace, ActorTemplate, WorkerPool, Worker, ate-api-server, atenet, atelet, ateom) and how they relate. * [Integration Repositories](docs/integration-repos.md): Where integrations live, how their repositories are named, and how fixes flow back to core. * [Observability Guide](docs/observability.md): Guide to actor logging, metrics, and distributed tracing. +* [Troubleshooting Guides](docs/troubleshooting/README.md): Symptom-first guides that go from a slow request or a 503 to the component that caused it. * [Authentication Guide](docs/authentication.md): Configure trusted JWT providers and human credentials. * [Request Parking](docs/request-parking.md): How the router parks requests through transient worker-pool saturation. * [Threat Model](docs/threat-model.md): Trust boundaries, assumptions, and known risks. diff --git a/docs/observability.md b/docs/observability.md index 91b121eff4..fde2225246 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -149,6 +149,10 @@ Agent Substrate emits foundational OpenTelemetry system and server metrics to mo > [`docs/metrics/registry/metrics.yaml`](metrics/registry/metrics.yaml) defines each instrument. Read it when you need all the labels, the bucket limits, or the permitted values of a label. The table below does not have each instrument. The request-parking instruments and the actor resource-usage instruments are in the registry only. Refer to [The metric registry](#the-metric-registry). +> To go from a symptom to a component, read the +> [troubleshooting guides](troubleshooting/README.md). They use the instruments +> below, step by step. + | Metric | Emitted by | Type | Measures | |--------|------------|------|----------| | `rpc.server.call.duration` | ateapi & atelet (gRPC servers, via `otelgrpc`) | histogram | per-method gRPC latency, request rate, and errors (labels `rpc.method`, `rpc.response.status_code`) | diff --git a/docs/troubleshooting/README.md b/docs/troubleshooting/README.md new file mode 100644 index 0000000000..d1463f2ee7 --- /dev/null +++ b/docs/troubleshooting/README.md @@ -0,0 +1,116 @@ +# Troubleshooting Agent Substrate + +These guides start from a symptom that a user or an operator sees, and end at +the component that caused it. Each one is a sequence of steps. Each step gives +a query, tells you how to read the result, and sends you to the next step or to +a different guide. + +| Guide | Start here when | +|---|---| +| [Requests are slow or return 503](requests-are-slow.md) | A client waited too long, or got a 503 | +| [Substrate has no capacity for an actor](capacity-is-full.md) | A resume fails because no worker is free, or a constraint hides the free ones | +| [Resumes are slow](resumes-are-slow.md) | The activation of a suspended actor is slow | + +**Start with [Requests are slow](requests-are-slow.md)** when a user reports a +fault. It is the triage: it tells you whether the cause is capacity, a resume, +the router, or the code of the actor. The other two guides go deeper into one +cause each. + +The instruments and their labels are defined in +[`docs/metrics/registry/metrics.yaml`](../metrics/registry/metrics.yaml), which +is the source of truth. [`docs/observability.md`](../observability.md) +describes logs, metrics, and traces as a whole. + +## The two paths + +Substrate has two paths, and the first question is always which one is slow. + +| Path | Who calls it | What it carries | +|---|---|---| +| Data plane | A client of the application | The traffic of the workload to an actor | +| Control plane | An operator, or the router | The lifecycle operations: create, resume, suspend, pause, delete | + +Each actor has one address, which atenet resolves: + +``` +..actors.resources.substrate.ate.dev +``` + +Envoy receives the request, and the atenet router makes the route decision +through the ext_proc interface of Envoy. The router resumes the actor first if +it is not on a worker. + +``` +client -> atenet DNS -> Envoy --ext_proc--> atenet router -> ateapi (if a resume is necessary) + | | + +--> worker pod <-- atelet restore <---+ +``` + +## The names on your backend + +Each step gives its query twice, once for each spelling of the names. Which one +you need depends on how the telemetry was ingested, not on where the cluster +runs. + +Substrate emits one name over OTLP, for example `ate.actor.crashes`. A path +that writes the Prometheus format applies three edits: each dot becomes an +underscore, the unit goes into the name, and a counter gets `_total`. A path +that takes the OTLP data as it is keeps the name of the instrument. + +| Ingest path | Name to query | +|---|---| +| Collector Prometheus exporter, or the default OTLP receiver of Prometheus | `ate_actor_crashes_total` | +| Google `googlemanagedprometheus` collector exporter | `ate_actor_crashes_total` | +| Google Telemetry API (`telemetry.googleapis.com`), used by the GKE managed collector | `ate.actor.crashes` | +| Prometheus with `otlp: translation_strategy: NoTranslation` | `ate.actor.crashes` | + +A dotted name is not a valid PromQL identifier, thus a backend that keeps the +dots needs the quoted form. Prometheus 3.0 and the Google Managed Prometheus +API both accept it: + +| Standard name | Dotted name | +|---|---| +| `atenet_router_route_duration_seconds_bucket` | `{__name__="atenet.router.route.duration_bucket"}` | +| `atenet_router_parking_rejected_total` | `{__name__="atenet.router.parking.rejected"}` | +| `sum by (ate_router_resume)` | `sum by ("ate.router.resume")` | + +**One query cannot serve both.** A name that matches the two spellings needs a +regular expression, and Cloud Monitoring refuses one on the name of a metric: +`=~ is an unsupported matchtype for the __name__ label`. A regular expression +on each other label is permitted. + +Do not ingest by both paths at the same time. Each path makes its own metric +descriptor, thus one instrument becomes two sets of data. + +## A query that returns nothing + +An empty result reads like a healthy system, thus it is the most dangerous +answer a query can give. There are four causes, and only one is a fault. + +1. **The name is wrong for the backend.** A standard underscore name does not + fail on Cloud Monitoring. It returns no data. Try the dotted name. +2. **Nothing happened in the window.** `rate(...[5m])` needs two samples in the + last five minutes. Widen the window, or read the counter with no window and + no function, which always draws a line: + + ```promql + sum by (ate_router_outcome) (atenet_router_route_duration_seconds_count) + ``` + +3. **The condition never occurred.** An OpenTelemetry counter is exported only + after its first increase, and a histogram after its first measurement. + `ate.actor.restore.duration` is absent on a cluster that only boots new + actors, because a boot is not a restore. +4. **The instrument is not in the deployed binary.** No metric can report its + own absence. Confirm the build rather than the query, for example: + + ```sh + kubectl logs -n ate-system -l app=atelet --tail=-1 | grep "Actor stats poller starting" + ``` + +## The subsystems with no metrics + +Each guide ends with the blind spots that apply to it. Read them before you +give the cause of a fault to a component that has metrics. +[`docs/metrics/substrate.yaml`](../metrics/substrate.yaml) holds the full list, +with the cardinality rules and the known exceptions. diff --git a/docs/troubleshooting/capacity-is-full.md b/docs/troubleshooting/capacity-is-full.md new file mode 100644 index 0000000000..a95c544331 --- /dev/null +++ b/docs/troubleshooting/capacity-is-full.md @@ -0,0 +1,281 @@ +# Substrate has no capacity for an actor + +## Context + +Substrate puts many actors on few workers. A worker is a pod in a WorkerPool. +An actor must hold a worker to run. When each worker is assigned, a new resume +cannot start. The router parks the request, and then it returns +`503 no free workers available`. + +Two different states look the same at the edge: + +| State | What it means | Where to see it | +|---|---|---| +| The pool is full | Each worker has an actor. | `ate.workerpool.workers`, state `idle` = 0 | +| The pool did not grow | Kubernetes did not give the pods that the pool asked for. | `desired_workers` − `ready_workers` > 0 | +| The workers are hidden | Free workers exist, but a constraint removes them. | `ate.scheduler.eligible_workers` = 0 | + +The last state is the one that confuses people. `ate.workerpool.workers` shows +idle workers and the resumes still fail. + +Two pool keys identify a pool together: `ate.workerpool.namespace` and +`ate.workerpool.name`. A WorkerPool has a namespace, thus the name alone merges +the pools of different namespaces into one series. + +Each step gives the query in two forms. Refer to +[the naming rules](README.md#the-names-on-your-backend) for which form your +backend needs, and for the three reasons a query can return nothing. + +--- + +## Step 1. Compare the demand with the supply + +**Prometheus** + +```promql +max by (ate_workerpool_namespace, ate_workerpool_name, ate_worker_state) ( + ate_workerpool_workers) +``` + +**Cloud Monitoring / GMP** + +```promql +max by("ate.workerpool.namespace", "ate.workerpool.name", "ate.worker.state") ( + {__name__="ate.workerpool.workers"}) +``` + +**Use `max` and not `sum` across the replicas of ateapi.** Each ateapi replica +reports the whole fleet, thus a sum multiplies the fleet by the number of +replicas. Two replicas make 10 idle workers read as 20. The `instance` label +divides the replicas: + +**Prometheus** + +```promql +sum by (instance, ate_worker_state) (ate_workerpool_workers) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by(instance, "ate.worker.state") ({__name__="ate.workerpool.workers"}) +``` + +After the `max`, you can add the counts together. The sum across the states is +the size of the pool. The sum across the pools is the size of the fleet. + +* `idle` = 0 — the pool is full. Go to step 2. +* `idle` > 0 and the resumes still fail — a constraint hides the workers. Go to + step 3. + +## Step 2. Find out if the new capacity arrived + +**Prometheus** + +```promql +ate_workerpool_desired_workers + - on(ate_workerpool_namespace, ate_workerpool_name) + ate_workerpool_ready_workers +``` + +**Cloud Monitoring / GMP** + +```promql +{__name__="ate.workerpool.desired_workers"} + - on("ate.workerpool.namespace", "ate.workerpool.name") + {__name__="ate.workerpool.ready_workers"} +``` + +A value above 0 for more than a few minutes means that Kubernetes did not give +the pods. The usual causes are an empty node pool, a quota, or a worker pod +that cannot start. + +```bash +kubectl ate get workers +kubectl get pods -n -o wide +kubectl describe pod -n +kubectl get events -n --sort-by=.lastTimestamp | tail -20 +``` + +If the difference is 0, the pool has each pod that it asked for. The pool is +too small. Make `spec.replicas` larger, or add nodes. + +## Step 3. Find out if a constraint hides the workers + +`ate.scheduler.eligible_workers` counts the free workers that remain after each +constraint filter. This is an early sign. It warns you before the first +rejection. + +**Prometheus** + +```promql +histogram_quantile(0.5, sum by (le, ate_scheduling_constraint) ( + rate(ate_scheduler_eligible_workers_bucket[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.5, sum by(le, "ate.scheduling.constraint") ( + rate({__name__="ate.scheduler.eligible_workers_bucket"}[5m]))) +``` + +| `ate.scheduling.constraint` | Meaning | +|---|---| +| `none` | The request has no constraint. | +| `selector` | A label selector of an actor or a template applies. | +| `required_nodes` | The request is pinned to specific node VMs. | + +**The value of this key does not tell you the cause.** An ActorTemplate with a +`workerSelector` makes each of its requests `selector`, thus you never see +`none` for that template. Compare this histogram with the idle count from step +1 instead: + +| Idle count (step 1) | Eligible workers | Cause | +|---|---|---| +| 0 | 0 | The pool is full. The constraint is not the subject. Go to step 2. | +| Above 0 | 0 | The constraint hides the free workers. Examine the selector of the actor and of the template, and the labels of the workers. | +| Above 0 | Above 0 | The capacity is available. The fault is elsewhere. Go to step 4. | + +A series with **both pool keys empty** means that no pool agreed with the +request. Only this instrument reports that state, as one series with the value +0. + +## Step 4. Read the decision of the scheduler + +**Prometheus** + +```promql +sum by (ate_scheduler_outcome) ( + rate(ate_scheduler_assignment_duration_seconds_count[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.scheduler.outcome") ( + rate({__name__="ate.scheduler.assignment.duration_count"}[5m])) +``` + +| Outcome | Meaning | +|---|---| +| `assigned` | The scheduler took a worker. | +| `no_free_worker` | No free worker was available. This shows the capacity. It is not a failure, thus it has no `error.type` key and it names no pool. | +| `error` | The attempt failed. Only this outcome has an `error.type` key. | + +**Prometheus** + +```promql +sum by (ate_scheduler_outcome, error_type) ( + rate(ate_scheduler_assignment_duration_seconds_count{ + ate_scheduler_outcome="error"}[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.scheduler.outcome", "error.type") ( + rate({__name__="ate.scheduler.assignment.duration_count", + "ate.scheduler.outcome"="error"}[5m])) +``` + +The scheduler can also be slow and not full: + +**Prometheus** + +```promql +histogram_quantile(0.95, sum by (le) ( + rate(ate_scheduler_assignment_duration_seconds_bucket{ + ate_scheduler_outcome="assigned"}[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.95, sum by(le) ( + rate({__name__="ate.scheduler.assignment.duration_bucket", + "ate.scheduler.outcome"="assigned"}[5m]))) +``` + +This step is a read of the cache and some writes to the store. A large value +means a delay in the store. The store has no metrics. Read the logs of ateapi. + +## Step 5. Measure the cost at the edge + +The steps above measure the fleet. This step measures what the users pay. + +**Prometheus** + +```promql +sum by (ate_router_outcome) ( + rate(atenet_router_route_duration_seconds_count[5m])) + +atenet_router_parking_active + +sum(rate(atenet_router_parking_rejected_total[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.router.outcome") ( + rate({__name__="atenet.router.route.duration_count"}[5m])) + +{__name__="atenet.router.parking.active"} + +sum(rate({__name__="atenet.router.parking.rejected"}[5m])) +``` + +* `no_capacity` on the router — the park budget ended and the fleet stayed + full. The user got a 503 error. +* `parking.rejected` above zero — the parking area is full. The router sheds + load before it tries a resume. + +Refer to [requests-are-slow.md](requests-are-slow.md) for the full path. + +## Step 6. Find out if the pressure is real + +A pool that is full of actors that do no work is a different fault. Read the +resource use of the node: + +**Prometheus** + +```promql +sum by (ate_template_name, ate_stats_source) ( + ate_actor_stats_memory_working_set_bytes) + +sum by (ate_template_name) ( + rate(ate_actor_stats_cpu_time_seconds_total[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.template.name", "ate.stats.source") ( + {__name__="ate.actor.stats.memory.working_set"}) + +sum by("ate.template.name") ( + rate({__name__="ate.actor.stats.cpu.time"}[5m])) +``` + +Group the data by `ate.stats.source`. Do not add the sources together. The +`cgroup` source includes the load of the sandbox runtime. The `guest-agent` +source includes only the containers of the workload. + +```bash +kubectl ate top workers +kubectl ate get actors -A +``` + +If the workers hold actors that are idle, the suspend policy is the subject, +not the size of the pool. + +--- + +## The blind spots of this scenario + +| Area | Effect | +|---|---| +| The worker cache in ateapi | If the view of the fleet is old, the scheduler gives a worker that is not in operation. This looks like a resume failure with no cause in the scheduler data. | +| The actor population | Nothing counts the actors by state. These metrics count the operations, not the actors. | +| The store in ateapi | A delay looks like unmeasured time in the assignment histogram. | diff --git a/docs/troubleshooting/requests-are-slow.md b/docs/troubleshooting/requests-are-slow.md new file mode 100644 index 0000000000..11850464f6 --- /dev/null +++ b/docs/troubleshooting/requests-are-slow.md @@ -0,0 +1,216 @@ +# Requests are slow or return 503 + +## Context + +The requests are the **data-plane requests of the workload**. They are the HTTP +or gRPC calls that a client sends to the address of the actor: + +``` +..actors.resources.substrate.ate.dev +``` + +They are not `kubectl ate` commands. Those go to ateapi. Use +`rpc.server.call.duration` for a slow command. + +`atenet.router.route.duration` measures only the decision of the router: from +the moment Envoy gives the request to the router, to the moment the router +gives the worker endpoint back. It does **not** include the work of the actor, +and it does not include the response. + +| The client is slow | The router metric | Where the cause is | +|---|---|---| +| Yes | Large | In Substrate. Use the steps below. | +| Yes | Small | In the code of the actor, or in the network. Read the logs of the actor. | +| No | Large | Somebody waited, but not this client. For example, an operator did a resume. | + +Three different faults give a 503 error to the client: + +| What the client sees | Label | Cause | +|---|---|---| +| A slow but correct response | `ate.router.resume="triggered"` | The actor was not on a worker. The request paid for the resume. | +| `503 no free workers available` | `ate.router.outcome="no_capacity"` | The park budget ended. The fleet stayed full. | +| `503 router at capacity` | Counted in `parking.rejected` | The parking area is full. The router sheds load. | +| A 503 error with no capacity pressure | `ate.router.outcome="resume_error"` | A defect. Examine the router and ateapi. | + +**Parking** is why a full fleet does not immediately give an error. The router +holds the request and does the resume again with a backoff. Refer to +[request-parking.md](../request-parking.md). The router also puts the requests +for the **same** actor into one resume. Thus 50 requests on one cold actor make +one `triggered` sample and 49 `joined` samples. Do not read `joined` as 50 slow +activations. + +Each step gives the query in two forms. Refer to +[the naming rules](README.md#the-names-on-your-backend) for which form your +backend needs, and for the three reasons a query can return nothing. + +--- + +## Step 1. Find the outcome + +**Prometheus** + +```promql +sum by (ate_router_outcome) ( + rate(atenet_router_route_duration_seconds_count[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.router.outcome") ( + rate({__name__="atenet.router.route.duration_count"}[5m])) +``` + +| Outcome | Go to | +|---|---| +| `no_capacity` | The fleet has no free worker. Read [capacity-is-full.md](capacity-is-full.md). | +| `resume_error` | Step 3, and then the logs of ateapi. | +| `ok` but slow | Step 2. | +| `ok`, but the client got an error | The fault is after the boundary of the router. The router found the endpoint and Envoy could not use it. Go to step 5. | +| `timeout` | The resume did not finish in the park budget. Go to step 3, and then read the logs of atelet on the worker node. | +| `cancelled` | The client gave up. Read step 2 to find how long it waited. | + +`ok` on this metric means only that the router found an endpoint. It does not +mean that the client got an answer. + +## Step 2. Divide the warm route from the resume + +**Keep both `ate.router.outcome` and `ate.router.resume` in the `by()` clause.** +The resume state alone does not tell you what it means, because the router also +reports `none` for a request that stopped before it reached a resume state. The +outcome is what separates the two readings, thus the query must group by both. + +Keep the resume key for a second reason: if you remove it, the aggregation adds +the warm route to the activation, and one distribution then holds both +milliseconds and seconds. On this data the warm route is 23 ms and the +activation is 488 ms, thus a merged number describes neither. + +**Prometheus** + +```promql +histogram_quantile(0.95, sum by (le, ate_router_outcome, ate_router_resume) ( + rate(atenet_router_route_duration_seconds_bucket[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.95, sum by(le, "ate.router.outcome", "ate.router.resume") ( + rate({__name__="atenet.router.route.duration_bucket"}[5m]))) +``` + +**Read this key only together with the outcome.** `none` is also the value that +the router uses when the request never got as far as a resume state. Thus a +failed route reports `none` although it did try to resume. + +| Series | With `outcome="ok"` | With a failed outcome | +|---|---|---| +| `none` | The warm route. The actor was already in operation. This must stay in milliseconds. Go to step 3. | No information. The request stopped before the router set the state. Use step 3 and step 4. | +| `triggered` | This request did the resume. Go to [resumes-are-slow.md](resumes-are-slow.md). | The resume failed. Go to [resumes-are-slow.md](resumes-are-slow.md). | +| `joined` | This request waited for the resume of a different request. Do not count these as separate activations. | The same, and the flight that it joined failed. | + +## Step 3. Examine the queue in the router + +**Prometheus** + +```promql +atenet_router_parking_active + +sum(rate(atenet_router_parking_rejected_total[5m])) + +histogram_quantile(0.95, sum by (le, outcome) ( + rate(atenet_router_parking_wait_duration_seconds_bucket[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +{__name__="atenet.router.parking.active"} + +sum(rate({__name__="atenet.router.parking.rejected"}[5m])) + +histogram_quantile(0.95, sum by(le, outcome) ( + rate({__name__="atenet.router.parking.wait.duration_bucket"}[5m]))) +``` + +* `parking.active` near the configured maximum (`--parked-request-max`, + default 1024) means that the parking area is almost full. +* `parking.rejected` above zero means that the router refuses requests at the + edge. Make the pool larger, or make the parking area larger. +* The `outcome` label on the wait histogram does not start with `ate.`. This is + a known exception in `docs/metrics/substrate.yaml`. + +| `outcome` | Meaning | +|---|---| +| `served` | The resume was correct and the router sent the request. | +| `budget_exhausted` | The park budget ended. The fleet stayed full. | +| `timeout` | The time limit of the request ended. | +| `canceled` | The client disconnected. | +| `error` | The resume failed. | + +A value of `budget_exhausted` below the full budget is normal. The budget is +per flight. A request that joins a flight late shares the remaining budget. + +## Step 4. Find out if a component is slow + +**Prometheus** + +```promql +histogram_quantile(0.95, sum by (le, rpc_method) ( + rate(rpc_server_call_duration_seconds_bucket[5m]))) + +histogram_quantile(0.95, sum by (le, rpc_method) ( + rate(rpc_client_call_duration_seconds_bucket[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.95, sum by(le, "rpc.method") ( + rate({__name__="rpc.server.call.duration_bucket"}[5m]))) + +histogram_quantile(0.95, sum by(le, "rpc.method") ( + rate({__name__="rpc.client.call.duration_bucket"}[5m]))) +``` + +Compare the two for the same method. If the client number is much larger than +the server number, the delay is not in the handler. It is in the network or in +a queue. + +## Step 5. Read the actor + +```bash +kubectl ate get actors -a +kubectl ate logs actors -a -f +``` + +If the route duration is small but the client is slow, the cause is here. No +Substrate metric covers the work of the actor. + +An actor can run more than one container. `--container`, or `-c`, keeps only +the lines of the named container: + +```bash +kubectl ate logs actors -a -c +``` + +Two things to know before you use it: + +* **It also removes the lifecycle records.** `Actor started`, `Actor restored` + and the others are about the actor, thus no container produced them and no + container name selects them. Read the logs without `-c` when you need the + lifecycle of the actor together with its output. +* **A name that does not match gives no output and no error.** The command ends + with status 0 and an empty result, which looks the same as a silent actor. + Take the container names from the ActorTemplate. + +--- + +## The blind spots of this scenario + +| Area | Effect | +|---|---| +| The work of the actor and the response | Outside the route duration. No metric. | +| atenet-dns | No instruments. If a reload fails, the answers stay old and no signal shows it. | +| The shutdown of the router | Nothing counts a drain that ends with an error. | +| The store in ateapi | A delay looks like unmeasured time inside a resume. | diff --git a/docs/troubleshooting/resumes-are-slow.md b/docs/troubleshooting/resumes-are-slow.md new file mode 100644 index 0000000000..364b718c65 --- /dev/null +++ b/docs/troubleshooting/resumes-are-slow.md @@ -0,0 +1,410 @@ +# Resumes are slow + +> Some documents call this a cold start. Substrate says **resume**, because the +> usual path restores a snapshot. It does not boot the actor from nothing. + +## Context + +A **resume** is the activation of an actor that is not on a worker. An actor is +idle most of the time, and Substrate suspends it to release its worker. The +next request must put the actor back on a worker before the actor can answer. +The request waits for that. This is the `triggered` series of +[requests-are-slow.md](requests-are-slow.md), measured from the other end. + +Two states give a resume, and their cost is not the same: + +| State before | Where the snapshot is | Cost | +|---|---|---| +| Paused | On the node VM, and the resume prefers that node | Low. No download. | +| Suspended | In object storage (GCS or S3) | High. A download and an unpack. | + +`ate.snapshot.kind` tells you which snapshot the resume read: + +| Value | Meaning | +|---|---| +| `local` | A snapshot on the node. A pause wrote it. | +| `latest` | The durable snapshot of the actor. | +| `golden` | The image of the ActorTemplate. This is the first activation of a new actor. | +| `boot` | A start from nothing. A boot is not a restore, thus this value never occurs on the atelet histograms. | + +Two instruments measure a resume. They do not measure the same part: + +| Metric | Emitted by | What it covers | +|---|---|---| +| `ate.actor.lifecycle.operation.duration` with `ate.actor.operation.name="resume"` | ateapi | The full operation, with the scheduler. | +| `ate.actor.restore.duration` | atelet | Only the part on the worker node. | + +If the ateapi number is much larger than the atelet `total` phase, the delay is +before the handoff. Examine the scheduler in step 5, and read the blind spots. + +**Do not add the phases together.** The download occurs at the same time as the +asset fetch and the OCI unpack. Each phase is an independent measurement. Use +`total` as the denominator. A phase that did not start is absent. It is not +zero. + +Each step gives the query in two forms. Refer to +[the naming rules](README.md#the-names-on-your-backend) for which form your +backend needs, and for the three reasons a query can return nothing. + +--- + +## Step 1. Confirm that the resume is the cause + +Read the two numbers together. The top line is what the user paid. The bottom +line is what the node used. + +**Prometheus** + +```promql +histogram_quantile(0.95, sum by (le) ( + rate(atenet_router_route_duration_seconds_bucket{ + ate_router_resume="triggered"}[5m]))) + +histogram_quantile(0.95, sum by (le) ( + rate(ate_actor_restore_duration_seconds_bucket{ + ate_snapshot_phase="total"}[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.95, sum by(le) ( + rate({__name__="atenet.router.route.duration_bucket", + "ate.router.resume"="triggered"}[5m]))) + +histogram_quantile(0.95, sum by(le) ( + rate({__name__="ate.actor.restore.duration_bucket", + "ate.snapshot.phase"="total"}[5m]))) +``` + +* The two numbers agree — the node is the cause. Go to step 2. +* The router number is much larger — the time went to the queue or to the + scheduler. Go to step 5. + +**A quantile at the last bucket is saturated.** The lifecycle histogram of +ateapi stops at 30 s. The restore histogram of atelet stops at 60 s. A value at +or near the end of the range means only that the true value is somewhere above +the buckets, thus the two instruments cannot be compared there. Read the mean +instead, as step 2 does. +* The restore query is empty but resumes occur — the resumes are boots. Confirm + it: + +**Prometheus** + +```promql +sum by (ate_snapshot_kind) ( + rate(ate_actor_lifecycle_operation_duration_seconds_count{ + ate_actor_operation_name="resume"}[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.snapshot.kind") ( + rate({__name__="ate.actor.lifecycle.operation.duration_count", + "ate.actor.operation.name"="resume"}[5m])) +``` + +## Step 2. Find the phase + +**Remove the failures before you read the time.** A phase that fails holds its +timer until it gives up. Thus a few failures make the phase look slow, and the +restores that were correct disappear into the tail. `ate.failure.reason` is on +the phase that failed and on `total`, and on no other phase. An empty value +selects the restores that were correct: + +**Prometheus** + +```promql +histogram_quantile(0.95, sum by (le, ate_snapshot_phase) ( + rate(ate_actor_restore_duration_seconds_bucket{ate_failure_reason=""}[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.95, sum by(le, "ate.snapshot.phase") ( + rate({__name__="ate.actor.restore.duration_bucket","ate.failure.reason"=""}[5m]))) +``` + +**Read the mean as well.** These buckets are wide at the tail, thus a quantile +in the last bucket is an interpolation that can be far above the true value: + +**Prometheus** + +```promql +sum by (ate_snapshot_phase) ( + increase(ate_actor_restore_duration_seconds_sum{ate_failure_reason=""}[30m])) +/ sum by (ate_snapshot_phase) ( + increase(ate_actor_restore_duration_seconds_count{ate_failure_reason=""}[30m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.snapshot.phase") ( + increase({__name__="ate.actor.restore.duration_sum","ate.failure.reason"=""}[30m])) +/ sum by("ate.snapshot.phase") ( + increase({__name__="ate.actor.restore.duration_count","ate.failure.reason"=""}[30m])) +``` + +| Phase | What is slow | Go to | +|---|---|---| +| `volume_mount` | The volumes of the actor. | The logs of atelet. | +| `manifest_fetch` | The read of the snapshot manifest. | Step 3. | +| `download` | Object storage. | Step 3. | +| `oci_unpack` | The node, or the image cache missed. | Step 4. | +| `sandbox_assets` | The sandbox assets on the node. | Step 4. | +| `ateom_restore` | The sandbox runtime. | The logs of ateom. | + +If the filtered numbers are small but the unfiltered numbers are large, the +subject is not the speed of the phase. It is the failures. Go to step 6. + +**A phase that disappears under the filter is the phase that failed.** The +reason key is on the failed phase and on `total`, and on no other phase. Thus a +filtered result that lists `download` and `oci_unpack` but not `ateom_restore` +and not `total` says that the restores reached the sandbox runtime and died +there. The phases before it were correct, and they are the ones you can still +read. + +## Step 3. Examine the snapshot and the storage + +A large snapshot makes a long download. Compare the templates. + +**Prometheus** + +```promql +histogram_quantile(0.95, sum by (le, ate_template_name) ( + rate(atelet_snapshot_size_bytes_bucket[1h]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.95, sum by(le, "ate.template.name") ( + rate({__name__="atelet.snapshot.size_bucket"}[1h]))) +``` + +atelet records one measurement for each image file, not one for each +checkpoint. Use `file.name` to compare the same type of image. + +```bash +kubectl ate get actor-snapshots -a +``` + +If the size did not change but the download did, the storage backend is the +cause. Read step 6 for the failure reasons. + +## Step 4. Examine the image cache on the node + +A miss adds a pull and an unpack to each resume. + +**Prometheus** + +```promql +sum by (ate_imagecache_outcome) ( + rate(ate_imagecache_requests_total[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.imagecache.outcome") ( + rate({__name__="ate.imagecache.requests"}[5m])) +``` + +Calculate the hit ratio as `hit / (hit + miss)`. Keep `error`, `cancelled` and +`timeout` out of the denominator. + +If the outcome is `error`, `error.type` holds the HTTP status of the registry. +The value `401` or `403` is a credential fault. The value `429` is a rate +limit. Each other status reports `_OTHER`. + +## Step 5. Examine the control plane + +Use this step only if step 1 sent you here. + +**Prometheus** + +```promql +sum by (ate_scheduler_outcome) ( + rate(ate_scheduler_assignment_duration_seconds_count[5m])) + +histogram_quantile(0.95, sum by (le) ( + rate(ate_scheduler_assignment_duration_seconds_bucket{ + ate_scheduler_outcome="assigned"}[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.scheduler.outcome") ( + rate({__name__="ate.scheduler.assignment.duration_count"}[5m])) + +histogram_quantile(0.95, sum by(le) ( + rate({__name__="ate.scheduler.assignment.duration_bucket", + "ate.scheduler.outcome"="assigned"}[5m]))) +``` + +* The outcome is `no_free_worker` — this is a capacity fault, not a resume + fault. Read [capacity-is-full.md](capacity-is-full.md). +* The outcome is `assigned` but the time is large — a delay in the store. The + store has no metrics. Read the logs of ateapi. + +The user also pays the parking time with the resume time: + +**Prometheus** + +```promql +histogram_quantile(0.95, sum by (le, outcome) ( + rate(atenet_router_parking_wait_duration_seconds_bucket[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +histogram_quantile(0.95, sum by(le, outcome) ( + rate({__name__="atenet.router.parking.wait.duration_bucket"}[5m]))) +``` + +## Step 6. Find out if the resumes fail + +A failed resume is not the same fault as a slow resume, but a failure also +makes the phase look slow, thus read this step together with step 2. atelet puts `ate.failure.reason` on the phase that failed and on the +total. It puts the key on no other phase. Thus the phases that were correct +stay queryable as successes. + +**Prometheus** + +```promql +sum by (ate_snapshot_phase, ate_failure_reason) ( + rate(ate_actor_restore_duration_seconds_count{ + ate_failure_reason!=""}[5m])) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.snapshot.phase", "ate.failure.reason") ( + rate({__name__="ate.actor.restore.duration_count", + "ate.failure.reason"!=""}[5m])) +``` + +| Reason | Cause | +|---|---| +| `FAILED_GET_EXTERNAL_OBJECT` | The storage backend has a fault. | +| `TERMINAL_FILE_SYSTEM_ERROR` | A permanent fault on the node. Usually the disks are full. | +| `LOCAL_SNAPSHOT_GONE` | The node no longer has the local snapshot. | +| `INVALID_SANDBOX_ASSET` | A sandbox asset is absent or bad. | +| `INVALID_CHECKPOINT_RESULT` | ateom returned a checkpoint that is not valid. | +| `INVALID_CONTAINER_CONFIG` | The ActorTemplate is not correct. | +| `INVALID_OBJECT_URL` | The URL of the snapshot object is bad. | +| `FAILED_SAVE_SNAPSHOT` | atelet could not write the snapshot. | +| `WORKER_POD_GONE`, `WORKER_REASSIGNED`, `CORRUPTED_ASSIGNMENT` | A control plane fault. Examine ateapi. | +| `UNKNOWN` | An infrastructure failure with no reason. Read the logs of atelet. | + +A slow resume and a failed suspend are related. A suspend that fails leaves no +good snapshot for the next resume. Read the crash counter, which uses the same +taxonomy: + +**Prometheus** + +```promql +sum by (ate_failure_reason, ate_template_name) ( + rate(ate_actor_crashes_total[5m])) + +histogram_quantile(0.95, sum by (le, ate_snapshot_phase) ( + rate(ate_actor_checkpoint_duration_seconds_bucket[5m]))) +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.failure.reason", "ate.template.name") ( + rate({__name__="ate.actor.crashes"}[5m])) + +histogram_quantile(0.95, sum by(le, "ate.snapshot.phase") ( + rate({__name__="ate.actor.checkpoint.duration_bucket"}[5m]))) +``` + +## Step 7. Examine the load on the node + +A node with no free memory or no free CPU makes each resume slow. + +**Prometheus** + +```promql +sum by (ate_template_name, ate_stats_source) ( + ate_actor_stats_memory_working_set_bytes) + +sum by (ate_template_name) ( + rate(ate_actor_stats_cpu_time_seconds_total[5m])) + +ate_actor_stats_sampled_actors +``` + +**Cloud Monitoring / GMP** + +```promql +sum by("ate.template.name", "ate.stats.source") ( + {__name__="ate.actor.stats.memory.working_set"}) + +sum by("ate.template.name") ( + rate({__name__="ate.actor.stats.cpu.time"}[5m])) + +{__name__="ate.actor.stats.sampled_actors"} +``` + +Group the data by `ate.stats.source`. Do not add the sources together. The +`cgroup` source includes the load of the sandbox runtime. The `guest-agent` +source includes only the containers of the workload. + +**Add these across the nodes with `sum`.** Each atelet measures only the actors +on its own node, thus one series for each node, and the sum is the fleet. This +is the opposite of `ate.workerpool.workers`, where each ateapi reports the whole +fleet and a sum multiplies it. Read the emitter before you choose the operator: + +| Metric | Emitter | Each series covers | Operator | +|---|---|---|---| +| `ate.actor.stats.*` | atelet, one for each node | One node | `sum` | +| `ate.workerpool.workers` | ateapi, some replicas | The whole fleet | `max` | + +The pool keys are absent when the atelet DaemonSet does not set `NODE_NAME` +through the Downward API. The samples still flow; they carry no +`ate.workerpool.*`. + +Use `working_set` against a memory limit. The `usage` value includes the page +cache that the node can release. `sampled_actors` is the denominator: if it +decreases but the number of actors does not, the sweep cannot measure some +actors. + +```bash +kubectl ate top workers +kubectl logs -n ate-system +``` + +--- + +## The blind spots of this scenario + +| Area | Effect on a slow resume | +|---|---| +| The store in ateapi | A delay looks like unmeasured time in the lifecycle and the assignment histograms. | +| The worker cache in ateapi | An old view of the fleet gives a worker that is not in operation. This looks like a resume failure with no cause. | +| The eviction of the image cache | You see the hits and the misses, but not the disk pressure from the layer pool. | +| The build of a golden image | Nothing measures it. A slow first activation of a new template has no data. | + +## Move from a template to an actor + +No resume metric has the name, the UID, or the atespace of an actor. The +cardinality rules forbid these keys. When the metrics give you a slow template, +use the logs and the traces to find the actor: + +```bash +kubectl ate get actors -a +kubectl ate logs actors -a -f +kubectl ate resume actor -a --trace +``` + +The `--trace` flag prints a trace ID. Put it in Cloud Trace or Jaeger to see +each step of the one resume. From d10fa0e037831ad07c666faafdff1bf561b49f4e Mon Sep 17 00:00:00 2001 From: Jeff Luo Date: Thu, 3 Sep 2026 14:39:19 -0400 Subject: [PATCH 2/2] docs: keep the troubleshooting guides thin The guides copied label taxonomies and flag defaults inline. A copy goes out of date without a signal, and one already had: the guide said that ate.imagecache.requests reports _OTHER for each status that is not 401, 403 or 429, but the registry and internal/imagecache/metrics.go also pass 404, 500, 502, 503 and 504 through as literal values. Give the guides one job. They own the decision tree: which query to run, how to read the result, and where to go next. The registry owns the definitions. Drop the value tables for ate.snapshot.kind, ate.failure.reason, ate.scheduling.constraint and the parking outcome, and link to the registry group instead. Drop the --parked-request-max default and link to request-parking.md, which owns the flag. Drop the histogram bucket ceilings and the two sample measurements, which the surrounding argument does not need. The phase, reason and outcome tables that remain hold routing and not definitions. Fix two drifts on the way: three guides said "three reasons" for an empty query where the README lists four, and capacity-is-full.md said "two states" above a three-row table. --- docs/troubleshooting/README.md | 6 ++ docs/troubleshooting/capacity-is-full.md | 20 +++--- docs/troubleshooting/requests-are-slow.md | 33 ++++----- docs/troubleshooting/resumes-are-slow.md | 86 +++++++++++++---------- 4 files changed, 80 insertions(+), 65 deletions(-) diff --git a/docs/troubleshooting/README.md b/docs/troubleshooting/README.md index d1463f2ee7..afd7254816 100644 --- a/docs/troubleshooting/README.md +++ b/docs/troubleshooting/README.md @@ -21,6 +21,12 @@ The instruments and their labels are defined in is the source of truth. [`docs/observability.md`](../observability.md) describes logs, metrics, and traces as a whole. +**These guides own the decision tree. The registry owns the definitions.** A +guide tells you which query to run, how to read the result, and where to go +next. It does not repeat the permitted values of a label, or the default of a +flag. For those, open the registry, or the document that owns the flag. A copy +in a guide goes out of date without a signal. + ## The two paths Substrate has two paths, and the first question is always which one is slow. diff --git a/docs/troubleshooting/capacity-is-full.md b/docs/troubleshooting/capacity-is-full.md index a95c544331..1a30427239 100644 --- a/docs/troubleshooting/capacity-is-full.md +++ b/docs/troubleshooting/capacity-is-full.md @@ -7,7 +7,7 @@ An actor must hold a worker to run. When each worker is assigned, a new resume cannot start. The router parks the request, and then it returns `503 no free workers available`. -Two different states look the same at the edge: +Three different states look the same at the edge: | State | What it means | Where to see it | |---|---|---| @@ -24,7 +24,7 @@ the pools of different namespaces into one series. Each step gives the query in two forms. Refer to [the naming rules](README.md#the-names-on-your-backend) for which form your -backend needs, and for the three reasons a query can return nothing. +backend needs, and for the reasons a query can return nothing. --- @@ -120,11 +120,9 @@ histogram_quantile(0.5, sum by(le, "ate.scheduling.constraint") ( rate({__name__="ate.scheduler.eligible_workers_bucket"}[5m]))) ``` -| `ate.scheduling.constraint` | Meaning | -|---|---| -| `none` | The request has no constraint. | -| `selector` | A label selector of an actor or a template applies. | -| `required_nodes` | The request is pinned to specific node VMs. | +The `registry.ate.scheduler` group of +[the registry](../metrics/registry/metrics.yaml) says what each value of +`ate.scheduling.constraint` is. **The value of this key does not tell you the cause.** An ActorTemplate with a `workerSelector` makes each of its requests `selector`, thus you never see @@ -157,11 +155,11 @@ sum by("ate.scheduler.outcome") ( rate({__name__="ate.scheduler.assignment.duration_count"}[5m])) ``` -| Outcome | Meaning | +| Outcome | Go to | |---|---| -| `assigned` | The scheduler took a worker. | -| `no_free_worker` | No free worker was available. This shows the capacity. It is not a failure, thus it has no `error.type` key and it names no pool. | -| `error` | The attempt failed. Only this outcome has an `error.type` key. | +| `assigned` | The scheduler took a worker. If the users still get a 503 error, go to step 5. | +| `no_free_worker` | This is capacity pressure and not a failure. Go to step 2 and to step 6. | +| `error` | The query below. Only this outcome has an `error.type` key. | **Prometheus** diff --git a/docs/troubleshooting/requests-are-slow.md b/docs/troubleshooting/requests-are-slow.md index 11850464f6..1c81569b1f 100644 --- a/docs/troubleshooting/requests-are-slow.md +++ b/docs/troubleshooting/requests-are-slow.md @@ -23,7 +23,7 @@ and it does not include the response. | Yes | Small | In the code of the actor, or in the network. Read the logs of the actor. | | No | Large | Somebody waited, but not this client. For example, an operator did a resume. | -Three different faults give a 503 error to the client: +Four outcomes reach the client, and three of them are a 503 error: | What the client sees | Label | Cause | |---|---|---| @@ -41,7 +41,7 @@ activations. Each step gives the query in two forms. Refer to [the naming rules](README.md#the-names-on-your-backend) for which form your -backend needs, and for the three reasons a query can return nothing. +backend needs, and for the reasons a query can return nothing. --- @@ -73,6 +73,12 @@ sum by("ate.router.outcome") ( `ok` on this metric means only that the router found an endpoint. It does not mean that the client got an answer. +The table above holds the outcomes that send you to a different step. The +router has more, and the `registry.ate.router` group of +[the registry](../metrics/registry/metrics.yaml) lists each one. An outcome +that is not in the table names its own cause; read it there and then go to +step 4. + ## Step 2. Divide the warm route from the resume **Keep both `ate.router.outcome` and `ate.router.resume` in the `by()` clause.** @@ -81,9 +87,9 @@ reports `none` for a request that stopped before it reached a resume state. The outcome is what separates the two readings, thus the query must group by both. Keep the resume key for a second reason: if you remove it, the aggregation adds -the warm route to the activation, and one distribution then holds both -milliseconds and seconds. On this data the warm route is 23 ms and the -activation is 488 ms, thus a merged number describes neither. +the warm route to the activation. A warm route is milliseconds and an +activation is hundreds of milliseconds or more, thus one distribution then +holds both and the merged number describes neither. **Prometheus** @@ -133,20 +139,15 @@ histogram_quantile(0.95, sum by(le, outcome) ( rate({__name__="atenet.router.parking.wait.duration_bucket"}[5m]))) ``` -* `parking.active` near the configured maximum (`--parked-request-max`, - default 1024) means that the parking area is almost full. +* `parking.active` near the configured maximum means that the parking area is + almost full. `--parked-request-max` sets it. Refer to + [request-parking.md](../request-parking.md) for the flag and its default. * `parking.rejected` above zero means that the router refuses requests at the edge. Make the pool larger, or make the parking area larger. * The `outcome` label on the wait histogram does not start with `ate.`. This is - a known exception in `docs/metrics/substrate.yaml`. - -| `outcome` | Meaning | -|---|---| -| `served` | The resume was correct and the router sent the request. | -| `budget_exhausted` | The park budget ended. The fleet stayed full. | -| `timeout` | The time limit of the request ended. | -| `canceled` | The client disconnected. | -| `error` | The resume failed. | + a known exception in `docs/metrics/substrate.yaml`. Its permitted values are + in the `registry.ate.deviation` group of + [the registry](../metrics/registry/metrics.yaml). A value of `budget_exhausted` below the full budget is normal. The budget is per flight. A request that joins a flight late shares the remaining budget. diff --git a/docs/troubleshooting/resumes-are-slow.md b/docs/troubleshooting/resumes-are-slow.md index 364b718c65..51dc2db4c9 100644 --- a/docs/troubleshooting/resumes-are-slow.md +++ b/docs/troubleshooting/resumes-are-slow.md @@ -18,14 +18,11 @@ Two states give a resume, and their cost is not the same: | Paused | On the node VM, and the resume prefers that node | Low. No download. | | Suspended | In object storage (GCS or S3) | High. A download and an unpack. | -`ate.snapshot.kind` tells you which snapshot the resume read: - -| Value | Meaning | -|---|---| -| `local` | A snapshot on the node. A pause wrote it. | -| `latest` | The durable snapshot of the actor. | -| `golden` | The image of the ActorTemplate. This is the first activation of a new actor. | -| `boot` | A start from nothing. A boot is not a restore, thus this value never occurs on the atelet histograms. | +`ate.snapshot.kind` tells you which snapshot the resume read. The permitted +values and their meaning are in the `registry.ate.snapshot` group of +[the registry](../metrics/registry/metrics.yaml). One of them changes what you +can query: a `boot` is a start from nothing, thus it is not a restore and the +atelet restore histogram has no data for it. Two instruments measure a resume. They do not measure the same part: @@ -44,7 +41,7 @@ zero. Each step gives the query in two forms. Refer to [the naming rules](README.md#the-names-on-your-backend) for which form your -backend needs, and for the three reasons a query can return nothing. +backend needs, and for the reasons a query can return nothing. --- @@ -81,11 +78,11 @@ histogram_quantile(0.95, sum by(le) ( * The router number is much larger — the time went to the queue or to the scheduler. Go to step 5. -**A quantile at the last bucket is saturated.** The lifecycle histogram of -ateapi stops at 30 s. The restore histogram of atelet stops at 60 s. A value at -or near the end of the range means only that the true value is somewhere above -the buckets, thus the two instruments cannot be compared there. Read the mean -instead, as step 2 does. +**A quantile at the last bucket is saturated.** The two instruments do not use +the same buckets, and the lifecycle histogram of ateapi ends before the restore +histogram of atelet. A value at or near the end of either range means only that +the true value is somewhere above the buckets, thus the two cannot be compared +there. Read the mean instead, as step 2 does. * The restore query is empty but resumes occur — the resumes are boots. Confirm it: @@ -148,14 +145,16 @@ sum by("ate.snapshot.phase") ( increase({__name__="ate.actor.restore.duration_count","ate.failure.reason"=""}[30m])) ``` -| Phase | What is slow | Go to | -|---|---|---| -| `volume_mount` | The volumes of the actor. | The logs of atelet. | -| `manifest_fetch` | The read of the snapshot manifest. | Step 3. | -| `download` | Object storage. | Step 3. | -| `oci_unpack` | The node, or the image cache missed. | Step 4. | -| `sandbox_assets` | The sandbox assets on the node. | Step 4. | -| `ateom_restore` | The sandbox runtime. | The logs of ateom. | +The `registry.ate.snapshot` group of +[the registry](../metrics/registry/metrics.yaml) says what each phase covers. +The slowest phase says where to go next: + +| Phase | Go to | +|---|---| +| `volume_mount` | The logs of atelet. | +| `manifest_fetch`, `download` | Step 3. | +| `oci_unpack`, `sandbox_assets` | Step 4. | +| `ateom_restore` | The logs of ateom. | If the filtered numbers are small but the unfiltered numbers are large, the subject is not the speed of the phase. It is the failures. Go to step 6. @@ -204,6 +203,10 @@ A miss adds a pull and an unpack to each resume. ```promql sum by (ate_imagecache_outcome) ( rate(ate_imagecache_requests_total[5m])) + +sum by (error_type) ( + rate(ate_imagecache_requests_total{ + ate_imagecache_outcome="error"}[5m])) ``` **Cloud Monitoring / GMP** @@ -211,14 +214,21 @@ sum by (ate_imagecache_outcome) ( ```promql sum by("ate.imagecache.outcome") ( rate({__name__="ate.imagecache.requests"}[5m])) + +sum by("error.type") ( + rate({__name__="ate.imagecache.requests", + "ate.imagecache.outcome"="error"}[5m])) ``` -Calculate the hit ratio as `hit / (hit + miss)`. Keep `error`, `cancelled` and -`timeout` out of the denominator. +Calculate the hit ratio as `hit / (hit + miss)`. Keep the outcomes that are not +a lookup result out of the denominator. The +`registry.ate.imagecache` group of +[the registry](../metrics/registry/metrics.yaml) lists them. -If the outcome is `error`, `error.type` holds the HTTP status of the registry. -The value `401` or `403` is a credential fault. The value `429` is a rate -limit. Each other status reports `_OTHER`. +Only the `error` outcome carries `error.type`, which holds the HTTP status that +the registry of the image returned. Group by it to divide a credential fault +from a rate limit from a fault of the registry. The permitted values are on +`metric.ate.imagecache.requests` in the same file. ## Step 5. Examine the control plane @@ -290,18 +300,18 @@ sum by("ate.snapshot.phase", "ate.failure.reason") ( "ate.failure.reason"!=""}[5m])) ``` -| Reason | Cause | +The `registry.ate.failure` group of +[the registry](../metrics/registry/metrics.yaml) says what each reason means. +The reason says which component to examine next: + +| Reason | Examine | |---|---| -| `FAILED_GET_EXTERNAL_OBJECT` | The storage backend has a fault. | -| `TERMINAL_FILE_SYSTEM_ERROR` | A permanent fault on the node. Usually the disks are full. | -| `LOCAL_SNAPSHOT_GONE` | The node no longer has the local snapshot. | -| `INVALID_SANDBOX_ASSET` | A sandbox asset is absent or bad. | -| `INVALID_CHECKPOINT_RESULT` | ateom returned a checkpoint that is not valid. | -| `INVALID_CONTAINER_CONFIG` | The ActorTemplate is not correct. | -| `INVALID_OBJECT_URL` | The URL of the snapshot object is bad. | -| `FAILED_SAVE_SNAPSHOT` | atelet could not write the snapshot. | -| `WORKER_POD_GONE`, `WORKER_REASSIGNED`, `CORRUPTED_ASSIGNMENT` | A control plane fault. Examine ateapi. | -| `UNKNOWN` | An infrastructure failure with no reason. Read the logs of atelet. | +| `FAILED_GET_EXTERNAL_OBJECT`, `INVALID_OBJECT_URL` | The storage backend, and the URL of the snapshot object. | +| `TERMINAL_FILE_SYSTEM_ERROR`, `LOCAL_SNAPSHOT_GONE`, `INVALID_SANDBOX_ASSET` | The node. Read the logs of atelet. | +| `INVALID_CHECKPOINT_RESULT`, `FAILED_SAVE_SNAPSHOT` | The suspend path. A bad checkpoint makes the next resume fail. | +| `INVALID_CONTAINER_CONFIG` | The ActorTemplate. | +| `WORKER_POD_GONE`, `WORKER_REASSIGNED`, `CORRUPTED_ASSIGNMENT` | The control plane. Examine ateapi. | +| `UNKNOWN` | Nothing else. The reason is absent, thus read the logs of atelet. | A slow resume and a failed suspend are related. A suspend that fails leaves no good snapshot for the next resume. Read the crash counter, which uses the same