perf: avoid needless downloads and track request latency (#876)

* perf: avoid needless downloads and track request latency

* fix: correct request timing and monitoring revalidation

src/core/AnonymizedFile.ts

@@ -22,6 +22,7 @@ import { IFile } from "./model/files/files.types";
 import { FilterQuery } from "mongoose";
 import { createLogger, serializeError } from "./logger";
 import { githubTokenForStreamer } from "./github-token-context";
+import { requestHeaders, startStage } from "./request-monitoring";
 
 const logger = createLogger("anonymized-file");
 
@@ -379,6 +380,7 @@ export default class AnonymizedFile {
     // use the streamer service
     return got.stream(join(config.STREAMER_ENTRYPOINT, "api"), {
       method: "POST",
+      headers: requestHeaders(),
       json: {
         token: await githubTokenForStreamer(await this.repository.getToken(), this.repository.model.source.repositoryName),
         repoFullName: this.repository.model.source.repositoryName,
@@ -423,9 +425,11 @@ export default class AnonymizedFile {
             this.size(),
             this.repository.getToken(),
           ]);
+          const headersDone = startStage("streamer_headers");
           const resStream = got
             .stream(join(config.STREAMER_ENTRYPOINT, "api"), {
               method: "POST",
+              headers: requestHeaders(),
               json: {
                 sha,
                 size,
@@ -445,6 +449,7 @@ export default class AnonymizedFile {
           // this, the parent response has no Content-Type and the browser
           // guesses (text renders as download, images as octet-stream).
           resStream.on("response", (upstream: { headers: Record<string, string | string[] | undefined> }) => {
+            headersDone();
             if (res.headersSent) return;
             const ct = upstream.headers["content-type"];
             if (typeof ct === "string") {
@@ -455,6 +460,8 @@ export default class AnonymizedFile {
               else if (isTextFile(this.anonymizedPath)) res.contentType("text/plain");
             }
           });
+          resStream.once("error", () => headersDone(true));
+          resStream.once("close", () => headersDone());
           await streamResponse(resStream, res, (err: Error) => {
               const { error } = streamerErrorToAnonymous(
                 err as Error & {

src/core/GitHubUtils.ts

@@ -11,6 +11,7 @@ import Repository from "./Repository";
 import { getCredential, replaceCredential, getCredentialToken } from "./credentials";
 import config from "../config";
 import { createLogger } from "./logger";
+import { measureStage } from "./request-monitoring";
 
 const logger = createLogger("github");
 
@@ -281,6 +282,7 @@ export function octokit(token: string) {
     }
     throw err;
   });
+  oct.hook.wrap("request", (request, options) => measureStage("upstream", async () => request(options)));
   return oct;
 }
 
@@ -308,6 +310,10 @@ export async function checkToken(token: string) {
 const checkedRepositoryTokens = new WeakMap<Repository, string>();
 
 export async function getToken(repository: Repository) {
+  return measureStage("authorization", () => resolveRepositoryToken(repository));
+}
+
+async function resolveRepositoryToken(repository: Repository) {
   repository.assertNotArchived();
   logger.debug("getToken", { repoId: repository.repoId });
   if (isConnected && !repository.model.isNew) {

src/core/anonymization-pool.ts

@@ -1,6 +1,8 @@
 import { Worker } from "worker_threads";
 import { existsSync } from "fs";
 import { join } from "path";
+import { startStage } from "./request-monitoring";
+import { AsyncResource } from "async_hooks";
 
 const MEMORY_BUDGET = Math.max(128, Number(process.env.ANONYMIZATION_MEMORY_MB) || 512) * 1024 * 1024;
 const MAX_WORKERS = Math.min(4, Math.max(1, Number(process.env.ANONYMIZATION_WORKERS) || 1));
@@ -12,6 +14,8 @@ interface Job {
   reject: (error: Error) => void;
   timer?: NodeJS.Timeout;
   abort?: () => void;
+  waitingDone: ReturnType<typeof startStage>;
+  transformDone: () => ReturnType<typeof startStage>;
 }
 const waiting: Job[] = [];
 const idle: Worker[] = [];
@@ -23,16 +27,20 @@ export function anonymizeOnWorker(message: Job["message"], size: number, signal:
   if (weight > MEMORY_BUDGET) return Promise.reject(new Error("anonymization_memory_budget_exceeded"));
   if (waiting.length >= 16) return Promise.reject(new Error("anonymization_queue_full"));
   return new Promise((resolve, reject) => {
-    const job: Job = { message, weight, signal, resolve, reject };
+    const waitingDone = startStage("worker_wait");
+    // Bind the stage factory to the submitting request, not the preceding job.
+    const transformDone = AsyncResource.bind(() => startStage("anonymize"));
+    const job: Job = { message, weight, signal, resolve, reject, waitingDone, transformDone };
     job.abort = () => {
       const index = waiting.indexOf(job);
       if (index < 0) return;
       waiting.splice(index, 1);
       clearTimeout(job.timer);
       signal.removeEventListener("abort", job.abort!);
+      waitingDone(true);
       reject(new Error("anonymization_cancelled"));
     };
-    if (signal.aborted) return reject(new Error("anonymization_cancelled"));
+    if (signal.aborted) { waitingDone(true); return reject(new Error("anonymization_cancelled")); }
     signal.addEventListener("abort", job.abort, { once: true });
     job.timer = setTimeout(job.abort, 30_000);
     waiting.push(job);
@@ -42,6 +50,8 @@ export function anonymizeOnWorker(message: Job["message"], size: number, signal:
 function pump() {
   while (waiting.length && running < MAX_WORKERS && bytes + waiting[0].weight <= MEMORY_BUDGET) {
     const job = waiting.shift()!;
+    job.waitingDone();
+    const transformDone = job.transformDone();
     clearTimeout(job.timer);
     job.signal.removeEventListener("abort", job.abort!);
     running++;
@@ -51,12 +61,13 @@ function pump() {
     try { worker = idle.pop() || new Worker(existsSync(compiled) ? compiled : join(__dirname, "anonymization.worker.ts"), {
       execArgv: existsSync(compiled) ? [] : ["-r", require.resolve("ts-node/register/transpile-only")],
       resourceLimits: { maxOldGenerationSizeMb: Math.ceil(MEMORY_BUDGET / 1024 / 1024) },
-    }); } catch (error) { running--; bytes -= job.weight; job.reject(error as Error); continue; }
+    }); } catch (error) { running--; bytes -= job.weight; transformDone(true); job.reject(error as Error); continue; }
     worker.ref();
     let finished = false;
     const finish = (error?: Error, changed = false) => {
       if (finished) return;
       finished = true;
+      transformDone(!!error);
       clearTimeout(deadline);
       job.signal.removeEventListener("abort", cancel);
       worker.removeListener("message", message);
@@ -89,3 +100,7 @@ export function reserveSpool(bytes: number) {
   spoolBytes += bytes;
 }
 export function releaseSpool(bytes: number) { spoolBytes -= bytes; }
+export function getAnonymizationPoolStats() {
+  return { running, waiting: waiting.length, idle: idle.length, reservedBytes: bytes, spoolBytes,
+    maxWorkers: MAX_WORKERS, maxWaiting: 16, memoryBudgetBytes: MEMORY_BUDGET };
+}

src/core/performance-monitoring.ts

@@ -0,0 +1,213 @@
+import { createClient, RedisClientType } from "redis";
+import { hostname } from "os";
+import { readdir, readFile, readlink } from "fs/promises";
+import { monitorEventLoopDelay, performance } from "perf_hooks";
+import config from "../config";
+import { AsyncCache } from "./async-cache";
+import { activeRequestCount, LATENCY_BUCKETS, Metric, requestMetrics, Service } from "./request-monitoring";
+
+const PREFIX = "performance:v1:";
+const RETENTION = 2 * 3600;
+let client: RedisClientType | undefined;
+let stop: (() => Promise<void>) | undefined;
+let flushNow: (() => Promise<void>) | undefined;
+const reports = new AsyncCache<unknown>(10000, 2);
+const emptyMetric = (metric: string, route: string, method: string): Metric => ({ metric, route, method,
+  count: 0, sumMs: 0, bytes: 0, aborted: 0, errors: 0, slow: 0, buckets: Array(LATENCY_BUCKETS.length + 1).fill(0) });
+
+async function containerMemoryLimit() {
+  for (const path of ["/sys/fs/cgroup/memory.max", "/sys/fs/cgroup/memory/memory.limit_in_bytes"]) {
+    const raw = await readFile(path, "utf8").catch(() => "");
+    const value = Number(raw.trim());
+    if (value > 0 && value < Number.MAX_SAFE_INTEGER) return value;
+  }
+  return null;
+}
+
+async function redisDeadline<T>(work: Promise<T>, redis: RedisClientType): Promise<T> {
+  let timer: NodeJS.Timeout | undefined;
+  try {
+    return await Promise.race([work, new Promise<never>((_resolve, reject) => {
+      timer = setTimeout(() => {
+        reject(new Error("performance_monitoring_timeout"));
+        if (redis.isOpen) void redis.disconnect().then(() => client === redis ? redis.connect() : undefined).catch(() => {});
+      }, 2000); timer.unref();
+    })]);
+  } finally { clearTimeout(timer); }
+}
+
+export async function flushPerformanceMetrics() { await flushNow?.(); reports.clear(); }
+
+export function percentileUpperBound(buckets: number[], percentile: number): number | null {
+  const total = buckets.reduce((sum, count) => sum + count, 0);
+  if (!total) return null;
+  let count = 0;
+  for (let i = 0; i < buckets.length; i++) {
+    count += buckets[i];
+    if (count >= Math.ceil(total * percentile)) return LATENCY_BUCKETS[i] ?? null;
+  }
+  return null;
+}
+
+/** PID-owned sockets only: /proc/net also includes healthcheck subprocesses. */
+export async function socketSnapshot() {
+  try {
+    const descriptors = (await readdir("/proc/self/fd")).slice(0, 4096);
+    const sockets = new Set<string>();
+    for (let i = 0; i < descriptors.length; i += 32) {
+      const links = await Promise.all(descriptors.slice(i, i + 32).map(fd => readlink(`/proc/self/fd/${fd}`).catch(() => "")));
+      for (const link of links) { const match = /^socket:\[(\d+)\]$/.exec(link); if (match) sockets.add(match[1]); }
+    }
+    const states: Record<string, number> = {};
+    for (const file of ["/proc/self/net/tcp", "/proc/self/net/tcp6"]) {
+      const table = await readFile(file, "utf8");
+      for (const line of table.trim().split("\n").slice(1)) {
+        const columns = line.trim().split(/\s+/);
+        if (sockets.has(columns[9])) states[columns[3]] = (states[columns[3]] || 0) + 1;
+      }
+    }
+    return { descriptors: sockets.size, established: states["01"] || 0, closeWait: states["08"] || 0,
+      listening: states["0A"] || 0, truncated: descriptors.length === 4096 };
+  } catch { return null; }
+}
+
+/** One bounded batch every 15s. Redis outages never queue commands or hold HTTP requests. */
+export function startPerformanceMonitoring(service: Service, workers: () => unknown = () => null) {
+  if (stop) return stop;
+  const redis = createClient({ disableOfflineQueue: true, socket: { host: config.REDIS_HOSTNAME,
+    port: config.REDIS_PORT, connectTimeout: 2000, reconnectStrategy: retries => Math.min(5000, 250 * (retries + 1)) } }) as RedisClientType;
+  client = redis;
+  redis.on("error", () => {});
+  void redis.connect().catch(() => {});
+  const loop = monitorEventLoopDelay({ resolution: 20 }); loop.enable();
+  let previousUtilization = performance.eventLoopUtilization();
+  let previousCpu = process.cpuUsage();
+  let previousCpuAt = performance.now();
+  let busy = false;
+  let droppedBatches = 0;
+  let lastFlushAt: number | null = null;
+  let stopped = false;
+  const instance = `${service}:${hostname()}`;
+  const flush = async () => {
+    if (busy || stopped) return;
+    busy = true;
+    const entries = requestMetrics.drain();
+    try {
+      if (!redis.isReady) { droppedBatches += entries.length ? 1 : 0; return; }
+      const utilization = performance.eventLoopUtilization(previousUtilization);
+      previousUtilization = performance.eventLoopUtilization();
+      const cpu = process.cpuUsage(previousCpu);
+      const cpuAt = performance.now();
+      const cpuPercent = (cpu.user + cpu.system) / ((cpuAt - previousCpuAt) * 1000) * 100;
+      previousCpu = process.cpuUsage(); previousCpuAt = cpuAt;
+      const runtime = { instance, service, sampledAt: Date.now(), uptime: process.uptime(),
+        cpuPercent, memoryLimitBytes: await containerMemoryLimit(),
+        memory: process.memoryUsage(), activeRequests: activeRequestCount(), sockets: await socketSnapshot(), workers: workers(),
+        eventLoop: { utilization: utilization.utilization, p95Ms: loop.percentile(95) / 1e6,
+          maxMs: Number.isFinite(loop.max) ? loop.max / 1e6 : 0 },
+        droppedMetrics: requestMetrics.dropped, droppedBatches, lastFlushAt };
+      loop.reset();
+      const tx = redis.multi();
+      const touched = new Set<string>();
+      for (const { minute, data } of entries) {
+        const key = `${PREFIX}minute:${service}:${minute}`;
+        touched.add(key);
+        const label = JSON.stringify([data.metric, data.route, data.method]);
+        const fields: Record<string, number> = { count: data.count, sumMs: data.sumMs, bytes: data.bytes,
+          aborted: data.aborted, errors: data.errors, slow: data.slow };
+        data.buckets.forEach((count, i) => { fields[`b${i}`] = count; });
+        for (const [field, value] of Object.entries(fields)) if (value) tx.hIncrBy(key, `${label}|${field}`, value);
+      }
+      for (const key of touched) tx.expire(key, RETENTION);
+      tx.set(`${PREFIX}instance:${instance}`, JSON.stringify(runtime), { EX: 90 });
+      tx.zAdd(`${PREFIX}instances`, { score: runtime.sampledAt, value: instance });
+      tx.zRemRangeByScore(`${PREFIX}instances`, 0, runtime.sampledAt - 90000);
+      tx.expire(`${PREFIX}instances`, 120);
+      tx.lPush(`${PREFIX}runtime:${service}`, JSON.stringify(runtime));
+      tx.lTrim(`${PREFIX}runtime:${service}`, 0, service === "api" ? 239 : 959);
+      tx.expire(`${PREFIX}runtime:${service}`, RETENTION);
+      await redisDeadline(tx.exec(), redis); lastFlushAt = Date.now();
+    } catch { droppedBatches++; }
+    finally { busy = false; }
+  };
+  const timer = setInterval(() => { void flush(); }, 15000); timer.unref();
+  flushNow = flush;
+  void flush();
+  stop = async () => {
+    stopped = true; clearInterval(timer); loop.disable();
+    if (redis.isOpen) await redis.disconnect();
+    client = undefined; stop = undefined; flushNow = undefined; reports.clear();
+  };
+  return stop;
+}
+
+export async function performanceReport(minutes: number) {
+  const windowMinutes = minutes === 60 ? 60 : 15;
+  if (!client?.isReady) return { available: false, windowMinutes, instances: [], routes: [], stages: [] };
+  const redis = client;
+  return reports.get(String(windowMinutes), async () => {
+    const minute = Math.floor(Date.now() / 60000) * 60000;
+    const groups = new Map<string, Metric & { service: Service }>();
+    const tx = redis.multi();
+    const requests: { service: Service; minute: number }[] = [];
+    for (const service of ["api", "streamer"] as const) {
+      for (let i = 0; i < windowMinutes; i++) {
+        requests.push({ service, minute: minute - i * 60000 });
+        tx.hGetAll(`${PREFIX}minute:${service}:${minute - i * 60000}`);
+      }
+    }
+    const values = await redisDeadline(tx.exec(), redis) as unknown as Record<string, string>[];
+    const series = new Map<number, { minute: number; requests: number; aborted: number; errors: number; sumMs: number }>();
+    values.forEach((hash, index) => {
+      for (const [key, raw] of Object.entries(hash || {})) {
+        const split = key.lastIndexOf("|");
+        const label = key.slice(0, split); const field = key.slice(split + 1);
+        const [metric, route, method] = JSON.parse(label) as string[];
+        const service = requests[index].service;
+        const id = `${service}:${label}`;
+        let row = groups.get(id);
+        if (!row) { row = { ...emptyMetric(metric, route, method), service }; groups.set(id, row); }
+        const value = Number(raw) || 0;
+        if (/^b\d+$/.test(field)) row.buckets[Number(field.slice(1))] += value;
+        else if (["count", "sumMs", "bytes", "aborted", "errors", "slow"].includes(field)) {
+          const numericField = field as "count" | "sumMs" | "bytes" | "aborted" | "errors" | "slow";
+          row[numericField] += value;
+        }
+        if (metric === "request" && service === "api") {
+          const timestamp = requests[index].minute;
+          const point = series.get(timestamp) || { minute: timestamp, requests: 0, aborted: 0, errors: 0, sumMs: 0 };
+          if (field === "count") point.requests += value;
+          if (field === "sumMs") point.sumMs += value;
+          if (field === "aborted") point.aborted += value;
+          if (field === "errors") point.errors += value;
+          series.set(timestamp, point);
+        }
+      }
+    });
+    const ids = await redisDeadline(redis.zRangeByScore(`${PREFIX}instances`, Date.now() - 90000, "+inf", { LIMIT: { offset: 0, count: 32 } }), redis);
+    const samples = ids.length ? await redisDeadline(redis.mGet(ids.map(id => `${PREFIX}instance:${id}`)), redis) : [];
+    const instances = samples.filter((sample): sample is string => !!sample).map(sample => JSON.parse(sample));
+    const runtimeSeries: { instance: string; service: string; sampledAt: number; rss: number; heapUsed: number; external: number;
+      cpuPercent: number; loopP95Ms: number; sockets: number | null; closeWait: number | null; waiting: number; reservedBytes: number }[] = [];
+    for (const service of ["api", "streamer"]) {
+      const samples = await redisDeadline(redis.lRange(`${PREFIX}runtime:${service}`, 0, service === "api" ? 239 : 959), redis);
+      for (const raw of samples) {
+        const sample = JSON.parse(raw);
+        if (sample.sampledAt >= Date.now() - windowMinutes * 60000) runtimeSeries.push({ service, instance: sample.instance,
+          sampledAt: sample.sampledAt, rss: sample.memory.rss, heapUsed: sample.memory.heapUsed, external: sample.memory.external,
+          cpuPercent: sample.cpuPercent, loopP95Ms: sample.eventLoop.p95Ms, sockets: sample.sockets?.descriptors ?? null,
+          closeWait: sample.sockets?.closeWait ?? null, waiting: sample.workers?.waiting || 0, reservedBytes: sample.workers?.reservedBytes || 0 });
+      }
+    }
+    const rows = [...groups.values()].map(row => ({ ...row, avgMs: row.count ? Math.round(row.sumMs / row.count) : 0,
+      p95UpperMs: percentileUpperBound(row.buckets, .95), p99UpperMs: percentileUpperBound(row.buckets, .99) }));
+    return { available: true, generatedAt: Date.now(), windowMinutes, instances,
+      routes: rows.filter(row => row.metric === "request").map(row => {
+        const firstByte = rows.find(sample => sample.metric === "first_byte" && sample.service === row.service && sample.route === row.route && sample.method === row.method);
+        return { ...row, firstByteCount: firstByte?.count || 0, firstByteP95UpperMs: firstByte?.p95UpperMs ?? null };
+      }).sort((a, b) => b.sumMs - a.sumMs),
+      stages: rows.filter(row => row.metric !== "request"), series: [...series.values()].sort((a, b) => a.minute - b.minute),
+      runtimeSeries, latencyBucketsMs: LATENCY_BUCKETS,
+      percentileNote: "Percentiles are histogram bucket upper bounds; null means no samples or above 60s." };
+  });
+}

src/core/request-monitoring.ts

@@ -0,0 +1,159 @@
+import { AsyncLocalStorage } from "async_hooks";
+import { randomUUID } from "crypto";
+import { performance } from "perf_hooks";
+import { RequestHandler } from "express";
+import { createLogger } from "./logger";
+
+export const LATENCY_BUCKETS = [10, 50, 100, 250, 500, 1000, 2500, 5000, 10000, 30000, 60000];
+export type Service = "api" | "streamer";
+export type Stage = "repository" | "authorization" | "upstream" | "cache_lookup" | "cache_fill" | "worker_wait" | "anonymize" | "streamer_headers";
+export interface Metric {
+  metric: string; route: string; method: string; count: number; sumMs: number;
+  bytes: number; aborted: number; errors: number; slow: number; buckets: number[];
+}
+const logger = createLogger("requests");
+const context = new AsyncLocalStorage<{ id: string; service: Service; stages: Partial<Record<Stage, number>> }>();
+const methods = new Set(["GET", "HEAD", "POST", "PUT", "PATCH", "DELETE", "OPTIONS"]);
+const staticRoutes = new Set([
+  "/", "/dashboard", "/anonymize", "/healthcheck", "/api/healthcheck", "/api/stat", "/api/stat/history",
+  "/api/options", "/api/message", "/api/user", "/api/user/quota", "/api/user/dashboard", "/api/repo",
+  "/api/anonymize-preview", "/api/admin/overview", "/api/admin/performance", "/api/admin/errors",
+  "/api/admin/errors/stats", "/api/admin/queues", "/api/admin/queues/metrics", "/github/app/webhook",
+]);
+
+/** Fixed labels: never use repository IDs, file names or query strings as metric keys. */
+export function requestRoute(url: string, service: Service): string {
+  const path = url.split("?", 1)[0].replace(/\/+$/, "") || "/";
+  if (service === "streamer") return ["/api/download", "/api", "/healthcheck"].includes(path) ? path : "other";
+  if (staticRoutes.has(path)) return path;
+  if (/^\/api\/repo\//.test(path)) {
+    const match = path.match(/^\/api\/repo\/[^/]+\/(file|files|zip|options|refresh|coauthors|extend)(?:\/|$)/);
+    if (match) {
+      const subroute = match[1] === "files" && /\/(counts|search)$/.exec(path);
+      return `/api/repo/:repoId/${match[1]}${match[1] === "file" ? "/:path" : subroute ? `/${subroute[1]}` : ""}`;
+    }
+    const github = path.match(/^\/api\/repo\/[^/]+\/[^/]+\/(readme|branches)$/);
+    if (github) return `/api/repo/:owner/:repo/${github[1]}`;
+    return "/api/repo/:repoId";
+  }
+  if (path.startsWith("/w/")) return "/w/:repoId/:path";
+  if (/^\/(r|repository)\//.test(path)) return "/r/:repoId/:path";
+  if (/^\/api\/(pr|gist)\//.test(path)) return `/api/${path.split("/")[2]}/:id/:path`;
+  if (/^\/(script|css|favicon|fonts|partials)\//.test(path)) return "/assets/:path";
+  if (path.startsWith("/github/")) return "/github/:action";
+  if (path.startsWith("/api/admin/")) return "/api/admin/:action";
+  if (path.startsWith("/api/user/")) return "/api/user/:action";
+  return "other";
+}
+
+export class RequestMetrics {
+  private pending = new Map<string, { minute: number; data: Metric }>();
+  dropped = 0;
+  constructor(private capacity = 512, private now = () => Date.now()) {}
+  get size() { return this.pending.size; }
+  observe(metric: string, route: string, method: string, ms: number,
+    detail: { bytes?: number; aborted?: boolean; error?: boolean; slow?: boolean } = {}) {
+    const minute = Math.floor(this.now() / 60000) * 60000;
+    const key = JSON.stringify([minute, metric, route, method]);
+    let entry = this.pending.get(key);
+    if (!entry) {
+      if (this.pending.size >= this.capacity) { this.dropped++; return; }
+      entry = { minute, data: { metric, route, method, count: 0, sumMs: 0, bytes: 0,
+        aborted: 0, errors: 0, slow: 0, buckets: Array(LATENCY_BUCKETS.length + 1).fill(0) } };
+      this.pending.set(key, entry);
+    }
+    const duration = Math.max(0, Number.isFinite(ms) ? ms : 0);
+    const data = entry.data;
+    data.count++; data.sumMs += Math.round(duration); data.bytes += detail.bytes || 0;
+    data.aborted += Number(!!detail.aborted); data.errors += Number(!!detail.error); data.slow += Number(!!detail.slow);
+    let bucket = LATENCY_BUCKETS.findIndex(bound => duration <= bound);
+    if (bucket < 0) bucket = LATENCY_BUCKETS.length;
+    data.buckets[bucket]++;
+  }
+  drain() { const entries = [...this.pending.values()]; this.pending.clear(); return entries; }
+}
+export const requestMetrics = new RequestMetrics();
+let activeRequests = 0;
+export function activeRequestCount() { return activeRequests; }
+export function requestHeaders(): Record<string, string> {
+  const id = context.getStore()?.id;
+  return id ? { "x-request-id": id } : {};
+}
+export function recordCacheHit(cache: "source" | "transformed", hit: boolean) {
+  if (context.getStore()) requestMetrics.observe(`${cache}_${hit ? "hit" : "miss"}`, "all", "all", 0);
+}
+
+/** Capture the context now: worker admission can resume from another request's callback. */
+export function startStage(stage: Stage) {
+  const started = performance.now();
+  const trace = context.getStore();
+  let ended = false;
+  return (error = false) => {
+    if (ended) return; ended = true;
+    if (!trace) return;
+    const ms = performance.now() - started;
+    trace.stages[stage] = (trace.stages[stage] || 0) + ms;
+    requestMetrics.observe(stage, "all", "all", ms, { error });
+  };
+}
+export async function measureStage<T>(stage: Stage, work: () => Promise<T>): Promise<T> {
+  const done = startStage(stage);
+  try { const value = await work(); done(); return value; }
+  catch (error) { done(true); throw error; }
+}
+
+export function monitorRequests(service: Service, metrics = requestMetrics,
+  log: Pick<typeof logger, "info" | "warn"> = logger): RequestHandler {
+  return (req, res, next) => {
+    const forwarded = service === "streamer" ? req.get("x-request-id") : undefined;
+    const id = forwarded && /^[a-f0-9-]{36}$/.test(forwarded) ? forwarded : randomUUID();
+    const trace = { id, service, stages: {} };
+    const route = requestRoute(req.originalUrl, service);
+    const method = methods.has(req.method) ? req.method : "OTHER";
+    const started = performance.now();
+    let firstByteMs: number | undefined;
+    let bytes = 0;
+    let ended = false;
+    activeRequests++;
+    res.setHeader("X-Request-ID", id);
+    const writeHead = res.writeHead;
+    res.writeHead = function (this: typeof res, ...args: unknown[]): typeof res {
+      firstByteMs ??= performance.now() - started;
+      return Reflect.apply(writeHead, this, args);
+    };
+    const count = (chunk: unknown, encoding: unknown) => {
+      if (req.method === "HEAD") return;
+      if (typeof chunk === "string") bytes += Buffer.byteLength(chunk, typeof encoding === "string" ? encoding as BufferEncoding : undefined);
+      else if (chunk instanceof Uint8Array) bytes += chunk.byteLength;
+    };
+    // Preserve callbacks, return values and receiver. Installed before compression,
+    // these count encoded body bytes without changing stream backpressure.
+    const write = res.write;
+    res.write = function (this: typeof res, ...args: unknown[]): boolean {
+      count(args[0], args[1]);
+      return Reflect.apply(write, this, args);
+    };
+    const end = res.end;
+    res.end = function (this: typeof res, ...args: unknown[]): typeof res {
+      count(args[0], args[1]);
+      return Reflect.apply(end, this, args);
+    };
+    const done = () => {
+      if (ended) return; ended = true;
+      activeRequests--;
+      res.removeListener("finish", done); res.removeListener("close", done);
+      const ms = performance.now() - started;
+      const aborted = !res.writableFinished;
+      const transfer = /\/(file|zip)(?:\/|$)/.test(route) || route.startsWith("/w/") || service === "streamer";
+      const slow = ms > (transfer ? 10000 : 1000);
+      metrics.observe("request", route, method, ms, { bytes, aborted, error: res.statusCode >= 500, slow });
+      if (firstByteMs != null) metrics.observe("first_byte", route, method, firstByteMs);
+      const detail = { requestId: id, service, method, route, status: res.statusCode,
+        outcome: aborted ? "interrupted" : "completed", ms: Math.round(ms), firstByteMs: firstByteMs == null ? null : Math.round(firstByteMs), bytes, stages: trace.stages };
+      if (slow || aborted) log.warn(aborted ? "request interrupted" : "slow request", detail);
+      else if (!route.includes("healthcheck")) log.info("request", detail);
+    };
+    res.once("finish", done); res.once("close", done);
+    context.run(trace, next);
+  };
+}

src/core/source/GitHubStream.ts

@@ -18,6 +18,7 @@ import { octokit, waitForTokenGate } from "../GitHubUtils";
 import FileModel from "../model/files/files.model";
 import { IFile } from "../model/files/files.types";
 import { createLogger, serializeError } from "../logger";
+import { measureStage, recordCacheHit } from "../request-monitoring";
 import config from "../../config";
 import { isConnected } from "../../server/database";
 import AnonymizedRepositoryModel from "../model/anonymizedRepositories/anonymizedRepositories.model";
@@ -286,7 +287,9 @@ export default class GitHubStream extends GitHubBase {
         return undefined;
       }
     };
-    if (await cached()) return storage.read(repoId, cachePath);
+    const hit = await measureStage("cache_lookup", cached);
+    recordCacheHit("source", !!hit);
+    if (hit) return storage.read(repoId, cachePath);
     if (expected.size != null && expected.size > config.MAX_FILE_SIZE) {
       throw new AnonymousError("file_too_big", { httpStatus: 413, object: filePath });
     }
@@ -295,37 +298,40 @@ export default class GitHubStream extends GitHubBase {
       if (cacheFills.size >= 64) throw new AnonymousError("cache_busy", { httpStatus: 503 });
       filling = coordinatedFill(key, cached, async () => {
         await assertActive();
-        const content = await this.downloadWithFallback(await this.data.getToken(), expected.sha, filePath);
-        let count = 0;
-        const limited = new stream.Transform({ transform(chunk, encoding, callback) {
-          count += chunk.length;
-          callback(count > config.MAX_FILE_SIZE ? new AnonymousError("file_too_big", { httpStatus: 413 }) : null, chunk);
-        } });
-        content.on("error", error => {
-          if (error instanceof AnonymousError) { limited.destroy(error); return; }
-          const status = (error as { response?: { statusCode?: number }; status?: number; httpStatus?: number });
-          const httpStatus = status.response?.statusCode ?? status.status ?? status.httpStatus;
-          const code = httpStatus === 403 ? "file_not_accessible"
-            : httpStatus === 404 ? "file_not_found"
-            : httpStatus === 422 ? "file_too_big" : "upstream_error";
-          limited.destroy(new AnonymousError(code, { httpStatus: httpStatus || 502, cause: error, object: filePath }));
+        const token = await this.data.getToken();
+        return measureStage("upstream", async () => {
+          const content = await this.downloadWithFallback(token, expected.sha, filePath);
+          let count = 0;
+          const limited = new stream.Transform({ transform(chunk, encoding, callback) {
+            count += chunk.length;
+            callback(count > config.MAX_FILE_SIZE ? new AnonymousError("file_too_big", { httpStatus: 413 }) : null, chunk);
+          } });
+          content.on("error", error => {
+            if (error instanceof AnonymousError) { limited.destroy(error); return; }
+            const status = (error as { response?: { statusCode?: number }; status?: number; httpStatus?: number });
+            const httpStatus = status.response?.statusCode ?? status.status ?? status.httpStatus;
+            const code = httpStatus === 403 ? "file_not_accessible"
+              : httpStatus === 404 ? "file_not_found"
+              : httpStatus === 422 ? "file_too_big" : "upstream_error";
+            limited.destroy(new AnonymousError(code, { httpStatus: httpStatus || 502, cause: error, object: filePath }));
+          });
+          limited.once("close", () => content.destroy());
+          limited.on("error", () => {});
+          content.pipe(limited);
+          const deadline = setTimeout(() => limited.destroy(new AnonymousError("upstream_error", { httpStatus: 502 })), 120_000);
+          try {
+            await storage.write(repoId, cachePath, limited, this.type, expected.size);
+            try { await assertActive(); }
+            catch (error) { await storage.rm(repoId, cachePath); throw error; }
+          }
+          finally { clearTimeout(deadline); limited.destroy(); content.destroy(); }
+          return true;
         });
-        limited.once("close", () => content.destroy());
-        limited.on("error", () => {});
-        content.pipe(limited);
-        const deadline = setTimeout(() => limited.destroy(new AnonymousError("upstream_error", { httpStatus: 502 })), 120_000);
-        try {
-          await storage.write(repoId, cachePath, limited, this.type, expected.size);
-          try { await assertActive(); }
-          catch (error) { await storage.rm(repoId, cachePath); throw error; }
-        }
-        finally { clearTimeout(deadline); limited.destroy(); content.destroy(); }
-        return true;
       }).then(() => {});
       cacheFills.set(key, filling);
       void filling.finally(() => { if (cacheFills.get(key) === filling) cacheFills.delete(key); }).catch(() => {});
     }
-    await filling;
+    await measureStage("cache_fill", () => filling!);
     return storage.read(repoId, cachePath);
   }
 

src/core/transformed-cache.ts

@@ -8,6 +8,7 @@ import { isConnected } from "../server/database";
 import RepositoryModel from "./model/anonymizedRepositories/anonymizedRepositories.model";
 import { RepositoryStatus } from "./types";
 import AnonymousError from "./AnonymousError";
+import { recordCacheHit } from "./request-monitoring";
 const root = join(tmpdir(), "anonymous-transformed-v1");
 const TTL = 3600_000;
 const DISK_BUDGET = 512 * 1024 * 1024;
@@ -62,8 +63,9 @@ export async function transformedFile(digest: string, options: unknown, output:
   };
   const hit = await read();
   if (hit !== undefined) {
-    try { return await copyCached(hit); } catch { /* eviction: retry the transformation */ }
+    try { const copied = await copyCached(hit); recordCacheHit("transformed", true); return copied; } catch { /* eviction: retry the transformation */ }
   }
+  recordCacheHit("transformed", false);
   const pending = fills.get(key);
   if (pending) {
     await pending.catch(() => {});

src/core/zipStream.ts

@@ -12,6 +12,7 @@ import {
   compileTerms,
 } from "./anonymize-utils";
 import { createLogger, serializeError } from "./logger";
+import { startStage } from "./request-monitoring";
 
 const logger = createLogger("zip-stream");
 
@@ -111,7 +112,11 @@ export async function streamAnonymizedZip(
       },
     });
   }
+  const upstreamDone = startStage("upstream");
   const downloadStream = got.stream(response.url);
+  downloadStream.once("end", () => upstreamDone());
+  downloadStream.once("error", () => upstreamDone(true));
+  downloadStream.once("close", () => upstreamDone(!downloadStream.readableEnded));
 
   const archive = archiver("zip", {});
   const parser = Parse() as Transform;

src/server/index.ts

@@ -36,6 +36,9 @@ import { getUser } from "./routes/route-utils";
 import config from "../config";
 import { resolveTrustProxy, isCloudflareIP } from "./trustProxy";
 import { createLogger, serializeError } from "../core/logger";
+import { monitorRequests } from "../core/request-monitoring";
+import { startPerformanceMonitoring } from "../core/performance-monitoring";
+import { getAnonymizationPoolStats } from "../core/anonymization-pool";
 
 const logger = createLogger("server");
 
@@ -99,6 +102,8 @@ function indexResponse(req: express.Request, res: express.Response) {
 
 export default async function start() {
   const app = express();
+  app.use(monitorRequests("api"));
+  startPerformanceMonitoring("api", getAnonymizationPoolStats);
   app.set("query parser", "extended");
   app.use("/github/app/webhook", githubAppWebhook);
   app.use(express.json());
@@ -228,20 +233,6 @@ export default async function start() {
     keyGenerator,
   });
 
-  app.use(function (req, res, next) {
-    const start = Date.now();
-    res.on("finish", function () {
-      const time = Date.now() - start;
-      logger.info("request", {
-        method: req.method,
-        status: res.statusCode,
-        url: join(req.baseUrl || "", req.url || ""),
-        ms: time,
-      });
-    });
-    next();
-  });
-
   app.use("/github", rate, speedLimiter, githubAppRouter);
   app.use("/github", rate, speedLimiter, connectionRouter);
 

src/server/routes/admin.ts

@@ -1,6 +1,7 @@
 import { AsyncCache } from "../../core/async-cache";
 import * as os from "os";
-import { execSync } from "child_process";
+import { execFile } from "child_process";
+import { promisify } from "util";
 import { Queue, JobType } from "bullmq";
 import * as express from "express";
 import AnonymousError from "../../core/AnonymousError";
@@ -30,8 +31,11 @@ import {
 } from "../../core/logger";
 import { createClient, RedisClientType } from "redis";
 import config from "../../config";
+import { performanceReport } from "../../core/performance-monitoring";
 
 const logger = createLogger("admin");
+const execFileAsync = promisify(execFile);
+const diskUsageCache = new AsyncCache<string>(30000, 1);
 
 let errorLogClient: RedisClientType | null = null;
 
@@ -78,6 +82,12 @@ router.use(
 
 router.use("/tokens", adminTokensRouter);
 
+router.get("/performance", async (req, res) => {
+  res.set("Cache-Control", "no-store");
+  try { res.json(await performanceReport(Number(req.query.minutes))); }
+  catch { res.json({ available: false, instances: [], routes: [], stages: [] }); }
+});
+
 function dashboardCache(
   _req: express.Request,
   res: express.Response,
@@ -627,7 +637,10 @@ router.get("/overview", async (req, res) => {
     // Disk usage via df (root partition)
     let diskTotal = 0, diskUsed = 0, diskFree = 0, diskPercent = 0, diskMount = "/";
     try {
-      const dfOut = execSync("df -k / 2>/dev/null", { timeout: 3000 }).toString();
+      const dfOut = await diskUsageCache.get("root", async () => {
+        const result = await execFileAsync("df", ["-k", "/"], { timeout: 3000, maxBuffer: 16384 });
+        return result.stdout;
+      });
       const lines = dfOut.trim().split("\n");
       if (lines.length >= 2) {
         const cols = lines[1].split(/\s+/);

src/server/routes/file.ts

@@ -3,6 +3,9 @@ import AnonymizedFile from "../../core/AnonymizedFile";
 import AnonymousError from "../../core/AnonymousError";
 import { getRepo, handleError } from "./route-utils";
 import { fileETag } from "./file-etag";
+import config from "../../config";
+import { lookup } from "mime-types";
+import { isTextFile } from "../../core/anonymize-utils";
 
 export const router = express.Router();
 
@@ -142,9 +145,17 @@ router.get(
       // anonymization term list left old anonymizations cached under the
       // same URL.
       res.header("Cache-Control", "private, no-cache, must-revalidate");
-      if (req.headers["if-none-match"] === etag) {
+      if (req.fresh) {
         return res.status(304).end();
       }
+      if (req.method === "HEAD") {
+        const size = await f.size();
+        if (size != null && size > config.MAX_FILE_SIZE) throw new AnonymousError("file_too_big", { httpStatus: 413 });
+        const mime = lookup(originalPath);
+        if (mime && !originalPath.endsWith(".ts")) res.type(mime);
+        else if (isTextFile(originalPath)) res.type("text/plain");
+        res.end(); return;
+      }
       await f.send(res);
       await repo.countView();
     } catch (error) {

src/server/routes/repository-public.ts

@@ -14,6 +14,7 @@ import FileModel from "../../core/model/files/files.model";
 import { createLogger, serializeError } from "../../core/logger";
 import { githubTokenForStreamer } from "../../core/github-token-context";
 import gh = require("parse-github-url");
+import { requestHeaders, startStage } from "../../core/request-monitoring";
 
 const logger = createLogger("repository-public");
 
@@ -52,16 +53,20 @@ router.get(
         });
       }
 
+      res.attachment(`${repo.repoId}.zip`);
+      if (req.method === "HEAD") { res.end(); return; }
       await repo.countView();
 
       if (config.STREAMER_ENTRYPOINT) {
         // use the streamer service
         const token = await repo.getToken();
         const anonymizer = repo.generateAnonymizeTransformer("");
+        const headersDone = startStage("streamer_headers");
         res.attachment(`${repo.repoId}.zip`);
         const reqStream = got
           .stream(join(config.STREAMER_ENTRYPOINT, "api/download"), {
             method: "POST",
+            headers: requestHeaders(),
             json: {
               token: await githubTokenForStreamer(token, repo.model.source.repositoryName),
               repoFullName: repo.model.source.repositoryName,
@@ -76,6 +81,7 @@ router.get(
             },
           })
           .on("error", (err: Error & { response?: { statusCode?: number; body?: unknown } }) => {
+            headersDone(true);
             const upstreamStatus = err?.response?.statusCode;
             let upstreamBody: string | undefined;
             let errCode = "zip_not_available";
@@ -130,6 +136,8 @@ router.get(
             // instead of waiting forever for the ZIP's central directory.
             if (streaming && !res.writableEnded) res.destroy();
           });
+        reqStream.once("response", () => headersDone());
+        reqStream.once("close", () => headersDone());
         reqStream.pipe(res);
         res.on("close", () => {
           reqStream.destroy();

src/server/routes/route-utils.ts

@@ -8,6 +8,7 @@ import { HTTPError } from "got";
 import { RepositoryStatus } from "../../core/types";
 import { createLogger, serializeError } from "../../core/logger";
 import { isDisabledAccount } from "./auth-utils";
+import { measureStage } from "../../core/request-monitoring";
 
 const logger = createLogger("route");
 
@@ -81,7 +82,8 @@ export async function getRepo(
     if (typeof req.params.repoId !== "string") {
       throw new AnonymousError("invalid_path", { httpStatus: 400 });
     }
-    const repo = await db.getRepository(req.params.repoId);
+    const repoId = req.params.repoId;
+    const repo = await measureStage("repository", () => db.getRepository(repoId));
     if (opt.nocheck !== true) {
       // redirect if the repository is expired
       if (

src/server/routes/webview.ts

@@ -5,8 +5,11 @@ import AnonymizedFile from "../../core/AnonymizedFile";
 import AnonymousError from "../../core/AnonymousError";
 import * as marked from "marked";
 import * as sanitizeHtml from "sanitize-html";
-import { streamToString } from "../../core/anonymize-utils";
+import { streamToString, isTextFile } from "../../core/anonymize-utils";
 import { IFile } from "../../core/model/files/files.types";
+import { fileETag } from "./file-etag";
+import { lookup } from "mime-types";
+import config from "../../config";
 
 function escapeHtml(str: string): string {
   return str
@@ -170,6 +173,19 @@ async function webView(
         object: f,
       });
     }
+    res.set("Cache-Control", "private, no-cache, must-revalidate");
+    const pageETag = fileETag(JSON.stringify(["web-v1", repo.model.source.commit, repo.model.treeGeneration, repo.model.contentCacheRevision,
+      await f.sha(), repo.model.source.repositoryName, repo.model.source.branch, config.APP_HOSTNAME, config.ANONYMIZATION_MASK]),
+      requestPath, repo.options);
+    res.set("ETag", pageETag);
+    if (req.fresh) { res.status(304).end(); return; }
+    if (req.method === "HEAD") {
+      const size = await f.size();
+      if (size != null && size > config.MAX_FILE_SIZE) throw new AnonymousError("file_too_big", { httpStatus: 413 });
+      const mime = lookup(requestPath);
+      res.type(f.extension() === "md" ? "text/html" : mime && !requestPath.endsWith(".ts") ? mime : isTextFile(requestPath) ? "text/plain" : "application/octet-stream");
+      res.end(); return;
+    }
     if (f.extension() == "md") {
       try {
         const content = await streamToString(await f.anonymizedContent());
@@ -177,6 +193,8 @@ async function webView(
         const html = `<!DOCTYPE html><html><head><title>Content</title></head><link rel="stylesheet" href="/css/all.min.css" /><body><div class="container p-3 file-content markdown-body">${body}</div></body></html>`;
         res.contentType("text/html").send(html);
       } catch {
+        // Raw Markdown must re-enter rendering when a transient failure clears.
+        res.set("ETag", fileETag(`web-raw:${pageETag}`, requestPath, repo.options));
         await f.send(res);
       }
     } else {

src/streamer/index.ts

@@ -11,10 +11,14 @@ import AnonymousError from "../core/AnonymousError";
 import { createLogger, serializeError } from "../core/logger";
 import { connect } from "../server/database";
 import { startTemporaryStorageMaintenance } from "../core/temporary-storage";
+import { monitorRequests } from "../core/request-monitoring";
+import { startPerformanceMonitoring } from "../core/performance-monitoring";
+import { getAnonymizationPoolStats } from "../core/anonymization-pool";
 
 const logger = createLogger("streamer");
 
 const app = express();
+app.use(monitorRequests("streamer"));
 app.use(express.json());
 
 app.use(
@@ -46,6 +50,7 @@ app.all("/{*path}", (req, res) => {
   );
 });
 async function start() {
+  startPerformanceMonitoring("streamer", getAnonymizationPoolStats);
   await connect({ appName: "Anonymous GitHub Streamer", maxPoolSize: 10, minPoolSize: 0 });
   await startTemporaryStorageMaintenance();
   app.listen(config.PORT, (error?: Error) => {