feature: can capture timing information. bugfix: timeout diffing when…

… too long.

src/command/render/filters.ts

@@ -70,6 +70,8 @@ const kMediabagDir = "mediabag-dir";
 
 const kResultsFile = "results-file";
 
+const kTimingFile = "timings-file";
+
 const kHasBootstrap = "has-bootstrap";
 
 export function filterParamsJson(
@@ -79,6 +81,7 @@ export function filterParamsJson(
   filterParams: Record<string, unknown>,
   resultsFile: string,
   dependenciesFile: string,
+  timingFile: string,
 ) {
   // extract include params (possibly mutating it's arguments)
   const includes = options.format.render[kMergeIncludes] !== false
@@ -108,6 +111,7 @@ export function filterParamsJson(
     ...languageFilterParams(options.format.language),
     ...filterParams,
     [kResultsFile]: pandocMetadataPath(resultsFile),
+    [kTimingFile]: pandocMetadataPath(timingFile),
   };
   return JSON.stringify(params);
 }

src/command/render/pandoc.ts

@@ -169,6 +169,12 @@ import {
   processFormatResources,
   writeFormatResources,
 } from "./pandoc-dependencies-resources.ts";
+import {
+  ExplicitTimingEntry,
+  getLuaTiming,
+  insertExplicitTimingEntries,
+  withTiming,
+} from "../../core/timing.ts";
 
 export async function runPandoc(
   options: PandocOptions,
@@ -641,6 +647,9 @@ export async function runPandoc(
   // filter results json file
   const filterResultsFile = options.temp.createFile();
 
+  // timing results json file
+  const timingResultsFile = options.temp.createFile();
+
   // set parameters required for filters (possibily mutating all of it's arguments
   // to pull includes out into quarto parameters so they can be merged)
   let pandocArgs = args;
@@ -651,6 +660,7 @@ export async function runPandoc(
     formatFilterParams,
     filterResultsFile,
     dependenciesFile,
+    timingResultsFile,
   );
 
   // remove selected args and defaults if we are handling some things on behalf of pandoc
@@ -924,6 +934,9 @@ export async function runPandoc(
     }
   }
 
+  // workaround for our wonky Lua timing routines
+  const luaEpoch = await getLuaTiming();
+
   // run pandoc
   const result = await execProcess(
     {
@@ -956,6 +969,22 @@ export async function runPandoc(
     }
   }
 
+  if (existsSync(timingResultsFile)) {
+    const timingResultsJSON = Deno.readTextFileSync(timingResultsFile);
+    if (timingResultsJSON.length > 0 && Deno.env.get("QUARTO_PROFILE")) {
+      // 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,
@@ -1044,12 +1073,16 @@ async function resolveExtras(
       doc: Document,
       _inputMedata: Metadata,
     ): Promise<HtmlPostProcessResult> => {
-      return readAndInjectDependencies(
-        dependenciesFile,
-        inputDir,
-        libDir,
-        doc,
-        project,
+      return withTiming(
+        "pandocDependenciesPostProcessor",
+        async () =>
+          await readAndInjectDependencies(
+            dependenciesFile,
+            inputDir,
+            libDir,
+            doc,
+            project,
+          ),
       );
     };
 

src/command/render/render-files.ts

@@ -77,6 +77,13 @@ import { isJupyterNotebook } from "../../core/jupyter/jupyter.ts";
 import { MappedString } from "../../core/lib/text-types.ts";
 import { createNamedLifetime } from "../../core/lifetimes.ts";
 import { resolveDependencies } from "./pandoc-dependencies-html.ts";
+import {
+  getData as getTimingData,
+  pop as popTiming,
+  push as pushTiming,
+  withTiming,
+  withTimingAsync,
+} from "../../core/timing.ts";
 
 export async function renderExecute(
   context: RenderContext,
@@ -153,6 +160,7 @@ export async function renderExecute(
   // calculate figsDir
   const figsDir = join(filesDir, figuresDir(context.format.pandoc.to));
 
+  pushTiming("render-execute");
   // execute computations
   const executeResult = await context.engine.execute({
     target: context.target,
@@ -167,6 +175,7 @@ export async function renderExecute(
     quiet: flags.quiet,
     handledLanguages: languages(),
   });
+  popTiming();
 
   // write the freeze file if we are in a project
   if (context.project && canFreeze) {
@@ -315,6 +324,7 @@ export async function renderFiles(
         executeResult.supporting.push(...results.supporting);
       };
       for (const format of Object.keys(contexts)) {
+        pushTiming("render-context");
         const context = ld.cloneDeep(contexts[format]) as RenderContext; // since we're going to mutate it...
 
         // Set the date locale for this render
@@ -370,14 +380,16 @@ export async function renderFiles(
           // for markdown processing pre-pandoc with mapped strings
           let mappedMarkdown: MappedString;
 
-          if (!isJupyterNotebook(context.target.source)) {
-            mappedMarkdown = mappedDiff(
-              context.target.markdown,
-              baseExecuteResult.markdown,
-            );
-          } else {
-            mappedMarkdown = asMappedString(baseExecuteResult.markdown);
-          }
+          withTiming("diff-execute-result", () => {
+            if (!isJupyterNotebook(context.target.source)) {
+              mappedMarkdown = mappedDiff(
+                context.target.markdown,
+                baseExecuteResult.markdown,
+              );
+            } else {
+              mappedMarkdown = asMappedString(baseExecuteResult.markdown);
+            }
+          });
 
           const resourceFiles: string[] = [];
           if (baseExecuteResult.resourceFiles) {
@@ -388,57 +400,63 @@ export async function renderFiles(
             name: "", // will be filled out by handleLanguageCells internally
             temp: tempContext,
             format: recipe.format,
-            markdown: mappedMarkdown,
+            markdown: mappedMarkdown!,
             context,
             stage: "post-engine",
           };
 
-          // handle language cells
-          const { markdown, results } = await handleLanguageCells(
-            languageCellHandlerOptions,
-          );
-          const mappedExecuteResult: MappedExecuteResult = {
-            ...baseExecuteResult,
-            markdown,
-          };
-
-          mergeHandlerResults(
-            context.target.preEngineExecuteResults,
-            mappedExecuteResult,
-            context,
-          );
-          mergeHandlerResults(results, mappedExecuteResult, context);
+          let unmappedExecuteResult: ExecuteResult;
+          await withTimingAsync("handle-language-cells", async () => {
+            // handle language cells
+            const { markdown, results } = await handleLanguageCells(
+              languageCellHandlerOptions,
+            );
+            const mappedExecuteResult: MappedExecuteResult = {
+              ...baseExecuteResult,
+              markdown,
+            };
 
-          // process ojs
-          const { executeResult, resourceFiles: ojsResourceFiles } =
-            await ojsExecuteResult(
-              context,
+            mergeHandlerResults(
+              context.target.preEngineExecuteResults,
               mappedExecuteResult,
-              ojsBlockLineNumbers,
+              context,
             );
-          resourceFiles.push(...ojsResourceFiles);
-
-          // keep md if requested
-          const keepMd = executionEngineKeepMd(context.target.input);
-          if (keepMd && context.format.execute[kKeepMd]) {
-            Deno.writeTextFileSync(keepMd, executeResult.markdown.value);
-          }
+            mergeHandlerResults(results, mappedExecuteResult, context);
+
+            // process ojs
+            const { executeResult, resourceFiles: ojsResourceFiles } =
+              await ojsExecuteResult(
+                context,
+                mappedExecuteResult,
+                ojsBlockLineNumbers,
+              );
+            resourceFiles.push(...ojsResourceFiles);
+
+            // keep md if requested
+            const keepMd = executionEngineKeepMd(context.target.input);
+            if (keepMd && context.format.execute[kKeepMd]) {
+              Deno.writeTextFileSync(keepMd, executeResult.markdown.value);
+            }
 
-          // now get "unmapped" execute result back to send to pandoc
-          const unmappedExecuteResult: ExecuteResult = {
-            ...executeResult,
-            markdown: executeResult.markdown.value,
-          };
+            // now get "unmapped" execute result back to send to pandoc
+            unmappedExecuteResult = {
+              ...executeResult,
+              markdown: executeResult.markdown.value,
+            };
+          });
 
           // callback
+          pushTiming("render-pandoc");
           await pandocRenderer.onRender(format, {
             context,
             recipe,
-            executeResult: unmappedExecuteResult,
+            executeResult: unmappedExecuteResult!,
             resourceFiles,
           }, pandocQuiet);
+          popTiming();
         } finally {
           fileLifetime.cleanup();
+          popTiming();
         }
       }
     }
@@ -455,6 +473,12 @@ export async function renderFiles(
     };
   } finally {
     tempContext.cleanup();
+    if (Deno.env.get("QUARTO_PROFILE")) {
+      Deno.writeTextFileSync(
+        Deno.env.get("QUARTO_PROFILE")!,
+        JSON.stringify(getTimingData()),
+      );
+    }
   }
 }