[feat] Improve time logger

packages/core/src/types.ts

@@ -57,11 +57,12 @@ export type SerializedEntry = Assign<Entry, { inputs: string[]; outputs: string[
 export type SerializedInput = Assign<Input, { dependencies: string[]; dependents: string[] }>;
 export type SerializedOutput = Assign<Output, { inputs: string[] }>;
 
+export type LogTags = string[];
 export type Timer = {
     label: string;
     pluginName: string;
-    spans: { start: number; end?: number; tags?: string[] }[];
-    tags: string[];
+    spans: { start: number; end?: number; tags: LogTags }[];
+    tags: LogTags;
     total: number;
     logLevel: LogLevel;
 };
@@ -128,16 +129,16 @@ export type ToInjectItem = {
 
 export type TimeLogger = {
     timer: Timer;
-    resume: () => void;
-    end: () => void;
-    pause: () => void;
-    tag: (tags: string[], opts?: { span?: boolean }) => void;
+    resume: (startTime?: number) => void;
+    end: (endTime?: number) => void;
+    pause: (pauseTime?: number) => void;
+    tag: (tags: LogTags, opts?: { span?: boolean }) => void;
 };
 
 // The rest parameter is a LogLevel or a boolean to auto start the timer.
 export type TimeLog = (
     label: string,
-    opts?: { level?: LogLevel; start?: boolean; log?: boolean; tags?: string[] },
+    opts?: { level?: LogLevel; start?: boolean | number; log?: boolean; tags?: LogTags },
 ) => TimeLogger;
 export type GetLogger = (name: string) => Logger;
 export type Logger = {

packages/factory/README.md

@@ -141,41 +141,34 @@ export const getMyPlugins = (context: GlobalContext) => {
 The time logger is a helper to log/report the duration of a task.
 It is useful to debug performance issues.
 
-It can be found in your logger.
-
-```typescript
-const log = context.getLogger('my-plugin');
-const timer = log.time('my-task');
-// [... do stuff ...]
-timer.end();
-```
+It can be found on your logger's instance.
 
 ### Options
 
-- `start`: Whether to start the timer immediately. Defaults to `true`.
-- `log`: Whether to log the timer. Defaults to `true`.
-- `level`: The log level to use. Defaults to `debug`.
-- `tags`: Initial tags to associate with the timer. Defaults to `[]`.
-
 ```typescript
-{
-    start: boolean,
+const logger = context.getLogger('my-plugin');
+const timer = logger.time('my-task', {
+    // Whether to start the timer immediately, at the given timestamp or not at all. Defaults to `true`.
+    start: boolean | number,
+    // Whether to log the timer or not when it starts and finishes. Defaults to `true`.
     log: boolean,
+    // The log level to use. Defaults to `debug`.
     level: LogLevel,
-    tags: string[]
-}
+    // Tags to associate with the timer. Defaults to `[]`.
+    tags: string[],
+});
 ```
 
 ### Features
 
 Pause/resume the timer.
 
 ```typescript
-timer.pause();
+timer.pause(timeOverride?: number);
 // [... do stuff ...]
-timer.resume();
+timer.resume(timeOverride?: number);
 // [... do more stuff ...]
-timer.end();
+timer.end(timeOverride?: number);
 ```
 
 Add tags to the timer or to active spans.
@@ -238,7 +231,7 @@ All the timers will be reported in `context.build.timings`, with all their spans
                     "tags": ["step:initialize"]
                 }
             ],
-            "tags": ["feature:upload", "operation:compress"],
+            "tags": ["feature:upload", "operation:compress", "plugin:my-plugin", "level:debug"],
             "total": 1000,
             "logLevel": "debug"
         }

packages/factory/src/helpers/logger.test.ts

@@ -210,13 +210,15 @@ describe('logger', () => {
                         {
                             start: expect.any(Number),
                             end: expect.any(Number),
+                            tags: ['plugin:testLogger'],
                         },
                         {
                             start: expect.any(Number),
                             end: expect.any(Number),
+                            tags: ['plugin:testLogger'],
                         },
                     ],
-                    tags: [],
+                    tags: ['plugin:testLogger', 'level:debug'],
                     total: 300,
                     logLevel: 'debug',
                 });
@@ -230,7 +232,8 @@ describe('logger', () => {
                 timer.tag(['tag1', 'tag2']);
                 timer.end();
 
-                expect(timer.timer.tags).toEqual(['tag1', 'tag2']);
+                expect(timer.timer.tags).toContain('tag1');
+                expect(timer.timer.tags).toContain('tag2');
             });
 
             test('Should tag the spans.', () => {
@@ -239,7 +242,8 @@ describe('logger', () => {
                 timer.tag(['tag1', 'tag2'], { span: true });
                 timer.end();
 
-                expect(timer.timer.spans[0].tags).toEqual(['tag1', 'tag2']);
+                expect(timer.timer.spans[0].tags).toContain('tag1');
+                expect(timer.timer.spans[0].tags).toContain('tag2');
             });
         });
 

packages/factory/src/helpers/logger.ts

@@ -50,7 +50,7 @@ export const getLoggerFactory =
             const content = typeof text === 'string' ? text : JSON.stringify(text, null, 2);
             build.logs.push({
                 bundler: build.bundler.fullName,
-                pluginName: cleanedName,
+                pluginName: name,
                 type,
                 message: content,
                 time: Date.now(),
@@ -72,10 +72,10 @@ export const getLoggerFactory =
         const time: TimeLog = (label, opts = {}) => {
             const { level = 'debug', start = true, log: toLog = true, tags = [] } = opts;
             const timer: Timer = {
-                pluginName: cleanedName,
+                pluginName: name,
                 label,
                 spans: [],
-                tags,
+                tags: [...tags, `plugin:${name}`, `level:${level}`],
                 logLevel: level,
                 total: 0,
             };
@@ -86,16 +86,27 @@ export const getLoggerFactory =
             const getUncompleteSpans = () => timer.spans.filter((span) => !span.end);
 
             // Push a new span.
-            const resume: TimeLogger['resume'] = () => {
+            const resume: TimeLogger['resume'] = (startTime?: number) => {
+                // Ignore if there is already an ongoing span.
+                const uncompleteSpans = getUncompleteSpans();
+                if (uncompleteSpans.length) {
+                    return;
+                }
+
                 // Log the start if it's the first span.
                 if (!timer.spans.length && toLog) {
                     log(c.dim(`[${c.cyan(label)}] : start`), 'debug');
                 }
-                timer.spans.push({ start: Date.now() });
+
+                // Add the new span.
+                timer.spans.push({
+                    start: startTime || Date.now(),
+                    tags: [`plugin:${name}`],
+                });
             };
 
             // Complete all the uncompleted spans.
-            const pause: TimeLogger['pause'] = () => {
+            const pause: TimeLogger['pause'] = (pauseTime?: number) => {
                 const uncompleteSpans = getUncompleteSpans();
 
                 if (!uncompleteSpans?.length) {
@@ -108,13 +119,13 @@ export const getLoggerFactory =
                 }
 
                 for (const span of uncompleteSpans) {
-                    span.end = Date.now();
+                    span.end = pauseTime || Date.now();
                 }
             };
 
             // End the timer and add it to the build report.
-            const end: TimeLogger['end'] = () => {
-                pause();
+            const end: TimeLogger['end'] = (endTime?: number) => {
+                pause(endTime);
                 const duration = timer.spans.reduce(
                     (acc, span) => acc + (span.end! - span.start),
                     0,
@@ -131,7 +142,6 @@ export const getLoggerFactory =
                 if (span) {
                     const uncompleteSpans = getUncompleteSpans();
                     for (const uncompleteSpan of uncompleteSpans) {
-                        uncompleteSpan.tags = uncompleteSpan.tags || [];
                         uncompleteSpan.tags.push(...tagsToAdd);
                     }
                 } else {
@@ -141,7 +151,11 @@ export const getLoggerFactory =
 
             // Auto start the timer.
             if (start) {
-                resume();
+                let param: number | undefined;
+                if (typeof start === 'number') {
+                    param = start;
+                }
+                resume(param);
             }
 
             const timeLogger: TimeLogger = {

packages/factory/src/helpers/wrapPlugins.test.ts

@@ -49,10 +49,8 @@ describe('profilePlugins', () => {
             expect(mockTimer.end).toHaveBeenCalledTimes(1);
 
             // Verify the timer got tagged with the plugin names.
-            expect(mockTimer.timer.tags).toEqual([
-                'plugin:datadog-test-1-plugin',
-                'plugin:datadog-test-2-plugin',
-            ]);
+            expect(mockTimer.timer.tags).toContain('plugin:datadog-test-1-plugin');
+            expect(mockTimer.timer.tags).toContain('plugin:datadog-test-2-plugin');
 
             // Verify the result contains the expected plugins
             expect(result).toHaveLength(2);

packages/factory/src/helpers/wrapPlugins.ts

@@ -3,6 +3,7 @@
 // Copyright 2019-Present Datadog, Inc.
 
 import { HOST_NAME } from '@dd/core/constants';
+import { cleanPluginName } from '@dd/core/helpers/plugins';
 import type {
     CustomPluginOptions,
     GetCustomPlugins,
@@ -49,7 +50,10 @@ type HookFn = NonNullable<CustomHooks[CustomHookName] | UnpluginOptions[Unplugin
 
 export const wrapHook = (pluginName: string, hookName: HookName, hook: HookFn, log: Logger) => {
     return (...args: Parameters<HookFn>) => {
-        const timer = log.time(`hook | ${pluginName} | ${hookName}`, { log: false });
+        const timer = log.time(`${pluginName} | ${hookName}`, {
+            log: false,
+            tags: ['type:hook', `hook:${hookName}`],
+        });
         // @ts-expect-error, can't type "args" correctly: "A spread argument must either have a tuple type or be passed to a rest parameter."
         const result = hook(...args);
 
@@ -68,12 +72,13 @@ export const wrapPlugin = (plugin: PluginOptions | CustomPluginOptions, log: Log
     const wrappedPlugin: PluginOptions | CustomPluginOptions = {
         ...plugin,
     };
+    const name = cleanPluginName(plugin.name);
 
     // Wrap all the hooks that we want to trace.
     for (const hookName of HOOKS_TO_TRACE) {
         const hook = plugin[hookName as PluginHookName];
         if (hook) {
-            wrappedPlugin[hookName as PluginHookName] = wrapHook(plugin.name, hookName, hook, log);
+            wrappedPlugin[hookName as PluginHookName] = wrapHook(name, hookName, hook, log);
         }
     }