From df34ae9872c9a83fe8cfafce94da805e81b336f0 Mon Sep 17 00:00:00 2001
From: Jonas Zeltner <jonas.zeltner@fau.de>
Date: Wed, 15 Jan 2025 17:03:10 +0100
Subject: [PATCH] Include hooks in block duration logging

---
 .../src/lib/blocks/block-execution-util.ts    | 57 ++++++++++++++-----
 libs/execution/src/lib/hooks/hook-context.ts  |  8 +--
 2 files changed, 46 insertions(+), 19 deletions(-)

diff --git a/libs/execution/src/lib/blocks/block-execution-util.ts b/libs/execution/src/lib/blocks/block-execution-util.ts
index 1d1f234b..140859e7 100644
--- 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
index adfe9c26..1e05b20c 100644
--- 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,7 +137,7 @@ 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,
@@ -145,7 +145,7 @@ export class HookContext {
       context,
       output,
     );
-    context.logger.logInfo(
+    context.logger.logDebug(
       `Executing post-block-hooks for blocktype ${blocktype}`,
     );
     const blockSpecific = executePostBlockHooks(