diff --git a/README.md b/README.md index f6445d5d89..1dab69e01a 100644 --- a/README.md +++ b/README.md @@ -205,6 +205,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 ae1958c1e5..c510023f1b 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -125,6 +125,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.