Add --log-markers option to extract Log-type marker payloads

README.md

@@ -89,13 +89,47 @@ profiler-cli <profile> --flamegraph 5
 ```
 
 ### `--top-markers [N]`
-Show the top 5 markers by total duration and by max single-instance duration. If N is specified, shows the top N markers.
+Show the top 5 markers by total duration and by max single-instance duration. If N is specified, shows the top N markers by frequency.
+
+Only counts markers that have a non-zero duration. Zero-duration log markers are not included — use `--log-markers` for those.
 
 ```bash
 profiler-cli <profile> --top-markers
 profiler-cli <profile> --top-markers 20
 ```
 
+### `--log-markers [FILTER]`
+Extract the text content of `Log`-type markers emitted by Firefox's `about:logging` media preset. These are instant, zero-duration markers that carry a module name and a log message as their payload — invisible to `--top-markers` and `--focus-marker`.
+
+Output is grouped by thread and sorted chronologically. An optional filter string restricts results to entries where the message, module name, or thread name contains the filter (case-insensitive).
+
+```bash
+# Show all log markers across all threads
+profiler-cli <profile> --log-markers
+
+# Filter by thread name
+profiler-cli <profile> --log-markers "MediaDecoderStateMachine"
+
+# Filter by message content
+profiler-cli <profile> --log-markers "blank media"
+
+# Filter by module name
+profiler-cli <profile> --log-markers "D/MediaDecoder"
+```
+
+Example output:
+```
+Log markers (filter: "MediaDecoder"): 14089 total
+
+[MediaDecoderStateMachine #3]
+  t=100.00ms  [D/MediaDecoder] StateChange DECODING
+  t=200.00ms  [D/MediaDecoder] StartBuffering reason=NotEnoughData
+```
+
+**When to use `--log-markers` vs `--focus-marker`:**
+- `--focus-marker` is a *sample filter* — it restricts which CPU samples appear in a `--calltree` or `--flamegraph`, using named markers as time windows. Use it to answer "what code was running during X?"
+- `--log-markers` is a *log reader* — it extracts the text payload of `about:logging` entries. Use it to answer "what did the media pipeline log?" No call tree involved.
+
 ### `--page-load`
 Show a page load performance summary including navigation timing (FCP, Load), resource loading statistics, CPU category breakdown, and jank period analysis.
 

src/index.ts

@@ -1,7 +1,7 @@
 #!/usr/bin/env node
 import { hideBin } from "yargs/helpers";
 import { chromium, firefox } from "playwright";
-import { getCallTreeData, getMarkerSummary, getFlamegraphData, getPageLoadSummary, getNetworkResources, annotateFunction } from "./profiler.js";
+import { getCallTreeData, getMarkerSummary, getLogMarkers, getFlamegraphData, getPageLoadSummary, getNetworkResources, annotateFunction } from "./profiler.js";
 import { FlameNode } from "./types.js";
 import { existsSync } from 'fs';
 import { spawn } from 'child_process';
@@ -353,6 +353,7 @@ if (validationError) {
 const profileUrl = argv._[0] as string;
 const hasTopMarkersFlag = process.argv.includes('--top-markers');
 const hasFlamegraphFlag = process.argv.includes('--flamegraph');
+const hasLogMarkersFlag = process.argv.includes('--log-markers');
 
 // Check if this is a local profile file (.json.gz), and if so start samply
 let samplyProcess: any = null;
@@ -509,6 +510,28 @@ try {
         console.log();
       }
     }
+  } else if (hasLogMarkersFlag) {
+    const filter = (argv.logMarkers && argv.logMarkers !== "") ? argv.logMarkers : null;
+    const entries = await getLogMarkers(browser, actualProfileUrl, filter);
+
+    if (entries.length === 0) {
+      console.log(filter
+        ? `No Log markers found matching "${filter}".`
+        : "No Log markers found in this profile.");
+    } else {
+      const filterLabel = filter ? ` (filter: "${filter}")` : "";
+      console.log(`\nLog markers${filterLabel}: ${entries.length} total\n`);
+
+      let currentThread = "";
+      for (const entry of entries) {
+        if (entry.thread !== currentThread) {
+          currentThread = entry.thread;
+          console.log(`\n[${currentThread}]`);
+        }
+        const moduleLabel = entry.module ? `[${entry.module}] ` : "";
+        console.log(`  t=${entry.time.toFixed(2)}ms  ${moduleLabel}${entry.message}`);
+      }
+    }
   } else if (hasFlamegraphFlag) {
     const maxDepth = argv.flamegraph || null;
     const flamegraphData = await getFlamegraphData(

src/options.ts

@@ -69,6 +69,10 @@ export function buildParser(args: string[]) {
       describe: "Collapse a function and its subtree into a single node",
       type: "string",
     })
+    .option("log-markers", {
+      describe: "Show Log-type markers (from about:logging captures) with their text payload. Optionally filter by keyword",
+      type: "string",
+    })
     .option("samply-path", {
       describe: "Path to samply binary (default: use samply from PATH)",
       type: "string",
@@ -92,6 +96,7 @@ export type ParsedArgs = {
   annotate?: string;
   color: boolean;
   collapseFunction?: string;
+  logMarkers?: string;
   samplyPath?: string;
 };
 
@@ -106,14 +111,15 @@ export function validateArgs(argv: ParsedArgs, rawArgs: string[]): string | null
 
   const hasTopMarkersFlag = rawArgs.includes('--top-markers');
   const hasFlamegraphFlag = rawArgs.includes('--flamegraph');
+  const hasLogMarkersFlag = rawArgs.includes('--log-markers');
 
-  if (!argv.calltree && !hasTopMarkersFlag && !hasFlamegraphFlag && !argv.pageLoad && !argv.network && !argv.annotate) {
-    return "Please specify one of: --calltree <N>, --flamegraph, --top-markers [N], --page-load, --network, or --annotate <asm|src|all> <function-name>";
+  if (!argv.calltree && !hasTopMarkersFlag && !hasFlamegraphFlag && !argv.pageLoad && !argv.network && !argv.annotate && !hasLogMarkersFlag) {
+    return "Please specify one of: --calltree <N>, --flamegraph, --top-markers [N], --page-load, --network, --log-markers [filter], or --annotate <asm|src|all> <function-name>";
   }
 
-  const optionCount = [argv.calltree, hasTopMarkersFlag, hasFlamegraphFlag, argv.pageLoad, argv.network, argv.annotate].filter(x => x !== undefined && x !== false).length;
+  const optionCount = [argv.calltree, hasTopMarkersFlag, hasFlamegraphFlag, argv.pageLoad, argv.network, argv.annotate, hasLogMarkersFlag].filter(x => x !== undefined && x !== false).length;
   if (optionCount > 1) {
-    return "Please specify only one of: --calltree, --flamegraph, --top-markers, --page-load, --network, or --annotate";
+    return "Please specify only one of: --calltree, --flamegraph, --top-markers, --page-load, --network, --log-markers, or --annotate";
   }
 
   if (argv.annotate && !argv._[1]) {

src/profiler.ts

@@ -1,5 +1,5 @@
 import { Browser } from "playwright";
-import { CallTreeNode, MarkerSummary, FlameNode, PageLoadSummary, NetworkResourceSummary } from "./types.js";
+import { CallTreeNode, MarkerSummary, LogMarkerEntry, FlameNode, PageLoadSummary, NetworkResourceSummary } from "./types.js";
 import { parseProfileFile } from "./profile-parser.js";
 
 declare const window: any;
@@ -499,6 +499,72 @@ export async function getMarkerSummary(
   return result.summaries;
 }
 
+export async function getLogMarkers(
+  browser: Browser,
+  url: string,
+  filter: string | null = null
+): Promise<LogMarkerEntry[]> {
+  const page = await browser.newPage({
+    bypassCSP: true,
+  });
+
+  page.setDefaultTimeout(0);
+
+  await page.goto(url);
+
+  await page.waitForFunction(() => {
+    return (
+      window.selectors &&
+      selectors.app.getView(getState()).phase == "DATA_LOADED"
+    );
+  });
+
+  await page.waitForFunction(() => {
+    return selectors.profile.getSymbolicationStatus(getState()) == "DONE";
+  });
+
+  const jsonString = await page.evaluate((filter: string | null) => {
+    const profile = selectors.profile.getProfile(getState());
+    const results: Array<{ thread: string; time: number; module: string; message: string }> = [];
+
+    for (const thread of profile.threads) {
+      const { name, markers } = thread;
+      if (!markers) continue;
+
+      const { startTime, data: markerData, length: markerLength } = markers;
+
+      for (let i = 0; i < markerLength; i++) {
+        const mData = markerData[i];
+        if (!mData || mData.type !== "Log") continue;
+
+        // data.name for Log markers is always a plain string in the profiler store
+        const message = String(mData.name ?? "");
+        const module = String(mData.module ?? "");
+
+        if (filter !== null && filter !== "") {
+          const lf = filter.toLowerCase();
+          if (!message.toLowerCase().includes(lf) && !module.toLowerCase().includes(lf) && !name.toLowerCase().includes(lf)) {
+            continue;
+          }
+        }
+
+        results.push({ thread: name, time: startTime[i] ?? 0, module, message });
+      }
+    }
+
+    results.sort((a, b) => a.time - b.time);
+    return JSON.stringify(results);
+  }, filter);
+
+  await page.close();
+
+  if (typeof jsonString !== "string") {
+    throw new Error("Did not get back a string");
+  }
+
+  return JSON.parse(jsonString);
+}
+
 export async function getFlamegraphData(
   browser: Browser,
   url: string,

src/types.ts

@@ -88,6 +88,13 @@ export interface PageLoadSummary {
   jankPeriods: JankPeriod[] | null;
 }
 
+export interface LogMarkerEntry {
+  thread: string;
+  time: number;
+  module: string;
+  message: string;
+}
+
 export interface AssemblyInstruction {
   address: string;
   instruction: string;

tests/log-markers.test.ts

@@ -0,0 +1,98 @@
+import { describe, it, expect } from "vitest";
+import { execFile } from "child_process";
+import { promisify } from "util";
+import { resolve } from "path";
+
+const execFileAsync = promisify(execFile);
+
+const PROFILE = resolve(import.meta.dirname, "fixtures/log-markers-profile.json.gz");
+const CLI = resolve(import.meta.dirname, "../dist/index.js");
+
+async function runCli(args: string[]): Promise<{ stdout: string; stderr: string }> {
+  return execFileAsync("node", [CLI, ...args], { timeout: 120_000 });
+}
+
+describe("--log-markers", () => {
+  describe("log-markers-profile", () => {
+    it("shows all Log markers across all threads when no filter given", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers"]);
+
+      expect(stdout).toContain("Log markers: 4 total");
+      expect(stdout).toContain("[MediaDecoderStateMachine #3]");
+      expect(stdout).toContain("[MediaSupervisor #1]");
+      expect(stdout).toContain("StateChange DECODING");
+      expect(stdout).toContain("StartBuffering reason=NotEnoughData");
+      expect(stdout).toContain("Update(Audio) desc:apple coremedia decoder");
+      expect(stdout).toContain("Update(Video) desc:blank media data decoder");
+    }, 120_000);
+
+    it("excludes non-Log markers", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers"]);
+
+      expect(stdout).not.toContain("DOMEvent");
+      expect(stdout).not.toContain("seeking");
+    }, 120_000);
+
+    it("shows module labels in output", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers"]);
+
+      expect(stdout).toContain("[D/MediaDecoder]");
+      expect(stdout).toContain("[V/MediaFormatReader]");
+    }, 120_000);
+
+    it("filters by message content", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers", "blank media"]);
+
+      expect(stdout).toContain("blank media data decoder");
+      expect(stdout).not.toContain("StateChange DECODING");
+      expect(stdout).not.toContain("Update(Audio)");
+    }, 120_000);
+
+    it("filters by module name", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers", "D/MediaDecoder"]);
+
+      expect(stdout).toContain("StateChange DECODING");
+      expect(stdout).toContain("StartBuffering reason=NotEnoughData");
+      expect(stdout).not.toContain("Update(Audio)");
+      expect(stdout).not.toContain("Update(Video)");
+    }, 120_000);
+
+    it("filters by thread name", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers", "MediaSupervisor"]);
+
+      expect(stdout).toContain("[MediaSupervisor #1]");
+      expect(stdout).toContain("Update(Audio)");
+      expect(stdout).toContain("Update(Video)");
+      expect(stdout).not.toContain("[MediaDecoderStateMachine #3]");
+    }, 120_000);
+
+    it("returns no-match message when filter finds nothing", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers", "xyz_not_found"]);
+
+      expect(stdout).toContain('No Log markers found matching "xyz_not_found"');
+    }, 120_000);
+
+    it("outputs markers sorted by time", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers"]);
+
+      const decoding = stdout.indexOf("StateChange DECODING");
+      const audio = stdout.indexOf("Update(Audio)");
+      const buffering = stdout.indexOf("StartBuffering");
+      const video = stdout.indexOf("Update(Video)");
+
+      // t=100 < t=150 < t=200 < t=250
+      expect(decoding).toBeLessThan(audio);
+      expect(audio).toBeLessThan(buffering);
+      expect(buffering).toBeLessThan(video);
+    }, 120_000);
+
+    it("shows timestamp for each entry", async () => {
+      const { stdout } = await runCli([PROFILE, "--log-markers"]);
+
+      expect(stdout).toMatch(/t=100\.00ms/);
+      expect(stdout).toMatch(/t=150\.00ms/);
+      expect(stdout).toMatch(/t=200\.00ms/);
+      expect(stdout).toMatch(/t=250\.00ms/);
+    }, 120_000);
+  });
+});

tests/options.test.ts

@@ -162,6 +162,18 @@ describe("buildParser", () => {
       expect(argv.topMarkers).toBe(10);
     });
   });
+
+  describe("--log-markers", () => {
+    it("parses filter string with camelCase key", async () => {
+      const argv = await parse([URL, "--log-markers", "MDSM"]);
+      expect(argv.logMarkers).toBe("MDSM");
+    });
+
+    it("is undefined when not provided", async () => {
+      const argv = await parse([URL, "--calltree", "5"]);
+      expect(argv.logMarkers).toBeUndefined();
+    });
+  });
 });
 
 describe("validateArgs", () => {
@@ -202,6 +214,22 @@ describe("validateArgs", () => {
     expect(validateArgs(argv, ["--top-markers"])).toBeNull();
   });
 
+  it("returns null for valid --log-markers args", () => {
+    const argv = makeArgv({ logMarkers: "" });
+    expect(validateArgs(argv, ["--log-markers"])).toBeNull();
+  });
+
+  it("returns null for --log-markers with a filter", () => {
+    const argv = makeArgv({ logMarkers: "MDSM" });
+    expect(validateArgs(argv, ["--log-markers", "MDSM"])).toBeNull();
+  });
+
+  it("rejects --log-markers combined with --calltree", () => {
+    const argv = makeArgv({ calltree: 10, logMarkers: "" });
+    const error = validateArgs(argv, ["--calltree", "10", "--log-markers"]);
+    expect(error).toMatch("only one");
+  });
+
   it("requires a profile URL", () => {
     const argv = makeArgv({ _: [] });
     expect(validateArgs(argv, ["--calltree", "10"])).toMatch("profile URL");