dial9-viewer 0.3.3

#!/usr/bin/env node
// dial9 trace analysis script — generated by `dial9-viewer agents analyze`
// Usage: node analyze.js <trace.bin>
// Modify this script to drill deeper into specific findings.

const fs = require('fs');
const path = require('path');
const { parseTrace, EVENT_TYPES, formatFrame, symbolizeChain, deduplicateSamples } = require(path.resolve(__dirname, 'trace_parser.js'));
const { buildWorkerSpans, attachCpuSamples, buildActiveTaskTimeline,
        computeSchedulingDelays, filterPointsOfInterest } = require(path.resolve(__dirname, 'trace_analysis.js'));

const TRACE_PATH = process.argv[2];
if (!TRACE_PATH) { console.error('Usage: node analyze.js <trace.bin>'); process.exit(1); }

// ── Helpers ──

/** Classify a symbol as kernel, libc, allocator, tokio-runtime, or application code */
function frameKind(sym) {
  if (!sym || sym.startsWith('0x')) return 'unknown';
  // C symbols (no :: separator) — check libc first to avoid __GI_ matching kernel __
  if (!sym.includes('::')) {
    if (/^(__GI_|__libc_|__pthread_|__clone|start_thread|__poll|__epoll|__futex|malloc|free|mmap|munmap|brk|sbrk)/.test(sym)) return 'libc';
    if (/^(je_|arena_|tcache_|extent_|large_|slab_|jemalloc)/.test(sym) || /^(mi_|_mi_|mi_heap_|mimalloc)/.test(sym)) return 'allocator';
    if (/^(__|do_|sys_|entry_|exit_to|irq_|page_|rcu_|synchronize_)/.test(sym)) return 'kernel';
    if (/^(schedule|expand_fd|expand_files|alloc_fd|ep_poll|ep_send|futex_|sock_|inet_|tcp_|vfs_|filp_|fd_install|ksys_|fput|fget)/.test(sym)) return 'kernel';
  }
  // Tokio runtime internals
  if (/^tokio::runtime::(scheduler|task|blocking|context|coop)/.test(sym)) return 'runtime';
  if (/^std::(panicking|sys|thread)::/.test(sym)) return 'runtime';
  return 'app';
}

/** Walk a symbolized stack to find the interesting frames:
 *  - The syscall (first libc frame)
 *  - The blocking kernel operation (kernel frame that isn't generic plumbing)
 *  - The first application frame that triggered it
 *  Returns { syscall, blocker, trigger, classified } */
function diagnoseStack(frames) {
  let syscall = null;
  let trigger = null;
  let blocker = null;
  const classified = frames.map(f => ({ ...f, kind: frameKind(f.symbol), display: formatFrame(f).text }));

  // Generic kernel plumbing — not the interesting part
  const PLUMBING = /^(__schedule|schedule$|schedule_timeout|do_syscall_64|entry_SYSCALL|__x64_sys_|__sys_|__wait_for_common|__wait_rcu_gp)/;

  for (let i = 0; i < classified.length; i++) {
    const f = classified[i];
    if (!syscall && f.kind === 'libc') syscall = f;
    if (!blocker && f.kind === 'kernel' && !PLUMBING.test(f.symbol)) blocker = f;
    if (!trigger && f.kind === 'app') { trigger = f; break; }
  }
  return { syscall, blocker, trigger, classified };
}

function fmtDur(ns) {
  if (ns >= 1e9) return (ns / 1e9).toFixed(2) + 's';
  if (ns >= 1e6) return (ns / 1e6).toFixed(2) + 'ms';
  if (ns >= 1e3) return (ns / 1e3).toFixed(1) + 'µs';
  return ns + 'ns';
}

function fmtRel(ns, minTs) { return fmtDur(ns - minTs); }

// ── Main ──

async function main() {
  console.log(`Loading ${TRACE_PATH}...`);
  const trace = await parseTrace(fs.readFileSync(TRACE_PATH));

  const workerIds = [...new Set(
    trace.events.filter(e => e.eventType !== EVENT_TYPES.QueueSample && e.eventType !== EVENT_TYPES.WakeEvent)
      .map(e => e.workerId)
  )].sort((a, b) => a - b);

  const minTs = trace.events.reduce((m, e) => Math.min(m, e.timestamp), Infinity);
  const maxTs = trace.events.reduce((m, e) => Math.max(m, e.timestamp), -Infinity);
  const durationMs = (maxTs - minTs) / 1e6;

  // Run full analysis pipeline
  const spans = buildWorkerSpans(trace.events, workerIds, maxTs);
  attachCpuSamples(trace.cpuSamples, spans.workerSpans);
  const taskTimeline = buildActiveTaskTimeline(trace.taskSpawnTimes, trace.taskTerminateTimes);
  const schedDelays = computeSchedulingDelays(spans.workerSpans, workerIds, spans.wakesByTask);

  console.log(`\n${'='.repeat(60)}`);
  console.log(`TRACE SUMMARY`);
  console.log(`${'='.repeat(60)}`);
  console.log(`Duration:       ${durationMs.toFixed(1)}ms`);
  console.log(`Workers:        ${workerIds.length} (IDs: ${workerIds.join(', ')})`);
  console.log(`Events:         ${trace.events.length.toLocaleString()}`);
  console.log(`CPU samples:    ${trace.cpuSamples.length.toLocaleString()}`);
  console.log(`Tasks spawned:  ${trace.taskSpawnTimes.size}`);
  console.log(`Tasks alive at end: ${trace.taskSpawnTimes.size - trace.taskTerminateTimes.size}`);

  // ── Worker utilization ──
  console.log(`\n${'─'.repeat(60)}`);
  console.log(`WORKER UTILIZATION`);
  console.log(`${'─'.repeat(60)}`);
  for (const w of workerIds) {
    const s = spans.workerSpans[w];
    const activeNs = s.actives.reduce((sum, a) => sum + (a.end - a.start), 0);
    const parkNs = s.parks.reduce((sum, p) => sum + (p.end - p.start), 0);
    const total = activeNs + parkNs;
    const util = total > 0 ? (activeNs / total * 100).toFixed(1) : '0.0';
    const avgCpu = s.actives.length > 0
      ? (s.actives.reduce((sum, a) => sum + a.ratio, 0) / s.actives.length).toFixed(3) : 'N/A';
    console.log(`  Worker ${w}: ${util}% active, ${s.polls.length} polls, ${s.parks.length} parks, avg CPU ratio: ${avgCpu}`);
  }

  // ── Long polls ──
  console.log(`\n${'─'.repeat(60)}`);
  console.log(`LONG POLLS (>1ms)`);
  console.log(`${'─'.repeat(60)}`);
  const longPolls = [];
  for (const w of workerIds) {
    for (const p of spans.workerSpans[w].polls) {
      const dur = p.end - p.start;
      if (dur > 1e6) longPolls.push({ dur, poll: p, worker: w });
    }
  }
  longPolls.sort((a, b) => b.dur - a.dur);

  if (longPolls.length === 0) {
    console.log('  None found ✅');
  } else {
    console.log(`  Found ${longPolls.length} long poll(s)\n`);
    for (const lp of longPolls.slice(0, 10)) {
      const p = lp.poll;
      console.log(`  ▸ ${fmtDur(lp.dur)} on worker ${lp.worker} at ${fmtRel(p.start, minTs)}`);
      console.log(`    Task ${p.taskId}, spawn: ${p.spawnLoc || '(unknown)'}`);

      // Deep-dive: scheduling samples show WHY the poll was long
      if (p.schedSamples?.length) {
        console.log(`    ${p.schedSamples.length} scheduling sample(s) — blocking call stacks:`);
        for (const s of p.schedSamples) {
          const frames = symbolizeChain(s.callchain, trace.callframeSymbols);
          const { syscall, blocker, trigger, classified } = diagnoseStack(frames);
          if (blocker) {
            console.log(`      Blocked by:  ${blocker.symbol} (kernel)`);
          }
          if (syscall) console.log(`      Syscall:     ${syscall.display}`);
          if (trigger) {
            console.log(`      Called from:  ${trigger.display}`);
            if (trigger.location) console.log(`        at ${trigger.location}`);
          }
          // Show the kernel path that explains the delay
          const kernelPath = classified.filter(f => f.kind === 'kernel').map(f => f.symbol);
          if (kernelPath.length > 1) {
            console.log(`      Kernel path: ${kernelPath.join(' → ')}`);
          }
          // Print condensed app stack (skip runtime/unknown, collapse long runs)
          const appFrames = classified.filter(f => f.kind === 'app');
          if (appFrames.length > 0) {
            console.log(`      App call chain (${appFrames.length} frames):`);
            // Show first 3 (closest to syscall) and last 3 (entry point)
            const show = appFrames.length <= 8 ? appFrames : [
              ...appFrames.slice(0, 3),
              { display: `... ${appFrames.length - 6} more frames ...`, kind: 'ellipsis' },
              ...appFrames.slice(-3),
            ];
            for (const f of show) {
              console.log(`        ${f.display}`);
            }
          }
        }
      }
      if (p.cpuSamples?.length) {
        console.log(`    ${p.cpuSamples.length} CPU sample(s) — on-CPU stacks:`);
        for (const s of p.cpuSamples.slice(0, 3)) {
          const frames = symbolizeChain(s.callchain, trace.callframeSymbols);
          const { trigger } = diagnoseStack(frames);
          if (trigger) console.log(`      ${trigger.display}`);
        }
      }
      if (!p.schedSamples?.length && !p.cpuSamples?.length) {
        console.log(`    (no profiling samples captured during this poll)`);
      }
      console.log();
    }
  }

  // ── Scheduling delays ──
  console.log(`${'─'.repeat(60)}`);
  console.log(`SCHEDULING DELAYS (wake → poll latency)`);
  console.log(`${'─'.repeat(60)}`);
  const highDelays = schedDelays.filter(d => d.delay > 1e6);
  if (highDelays.length === 0) {
    console.log('  No delays > 1ms ✅');
  } else {
    highDelays.sort((a, b) => b.delay - a.delay);
    console.log(`  ${highDelays.length} delays > 1ms`);
    console.log(`  Worst: ${fmtDur(highDelays[0].delay)}`);
    console.log(`  p50:   ${fmtDur(highDelays[Math.floor(highDelays.length * 0.5)]?.delay || 0)}`);
    console.log(`  p99:   ${fmtDur(highDelays[Math.floor(highDelays.length * 0.01)]?.delay || 0)}`);
    console.log(`\n  Top 5 worst:`);
    for (const d of highDelays.slice(0, 5)) {
      console.log(`    ${fmtDur(d.delay)} — task ${d.taskId} (spawn: ${d.poll.spawnLoc || '?'}) at ${fmtRel(d.wakeTime, minTs)}`);
    }
  }

  // ── Task lifecycle ──
  console.log(`\n${'─'.repeat(60)}`);
  console.log(`TASK LIFECYCLE`);
  console.log(`${'─'.repeat(60)}`);
  const spawnCounts = new Map();
  for (const [, loc] of trace.taskSpawnLocs) {
    spawnCounts.set(loc || '(unknown)', (spawnCounts.get(loc || '(unknown)') || 0) + 1);
  }
  console.log('  Spawns by location:');
  for (const [loc, count] of [...spawnCounts.entries()].sort((a, b) => b[1] - a[1])) {
    console.log(`    ${String(count).padStart(5)} × ${loc}`);
  }

  // Task leak check
  const atSamples = taskTimeline.activeTaskSamples;
  if (atSamples.length > 0) {
    const peak = Math.max(...atSamples.map(s => s.count));
    const final_ = atSamples[atSamples.length - 1].count;
    console.log(`\n  Peak active tasks: ${peak}`);
    console.log(`  Active at trace end: ${final_}`);
    if (final_ > atSamples[0].count * 2 && final_ === peak) {
      console.log('  ⚠ POSSIBLE TASK LEAK — active count grew monotonically');
      const alive = new Map();
      for (const [taskId] of trace.taskSpawnTimes) {
        if (!trace.taskTerminateTimes.has(taskId)) {
          const loc = trace.taskSpawnLocs.get(taskId) || '(unknown)';
          alive.set(loc, (alive.get(loc) || 0) + 1);
        }
      }
      for (const [loc, count] of [...alive.entries()].sort((a, b) => b[1] - a[1])) {
        console.log(`    ${count} leaked from ${loc}`);
      }
    }
  }

  // ── Blocking calls (off-CPU samples) ──
  console.log(`\n${'─'.repeat(60)}`);
  console.log(`BLOCKING CALLS (scheduling/off-CPU samples)`);
  console.log(`${'─'.repeat(60)}`);
  const schedSamples = trace.cpuSamples.filter(s => s.source === 1);
  if (schedSamples.length === 0) {
    console.log('  No off-CPU samples in trace');
  } else {
    console.log(`  ${schedSamples.length} off-CPU sample(s)\n`);
    const groups = deduplicateSamples(schedSamples, trace.callframeSymbols);
    for (const g of groups.slice(0, 10)) {
      const pct = (g.count / schedSamples.length * 100).toFixed(1);
      // Walk past kernel/libc to find the blocking operation
      const { syscall, blocker, trigger } = diagnoseStack(g.frames);
      console.log(`  ${String(g.count).padStart(5)} samples (${pct}%) — leaf: ${g.leaf}`);
      if (blocker) console.log(`         blocked by: ${blocker.symbol} (kernel)`);
      if (syscall) console.log(`         syscall:    ${syscall.display}`);
      if (trigger) console.log(`         called from: ${trigger.display}`);
    }
  }

  // ── CPU hotspots ──
  console.log(`\n${'─'.repeat(60)}`);
  console.log(`CPU HOTSPOTS (on-CPU samples)`);
  console.log(`${'─'.repeat(60)}`);
  const cpuSamples = trace.cpuSamples.filter(s => s.source === 0);
  if (cpuSamples.length === 0) {
    console.log('  No CPU samples in trace');
  } else {
    console.log(`  ${cpuSamples.length} CPU sample(s)\n`);
    const groups = deduplicateSamples(cpuSamples, trace.callframeSymbols);
    for (const g of groups.slice(0, 10)) {
      const pct = (g.count / cpuSamples.length * 100).toFixed(1);
      const { trigger } = diagnoseStack(g.frames);
      console.log(`  ${String(g.count).padStart(5)} samples (${pct}%) — leaf: ${g.leaf}`);
      if (trigger) console.log(`         app frame: ${trigger.display}`);
    }
  }

  // ── Queue depth ──
  console.log(`\n${'─'.repeat(60)}`);
  console.log(`QUEUE DEPTH`);
  console.log(`${'─'.repeat(60)}`);
  if (spans.queueSamples.length > 0) {
    const maxQ = Math.max(...spans.queueSamples.map(s => s.global));
    const avgQ = spans.queueSamples.reduce((s, q) => s + q.global, 0) / spans.queueSamples.length;
    console.log(`  Global queue: max=${maxQ}, avg=${avgQ.toFixed(1)}, samples=${spans.queueSamples.length}`);
    if (maxQ > 100) console.log('  ⚠ High queue depth — runtime may be overloaded');
  } else {
    console.log('  No queue samples');
  }
  console.log(`  Max local queue: ${spans.maxLocalQueue}`);

  // ── Kernel scheduling wait ──
  console.log(`\n${'─'.repeat(60)}`);
  console.log(`KERNEL SCHEDULING WAIT`);
  console.log(`${'─'.repeat(60)}`);
  for (const w of workerIds) {
    const parks = spans.workerSpans[w].parks.filter(p => p.schedWait > 0);
    if (parks.length === 0) continue;
    const waits = parks.map(p => p.schedWait).sort((a, b) => b - a);
    const max = waits[0];
    const p50 = waits[Math.floor(waits.length * 0.5)];
    // schedWait is in ns
    console.log(`  Worker ${w}: max=${(max/1e6).toFixed(1)}ms, p50=${(p50/1e6).toFixed(2)}ms, ${waits.filter(w => w > 1e6).length} events > 1ms`);
  }

  console.log(`\n${'='.repeat(60)}`);
}

main().catch(err => { console.error(err); process.exit(1); });