From 2666194d5cfe13018208176a4b4daa70540fbd5c Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Tue, 26 May 2026 23:20:39 +0200 Subject: [PATCH] Improve internal instrumentation module (#20119) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This PR improves some of the internal instrumentation tooling we have. While working on another branch, I updated the instrumentation tooling to have a few different ways of measuring what's going on. Until now, we had an `I.start(label)` and corresponding `I.end(label)`. While this works, it also means that you have to make sure that you call `I.end(label)` before every `return` to track things properly. With this PR, I added a `I.span(label, () => /* some callback*/{})` API that essentially does that in one go. It also handles promises and resturns the value that was returned from the callback. This can be useful in situations where you have a one-liner: ```ts let css = I.span('toCss(…)', () => toCss(ast)) ``` If your callback is longer, then you end up in a situation where you have to indent your code, and if you want to stop measuring you have to drop code in 2 places and re-indent: ```diff - I.span('label', () => { … - }) ``` For this situation, I also added a `using _ = I.track(label)` API instead. This can also be used in any block and automatically inserts the `I.end(label)` on every exit point. This relies on the new `using` keyword, but we already relied on that for the instrumentation module. Last but not least, the constructor accepts a `shouldReport` which defaults to the `env.DEBUG`. The reason for this change is so that it's easier to report / not report during development instead of swapping out an environment variable. Again, this is internal so there is no public API change happening here. ## Test plan All tests should still pass. --- .../src/instrumentation.test.ts | 103 +++++++++++++++++- .../@tailwindcss-node/src/instrumentation.ts | 38 ++++++- 2 files changed, 139 insertions(+), 2 deletions(-) diff --git a/packages/@tailwindcss-node/src/instrumentation.test.ts b/packages/@tailwindcss-node/src/instrumentation.test.ts index 1f06796fd..f6ae55741 100644 --- a/packages/@tailwindcss-node/src/instrumentation.test.ts +++ b/packages/@tailwindcss-node/src/instrumentation.test.ts @@ -1,8 +1,9 @@ import { stripVTControlCharacters } from 'util' import { expect, it } from 'vitest' +import { dimensions } from '../../tailwindcss/src/utils/dimensions' import { Instrumentation } from './instrumentation' -it('should add instrumentation', () => { +it('should add instrumentation using start/end markers', () => { let I = new Instrumentation() I.start('Foo') @@ -35,6 +36,80 @@ it('should add instrumentation', () => { }) }) +it('should measure callbacks via the `span` api', () => { + let I = new Instrumentation() + + I.span('Foo', () => { + let x = 1 + for (let i = 0; i < 100; i++) { + I.span('Bar', () => { + x **= 2 + }) + } + }) + + expect.assertions(1) + + I.report((output) => { + expect(stripVTControlCharacters(output).replace(/\[.*\]/g, '[0.xxms]')).toMatchInlineSnapshot(` + " + [0.xxms] Foo + [0.xxms] ↳ Bar × 100 + " + `) + }) +}) + +it('should measure async callbacks via the `span` api', async () => { + let I = new Instrumentation() + + await I.span('Foo', async () => { + let x = 1 + for (let i = 0; i < 100; i++) { + I.span('Bar', () => { + x **= 2 + }) + } + await new Promise((r) => setTimeout(r, 500)) + }) + + expect.assertions(1) + + I.report((output) => { + expect(stabilize(output)).toMatchInlineSnapshot(` + " + [510.00ms] Foo + [ 0.05ms] ↳ Bar × 100 + " + `) + }) +}) + +it('should measure blocks until they go out of scope via `using`', () => { + let I = new Instrumentation() + + { + using _ = I.track('Foo') + + let x = 1 + for (let i = 0; i < 100; i++) { + using _ = I.track('Bar') + x **= 2 + } + } + + expect.assertions(1) + + I.report((output) => { + expect(stripVTControlCharacters(output).replace(/\[.*\]/g, '[0.xxms]')).toMatchInlineSnapshot(` + " + [0.xxms] Foo + [0.xxms] ↳ Bar × 100 + " + `) + }) +}) + it('should auto end pending timers when reporting', () => { let I = new Instrumentation() @@ -59,3 +134,29 @@ it('should auto end pending timers when reporting', () => { `) }) }) + +let nf = new Intl.NumberFormat(undefined, { + style: 'decimal', + minimumFractionDigits: 2, +}) + +function stabilize(output: string) { + return stripVTControlCharacters(output).replace(/\[(\s*)(.*)\]/g, (_, whitespace, duration) => { + let [value, unit] = dimensions.get(duration.trim())! + return `[${whitespace}${nf.format(stableRound(value))}${unit}]` + }) +} + +function stableRound(value: number) { + if (value === 0) return 0 + + let sign = Math.sign(value) + let abs = Math.abs(value) + + let magnitude = 10 ** Math.floor(Math.log10(abs)) + + let step = magnitude / 10 + if (abs < 0.1) step = 0.05 + + return sign * Math.ceil(abs / step) * step +} diff --git a/packages/@tailwindcss-node/src/instrumentation.ts b/packages/@tailwindcss-node/src/instrumentation.ts index d27858d88..e454e6744 100644 --- a/packages/@tailwindcss-node/src/instrumentation.ts +++ b/packages/@tailwindcss-node/src/instrumentation.ts @@ -13,6 +13,7 @@ export class Instrumentation implements Disposable { #timerStack: { id: string; label: string; namespace: string; value: bigint }[] = [] constructor( + private shouldReport = env.DEBUG, private defaultFlush = (message: string) => void process.stderr.write(`${message}\n`), ) {} @@ -48,6 +49,41 @@ export class Instrumentation implements Disposable { this.#timers.get(parent.id).value += elapsed } + track(label: string) { + this.start(label) + let done = false + + return { + [Symbol.dispose]: () => { + if (!done) { + this.end(label) + done = true + } + }, + [Symbol.asyncDispose]: () => { + if (!done) { + this.end(label) + done = true + } + }, + } + } + + span(label: string, fn: () => T): T { + this.start(label) + let isPromise = false + try { + let result = fn() + + isPromise = result && typeof (result as any).then === 'function' + + // @ts-expect-error — TS can't infer that result is a Promise here + return isPromise ? result.finally(() => this.end(label)) : result + } finally { + if (!isPromise) this.end(label) + } + } + reset() { this.#hits.clear() this.#timers.clear() @@ -100,7 +136,7 @@ export class Instrumentation implements Disposable { } [Symbol.dispose]() { - env.DEBUG && this.report() + this.shouldReport && this.report() } }