[feature] perf - add QUARTO_COMBINED_LUA_PROFILE feature

Author: cscheid

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

@@ -30,16 +30,23 @@ 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'
 ```
 
-## Use the custom Pandoc binary
+## 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 ...
 ```
 
-To get Lua profiling output from Quarto, use the `lua-profiler-output` metadata option to provide an output file name.
 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
+### 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.

src/command/render/filters.ts

@@ -130,7 +130,7 @@ export async function filterParamsJson(
   filterParams: Record<string, unknown>,
   resultsFile: string,
   dependenciesFile: string,
-) {
+): Promise<Record<string, unknown>> {
   // extract include params (possibly mutating it's arguments)
   const includes = options.format.render[kMergeIncludes] !== false
     ? extractIncludeParams(
@@ -195,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/pandoc.ts

@@ -203,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");
@@ -881,6 +919,14 @@ export async function runPandoc(
     dependenciesFile,
   );
 
+  setupPandocHooks(
+    handleCombinedLuaProfiles(
+      options.source,
+      paramsJson,
+      options.services.temp,
+    ),
+  );
+
   // remove selected args and defaults if we are handling some things on behalf of pandoc
   // (e.g. handling section numbering). note that section numbering is handled by the
   // crossref filter so we only do this if the user hasn't disabled the crossref filter
@@ -1180,13 +1226,13 @@ export async function runPandoc(
     );
   }
 
-  setupPandocEnv();
-
   // run beforePandoc hooks
   for (const hook of beforePandocHooks) {
     await hook();
   }
 
+  setupPandocEnv();
+
   // run pandoc
   const result = await execProcess(
     {

src/core/main.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/performance/function-times.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 {

src/resources/filters/ast/runemulation.lua

@@ -131,7 +131,7 @@ local function emulate_pandoc_filter(filters, afterFilterPass)
   return {
     traverse = 'topdown',
     Pandoc = function(doc)
-      local profiling = option("lua-profiler-output", false)
+      local profiling = option("lua-profiler-output", false) or param("lua-profiler-output", false)
       if not profiling then
         return run_emulated_filter_chain(doc, filters, afterFilterPass), false
       end

src/resources/pandoc/datadir/profiler.lua

@@ -28,8 +28,10 @@ local onDebugHook = function(hookType, line)
   while information ~= nil do
     local source = information.source or "unknown"
     local name = information.name or "anon"
-    if string.match(source, ".lua$") then
+    if source:sub(1, 1) == "@" then
       outputfile:write(name, " ", source, " ", information.linedefined, "\n")
+    else
+      outputfile:write(name, " ", "<inline>", " ", 0, "\n")
     end
     no = no + 1
     information = debug.getinfo(no, "nS")
@@ -45,7 +47,7 @@ end
 function module.start(filename, ms)
   outputfile = io.open(filename, "a")
   if outputfile == nil then
-    error("Could not open profiler.txt for writing")
+    error("Could not open " .. filename .. " for writing")
     return
   end
   debug.sethook(onDebugHook, "t", ms or 5) -- NB: "t" debugging only exists in our patched Lua interpreter/pandoc binary!