# Investigating Executor Performance

> Investigating worker-executor performance by running executor tests with OTLP tracing enabled and analyzing trace data from Jaeger. Use when diagnosing slow tests, understanding executor call flows, or profiling span durations.

- Skill: `golemcloud/investigating-executor-performance` (Agent Skill)
- Install (CLI): `npx skillmds@latest add golemcloud/investigating-executor-performance`
- Raw SKILL.md: https://api.skillmd.com/api/skills/golemcloud/investigating-executor-performance/raw
- Safety review: pending
- Works with: Claude Code, Claude.ai, OpenAI Codex
- Category: Coding & Dev Tools
- Author: golemcloud (https://skillmd.com/u/golemcloud)
- Updated: 2026-09-17
- Page: https://skillmd.com/skills/golemcloud/investigating-executor-performance

---


# Investigating Worker-Executor Performance

Run worker-executor tests with distributed tracing enabled and analyze the resulting traces in Jaeger to understand performance characteristics, call flows, and bottlenecks.

## Prerequisites

- Docker and Docker Compose installed
- The monitoring stack defined in `integration-tests/monitoring/docker-compose.yml`
- The test WASM components required by the selected test or group. Build them first using the
  `modifying-test-components` skill; use `rebuild-all-test-components` only when a targeted build
  cannot cover the affected set.

## Step 1: Start the Monitoring Stack

From the `integration-tests/monitoring/` directory:

```shell
cd integration-tests/monitoring
docker compose down && docker compose up -d
```

This starts:
- **Jaeger** — UI on `localhost:16686`, OTLP collector on `localhost:4318`
- **Prometheus** — on `localhost:9090`
- **Grafana** — on `localhost:3000` (admin/admin)

## Step 2: Run Tests with OTLP Tracing

Set these environment variables before the cargo make task:

```shell
GOLEM__TRACING__OTLP__ENABLED=true \
GOLEM__TRACING__OTLP__HOST=localhost \
GOLEM__TRACING__OTLP__PORT=4318 \
GOLEM__TRACING__OTLP__SERVICE_NAME=worker-executor-tests \
GOLEM_OTLP_FILTER=info \
RUST_LOG=info,h2=warn,hyper=warn \
cargo make worker-executor-tests-group1
```

To run a single test instead of a full group:

```shell
GOLEM__TRACING__OTLP__ENABLED=true \
GOLEM__TRACING__OTLP__HOST=localhost \
GOLEM__TRACING__OTLP__PORT=4318 \
GOLEM__TRACING__OTLP__SERVICE_NAME=worker-executor-tests \
GOLEM_OTLP_FILTER=info \
RUST_LOG=info,h2=warn,hyper=warn \
cargo test -p golem-worker-executor --test integration -- <test_name> --report-time --nocapture
```

### How it works

The test `lib.rs` at `golem-worker-executor/tests/lib.rs` initializes tracing via:
```rust
TracingConfig::test_pretty_without_time("worker-executor-tests").with_env_overrides()
```

The `.with_env_overrides()` call uses Figment to merge `GOLEM__*` env vars into the `TracingConfig`, which includes `OtlpConfig` (defined in `golem-common/src/tracing.rs`). Since worker-executor tests run in-process (not spawned as child processes), the OTLP config applies to the single test process directly.

### Choosing what to export

`GOLEM_OTLP_FILTER` is `RUST_LOG` syntax over the trace pipeline, and it is required:
unset means `off`, so the four `GOLEM__TRACING__OTLP__*` variables on their own export
nothing. It is separate from `RUST_LOG` because console verbosity and what is worth
sending to a trace store are different questions.

`info` is the level worth starting from: the spans bounding an operation — requests,
invocations, worker admission, background loop ticks — are `info`, and the detail inside
them is `debug`, so `debug` deepens a trace rather than changing what it is about.
Anything less verbose than `info` exports nothing at all, since no span is emitted at
`warn` or `error`.

Two high-volume sources have targets of their own and can be turned up when you are
chasing them specifically:

| Target | What it is |
|---|---|
| `golem::plugin_log` | log output from oplog-processor plugin agents |
| `golem::agent_rdbms` | SQL an agent runs against its own database |

So `GOLEM_OTLP_FILTER=info,golem::agent_rdbms=debug` adds per-statement SQL without
raising anything else. The filter actually in force is logged at startup as
`otlp_filter`, alongside which variable it came from.

### Suppressing noise

Set `RUST_LOG=info,h2=warn,hyper=warn` to suppress verbose HTTP/2 and Hyper logs that the OTLP exporter generates. Without this, the test output is flooded with transport-level noise.

## Step 3: View Traces in Jaeger

Open `http://localhost:16686` in a browser. Select service `worker-executor-tests` from the dropdown.

### Available test groups

| Task | Tag | Description |
|------|-----|-------------|
| `worker-executor-tests-group1` | group1 | api, retry lifecycle, blobstore, keyvalue, HTTP, RDBMS, resource limits, oplog metrics, and tool discovery |
| `worker-executor-tests-group2` | group2 | hot update, instance layer, transactions, observability, and retry policies; the task also runs `in_function_retry` and `storage_quota` separately |
| `worker-executor-tests-group3` | group3 | RPC, WASI, and revert |
| `worker-executor-tests-group4` | group4 | websocket, agent, TypeScript agent SDK, durability, scope cards, scalability, and readonly behavior |
| `worker-executor-tests-misc` | untagged, rdbms_service, ignite_service | untagged coverage, agent extraction, and database-service variants |

## Step 4: Analyze Traces via Jaeger API

Jaeger exposes an HTTP API at `localhost:16686`. Use it to programmatically analyze trace data.

### Fetch traces

```shell
# List services (verify the service name appears)
curl -s 'http://localhost:16686/api/services' | python3 -m json.tool

# Fetch traces (limit and lookback are adjustable)
curl -s 'http://localhost:16686/api/traces?service=worker-executor-tests&limit=1000&lookback=1h' \
  -o tmp/traces.json
```

### Analysis patterns

All examples assume traces are saved in `tmp/traces.json`. Span durations in the Jaeger JSON are in **microseconds** (divide by 1000 for milliseconds).

#### Summary statistics

```python
python3 -c "
import json
data = json.load(open('tmp/traces.json'))
traces = data['data']
total_spans = sum(len(t['spans']) for t in traces)
print(f'Traces: {len(traces)}, Total spans: {total_spans}')
"
```

#### Operation name distribution

```python
python3 -c "
import json
from collections import Counter
data = json.load(open('tmp/traces.json'))
ops = Counter()
for t in data['data']:
    for s in t['spans']:
        ops[s['operationName']] += 1
for op, count in ops.most_common(30):
    print(f'{count:6d}  {op}')
"
```

#### Find slowest spans

```python
python3 -c "
import json
data = json.load(open('tmp/traces.json'))
spans = []
for t in data['data']:
    for s in t['spans']:
        spans.append((s['duration']/1000, s['operationName'], s['traceID'][:12]))
spans.sort(reverse=True)
for dur_ms, op, tid in spans[:20]:
    print(f'{dur_ms:10.1f}ms  {op}  trace:{tid}')
"
```

#### Find error spans

```python
python3 -c "
import json
data = json.load(open('tmp/traces.json'))
for t in data['data']:
    for s in t['spans']:
        for tag in s.get('tags', []):
            if tag['key'] == 'otel.status_code' and tag['value'] == 'ERROR':
                dur = s['duration'] / 1000
                print(f'{dur:.1f}ms  {s[\"operationName\"]}  trace:{s[\"traceID\"][:12]}')
"
```

#### Trace size distribution (spans per trace)

```python
python3 -c "
import json
from collections import Counter
data = json.load(open('tmp/traces.json'))
sizes = Counter(len(t['spans']) for t in data['data'])
for size, count in sorted(sizes.items()):
    print(f'{count:4d} traces with {size:4d} spans')
"
```

#### Detect single-span traces

Handed-off work is a linked root by design, so a single-span trace is usually expected
rather than broken. The rule, rather than a list that goes stale: any span built with
`related_span!` starts its own trace and carries a link back to whatever handed the work
off. For example the invocation hand-off (`invocation_queue_pickup`), the retry tasks
(`rpc_invoke_retry`, `http_request_retry`), the oplog transfer and flush spans, and every
worker phase span (`create_instance`, `recover_instance_state`, `suspend_worker`,
`resume_replay`, and the admission waits). Check the link, not the parent.

What this is good for is spotting a span that is *neither* a linked root *nor* connected
— that is a genuine propagation gap.

```python
python3 -c "
import json
from collections import Counter
data = json.load(open('tmp/traces.json'))
orphans = Counter()
for t in data['data']:
    if len(t['spans']) == 1:
        orphans[t['spans'][0]['operationName']] += 1
print(f'Total single-span traces: {sum(orphans.values())}')
for op, count in orphans.most_common(15):
    print(f'{count:4d}  {op}')
"
```

#### Identify background noise traces

Background-loop spans can dominate the trace data. Filter them out for focused analysis:

```python
python3 -c "
import json
data = json.load(open('tmp/traces.json'))
NOISE = {'oplog_background_transfer', 'ephemeral_oplog_background_transfer',
         'oplog_forwarding_flush', 'oplog_forwarding_threshold_flush',
         'scheduler_tick', 'quota_renewal',
         'resource_limits_batch_update', 'agent_status_flush_sweep'}
clean = [t for t in data['data']
         if not any(s['operationName'] in NOISE for s in t['spans'])]
print(f'Total: {len(data[\"data\"])}, After filtering noise: {len(clean)}')
"
```

## Known Caveats

- **An invocation spans two traces, joined by a link**: the request side ends at `wait_for_invocation_result`, and the execution is the root of its own trace linked back to `enqueue_invocation`. That is deliberate — the worker runs the invocation independently and outlives the caller, so nesting would report a child outliving its parent. To follow one to the other, search on the `idempotency_key` both sides carry. gRPC client and server spans within a single service's request path do still connect normally via `traceparent`.
- **Nothing exported at all**: check `GOLEM_OTLP_FILTER` first — unset means `off`, so the `GOLEM__TRACING__OTLP__*` variables on their own produce nothing. The effective filter is logged at startup as `otlp_filter`. If that looks right, then verify the `GOLEM__TRACING__OTLP__*` variables, without which the `tracing_opentelemetry` layer is never added to the subscriber.
- **Span queue size (`OTEL_BSP_MAX_QUEUE_SIZE`)**: The `BatchSpanProcessor` has a default queue size of 2048 spans. Under high-throughput tests this queue can overflow, causing spans to be silently dropped. Set `OTEL_BSP_MAX_QUEUE_SIZE=262144` alongside the other env vars to match spawned benchmark services. Example: `OTEL_BSP_MAX_QUEUE_SIZE=262144 GOLEM__TRACING__OTLP__ENABLED=true ... cargo test ...`.
- **Background loop noise**: Background spans close after each tick or operation; they are not test-long spans. Their volume can still obscure focused traces.
- **Fresh Jaeger**: Always restart Jaeger with `docker compose down && docker compose up -d` before a new investigation to avoid mixing traces from different runs.

## Resetting Between Runs

```shell
cd integration-tests/monitoring
docker compose down && docker compose up -d
```

This clears all stored trace data so the next test run starts fresh.