Expressions timings in the browser console

src/plugins/expressions/common/execution/execution.ts

@@ -237,8 +237,8 @@ export class Execution<
             success: true,
             fn: fn.name,
             input,
-            args: resolvedArgs,
-            output,
+            // args: resolvedArgs,
+            // output,
             duration: timeEnd - timeStart,
           };
         }

src/plugins/expressions/common/executor/executor.ts

@@ -165,8 +165,13 @@ export class Executor<Context extends Record<string, unknown> = Record<string, u
     Input,
     Output,
     ExtraContext extends Record<string, unknown> = Record<string, unknown>
-  >(ast: string | ExpressionAstExpression, input: Input, context?: ExtraContext) {
-    const execution = this.createExecution(ast, context);
+  >(
+    ast: string | ExpressionAstExpression,
+    input: Input,
+    context?: ExtraContext,
+    options?: ExpressionExecOptions
+  ) {
+    const execution = this.createExecution(ast, context, options);
     execution.start(input);
     return (await execution.result) as Output;
   }

src/plugins/expressions/common/service/expressions_services.ts

@@ -17,7 +17,7 @@
  * under the License.
  */
 
-import { Executor } from '../executor';
+import { Executor, ExpressionExecOptions } from '../executor';
 import { ExpressionRendererRegistry } from '../expression_renderers';
 import { ExpressionAstExpression } from '../ast';
 import { ExecutionContract } from '../execution/execution_contract';
@@ -169,8 +169,10 @@ export class ExpressionsService {
   >(
     ast: string | ExpressionAstExpression,
     input: Input,
-    context?: ExtraContext
-  ): Promise<Output> => this.executor.run<Input, Output, ExtraContext>(ast, input, context);
+    context?: ExtraContext,
+    options?: ExpressionExecOptions
+  ): Promise<Output> =>
+    this.executor.run<Input, Output, ExtraContext>(ast, input, context, options);
 
   /**
    * Get a registered `ExpressionFunction` by its name, which was registered
@@ -232,9 +234,14 @@ export class ExpressionsService {
     ast: string | ExpressionAstExpression,
     // This any is for legacy reasons.
     input: Input = { type: 'null' } as any,
-    context?: ExtraContext
+    context?: ExtraContext,
+    options?: ExpressionExecOptions
   ): ExecutionContract<ExtraContext, Input, Output> => {
-    const execution = this.executor.createExecution<ExtraContext, Input, Output>(ast, context);
+    const execution = this.executor.createExecution<ExtraContext, Input, Output>(
+      ast,
+      context,
+      options
+    );
     execution.start(input);
     return execution.contract;
   };

src/plugins/expressions/public/loader.ts

@@ -22,7 +22,7 @@ import { filter, map } from 'rxjs/operators';
 import { defaults } from 'lodash';
 import { Adapters } from '../../inspector/public';
 import { IExpressionLoaderParams } from './types';
-import { ExpressionAstExpression } from '../common';
+import { ExpressionAstExpression, ExpressionAstFunction } from '../common';
 import { ExecutionContract } from '../common/execution/execution_contract';
 
 import { ExpressionRenderHandler } from './render';
@@ -145,20 +145,67 @@ export class ExpressionLoader {
       this.execution.cancel();
     }
     this.setParams(params);
-    this.execution = getExpressionsService().execute(expression, params.context, {
-      search: params.searchContext,
-      variables: params.variables || {},
-      inspectorAdapters: params.inspectorAdapters,
-    });
+    this.execution = getExpressionsService().execute(
+      expression,
+      params.context,
+      {
+        search: params.searchContext,
+        variables: params.variables || {},
+        inspectorAdapters: params.inspectorAdapters,
+      },
+      {
+        debug: params.debug,
+      }
+    );
 
     const prevDataHandler = this.execution;
     const data = await prevDataHandler.getData();
     if (this.execution !== prevDataHandler) {
       return;
     }
+    if (params.debug) {
+      this.displayTiming(this.execution.getAst());
+    }
     this.dataSubject.next(data);
   };
 
+  private forEachAst(
+    ast: ExpressionAstExpression,
+    cb: (fn: ExpressionAstFunction, depth: number) => void,
+    depth: number
+  ) {
+    ast.chain.forEach((f) => {
+      cb(f, depth);
+      Object.values(f.arguments).forEach((args) => {
+        args.forEach((arg) => {
+          if (typeof arg === 'object' && arg && arg.type === 'expression') {
+            this.forEachAst(arg, cb, depth + 1);
+          }
+        });
+      });
+    });
+  }
+
+  private displayTiming(ast: ExpressionAstExpression) {
+    const times: any[] = [];
+    this.forEachAst(
+      ast,
+      (fn: ExpressionAstFunction, depth) => {
+        times.push({
+          name: fn.debug?.fn,
+          duration_ms: fn.debug?.duration ?? 0,
+          depth,
+        });
+      },
+      0
+    );
+    console.table(times);
+    console.log(
+      'Total time',
+      times.reduce((prev, current) => prev + current.duration_ms, 0)
+    );
+  }
+
   private render(data: Data): void {
     this.renderHandler.render(data, this.params.uiState);
   }
@@ -181,6 +228,7 @@ export class ExpressionLoader {
     if (params.variables && this.params) {
       this.params.variables = params.variables;
     }
+    this.params.debug = Boolean(params.debug);
 
     this.params.inspectorAdapters = (params.inspectorAdapters ||
       this.execution?.inspect()) as Adapters;

src/plugins/expressions/public/types/index.ts

@@ -45,6 +45,8 @@ export interface IExpressionLoaderParams {
   searchContext?: ExecutionContextSearch;
   context?: ExpressionValue;
   variables?: Record<string, any>;
+  // Enables debug tracking on each expression in the AST
+  debug?: boolean;
   disableCaching?: boolean;
   customFunctions?: [];
   customRenderers?: [];

src/plugins/visualizations/public/embeddable/visualize_embeddable.ts

@@ -295,6 +295,7 @@ export class VisualizeEmbeddable
       onRenderError: (element: HTMLElement, error: ExpressionRenderError) => {
         this.onContainerError(error);
       },
+      debug: true,
     });
 
     this.subscriptions.push(
@@ -376,6 +377,7 @@ export class VisualizeEmbeddable
       },
       uiState: this.vis.uiState,
       inspectorAdapters: this.inspectorAdapters,
+      debug: true,
     };
     if (this.abortController) {
       this.abortController.abort();

x-pack/plugins/canvas/public/lib/run_interpreter.ts

@@ -20,7 +20,10 @@ export async function interpretAst(
   variables: Record<string, any>
 ): Promise<ExpressionValue> {
   const context = { variables };
-  return await expressionsService.getService().execute(ast, null, context).getData();
+  const executor = expressionsService.getService().execute(ast, null, context, { debug: true });
+  const finalData = await executor.getData();
+  displayTiming(executor.getAst());
+  return finalData;
 }
 
 /**
@@ -39,14 +42,17 @@ export async function runInterpreter(
   variables: Record<string, any>,
   options: Options = {}
 ): Promise<ExpressionValue> {
-  const context = { variables };
+  const context = { variables, debug: true };
 
   try {
-    const renderable = await expressionsService.getService().execute(ast, input, context).getData();
+    const executor = expressionsService.getService().execute(ast, input, context, { debug: true });
+    const renderable = await executor.getData();
+    displayTiming(executor.getAst());
 
     if (getType(renderable) === 'render') {
       return renderable;
     }
+    debugger;
 
     if (options.castToRender) {
       return runInterpreter(fromExpression('render'), renderable, variables, {
@@ -60,3 +66,36 @@ export async function runInterpreter(
     throw err;
   }
 }
+
+function forEachAst(ast, cb, depth) {
+  ast.chain.forEach((f) => {
+    cb(f, depth);
+    Object.values(f.arguments).forEach((args) => {
+      args.forEach((arg) => {
+        if (typeof arg === 'object' && arg && arg.type === 'expression') {
+          forEachAst(arg, cb, depth + 1);
+        }
+      });
+    });
+  });
+}
+
+function displayTiming(ast) {
+  const times = [];
+  forEachAst(
+    ast,
+    (fn, depth) => {
+      times.push({
+        name: fn.debug?.fn,
+        duration_ms: fn.debug?.duration ?? 0,
+        depth,
+      });
+    },
+    0
+  );
+  console.table(times);
+  console.log(
+    'Total time',
+    times.reduce((prev, current) => prev + current.duration_ms, 0)
+  );
+}

x-pack/plugins/lens/public/editor_frame_service/editor_frame/workspace_panel/workspace_panel.tsx

@@ -281,6 +281,7 @@ export function InnerWorkspacePanel({
           searchContext={context}
           reload$={autoRefreshFetch$}
           onEvent={onEvent}
+          debug={true}
           renderError={(errorMessage?: string | null) => {
             return (
               <EuiFlexGroup direction="column" alignItems="center">

x-pack/plugins/lens/public/editor_frame_service/embeddable/expression_wrapper.tsx

@@ -52,6 +52,7 @@ export function ExpressionWrapper({
             searchContext={searchContext}
             renderError={(error) => <div data-test-subj="expression-renderer-error">{error}</div>}
             onEvent={handleEvent}
+            debug={true}
           />
         </div>
       )}