Include hooks in block duration logging

jvalue · Jan 15, 2025 · df34ae9 · df34ae9
1 parent a5191a4
commit df34ae9
Show file tree

Hide file tree

Showing 2 changed files with 46 additions and 19 deletions.
diff --git a/libs/execution/src/lib/blocks/block-execution-util.ts b/libs/execution/src/lib/blocks/block-execution-util.ts
@@ -62,14 +62,11 @@ export async function executeBlocks(
 
     executionContext.enterNode(block);
 
-    await executionContext.executeHooks(inputValue);
-
     const executionResult = await executeBlock(
       inputValue,
       block,
       executionContext,
     );
-    await executionContext.executeHooks(inputValue, executionResult);
 
     if (R.isErr(executionResult)) {
       return executionResult;
@@ -88,24 +85,37 @@ export async function executeBlock(
   block: BlockDefinition,
   executionContext: ExecutionContext,
 ): Promise<R.Result<IOTypeImplementation | null>> {
+  const blockExecutor =
+    executionContext.executionExtension.createBlockExecutor(block);
+
+  const startTime = new Date();
+
+  await executionContext.executeHooks(inputValue);
+  logDurationUntilNow(startTime, 'pre-block-hooks', (msg) =>
+    executionContext.logger.logDebug(msg),
+  );
+
   if (inputValue == null) {
     executionContext.logger.logInfoDiagnostic(
       `Skipped execution because parent block emitted no value.`,
       { node: block, property: 'name' },
     );
-    return R.ok(null);
+    const result = R.ok(null);
+    const postHookStartTime = new Date();
+    await executionContext.executeHooks(inputValue, result);
+    logDurationUntilNow(postHookStartTime, 'post-block-hooks', (msg) =>
+      executionContext.logger.logDebug(msg),
+    );
+    return result;
   }
 
-  const blockExecutor =
-    executionContext.executionExtension.createBlockExecutor(block);
-
-  const startTime = new Date();
+  const blockStartTime = new Date();
 
   let result: R.Result<IOTypeImplementation | null>;
   try {
     result = await blockExecutor.execute(inputValue, executionContext);
   } catch (unexpectedError) {
-    return R.err({
+    result = R.err({
       message: `An unknown error occurred: ${
         unexpectedError instanceof Error
           ? unexpectedError.stack ?? unexpectedError.message
@@ -114,16 +124,33 @@ export async function executeBlock(
       diagnostic: { node: block, property: 'name' },
     });
   }
+  logDurationUntilNow(blockStartTime, 'Block', (msg) =>
+    executionContext.logger.logDebug(msg),
+  );
+
+  const postHookStartTime = new Date();
+  await executionContext.executeHooks(inputValue, result);
+  logDurationUntilNow(postHookStartTime, 'post-block-hooks', (msg) =>
+    executionContext.logger.logDebug(msg),
+  );
 
-  logExecutionDuration(startTime, executionContext.logger);
+  logDurationUntilNow(startTime, 'Total', (msg) =>
+    executionContext.logger.logDebug(msg),
+  );
 
   return result;
 }
 
-export function logExecutionDuration(startTime: Date, logger: Logger): void {
+export function logExecutionDuration(startTime: Date, logger: Logger) {
+  logDurationUntilNow(startTime, 'Execution', (msg) => logger.logDebug(msg));
+}
+
+function logDurationUntilNow(
+  startTime: Date,
+  name: string,
+  log: (message: string) => void,
+) {
   const endTime = new Date();
-  const executionDurationMs = Math.round(
-    endTime.getTime() - startTime.getTime(),
-  );
-  logger.logDebug(`Execution duration: ${executionDurationMs} ms.`);
+  const durationMs = Math.round(endTime.getTime() - startTime.getTime());
+  log(`${name} duration: ${durationMs} ms.`);
 }
diff --git a/libs/execution/src/lib/hooks/hook-context.ts b/libs/execution/src/lib/hooks/hook-context.ts
@@ -111,14 +111,14 @@ export class HookContext {
     input: IOTypeImplementation | null,
     context: ExecutionContext,
   ) {
-    context.logger.logInfo(`Executing general pre-block-hooks`);
+    context.logger.logDebug(`Executing general pre-block-hooks`);
     const general = executePreBlockHooks(
       this.hooks.pre[AllBlocks] ?? [],
       blocktype,
       input,
       context,
     );
-    context.logger.logInfo(
+    context.logger.logDebug(
       `Executing pre-block-hooks for blocktype ${blocktype}`,
     );
     const blockSpecific = executePreBlockHooks(
@@ -137,15 +137,15 @@ export class HookContext {
     context: ExecutionContext,
     output: Result<IOTypeImplementation | null>,
   ) {
-    context.logger.logInfo(`Executing general post-block-hooks`);
+    context.logger.logDebug(`Executing general post-block-hooks`);
     const general = executePostBlockHooks(
       this.hooks.post[AllBlocks] ?? [],
       blocktype,
       input,
       context,
       output,
     );
-    context.logger.logInfo(
+    context.logger.logDebug(
       `Executing post-block-hooks for blocktype ${blocktype}`,
     );
     const blockSpecific = executePostBlockHooks(