Merge branch 'main' into jog-as-default

Author: cscheid

dev-docs/checklist-make-a-new-stable-quarto-release copy.md

@@ -0,0 +1,52 @@
+To perform fine-grained profiling of Pandoc Lua filters, we use custom binaries:
+
+- a patch of Lua that supports sample-based profiling
+- a custom binary of Pandoc linked against that version of Lua
+
+## Compile the custom Lua version
+
+This has currently only been tested on Macos and Linux.
+
+```
+$ git clone [email protected]:cscheid/lua-fast-profiler.git
+$ cd lua-fast-profiler
+$ git checkout feature/fast-profiler-5.4
+$ make
+```
+
+You should have `lua` and `liblua.a` in the `lua-fast-profiler` directory.
+
+This version of Lua adds a new debugging hook, "time".
+This hook triggers at specified intervals, and is enabled using the letter `t` in the `debug.sethook` call.
+The debug hook callback also supports the "alarm" hook, used when calling the `sethook` callback.
+
+Quarto ships with a custom Lua profiler that supports these hooks and performs low-overhead stack profiling.
+
+## Compile the custom Pandoc binary
+
+Clone the Pandoc repository, and then
+
+```
+$ C_INCLUDE_PATH=<path-lua-fast-profiler> LIBRARY_PATH=<path-lua-fast-profiler> cabal build pandoc-cli --constraint 'lua +system-lua'
+```
+
+## Run Quarto with profiling
+
+To get Lua profiling output from Quarto, use the `lua-profiler-output` metadata option to provide an output file name, and ensure that Quarto uses the
+`pandoc` binary you just compiled.
+
+```
+$ QUARTO_PANDOC=<path-to-built-pandoc> quarto render ...
+```
+
+The output will be written as JSON, in a format compatible with [Perfetto](https://ui.perfetto.dev).
+The default sampling interval is 5ms, but you can customize that by setting the `lua-profiler-interval-ms` metadata option.
+
+### Analyze profile
+
+The resulting profile can be visualized and analyzed as a trace file at <https://ui.perfetto.dev>.
+
+### Profiling multiple-file projects
+
+In multiple-file projects, you can get a summary of the runtime of individual filter steps by providing the `QUARTO_COMBINED_LUA_PROFILE` environment variable.
+At the end of rendering a project, the name of the file pointed to `QUARTO_COMBINED_LUA_PROFILE` will contain a CSV file with the columns `filter`, `filename`, and `time`, corresponding to an estimate of time (in microseconds) taken by each stage of Quarto's filtering pipeline.

dev-docs/performance-monitoring/pandoc-profiling.md

@@ -104,8 +104,6 @@ const kMediabagDir = "mediabag-dir";
 
 const kResultsFile = "results-file";
 
-const kTimingFile = "timings-file";
-
 const kHasBootstrap = "has-bootstrap";
 
 const kActiveFilters = "active-filters";
@@ -132,8 +130,7 @@ export async function filterParamsJson(
   filterParams: Record<string, unknown>,
   resultsFile: string,
   dependenciesFile: string,
-  timingFile: string,
-) {
+): Promise<Record<string, unknown>> {
   // extract include params (possibly mutating it's arguments)
   const includes = options.format.render[kMergeIncludes] !== false
     ? extractIncludeParams(
@@ -185,7 +182,6 @@ export async function filterParamsJson(
     ...customFormatParams,
     ...typstFilterParams,
     [kResultsFile]: pandocMetadataPath(resultsFile),
-    [kTimingFile]: pandocMetadataPath(timingFile),
     [kQuartoFilters]: filterSpec,
     [kActiveFilters]: {
       normalization: metadataNormalizationFilterActive(options),
@@ -199,7 +195,7 @@ export async function filterParamsJson(
     [kBrand]: options.format.render[kBrand],
     "quarto-environment": await quartoEnvironmentParams(options),
   };
-  return JSON.stringify(params);
+  return params;
 }
 
 async function quartoEnvironmentParams(_options: PandocOptions) {

src/command/render/filters.ts

@@ -181,12 +181,7 @@ import {
   processFormatResources,
   writeFormatResources,
 } from "./pandoc-dependencies-resources.ts";
-import {
-  ExplicitTimingEntry,
-  getLuaTiming,
-  insertExplicitTimingEntries,
-  withTiming,
-} from "../../core/timing.ts";
+import { withTiming } from "../../core/timing.ts";
 
 import {
   requiresShortcodeUnescapePostprocessor,
@@ -208,21 +203,59 @@ import {
 } from "../../resources/types/schema-types.ts";
 import { kFieldCategories } from "../../project/types/website/listing/website-listing-shared.ts";
 import { isWindows } from "../../deno_ral/platform.ts";
+import { appendToCombinedLuaProfile } from "../../core/performance/perfetto-utils.ts";
 
 // in case we are running multiple pandoc processes
 // we need to make sure we capture all of the trace files
 let traceCount = 0;
 
+const handleCombinedLuaProfiles = (
+  source: string,
+  paramsJson: Record<string, unknown>,
+  temp: TempContext,
+) => {
+  const beforePandocHooks: (() => unknown)[] = [];
+  const afterPandocHooks: (() => unknown)[] = [];
+  const tmp = temp.createFile();
+
+  const combinedProfile = Deno.env.get("QUARTO_COMBINED_LUA_PROFILE");
+  if (combinedProfile) {
+    beforePandocHooks.push(() => {
+      paramsJson["lua-profiler-output"] = tmp;
+    });
+    afterPandocHooks.push(() => {
+      appendToCombinedLuaProfile(
+        source,
+        tmp,
+        combinedProfile,
+      );
+    });
+  }
+  return {
+    before: beforePandocHooks,
+    after: afterPandocHooks,
+  };
+};
+
 export async function runPandoc(
   options: PandocOptions,
   sysFilters: string[],
 ): Promise<RunPandocResult | null> {
   const beforePandocHooks: (() => unknown)[] = [];
   const afterPandocHooks: (() => unknown)[] = [];
+  const setupPandocHooks = (
+    hooks: { before: (() => unknown)[]; after: (() => unknown)[] },
+  ) => {
+    beforePandocHooks.push(...hooks.before);
+    afterPandocHooks.push(...hooks.after);
+  };
+
   const pandocEnv: { [key: string]: string } = {};
 
   const setupPandocEnv = () => {
-    pandocEnv["QUARTO_FILTER_PARAMS"] = encodeBase64(paramsJson);
+    pandocEnv["QUARTO_FILTER_PARAMS"] = encodeBase64(
+      JSON.stringify(paramsJson),
+    );
 
     const traceFilters = pandocMetadata?.["_quarto"]?.["trace-filters"] ||
       Deno.env.get("QUARTO_TRACE_FILTERS");
@@ -884,7 +917,14 @@ export async function runPandoc(
     formatFilterParams,
     filterResultsFile,
     dependenciesFile,
-    timingResultsFile,
+  );
+
+  setupPandocHooks(
+    handleCombinedLuaProfiles(
+      options.source,
+      paramsJson,
+      options.services.temp,
+    ),
   );
 
   // remove selected args and defaults if we are handling some things on behalf of pandoc
@@ -1186,16 +1226,13 @@ export async function runPandoc(
     );
   }
 
-  // workaround for our wonky Lua timing routines
-  const luaEpoch = await getLuaTiming();
-
-  setupPandocEnv();
-
   // run beforePandoc hooks
   for (const hook of beforePandocHooks) {
     await hook();
   }
 
+  setupPandocEnv();
+
   // run pandoc
   const result = await execProcess(
     {
@@ -1231,24 +1268,6 @@ export async function runPandoc(
     }
   }
 
-  if (existsSync(timingResultsFile)) {
-    const timingResultsJSON = Deno.readTextFileSync(timingResultsFile);
-    if (
-      timingResultsJSON.length > 0 && Deno.env.get("QUARTO_PROFILER_OUTPUT")
-    ) {
-      // workaround for our wonky Lua timing routines
-      const luaNow = await getLuaTiming();
-      const entries = JSON.parse(timingResultsJSON) as ExplicitTimingEntry[];
-
-      insertExplicitTimingEntries(
-        luaEpoch,
-        luaNow,
-        entries,
-        "pandoc",
-      );
-    }
-  }
-
   if (result.success) {
     return {
       inputMetadata: pandocMetadata,

src/command/render/pandoc.ts

@@ -17,6 +17,7 @@ import {
 } from "./performance/metrics.ts";
 import { makeTimedFunctionAsync } from "./performance/function-times.ts";
 import { isWindows } from "../deno_ral/platform.ts";
+import { convertCombinedLuaProfileToCSV } from "./performance/perfetto-utils.ts";
 
 type Runner = (args: Args) => Promise<unknown>;
 export async function mainRunner(runner: Runner) {
@@ -48,6 +49,11 @@ export async function mainRunner(runner: Runner) {
       await new Promise((resolve) => setTimeout(resolve, 10000));
     }
 
+    const combinedLuaProfile = Deno.env.get("QUARTO_COMBINED_LUA_PROFILE");
+    if (combinedLuaProfile) {
+      convertCombinedLuaProfileToCSV(combinedLuaProfile);
+    }
+
     if (metricEnv !== undefined) {
       if (metricEnv !== "true") {
         reportPerformanceMetrics(metricEnv.split(",") as MetricsKeys[]);

src/core/main.ts

@@ -16,7 +16,9 @@ export const makeTimedFunction = <T extends (...args: any[]) => any>(
   if (Deno.env.get("QUARTO_REPORT_PERFORMANCE_METRICS") === undefined) {
     return fn;
   }
-  functionTimes[name] = new Stats();
+  if (!functionTimes[name]) {
+    functionTimes[name] = new Stats();
+  }
   return function (...args: Parameters<T>): ReturnType<T> {
     const start = performance.now();
     try {
@@ -46,7 +48,9 @@ export const makeTimedFunctionAsync = <
   if (Deno.env.get("QUARTO_REPORT_PERFORMANCE_METRICS") === undefined) {
     return fn;
   }
-  functionTimes[name] = new Stats();
+  if (!functionTimes[name]) {
+    functionTimes[name] = new Stats();
+  }
   return async function (...args: Parameters<T>): Promise<ReturnType<T>> {
     const start = performance.now();
     try {