async-profiler

JFR — это always-on baseline. async-profiler — это инструмент для глубоких investigations. Когда вам нужно understand “что точно происходит в этом hot method за последние 30 секунд” — async-profiler даёт самые точные flame graphs из всех доступных инструментов JVM.

Этот урок про async-profiler: установку, режимы работы, чтение flame graphs, integration с Flink, и concrete examples из production debugging.

Что такое async-profiler

async-profiler — это open-source low-overhead sampling profiler для JVM. Работает через signal-based sampling (UNIX signals SIGPROF), что отличается от других profilers тем, что:

1. Не использует Safepoints. Большинство Java profilers могут sampling только на safepoints — special JVM points между bytecode operations. Это даёт safepoint bias — методы между safepoints (например loops с counted iterations) не профилируются корректно. async-profiler использует AsyncGetCallTrace API — недокументированный internal API JVM, который позволяет получить stack trace в любой момент.

2. Поддерживает native frames. Кроме JVM stack frames, async-profiler показывает C/C++ frames из native libraries (RocksDB, OpenSSL, etc). Это критично для Flink с RocksDB state backend.

3. Kernel frames. Может показывать kernel stack traces — например когда поток ждёт в syscall (read, write, futex). Это поможет find IO bottlenecks.

4. Multiple modes. CPU profiling, allocation profiling, wall-clock profiling, lock contention — всё через один инструмент.

Overhead: 0.5-2% на типичных workloads. Можно безопасно запускать на production.

Установка

async-profiler distributed как самодостаточная shared library + helper script. Не требует instrumentation, не нужно перезапускать JVM.

# Linux x86_64
wget https://github.com/async-profiler/async-profiler/releases/latest/download/async-profiler-3.0-linux-x64.tar.gz
tar xzf async-profiler-3.0-linux-x64.tar.gz
cd async-profiler-3.0-linux-x64

# В директории есть:
# - profiler.sh — wrapper script
# - lib/libasyncProfiler.so — shared library
# - bin/jfrconv — конвертер в JFR format

Для Docker images просто COPY эти файлы в /opt/async-profiler/. Они не зависят от JDK install.

FROM flink:2.2
COPY async-profiler-3.0-linux-x64 /opt/async-profiler

Базовые режимы

CPU profiling — самый частый use case:

# Профилируем PID 12345 в течение 30 секунд, output в HTML flame graph
./profiler.sh -d 30 -f cpu.html 12345

-d 30 — duration, -f cpu.html — output file. По умолчанию режим — CPU profiling через perf events (Linux) или ITIMER (другие OS).

Результат — cpu.html файл с интерактивным flame graph. Открывайте в браузере.

Allocation profiling — какие классы аллоцируются больше всего:

./profiler.sh -d 30 -e alloc -f alloc.html 12345

-e alloc переключает на allocation profiling. Output показывает классы и call sites, где происходят allocations. Полезно для finding GC pressure causes.

Wall-clock profiling — где потоки тратят wall-clock time, включая waits:

./profiler.sh -d 30 -e wall -f wall.html 12345

Wall-clock показывает не только CPU, но и time spent в I/O, locks, sleeps. Это главное отличие от CPU profiling: CPU profiling не покажет вам, что thread ждёт в read() syscall, потому что он не использует CPU. Wall-clock покажет.

Lock contention — кто кого ждёт:

./profiler.sh -d 30 -e lock -f lock.html 12345

Показывает sync блоки и LockSupport.park calls, как часто и в каких stacks.

Чтение flame graph

Flame graph — это визуализация stack traces. Каждый прямоугольник — это method call. Ширина прямоугольника пропорциональна frequency его появления в samples (= time spent в этом call path).

Главное при чтении flame graph:

1. Ищите wide leaves в top — они показывают где CPU thực sự тратится. Не на root, не в middle — а в leaves.
2. Каскадирующие patterns: если widest leaf is Map.merge -> boxing -> Long.valueOf — auto-boxing eats CPU.
3. Native frames: если top frames in C code (typically RocksDB) — это normal для stateful jobs.
4. Чужой код: иногда flame graph показывает hot path в библиотеке (Jackson parsing, gRPC encoding) — это указатель на ваше использование этой библиотеки.

Allocation profiling deep dive

Allocation profiling в async-profiler работает через trace вызовов Object.{'<'}init{'>'}. Каждый new object -> sample (с probability based на sampling rate). Output показывает классы и stacks.

./profiler.sh -d 60 -e alloc -f alloc.html 12345

Allocation rate в JFR vs async-profiler:

Async-profiler даёт более accurate picture для small object allocations, которые TLAB samples missing. Для finding hot allocation sites — async-profiler usually preferred.

Типичные patterns:

1. Boxing hotspot. Wide block с Long.valueOf или Integer.valueOf — auto-boxing в Map operations. Fix: primitive maps.

2. String concatenation. Wide StringBuilder.{'<'}init{'>'} или String.concat — много string operations без reuse. Fix: ThreadLocal builders.

3. Tuple/POJO creation. Wide Tuple2.of или constructors — много intermediate tuples. Norm для streaming, но если значительно — рассмотрите object pooling или reuse.

4. ByteBuffer allocation. Wide ByteBuffer.allocateDirect — direct buffer allocation в hot path. Direct buffers expensive — рассмотрите buffer pooling.

Wall-clock profiling: где waiting time

Wall-clock — это профилирование “wall clock time”, включая wait events. Critical для diagnosing IO bottlenecks, blocking calls, lock contention.

./profiler.sh -d 60 -e wall -f wall.html 12345

Сценарии:

1. Network IO wait. Если wall-clock показывает wide EpollEventLoop.processSelectedKeys, SocketRead.read — много времени wait на network. Это может быть Kafka source backpressure или slow downstream.

2. Disk IO wait. Wide FileChannelImpl.read, RocksDB.write — disk-bound. Для RocksDB это compaction backpressure (см. урок 19.3).

3. Lock contention. Wide LockSupport.park, Unsafe.park — threads ждут. Combine with lock profiling для finding конкретного lock.

4. Sleep / wait. Если wide Thread.sleep — вероятно retry loops или back-off в user code. Может быть intentional, может быть bug.

CPU profile vs wall-clock на одном и том же job обычно дают разные pictures:

CPU profile:
  - MyMapFunction.map: 40%
  - RocksDB.get: 25%
  - Serialize: 20%

Wall-clock profile (same period):
  - SocketRead.read: 60% (idle waiting for events from upstream)
  - MyMapFunction.map: 15%
  - RocksDB.get: 10%
  - Serialize: 8%

В этом примере CPU profile показывает что MyMap busy, но wall-clock показывает что thread больше всего waits для events from upstream — то есть source side bottleneck. Без wall-clock этот insight потерян.

Integration с Flink REST API

Async-profiler не имеет built-in integration с Flink. Но Flink имеет REST API, через который можно triggering profiling jobs.

Workflow:

1. Установить async-profiler в TaskManager Docker image.
2. Создать REST endpoint в JobManager (или use sidecar) который запускает profiler.sh на nominated TaskManager.
3. Сохранять results в S3/blob storage с metadata (job ID, timestamp, JobManager URL).
4. UI или CLI для browsing results.

Пример sidecar pattern:

# TaskManager pod
apiVersion: v1
kind: Pod
metadata:
  name: flink-tm
spec:
  containers:
    - name: taskmanager
      image: my-flink:2.2
    - name: profiler-sidecar
      image: my-profiler-helper:latest
      ports:
        - containerPort: 8765
      env:
        - name: TM_PROCESS_NAME
          value: "TaskManagerRunner"
      volumeMounts:
        - name: shared-tmp
          mountPath: /tmp/profiles
  shareProcessNamespace: true  # доступ к процессам TM

Sidecar exposing REST endpoint:

# profiler-sidecar
from flask import Flask, jsonify, request
import subprocess, time

app = Flask(__name__)

@app.route('/profile', methods=['POST'])
def profile():
    duration = request.json.get('duration', 30)
    mode = request.json.get('mode', 'cpu')  # cpu, alloc, wall

    pid = subprocess.check_output(["pgrep", "-f", "TaskManagerRunner"]).strip().decode()
    timestamp = int(time.time())
    output_file = f"/tmp/profiles/{mode}-{timestamp}.html"

    subprocess.run([
        "/opt/async-profiler/profiler.sh",
        "-d", str(duration),
        "-e", mode,
        "-f", output_file,
        pid
    ], check=True)

    # Upload в S3 для permanent storage
    upload_to_s3(output_file, f"profiles/tm-{timestamp}.html")

    return jsonify({"file": output_file, "uploaded": True})

if __name__ == "__main__":
    app.run(host="0.0.0.0", port=8765)

Теперь можно one-line trigger профилирование любого TM:

curl -X POST http://flink-tm-0:8765/profile \
    -H "Content-Type: application/json" \
    -d '{"duration": 60, "mode": "cpu"}'

Flink 2.2 имеет experimental REST endpoint для profiling, но кастомный sidecar даёт больше контроля.

Production debugging case study

Real case из production-кластера. Symptom: один TaskManager среди 50 показывает 95% CPU при 30% throughput. Остальные TM норм.

Debug workflow:

Step 1: JFR на проблемном TM. Запустили rolling JFR snapshot. Method profiling показал 60% времени в RocksDBValueState.update -> RocksDB.put -> ...native.... RocksDB native code — JFR не показывает что внутри.

Step 2: async-profiler с native frames.

./profiler.sh -d 60 -e cpu -f deep.html {TM_PID}

Flame graph показал внутри RocksDB:

... RocksDBValueState.update
    rocksdb::DBImpl::Put
        rocksdb::DBImpl::Write
            rocksdb::DBImpl::WriteImpl
                rocksdb::WriteBatchInternal::InsertInto
                    rocksdb::MemTable::Add  -- 40%
                        rocksdb::SkipListRep::Insert  -- 35%
                            ... (skip list traversal)

35% времени в SkipList Insert — это означает MemTable очень большая. Skip list O(log N), на big MemTable insertions становятся slow.

Step 3: Hypothesis. MemTable size badly configured — она растёт без bound, и slow inserts создают backpressure.

Step 4: Verification through RocksDB stats. Включили RocksDB stats reporting:

state.backend.rocksdb.metrics.estimate-num-keys: true
state.backend.rocksdb.metrics.cur-size-active-mem-table: true

Через 10 минут — MemTable size показал 4 GB (limit был 64 MB defaults, но job specific overrides set 4 GB). Когда MemTable достигает 4 GB, каждый insert обходит skip list of 100M+ entries — slow.

Step 5: Fix.

state.backend.rocksdb.writebuffer.size: 64mb  # вернули to default
state.backend.rocksdb.writebuffer.count: 4

Перезапустили job. После 1 hour soak — CPU dropped to 35%, throughput recovered. JFR + async-profiler combined нашли root cause за 2 часа.

Comparison: async-profiler vs JFR

Когда какой использовать:

Используйте JFR когда:

• Continuous monitoring/always-on recording.
• Hub for всех JVM events (GC, allocation, threads, IO).
• Production safety (1-3% overhead).
• Custom events для domain-specific tracking.
• Cross-platform (любая Java).

Используйте async-profiler когда:

• Conkretная investigation после JFR identification.
• Нужны native frames (RocksDB, OpenSSL, etc).
• Нужна более точная sampling (без safepoint bias).
• Wall-clock profiling (CPU-profiler не покрывает IO waits).
• Allocation profiling без TLAB bias.

Обычно: JFR для baseline, async-profiler для deep dives.

Попробуй сам

1. Setup async-profiler. Download release, попробуйте на любом Java процессе. Generate CPU flame graph за 30 секунд.

2. Allocation analysis. Создайте Flink job с auto-boxing hotspot (Map<String, Long> merge). Запустите async-profiler в allocation mode. Подтвердите Long.valueOf в top.

3. Wall-clock vs CPU comparison. Запустите CPU profile и wall-clock profile на одном Flink job одновременно. Сравните top stacks — should be different.