From 2b08a29e6fa66efed1af864ac9707e3deed4e066 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Wed, 4 Dec 2024 18:57:03 +0100 Subject: [PATCH 01/20] =?UTF-8?q?fix=20missing=20`console.timeEnd(?= =?UTF-8?q?=E2=80=A6)`?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit If we bail early, then a `console.time('…')` was already started and subsequent calls to `console.timeEnd('…')` will fail because the `console.time` and `console.timeEnd` don't line up. --- packages/@tailwindcss-postcss/src/index.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/@tailwindcss-postcss/src/index.ts b/packages/@tailwindcss-postcss/src/index.ts index 52a1e2efac1b..6535f3fa397f 100644 --- a/packages/@tailwindcss-postcss/src/index.ts +++ b/packages/@tailwindcss-postcss/src/index.ts @@ -118,6 +118,8 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.compiler ??= await createCompiler() if (context.compiler.features === Features.None) { + env.DEBUG && + console.timeEnd('[@tailwindcss/postcss] Total time in @tailwindcss/postcss') return } From 7076c9b3224ee422c163c5dc574bb3e9c48d1065 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Wed, 4 Dec 2024 20:32:43 +0100 Subject: [PATCH 02/20] splitup steps, and add a few more timing logs --- packages/@tailwindcss-postcss/src/index.ts | 43 +++++++++++++++------- 1 file changed, 30 insertions(+), 13 deletions(-) diff --git a/packages/@tailwindcss-postcss/src/index.ts b/packages/@tailwindcss-postcss/src/index.ts index 6535f3fa397f..0baeb68d0b2f 100644 --- a/packages/@tailwindcss-postcss/src/index.ts +++ b/packages/@tailwindcss-postcss/src/index.ts @@ -98,7 +98,11 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.fullRebuildPaths = [] - let compiler = await compileAst(postCssAstToCssAst(root), { + env.DEBUG && console.time('[@tailwindcss/postcss] PostCSS AST -> Tailwind CSS AST') + let ast = postCssAstToCssAst(root) + env.DEBUG && console.timeEnd('[@tailwindcss/postcss] PostCSS AST -> Tailwind CSS AST') + + let compiler = await compileAst(ast, { base: inputBasePath, onDependency: (path) => { context.fullRebuildPaths.push(path) @@ -234,26 +238,39 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { } } - env.DEBUG && console.time('[@tailwindcss/postcss] Build AST') + env.DEBUG && console.time('[@tailwindcss/postcss] Build utilities') let tailwindCssAst = context.compiler.build(candidates) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Build AST') + env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Build utilities') if (context.tailwindCssAst !== tailwindCssAst) { if (optimize) { - env.DEBUG && console.time('[@tailwindcss/postcss] Optimize CSS') - context.optimizedPostCssAst = postcss.parse( - optimizeCss(toCss(tailwindCssAst), { - minify: typeof optimize === 'object' ? optimize.minify : true, - }), - result.opts, - ) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Optimize CSS') + env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] Total') + + env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] AST -> CSS') + let css = toCss(tailwindCssAst) + env.DEBUG && console.timeEnd('[@tailwindcss/postcss][Optimization] AST -> CSS') + + env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] Lightning CSS') + let ast = optimizeCss(css, { + minify: typeof optimize === 'object' ? optimize.minify : true, + }) + env.DEBUG && console.timeEnd('[@tailwindcss/postcss][Optimization] Lightning CSS') + + env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] CSS -> PostCSS AST') + context.optimizedPostCssAst = postcss.parse(ast, result.opts) + env.DEBUG && + console.timeEnd('[@tailwindcss/postcss][Optimization] CSS -> PostCSS AST') + + env.DEBUG && console.timeEnd('[@tailwindcss/postcss][Optimization] Total') } else { // Convert our AST to a PostCSS AST - env.DEBUG && console.time('[@tailwindcss/postcss] Transform CSS AST into PostCSS AST') + env.DEBUG && + console.time('[@tailwindcss/postcss] Transform Tailwind CSS AST into PostCSS AST') context.cachedPostCssAst = cssAstToPostCssAst(tailwindCssAst, root.source) env.DEBUG && - console.timeEnd('[@tailwindcss/postcss] Transform CSS AST into PostCSS AST') + console.timeEnd( + '[@tailwindcss/postcss] Transform Tailwind CSS AST into PostCSS AST', + ) } } From 1b7c9798ae94e535b1abe74446914e99a0c2e453 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Wed, 4 Dec 2024 20:47:19 +0100 Subject: [PATCH 03/20] add used file to the debug logs --- packages/@tailwindcss-postcss/src/index.ts | 61 ++++++++++------------ 1 file changed, 28 insertions(+), 33 deletions(-) diff --git a/packages/@tailwindcss-postcss/src/index.ts b/packages/@tailwindcss-postcss/src/index.ts index 0baeb68d0b2f..002b4b076301 100644 --- a/packages/@tailwindcss-postcss/src/index.ts +++ b/packages/@tailwindcss-postcss/src/index.ts @@ -4,7 +4,7 @@ import { clearRequireCache } from '@tailwindcss/node/require-cache' import { Scanner } from '@tailwindcss/oxide' import { Features as LightningCssFeatures, transform } from 'lightningcss' import fs from 'node:fs' -import path from 'node:path' +import path, { relative } from 'node:path' import postcss, { type AcceptedPlugin, type PluginCreator } from 'postcss' import { toCss, type AstNode } from '../../tailwindcss/src/ast' import { cssAstToPostCssAst, postCssAstToCssAst } from './ast' @@ -62,7 +62,10 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { { postcssPlugin: 'tailwindcss', async Once(root, { result }) { - env.DEBUG && console.time('[@tailwindcss/postcss] Total time in @tailwindcss/postcss') + let inputFile = result.opts.from ?? '' + let scope = env.DEBUG ? `[@tailwindcss/postcss] ${relative(base, inputFile)}` : '' + + env.DEBUG && console.time(`${scope} Total time in @tailwindcss/postcss`) // Bail out early if this is guaranteed to be a non-Tailwind CSS file. { @@ -80,27 +83,25 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { } }) if (canBail) { - env.DEBUG && - console.timeEnd('[@tailwindcss/postcss] Total time in @tailwindcss/postcss') + env.DEBUG && console.timeEnd(`${scope} Total time in @tailwindcss/postcss`) return } } - let inputFile = result.opts.from ?? '' let context = getContextFromCache(inputFile, opts) let inputBasePath = path.dirname(path.resolve(inputFile)) async function createCompiler() { - env.DEBUG && console.time('[@tailwindcss/postcss] Setup compiler') + env.DEBUG && console.time(`${scope} Setup compiler`) if (context.fullRebuildPaths.length > 0 && !isInitialBuild) { clearRequireCache(context.fullRebuildPaths) } context.fullRebuildPaths = [] - env.DEBUG && console.time('[@tailwindcss/postcss] PostCSS AST -> Tailwind CSS AST') + env.DEBUG && console.time(`${scope} PostCSS AST -> Tailwind CSS AST`) let ast = postCssAstToCssAst(root) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] PostCSS AST -> Tailwind CSS AST') + env.DEBUG && console.timeEnd(`${scope} PostCSS AST -> Tailwind CSS AST`) let compiler = await compileAst(ast, { base: inputBasePath, @@ -109,7 +110,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { }, }) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Setup compiler') + env.DEBUG && console.timeEnd(`${scope} Setup compiler`) return compiler } @@ -122,8 +123,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.compiler ??= await createCompiler() if (context.compiler.features === Features.None) { - env.DEBUG && - console.timeEnd('[@tailwindcss/postcss] Total time in @tailwindcss/postcss') + env.DEBUG && console.timeEnd(`${scope} Total time in @tailwindcss/postcss`) return } @@ -192,10 +192,10 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.scanner = new Scanner({ sources }) } - env.DEBUG && console.time('[@tailwindcss/postcss] Scan for candidates') + env.DEBUG && console.time(`${scope} Scan for candidates`) let candidates = context.compiler.features & Features.Utilities ? context.scanner.scan() : [] - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Scan for candidates') + env.DEBUG && console.timeEnd(`${scope} Scan for candidates`) if (context.compiler.features & Features.Utilities) { // Add all found files as direct dependencies @@ -238,45 +238,40 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { } } - env.DEBUG && console.time('[@tailwindcss/postcss] Build utilities') + env.DEBUG && console.time(`${scope} Build utilities`) let tailwindCssAst = context.compiler.build(candidates) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Build utilities') + env.DEBUG && console.timeEnd(`${scope} Build utilities`) if (context.tailwindCssAst !== tailwindCssAst) { if (optimize) { - env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] Total') + env.DEBUG && console.time(`${scope} [Optimization] Total`) - env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] AST -> CSS') + env.DEBUG && console.time(`${scope} [Optimization] AST -> CSS`) let css = toCss(tailwindCssAst) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss][Optimization] AST -> CSS') + env.DEBUG && console.timeEnd(`${scope} [Optimization] AST -> CSS`) - env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] Lightning CSS') + env.DEBUG && console.time(`${scope} [Optimization] Lightning CSS`) let ast = optimizeCss(css, { minify: typeof optimize === 'object' ? optimize.minify : true, }) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss][Optimization] Lightning CSS') + env.DEBUG && console.timeEnd(`${scope} [Optimization] Lightning CSS`) - env.DEBUG && console.time('[@tailwindcss/postcss][Optimization] CSS -> PostCSS AST') + env.DEBUG && console.time(`${scope} [Optimization] CSS -> PostCSS AST`) context.optimizedPostCssAst = postcss.parse(ast, result.opts) - env.DEBUG && - console.timeEnd('[@tailwindcss/postcss][Optimization] CSS -> PostCSS AST') + env.DEBUG && console.timeEnd(`${scope} [Optimization] CSS -> PostCSS AST`) - env.DEBUG && console.timeEnd('[@tailwindcss/postcss][Optimization] Total') + env.DEBUG && console.timeEnd(`${scope} [Optimization] Total`) } else { // Convert our AST to a PostCSS AST - env.DEBUG && - console.time('[@tailwindcss/postcss] Transform Tailwind CSS AST into PostCSS AST') + env.DEBUG && console.time(`${scope} Transform Tailwind CSS AST into PostCSS AST`) context.cachedPostCssAst = cssAstToPostCssAst(tailwindCssAst, root.source) - env.DEBUG && - console.timeEnd( - '[@tailwindcss/postcss] Transform Tailwind CSS AST into PostCSS AST', - ) + env.DEBUG && console.timeEnd(`${scope} Transform Tailwind CSS AST into PostCSS AST`) } } context.tailwindCssAst = tailwindCssAst - env.DEBUG && console.time('[@tailwindcss/postcss] Update PostCSS AST') + env.DEBUG && console.time(`${scope} Update PostCSS AST`) root.removeAll() root.append( optimize @@ -288,8 +283,8 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { // as the default instead of 4. root.raws.indent = ' ' - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Update PostCSS AST') - env.DEBUG && console.timeEnd('[@tailwindcss/postcss] Total time in @tailwindcss/postcss') + env.DEBUG && console.timeEnd(`${scope} Update PostCSS AST`) + env.DEBUG && console.timeEnd(`${scope} Total time in @tailwindcss/postcss`) }, }, ], From 31a5e679c7042a8765608522374872287fc7caf2 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Wed, 4 Dec 2024 20:47:34 +0100 Subject: [PATCH 04/20] only enable oxide logs using `DEBUG=tailwindcss:oxide` or `DEBUG=*` --- crates/oxide/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/oxide/src/lib.rs b/crates/oxide/src/lib.rs index f7da2be772ce..4631cabc843c 100644 --- a/crates/oxide/src/lib.rs +++ b/crates/oxide/src/lib.rs @@ -24,7 +24,7 @@ pub mod paths; pub mod scanner; static SHOULD_TRACE: sync::LazyLock = sync::LazyLock::new( - || matches!(std::env::var("DEBUG"), Ok(value) if value.eq("*") || value.eq("1") || value.eq("true") || value.contains("tailwind")), + || matches!(std::env::var("DEBUG"), Ok(value) if value.eq("*") || (value.contains("tailwindcss:oxide") && !value.contains("-tailwindcss:oxide"))), ); fn init_tracing() { From f6229ca1cd745c1edf333b25c52bef1ee66873a1 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Sat, 24 Feb 2024 23:48:13 +0100 Subject: [PATCH 05/20] add instrumentation --- packages/@tailwindcss-node/src/index.cts | 3 +- packages/@tailwindcss-node/src/index.ts | 3 +- .../src/instrumentation.test.ts | 57 ++++++++++ .../@tailwindcss-node/src/instrumentation.ts | 106 ++++++++++++++++++ 4 files changed, 167 insertions(+), 2 deletions(-) create mode 100644 packages/@tailwindcss-node/src/instrumentation.test.ts create mode 100644 packages/@tailwindcss-node/src/instrumentation.ts diff --git a/packages/@tailwindcss-node/src/index.cts b/packages/@tailwindcss-node/src/index.cts index da67709545fb..fd74aa01bf1b 100644 --- a/packages/@tailwindcss-node/src/index.cts +++ b/packages/@tailwindcss-node/src/index.cts @@ -1,9 +1,10 @@ import * as Module from 'node:module' import { pathToFileURL } from 'node:url' import * as env from './env' +import * as instrumentation from './instrumentation' export * from './compile' export * from './normalize-path' -export { env } +export { env, instrumentation } // In Bun, ESM modules will also populate `require.cache`, so the module hook is // not necessary. diff --git a/packages/@tailwindcss-node/src/index.ts b/packages/@tailwindcss-node/src/index.ts index c4b88e981650..db784ffcdb69 100644 --- a/packages/@tailwindcss-node/src/index.ts +++ b/packages/@tailwindcss-node/src/index.ts @@ -1,9 +1,10 @@ import * as Module from 'node:module' import { pathToFileURL } from 'node:url' import * as env from './env' +import * as instrumentation from './instrumentation' export { __unstable__loadDesignSystem, compile, compileAst, Features } from './compile' export * from './normalize-path' -export { env } +export { env, instrumentation } // In Bun, ESM modules will also populate `require.cache`, so the module hook is // not necessary. diff --git a/packages/@tailwindcss-node/src/instrumentation.test.ts b/packages/@tailwindcss-node/src/instrumentation.test.ts new file mode 100644 index 000000000000..70032a70f7f9 --- /dev/null +++ b/packages/@tailwindcss-node/src/instrumentation.test.ts @@ -0,0 +1,57 @@ +import { stripVTControlCharacters } from 'util' +import { expect, it } from 'vitest' +import * as I from './instrumentation' + +it('should add instrumentation', () => { + I.reset() + + I.start('Foo') + let x = 1 + for (let i = 0; i < 100; i++) { + I.start('Bar') + x **= 2 + I.end('Bar') + } + I.end('Foo') + + I.hit('Potato') + I.hit('Potato') + I.hit('Potato') + I.hit('Potato') + + expect.assertions(1) + + I.report((output) => { + expect(stripVTControlCharacters(output).replace(/\[.*\]/g, '[0.xxms]')).toMatchInlineSnapshot(` + "Hits: + Potato × 4 + + Timers: + [0.xxms] Foo + [0.xxms] ↳ Bar × 100" + `) + }) +}) + +it('should auto end pending timers when reporting', () => { + I.reset() + + I.start('Foo') + let x = 1 + for (let i = 0; i < 100; i++) { + I.start('Bar') + x **= 2 + I.end('Bar') + } + I.start('Baz') + + expect.assertions(1) + + I.report((output) => { + expect(stripVTControlCharacters(output).replace(/\[.*\]/g, '[0.xxms]')).toMatchInlineSnapshot(` + "[0.xxms] Foo + [0.xxms] ↳ Bar × 100 + [0.xxms] ↳ Baz" + `) + }) +}) diff --git a/packages/@tailwindcss-node/src/instrumentation.ts b/packages/@tailwindcss-node/src/instrumentation.ts new file mode 100644 index 000000000000..e5037abc9fe6 --- /dev/null +++ b/packages/@tailwindcss-node/src/instrumentation.ts @@ -0,0 +1,106 @@ +import { DefaultMap } from '../../tailwindcss/src/utils/default-map' + +const hits = new DefaultMap(() => ({ value: 0 })) +const timerStack: { + id: string + label: string + namespace: string + value: bigint +}[] = [] +const timers = new DefaultMap(() => ({ value: 0n })) + +export function hit(label: string) { + hits.get(label).value++ +} + +export function start(label: string) { + let namespace = timerStack.map((t) => t.label).join('//') + let id = `${namespace}${namespace.length === 0 ? '' : '//'}${label}` + + hits.get(id).value++ + + // Create the timer if it doesn't exist yet + timers.get(id) + + timerStack.push({ id, label, namespace, value: process.hrtime.bigint() }) +} + +export function end(label: string) { + let end = process.hrtime.bigint() + + if (timerStack[timerStack.length - 1].label !== label) { + throw new Error( + `Mismatched timer label: \`${label}\`, expected \`${ + timerStack[timerStack.length - 1].label + }\``, + ) + } + + let parent = timerStack.pop()! + let elapsed = end - parent.value + timers.get(parent.id).value += elapsed +} + +export function reset() { + hits.clear() + timers.clear() + timerStack.splice(0) +} + +function white(input: string) { + return `\u001b[37m${input}\u001b[39m` +} + +function dim(input: string) { + return `\u001b[2m${input}\u001b[22m` +} + +function blue(input: string) { + return `\u001b[34m${input}\u001b[39m` +} + +export function report(flush = console.error) { + let output: string[] = [] + let hasHits = false + + // Auto end any pending timers + for (let i = timerStack.length - 1; i >= 0; i--) { + end(timerStack[i].label) + } + + for (let [label, { value: count }] of hits.entries()) { + if (timers.has(label)) continue + if (output.length === 0) { + hasHits = true + output.push(white('Hits:')) + } + + let depth = label.split('//').length + output.push(`${' '.repeat(depth)}${label} ${dim(blue(`× ${count}`))}`) + } + + if (timers.size > 0 && hasHits) { + output.push(white('\nTimers:')) + } + + let max = -Infinity + let computed = new Map() + for (let [label, { value }] of timers) { + let x = `${(Number(value) / 1e6).toFixed(2)}ms` + computed.set(label, x) + max = Math.max(max, x.length) + } + + for (let label of timers.keys()) { + let depth = label.split('//').length + output.push( + white( + `${dim(`[${computed.get(label)!.padStart(max, ' ')}]`)}${' '.repeat(depth - 1)}${depth === 1 ? ' ' : ' ↳ '}${label.split('//').pop()} ${ + hits.get(label).value === 1 ? '' : dim(blue(`× ${hits.get(label).value}`)) + }`.trimEnd(), + ), + ) + } + + flush(output.join('\n')) +} From 562018fada154c851ffe4155546e82245cb13d1b Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Wed, 4 Dec 2024 21:21:28 +0100 Subject: [PATCH 06/20] use custom intstrumentation --- packages/@tailwindcss-postcss/src/index.ts | 54 +++++++++++----------- 1 file changed, 28 insertions(+), 26 deletions(-) diff --git a/packages/@tailwindcss-postcss/src/index.ts b/packages/@tailwindcss-postcss/src/index.ts index 002b4b076301..587a67618b12 100644 --- a/packages/@tailwindcss-postcss/src/index.ts +++ b/packages/@tailwindcss-postcss/src/index.ts @@ -1,5 +1,5 @@ import QuickLRU from '@alloc/quick-lru' -import { compileAst, env, Features } from '@tailwindcss/node' +import { compileAst, env, Features, instrumentation as I } from '@tailwindcss/node' import { clearRequireCache } from '@tailwindcss/node/require-cache' import { Scanner } from '@tailwindcss/oxide' import { Features as LightningCssFeatures, transform } from 'lightningcss' @@ -62,10 +62,11 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { { postcssPlugin: 'tailwindcss', async Once(root, { result }) { + env.DEBUG && I.reset() + let inputFile = result.opts.from ?? '' - let scope = env.DEBUG ? `[@tailwindcss/postcss] ${relative(base, inputFile)}` : '' - env.DEBUG && console.time(`${scope} Total time in @tailwindcss/postcss`) + env.DEBUG && I.start(`[@tailwindcss/postcss] ${relative(base, inputFile)}`) // Bail out early if this is guaranteed to be a non-Tailwind CSS file. { @@ -83,7 +84,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { } }) if (canBail) { - env.DEBUG && console.timeEnd(`${scope} Total time in @tailwindcss/postcss`) + env.DEBUG && I.report() return } } @@ -92,16 +93,16 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { let inputBasePath = path.dirname(path.resolve(inputFile)) async function createCompiler() { - env.DEBUG && console.time(`${scope} Setup compiler`) + env.DEBUG && I.start('Setup compiler') if (context.fullRebuildPaths.length > 0 && !isInitialBuild) { clearRequireCache(context.fullRebuildPaths) } context.fullRebuildPaths = [] - env.DEBUG && console.time(`${scope} PostCSS AST -> Tailwind CSS AST`) + env.DEBUG && I.start('PostCSS AST -> Tailwind CSS AST') let ast = postCssAstToCssAst(root) - env.DEBUG && console.timeEnd(`${scope} PostCSS AST -> Tailwind CSS AST`) + env.DEBUG && I.end('PostCSS AST -> Tailwind CSS AST') let compiler = await compileAst(ast, { base: inputBasePath, @@ -110,7 +111,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { }, }) - env.DEBUG && console.timeEnd(`${scope} Setup compiler`) + env.DEBUG && I.end('Setup compiler') return compiler } @@ -123,7 +124,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.compiler ??= await createCompiler() if (context.compiler.features === Features.None) { - env.DEBUG && console.timeEnd(`${scope} Total time in @tailwindcss/postcss`) + env.DEBUG && I.report() return } @@ -192,10 +193,10 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.scanner = new Scanner({ sources }) } - env.DEBUG && console.time(`${scope} Scan for candidates`) + env.DEBUG && I.start('Scan for candidates') let candidates = context.compiler.features & Features.Utilities ? context.scanner.scan() : [] - env.DEBUG && console.timeEnd(`${scope} Scan for candidates`) + env.DEBUG && I.end('Scan for candidates') if (context.compiler.features & Features.Utilities) { // Add all found files as direct dependencies @@ -238,40 +239,40 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { } } - env.DEBUG && console.time(`${scope} Build utilities`) + env.DEBUG && I.start('Build utilities') let tailwindCssAst = context.compiler.build(candidates) - env.DEBUG && console.timeEnd(`${scope} Build utilities`) + env.DEBUG && I.end('Build utilities') if (context.tailwindCssAst !== tailwindCssAst) { if (optimize) { - env.DEBUG && console.time(`${scope} [Optimization] Total`) + env.DEBUG && I.start('Optimization') - env.DEBUG && console.time(`${scope} [Optimization] AST -> CSS`) + env.DEBUG && I.start('AST -> CSS') let css = toCss(tailwindCssAst) - env.DEBUG && console.timeEnd(`${scope} [Optimization] AST -> CSS`) + env.DEBUG && I.end('AST -> CSS') - env.DEBUG && console.time(`${scope} [Optimization] Lightning CSS`) + env.DEBUG && I.start('Lightning CSS') let ast = optimizeCss(css, { minify: typeof optimize === 'object' ? optimize.minify : true, }) - env.DEBUG && console.timeEnd(`${scope} [Optimization] Lightning CSS`) + env.DEBUG && I.end('Lightning CSS') - env.DEBUG && console.time(`${scope} [Optimization] CSS -> PostCSS AST`) + env.DEBUG && I.start('CSS -> PostCSS AST') context.optimizedPostCssAst = postcss.parse(ast, result.opts) - env.DEBUG && console.timeEnd(`${scope} [Optimization] CSS -> PostCSS AST`) + env.DEBUG && I.end('CSS -> PostCSS AST') - env.DEBUG && console.timeEnd(`${scope} [Optimization] Total`) + env.DEBUG && I.end('Optimization') } else { // Convert our AST to a PostCSS AST - env.DEBUG && console.time(`${scope} Transform Tailwind CSS AST into PostCSS AST`) + env.DEBUG && I.start('Transform Tailwind CSS AST into PostCSS AST') context.cachedPostCssAst = cssAstToPostCssAst(tailwindCssAst, root.source) - env.DEBUG && console.timeEnd(`${scope} Transform Tailwind CSS AST into PostCSS AST`) + env.DEBUG && I.end('Transform Tailwind CSS AST into PostCSS AST') } } context.tailwindCssAst = tailwindCssAst - env.DEBUG && console.time(`${scope} Update PostCSS AST`) + env.DEBUG && I.start('Update PostCSS AST') root.removeAll() root.append( optimize @@ -283,8 +284,9 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { // as the default instead of 4. root.raws.indent = ' ' - env.DEBUG && console.timeEnd(`${scope} Update PostCSS AST`) - env.DEBUG && console.timeEnd(`${scope} Total time in @tailwindcss/postcss`) + env.DEBUG && I.end('Update PostCSS AST') + env.DEBUG && I.end(`[@tailwindcss/postcss] ${relative(base, inputFile)}`) + env.DEBUG && I.report() }, }, ], From 5e885dcfa0e43d4576228ada7d40d919524ead73 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Wed, 4 Dec 2024 21:25:28 +0100 Subject: [PATCH 07/20] add a few more logs --- packages/@tailwindcss-postcss/src/index.ts | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/packages/@tailwindcss-postcss/src/index.ts b/packages/@tailwindcss-postcss/src/index.ts index 587a67618b12..d9f5a6276161 100644 --- a/packages/@tailwindcss-postcss/src/index.ts +++ b/packages/@tailwindcss-postcss/src/index.ts @@ -104,12 +104,14 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { let ast = postCssAstToCssAst(root) env.DEBUG && I.end('PostCSS AST -> Tailwind CSS AST') + env.DEBUG && I.start('Create compiler') let compiler = await compileAst(ast, { base: inputBasePath, onDependency: (path) => { context.fullRebuildPaths.push(path) }, }) + env.DEBUG && I.end('Create compiler') env.DEBUG && I.end('Setup compiler') return compiler @@ -131,6 +133,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { let rebuildStrategy: 'full' | 'incremental' = 'incremental' // Track file modification times to CSS files + env.DEBUG && I.start('Register full rebuild paths') { for (let file of context.fullRebuildPaths) { result.messages.push({ @@ -163,6 +166,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.mtimes.set(file, changedTime) } } + env.DEBUG && I.end('Register full rebuild paths') if ( rebuildStrategy === 'full' && @@ -174,6 +178,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { } if (context.scanner === null || rebuildStrategy === 'full') { + env.DEBUG && I.start('Setup scanner') let sources = (() => { // Disable auto source detection if (context.compiler.root === 'none') { @@ -191,6 +196,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { // Look for candidates used to generate the CSS context.scanner = new Scanner({ sources }) + env.DEBUG && I.end('Setup scanner') } env.DEBUG && I.start('Scan for candidates') @@ -199,6 +205,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { env.DEBUG && I.end('Scan for candidates') if (context.compiler.features & Features.Utilities) { + env.DEBUG && I.start('Register dependency messages') // Add all found files as direct dependencies for (let file of context.scanner.files) { result.messages.push({ @@ -237,6 +244,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { }) } } + env.DEBUG && I.end('Register dependency messages') } env.DEBUG && I.start('Build utilities') @@ -283,8 +291,8 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { // Trick PostCSS into thinking the indent is 2 spaces, so it uses that // as the default instead of 4. root.raws.indent = ' ' - env.DEBUG && I.end('Update PostCSS AST') + env.DEBUG && I.end(`[@tailwindcss/postcss] ${relative(base, inputFile)}`) env.DEBUG && I.report() }, From 903fc261da65742d988217c28d425d71ee0437ee Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Thu, 5 Dec 2024 00:18:11 +0100 Subject: [PATCH 08/20] use custom instrumentation in `@tailwindcss/cli` --- .../src/commands/build/index.ts | 47 +++++++++++-------- 1 file changed, 28 insertions(+), 19 deletions(-) diff --git a/packages/@tailwindcss-cli/src/commands/build/index.ts b/packages/@tailwindcss-cli/src/commands/build/index.ts index b04c779dd548..37edc25a8339 100644 --- a/packages/@tailwindcss-cli/src/commands/build/index.ts +++ b/packages/@tailwindcss-cli/src/commands/build/index.ts @@ -1,5 +1,5 @@ import watcher from '@parcel/watcher' -import { compile, env } from '@tailwindcss/node' +import { compile, env, instrumentation as I } from '@tailwindcss/node' import { clearRequireCache } from '@tailwindcss/node/require-cache' import { Scanner, type ChangedContent } from '@tailwindcss/oxide' import { Features, transform } from 'lightningcss' @@ -66,6 +66,9 @@ async function handleError(fn: () => T): Promise { } export async function handle(args: Result>) { + env.DEBUG && I.reset() + env.DEBUG && I.start('[@tailwindcss/cli]') + let base = path.resolve(args['--cwd']) // Resolve the output as an absolute path. @@ -109,12 +112,12 @@ export async function handle(args: Result>) { // Optimize the output if (args['--minify'] || args['--optimize']) { if (css !== previous.css) { - env.DEBUG && console.time('[@tailwindcss/cli] Optimize CSS') + env.DEBUG && I.start('Optimize CSS') let optimizedCss = optimizeCss(css, { file: args['--input'] ?? 'input.css', minify: args['--minify'] ?? false, }) - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Optimize CSS') + env.DEBUG && I.end('Optimize CSS') previous.css = css previous.optimizedCss = optimizedCss output = optimizedCss @@ -124,13 +127,13 @@ export async function handle(args: Result>) { } // Write the output - env.DEBUG && console.time('[@tailwindcss/cli] Write output') + env.DEBUG && I.start('Write output') if (args['--output']) { await outputFile(args['--output'], output) } else { println(output) } - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Write output') + env.DEBUG && I.end('Write output') } let inputFilePath = @@ -141,7 +144,7 @@ export async function handle(args: Result>) { let fullRebuildPaths: string[] = inputFilePath ? [inputFilePath] : [] async function createCompiler(css: string) { - env.DEBUG && console.time('[@tailwindcss/cli] Setup compiler') + env.DEBUG && I.start('Setup compiler') let compiler = await compile(css, { base: inputBasePath, onDependency(path) { @@ -165,7 +168,7 @@ export async function handle(args: Result>) { })().concat(compiler.globs) let scanner = new Scanner({ sources }) - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Setup compiler') + env.DEBUG && I.end('Setup compiler') return [compiler, scanner] as const } @@ -177,6 +180,8 @@ export async function handle(args: Result>) { let cleanupWatchers = await createWatchers( watchDirectories(scanner), async function handle(files) { + env.DEBUG && I.reset() + try { // If the only change happened to the output file, then we don't want to // trigger a rebuild because that will result in an infinite loop. @@ -229,9 +234,9 @@ export async function handle(args: Result>) { ;[compiler, scanner] = await createCompiler(input) // Scan the directory for candidates - env.DEBUG && console.time('[@tailwindcss/cli] Scan for candidates') + env.DEBUG && I.start('Scan for candidates') let candidates = scanner.scan() - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Scan for candidates') + env.DEBUG && I.end('Scan for candidates') // Setup new watchers let newCleanupWatchers = await createWatchers(watchDirectories(scanner), handle) @@ -242,16 +247,16 @@ export async function handle(args: Result>) { cleanupWatchers = newCleanupWatchers // Re-compile the CSS - env.DEBUG && console.time('[@tailwindcss/cli] Build CSS') + env.DEBUG && I.start('Build CSS') compiledCss = compiler.build(candidates) - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Build CSS') + env.DEBUG && I.end('Build CSS') } // Scan changed files only for incremental rebuilds. else if (rebuildStrategy === 'incremental') { - env.DEBUG && console.time('[@tailwindcss/cli] Scan for candidates') + env.DEBUG && I.start('Scan for candidates') let newCandidates = scanner.scanFiles(changedFiles) - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Scan for candidates') + env.DEBUG && I.end('Scan for candidates') // No new candidates found which means we don't need to write to // disk, and can return early. @@ -261,21 +266,23 @@ export async function handle(args: Result>) { return } - env.DEBUG && console.time('[@tailwindcss/cli] Build CSS') + env.DEBUG && I.start('Build CSS') compiledCss = compiler.build(newCandidates) - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Build CSS') + env.DEBUG && I.end('Build CSS') } await write(compiledCss, args) let end = process.hrtime.bigint() eprintln(`Done in ${formatDuration(end - start)}`) + env.DEBUG && I.report() } catch (err) { // Catch any errors and print them to stderr, but don't exit the process // and keep watching. if (err instanceof Error) { eprintln(err.toString()) } + env.DEBUG && I.report() } }, ) @@ -295,18 +302,20 @@ export async function handle(args: Result>) { process.stdin.resume() } - env.DEBUG && console.time('[@tailwindcss/cli] Scan for candidates') + env.DEBUG && I.start('Scan for candidates') let candidates = scanner.scan() - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Scan for candidates') - env.DEBUG && console.time('[@tailwindcss/cli] Build CSS') + env.DEBUG && I.end('Scan for candidates') + env.DEBUG && I.start('Build CSS') let output = await handleError(() => compiler.build(candidates)) - env.DEBUG && console.timeEnd('[@tailwindcss/cli] Build CSS') + env.DEBUG && I.end('Build CSS') await write(output, args) let end = process.hrtime.bigint() eprintln(header()) eprintln() eprintln(`Done in ${formatDuration(end - start)}`) + env.DEBUG && I.end('[@tailwindcss/cli]') + env.DEBUG && I.report() } function watchDirectories(scanner: Scanner) { From b1c02ad6758491c694255246a4d505a9f8b75ddf Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Thu, 5 Dec 2024 11:21:08 +0100 Subject: [PATCH 09/20] implement `Instrumentation` as a class This also allows us to make it disposable. This allows us to create a new instrumentation instance using the `using` keyword, which automatically reports the findings when it's being disposed. --- packages/@tailwindcss-node/src/index.cts | 4 +- packages/@tailwindcss-node/src/index.ts | 4 +- .../src/instrumentation.test.ts | 6 +- .../@tailwindcss-node/src/instrumentation.ts | 163 +++++++++--------- 4 files changed, 90 insertions(+), 87 deletions(-) diff --git a/packages/@tailwindcss-node/src/index.cts b/packages/@tailwindcss-node/src/index.cts index fd74aa01bf1b..2e79e25c7566 100644 --- a/packages/@tailwindcss-node/src/index.cts +++ b/packages/@tailwindcss-node/src/index.cts @@ -1,10 +1,10 @@ import * as Module from 'node:module' import { pathToFileURL } from 'node:url' import * as env from './env' -import * as instrumentation from './instrumentation' export * from './compile' +export * from './instrumentation' export * from './normalize-path' -export { env, instrumentation } +export { env } // In Bun, ESM modules will also populate `require.cache`, so the module hook is // not necessary. diff --git a/packages/@tailwindcss-node/src/index.ts b/packages/@tailwindcss-node/src/index.ts index db784ffcdb69..4ee2fe80587d 100644 --- a/packages/@tailwindcss-node/src/index.ts +++ b/packages/@tailwindcss-node/src/index.ts @@ -1,10 +1,10 @@ import * as Module from 'node:module' import { pathToFileURL } from 'node:url' import * as env from './env' -import * as instrumentation from './instrumentation' export { __unstable__loadDesignSystem, compile, compileAst, Features } from './compile' +export * from './instrumentation' export * from './normalize-path' -export { env, instrumentation } +export { env } // In Bun, ESM modules will also populate `require.cache`, so the module hook is // not necessary. diff --git a/packages/@tailwindcss-node/src/instrumentation.test.ts b/packages/@tailwindcss-node/src/instrumentation.test.ts index 70032a70f7f9..ee2ae26f73bf 100644 --- a/packages/@tailwindcss-node/src/instrumentation.test.ts +++ b/packages/@tailwindcss-node/src/instrumentation.test.ts @@ -1,9 +1,9 @@ import { stripVTControlCharacters } from 'util' import { expect, it } from 'vitest' -import * as I from './instrumentation' +import { Instrumentation } from './instrumentation' it('should add instrumentation', () => { - I.reset() + let I = new Instrumentation() I.start('Foo') let x = 1 @@ -34,7 +34,7 @@ it('should add instrumentation', () => { }) it('should auto end pending timers when reporting', () => { - I.reset() + let I = new Instrumentation() I.start('Foo') let x = 1 diff --git a/packages/@tailwindcss-node/src/instrumentation.ts b/packages/@tailwindcss-node/src/instrumentation.ts index e5037abc9fe6..d23bc3959dad 100644 --- a/packages/@tailwindcss-node/src/instrumentation.ts +++ b/packages/@tailwindcss-node/src/instrumentation.ts @@ -1,106 +1,109 @@ import { DefaultMap } from '../../tailwindcss/src/utils/default-map' -const hits = new DefaultMap(() => ({ value: 0 })) -const timerStack: { - id: string - label: string - namespace: string - value: bigint -}[] = [] -const timers = new DefaultMap(() => ({ value: 0n })) - -export function hit(label: string) { - hits.get(label).value++ -} +export class Instrumentation implements Disposable { + #hits = new DefaultMap(() => ({ value: 0 })) + #timers = new DefaultMap(() => ({ value: 0n })) + #timerStack: { id: string; label: string; namespace: string; value: bigint }[] = [] -export function start(label: string) { - let namespace = timerStack.map((t) => t.label).join('//') - let id = `${namespace}${namespace.length === 0 ? '' : '//'}${label}` + constructor(private defaultFlush = console.error) {} - hits.get(id).value++ + hit(label: string) { + this.#hits.get(label).value++ + } - // Create the timer if it doesn't exist yet - timers.get(id) + start(label: string) { + let namespace = this.#timerStack.map((t) => t.label).join('//') + let id = `${namespace}${namespace.length === 0 ? '' : '//'}${label}` - timerStack.push({ id, label, namespace, value: process.hrtime.bigint() }) -} + this.#hits.get(id).value++ -export function end(label: string) { - let end = process.hrtime.bigint() + // Create the timer if it doesn't exist yet + this.#timers.get(id) - if (timerStack[timerStack.length - 1].label !== label) { - throw new Error( - `Mismatched timer label: \`${label}\`, expected \`${ - timerStack[timerStack.length - 1].label - }\``, - ) + this.#timerStack.push({ id, label, namespace, value: process.hrtime.bigint() }) } - let parent = timerStack.pop()! - let elapsed = end - parent.value - timers.get(parent.id).value += elapsed -} + end(label: string) { + let end = process.hrtime.bigint() -export function reset() { - hits.clear() - timers.clear() - timerStack.splice(0) -} + if (this.#timerStack[this.#timerStack.length - 1].label !== label) { + throw new Error( + `Mismatched timer label: \`${label}\`, expected \`${ + this.#timerStack[this.#timerStack.length - 1].label + }\``, + ) + } -function white(input: string) { - return `\u001b[37m${input}\u001b[39m` -} + let parent = this.#timerStack.pop()! + let elapsed = end - parent.value + this.#timers.get(parent.id).value += elapsed + } -function dim(input: string) { - return `\u001b[2m${input}\u001b[22m` -} + reset() { + this.#hits.clear() + this.#timers.clear() + this.#timerStack.splice(0) + } -function blue(input: string) { - return `\u001b[34m${input}\u001b[39m` -} + report(flush = this.defaultFlush) { + let output: string[] = [] + let hasHits = false + + // Auto end any pending timers + for (let i = this.#timerStack.length - 1; i >= 0; i--) { + this.end(this.#timerStack[i].label) + } -export function report(flush = console.error) { - let output: string[] = [] - let hasHits = false + for (let [label, { value: count }] of this.#hits.entries()) { + if (this.#timers.has(label)) continue + if (output.length === 0) { + hasHits = true + output.push(white('Hits:')) + } - // Auto end any pending timers - for (let i = timerStack.length - 1; i >= 0; i--) { - end(timerStack[i].label) - } + let depth = label.split('//').length + output.push(`${' '.repeat(depth)}${label} ${dim(blue(`× ${count}`))}`) + } - for (let [label, { value: count }] of hits.entries()) { - if (timers.has(label)) continue - if (output.length === 0) { - hasHits = true - output.push(white('Hits:')) + if (this.#timers.size > 0 && hasHits) { + output.push(white('\nTimers:')) } - let depth = label.split('//').length - output.push(`${' '.repeat(depth)}${label} ${dim(blue(`× ${count}`))}`) - } + let max = -Infinity + let computed = new Map() + for (let [label, { value }] of this.#timers) { + let x = `${(Number(value) / 1e6).toFixed(2)}ms` + computed.set(label, x) + max = Math.max(max, x.length) + } - if (timers.size > 0 && hasHits) { - output.push(white('\nTimers:')) - } + for (let label of this.#timers.keys()) { + let depth = label.split('//').length + output.push( + white( + `${dim(`[${computed.get(label)!.padStart(max, ' ')}]`)}${' '.repeat(depth - 1)}${depth === 1 ? ' ' : ' ↳ '}${label.split('//').pop()} ${ + this.#hits.get(label).value === 1 ? '' : dim(blue(`× ${this.#hits.get(label).value}`)) + }`.trimEnd(), + ), + ) + } - let max = -Infinity - let computed = new Map() - for (let [label, { value }] of timers) { - let x = `${(Number(value) / 1e6).toFixed(2)}ms` - computed.set(label, x) - max = Math.max(max, x.length) + flush(output.join('\n')) } - for (let label of timers.keys()) { - let depth = label.split('//').length - output.push( - white( - `${dim(`[${computed.get(label)!.padStart(max, ' ')}]`)}${' '.repeat(depth - 1)}${depth === 1 ? ' ' : ' ↳ '}${label.split('//').pop()} ${ - hits.get(label).value === 1 ? '' : dim(blue(`× ${hits.get(label).value}`)) - }`.trimEnd(), - ), - ) + [Symbol.dispose]() { + this.report() } +} + +function white(input: string) { + return `\u001b[37m${input}\u001b[39m` +} - flush(output.join('\n')) +function dim(input: string) { + return `\u001b[2m${input}\u001b[22m` +} + +function blue(input: string) { + return `\u001b[34m${input}\u001b[39m` } From 7c13e79b605970a038dd275b29e311a06d128f3a Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Thu, 5 Dec 2024 11:22:14 +0100 Subject: [PATCH 10/20] ensure `using` keyword is being compiled --- packages/tsconfig.base.json | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/packages/tsconfig.base.json b/packages/tsconfig.base.json index 32597214af2e..93af606691f4 100644 --- a/packages/tsconfig.base.json +++ b/packages/tsconfig.base.json @@ -1,7 +1,8 @@ { "compilerOptions": { - "lib": ["ESNext", "DOM"], - "target": "ESNext", + "target": "es2022", + "lib": ["es2022", "esnext.disposable", "dom"], + "module": "ESNext", "moduleDetection": "force", "allowJs": true, From d458ae1be2ee801cd065263792f728582bf56f7a Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Thu, 5 Dec 2024 11:23:01 +0100 Subject: [PATCH 11/20] use new `Instrumentation` --- .../src/commands/build/index.ts | 38 ++++++++++--------- packages/@tailwindcss-postcss/src/index.ts | 6 +-- 2 files changed, 22 insertions(+), 22 deletions(-) diff --git a/packages/@tailwindcss-cli/src/commands/build/index.ts b/packages/@tailwindcss-cli/src/commands/build/index.ts index 37edc25a8339..3c6e456cced5 100644 --- a/packages/@tailwindcss-cli/src/commands/build/index.ts +++ b/packages/@tailwindcss-cli/src/commands/build/index.ts @@ -1,11 +1,12 @@ import watcher from '@parcel/watcher' -import { compile, env, instrumentation as I } from '@tailwindcss/node' +import { compile, env } from '@tailwindcss/node' import { clearRequireCache } from '@tailwindcss/node/require-cache' import { Scanner, type ChangedContent } from '@tailwindcss/oxide' import { Features, transform } from 'lightningcss' import { existsSync, type Stats } from 'node:fs' import fs from 'node:fs/promises' import path from 'node:path' +import { Instrumentation } from '../../../../@tailwindcss-node/src/instrumentation' import type { Arg, Result } from '../../utils/args' import { Disposables } from '../../utils/disposables' import { @@ -66,8 +67,8 @@ async function handleError(fn: () => T): Promise { } export async function handle(args: Result>) { - env.DEBUG && I.reset() - env.DEBUG && I.start('[@tailwindcss/cli]') + using I = new Instrumentation() + env.DEBUG && I.start('[@tailwindcss/cli] (initial build)') let base = path.resolve(args['--cwd']) @@ -106,7 +107,7 @@ export async function handle(args: Result>) { optimizedCss: '', } - async function write(css: string, args: Result>) { + async function write(css: string, args: Result>, I: Instrumentation) { let output = css // Optimize the output @@ -143,7 +144,7 @@ export async function handle(args: Result>) { let fullRebuildPaths: string[] = inputFilePath ? [inputFilePath] : [] - async function createCompiler(css: string) { + async function createCompiler(css: string, I: Instrumentation) { env.DEBUG && I.start('Setup compiler') let compiler = await compile(css, { base: inputBasePath, @@ -173,20 +174,24 @@ export async function handle(args: Result>) { return [compiler, scanner] as const } - let [compiler, scanner] = await handleError(() => createCompiler(input)) + let [compiler, scanner] = await handleError(() => createCompiler(input, I)) // Watch for changes if (args['--watch']) { let cleanupWatchers = await createWatchers( watchDirectories(scanner), async function handle(files) { - env.DEBUG && I.reset() - try { // If the only change happened to the output file, then we don't want to // trigger a rebuild because that will result in an infinite loop. if (files.length === 1 && files[0] === args['--output']) return + using I = new Instrumentation() + env.DEBUG && I.start('[@tailwindcss/cli] (watcher)') + + // Re-compile the input + let start = process.hrtime.bigint() + let changedFiles: ChangedContent[] = [] let rebuildStrategy: 'incremental' | 'full' = 'incremental' @@ -211,9 +216,6 @@ export async function handle(args: Result>) { } satisfies ChangedContent) } - // Re-compile the input - let start = process.hrtime.bigint() - // Track the compiled CSS let compiledCss = '' @@ -231,7 +233,7 @@ export async function handle(args: Result>) { fullRebuildPaths = inputFilePath ? [inputFilePath] : [] // Create a new compiler, given the new `input` - ;[compiler, scanner] = await createCompiler(input) + ;[compiler, scanner] = await createCompiler(input, I) // Scan the directory for candidates env.DEBUG && I.start('Scan for candidates') @@ -239,10 +241,14 @@ export async function handle(args: Result>) { env.DEBUG && I.end('Scan for candidates') // Setup new watchers + env.DEBUG && I.start('Setup new watchers') let newCleanupWatchers = await createWatchers(watchDirectories(scanner), handle) + env.DEBUG && I.end('Setup new watchers') // Clear old watchers + env.DEBUG && I.start('Cleanup old watchers') await cleanupWatchers() + env.DEBUG && I.end('Cleanup old watchers') cleanupWatchers = newCleanupWatchers @@ -271,18 +277,16 @@ export async function handle(args: Result>) { env.DEBUG && I.end('Build CSS') } - await write(compiledCss, args) + await write(compiledCss, args, I) let end = process.hrtime.bigint() eprintln(`Done in ${formatDuration(end - start)}`) - env.DEBUG && I.report() } catch (err) { // Catch any errors and print them to stderr, but don't exit the process // and keep watching. if (err instanceof Error) { eprintln(err.toString()) } - env.DEBUG && I.report() } }, ) @@ -308,14 +312,12 @@ export async function handle(args: Result>) { env.DEBUG && I.start('Build CSS') let output = await handleError(() => compiler.build(candidates)) env.DEBUG && I.end('Build CSS') - await write(output, args) + await write(output, args, I) let end = process.hrtime.bigint() eprintln(header()) eprintln() eprintln(`Done in ${formatDuration(end - start)}`) - env.DEBUG && I.end('[@tailwindcss/cli]') - env.DEBUG && I.report() } function watchDirectories(scanner: Scanner) { diff --git a/packages/@tailwindcss-postcss/src/index.ts b/packages/@tailwindcss-postcss/src/index.ts index d9f5a6276161..39d2f9f1c6bf 100644 --- a/packages/@tailwindcss-postcss/src/index.ts +++ b/packages/@tailwindcss-postcss/src/index.ts @@ -1,5 +1,5 @@ import QuickLRU from '@alloc/quick-lru' -import { compileAst, env, Features, instrumentation as I } from '@tailwindcss/node' +import { compileAst, env, Features, Instrumentation } from '@tailwindcss/node' import { clearRequireCache } from '@tailwindcss/node/require-cache' import { Scanner } from '@tailwindcss/oxide' import { Features as LightningCssFeatures, transform } from 'lightningcss' @@ -62,7 +62,7 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { { postcssPlugin: 'tailwindcss', async Once(root, { result }) { - env.DEBUG && I.reset() + using I = new Instrumentation() let inputFile = result.opts.from ?? '' @@ -126,7 +126,6 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { context.compiler ??= await createCompiler() if (context.compiler.features === Features.None) { - env.DEBUG && I.report() return } @@ -294,7 +293,6 @@ function tailwindcss(opts: PluginOptions = {}): AcceptedPlugin { env.DEBUG && I.end('Update PostCSS AST') env.DEBUG && I.end(`[@tailwindcss/postcss] ${relative(base, inputFile)}`) - env.DEBUG && I.report() }, }, ], From 94f823e021db26e00cd7f25bd2b1933e191d6381 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Thu, 5 Dec 2024 12:00:24 +0100 Subject: [PATCH 12/20] only report when `env.DEBUG` is true This is only the case for when we are automatically disposing the `Instrumentation`. --- .../@tailwindcss-node/src/instrumentation.test.ts | 12 ++++++++---- packages/@tailwindcss-node/src/instrumentation.ts | 5 +++-- 2 files changed, 11 insertions(+), 6 deletions(-) diff --git a/packages/@tailwindcss-node/src/instrumentation.test.ts b/packages/@tailwindcss-node/src/instrumentation.test.ts index ee2ae26f73bf..1f06796fdd3e 100644 --- a/packages/@tailwindcss-node/src/instrumentation.test.ts +++ b/packages/@tailwindcss-node/src/instrumentation.test.ts @@ -23,12 +23,14 @@ it('should add instrumentation', () => { I.report((output) => { expect(stripVTControlCharacters(output).replace(/\[.*\]/g, '[0.xxms]')).toMatchInlineSnapshot(` - "Hits: + " + Hits: Potato × 4 Timers: [0.xxms] Foo - [0.xxms] ↳ Bar × 100" + [0.xxms] ↳ Bar × 100 + " `) }) }) @@ -49,9 +51,11 @@ it('should auto end pending timers when reporting', () => { I.report((output) => { expect(stripVTControlCharacters(output).replace(/\[.*\]/g, '[0.xxms]')).toMatchInlineSnapshot(` - "[0.xxms] Foo + " + [0.xxms] Foo [0.xxms] ↳ Bar × 100 - [0.xxms] ↳ Baz" + [0.xxms] ↳ Baz + " `) }) }) diff --git a/packages/@tailwindcss-node/src/instrumentation.ts b/packages/@tailwindcss-node/src/instrumentation.ts index d23bc3959dad..b266806898ca 100644 --- a/packages/@tailwindcss-node/src/instrumentation.ts +++ b/packages/@tailwindcss-node/src/instrumentation.ts @@ -1,4 +1,5 @@ import { DefaultMap } from '../../tailwindcss/src/utils/default-map' +import * as env from './env' export class Instrumentation implements Disposable { #hits = new DefaultMap(() => ({ value: 0 })) @@ -88,11 +89,11 @@ export class Instrumentation implements Disposable { ) } - flush(output.join('\n')) + flush(`\n${output.join('\n')}\n`) } [Symbol.dispose]() { - this.report() + env.DEBUG && this.report() } } From 9f5908521825937f59b4dc1d5a19d1ff5da343c6 Mon Sep 17 00:00:00 2001 From: Robin Malfait Date: Thu, 5 Dec 2024 12:00:59 +0100 Subject: [PATCH 13/20] use the `Instrumentation` in the `Vite` plugin --- packages/@tailwindcss-vite/src/index.ts | 49 +++++++++++++++++-------- 1 file changed, 34 insertions(+), 15 deletions(-) diff --git a/packages/@tailwindcss-vite/src/index.ts b/packages/@tailwindcss-vite/src/index.ts index a6ba5db3f2bb..ed04cdaab848 100644 --- a/packages/@tailwindcss-vite/src/index.ts +++ b/packages/@tailwindcss-vite/src/index.ts @@ -1,4 +1,4 @@ -import { compile, env, Features, normalizePath } from '@tailwindcss/node' +import { compile, env, Features, Instrumentation, normalizePath } from '@tailwindcss/node' import { clearRequireCache } from '@tailwindcss/node/require-cache' import { Scanner } from '@tailwindcss/oxide' import { Features as LightningCssFeatures, transform } from 'lightningcss' @@ -110,15 +110,19 @@ export default function tailwindcss(): Plugin[] { } } - async function regenerateOptimizedCss(root: Root, addWatchFile: (file: string) => void) { + async function regenerateOptimizedCss( + root: Root, + addWatchFile: (file: string) => void, + I: Instrumentation, + ) { let content = root.lastContent - let generated = await root.generate(content, addWatchFile) + let generated = await root.generate(content, addWatchFile, I) if (generated === false) { return } - env.DEBUG && console.time('[@tailwindcss/vite] Optimize CSS') + env.DEBUG && I.start('Optimize CSS') let result = optimizeCss(generated, { minify }) - env.DEBUG && console.timeEnd('[@tailwindcss/vite] Optimize CSS') + env.DEBUG && I.end('Optimize CSS') return result } @@ -215,6 +219,9 @@ export default function tailwindcss(): Plugin[] { async transform(src, id, options) { if (!isPotentialCssRootFile(id)) return + using I = new Instrumentation() + I.start('[@tailwindcss/vite] Generate CSS (serve)') + let root = roots.get(id) // If the root was built outside of the transform hook (e.g. in the @@ -241,7 +248,7 @@ export default function tailwindcss(): Plugin[] { await Promise.all(servers.map((server) => server.waitForRequestsIdle(id))) } - let generated = await root.generate(src, (file) => this.addWatchFile(file)) + let generated = await root.generate(src, (file) => this.addWatchFile(file), I) if (!generated) { roots.delete(id) return src @@ -259,6 +266,9 @@ export default function tailwindcss(): Plugin[] { async transform(src, id) { if (!isPotentialCssRootFile(id)) return + using I = new Instrumentation() + I.start('[@tailwindcss/vite] Generate CSS (build)') + let root = roots.get(id) // If the root was built outside of the transform hook (e.g. in the @@ -277,7 +287,7 @@ export default function tailwindcss(): Plugin[] { // We do a first pass to generate valid CSS for the downstream plugins. // However, since not all candidates are guaranteed to be extracted by // this time, we have to re-run a transform for the root later. - let generated = await root.generate(src, (file) => this.addWatchFile(file)) + let generated = await root.generate(src, (file) => this.addWatchFile(file), I) if (!generated) { roots.delete(id) return src @@ -289,6 +299,9 @@ export default function tailwindcss(): Plugin[] { // We must run before `enforce: post` so the updated chunks are picked up // by vite:css-post. async renderStart() { + using I = new Instrumentation() + I.start('[@tailwindcss/vite] (render start)') + for (let [id, root] of roots.entries()) { // Do not do a second render pass on Svelte `