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:

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:

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:

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:

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:

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

Step 4: Analyze Traces via Jaeger API

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

Fetch traces

# 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

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

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

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

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)

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.

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:

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

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

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