Improve debug logs (#15303)

This PR improves the debug logs for the `@tailwindcss/postcss`
integration. It uses custom instrumentation to provide a nested but
detailed overview of where time is spent during the build process.

The updated logs look like this:
```
[0.15ms] [@tailwindcss/postcss] src/app/geistsans_9fc57718.module.css
[0.14ms]   ↳ Quick bail check
[0.02ms] [@tailwindcss/postcss] src/app/geistsans_9fc57718.module.css
[0.01ms]   ↳ Quick bail check

[0.03ms] [@tailwindcss/postcss] src/app/geistmono_b9f59162.module.css
[0.02ms]   ↳ Quick bail check
[0.12ms] [@tailwindcss/postcss] src/app/geistmono_b9f59162.module.css
[0.11ms]   ↳ Quick bail check

[42.09ms] [@tailwindcss/postcss] src/app/globals.css
[ 0.01ms]   ↳ Quick bail check
[12.12ms]   ↳ Setup compiler
[ 0.11ms]     ↳ PostCSS AST -> Tailwind CSS AST
[11.99ms]     ↳ Create compiler
[ 0.07ms]   ↳ Register full rebuild paths
[ 0.06ms]   ↳ Setup scanner
[ 7.51ms]   ↳ Scan for candidates
[ 5.86ms]   ↳ Register dependency messages
[ 5.88ms]   ↳ Build utilities
[ 8.34ms]   ↳ Optimization
[ 0.23ms]     ↳ AST -> CSS
[ 4.20ms]     ↳ Lightning CSS
[ 3.89ms]     ↳ CSS -> PostCSS AST
[ 1.97ms]   ↳ Update PostCSS AST
```

Author: RobinMalfait

CHANGELOG.md

@@ -17,6 +17,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - Skip creating a compiler for CSS files that should not be processed ([#15340](https://github.com/tailwindlabs/tailwindcss/pull/15340))
 - Fix missing `shadow-none` suggestion in IntelliSense ([#15342](https://github.com/tailwindlabs/tailwindcss/pull/15342))
 - Optimize AST before printing for IntelliSense ([#15347](https://github.com/tailwindlabs/tailwindcss/pull/15347))
+- Improve debug logs to get better insights ([#15303](https://github.com/tailwindlabs/tailwindcss/pull/15303))
 
 ### Changed
 

crates/oxide/src/lib.rs

@@ -24,7 +24,7 @@ pub mod paths;
 pub mod scanner;
 
 static SHOULD_TRACE: sync::LazyLock<bool> = 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() {

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 } from '@tailwindcss/node'
 import { clearRequireCache } from '@tailwindcss/node/require-cache'
 import { Scanner, type ChangedContent } from '@tailwindcss/oxide'
 import { Features, transform } from 'lightningcss'
@@ -19,6 +19,7 @@ import {
 import { drainStdin, outputFile } from './utils'
 
 const css = String.raw
+const DEBUG = env.DEBUG
 
 export function options() {
   return {
@@ -66,6 +67,9 @@ async function handleError<T>(fn: () => T): Promise<T> {
 }
 
 export async function handle(args: Result<ReturnType<typeof options>>) {
+  using I = new Instrumentation()
+  DEBUG && I.start('[@tailwindcss/cli] (initial build)')
+
   let base = path.resolve(args['--cwd'])
 
   // Resolve the output as an absolute path.
@@ -103,18 +107,18 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
     optimizedCss: '',
   }
 
-  async function write(css: string, args: Result<ReturnType<typeof options>>) {
+  async function write(css: string, args: Result<ReturnType<typeof options>>, I: Instrumentation) {
     let output = css
 
     // Optimize the output
     if (args['--minify'] || args['--optimize']) {
       if (css !== previous.css) {
-        env.DEBUG && console.time('[@tailwindcss/cli] Optimize CSS')
+        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')
+        DEBUG && I.end('Optimize CSS')
         previous.css = css
         previous.optimizedCss = optimizedCss
         output = optimizedCss
@@ -124,13 +128,13 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
     }
 
     // Write the output
-    env.DEBUG && console.time('[@tailwindcss/cli] Write output')
+    DEBUG && I.start('Write output')
     if (args['--output']) {
       await outputFile(args['--output'], output)
     } else {
       println(output)
     }
-    env.DEBUG && console.timeEnd('[@tailwindcss/cli] Write output')
+    DEBUG && I.end('Write output')
   }
 
   let inputFilePath =
@@ -140,8 +144,8 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
 
   let fullRebuildPaths: string[] = inputFilePath ? [inputFilePath] : []
 
-  async function createCompiler(css: string) {
-    env.DEBUG && console.time('[@tailwindcss/cli] Setup compiler')
+  async function createCompiler(css: string, I: Instrumentation) {
+    DEBUG && I.start('Setup compiler')
     let compiler = await compile(css, {
       base: inputBasePath,
       onDependency(path) {
@@ -165,12 +169,12 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
     })().concat(compiler.globs)
 
     let scanner = new Scanner({ sources })
-    env.DEBUG && console.timeEnd('[@tailwindcss/cli] Setup compiler')
+    DEBUG && I.end('Setup compiler')
 
     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']) {
@@ -182,6 +186,12 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
           // trigger a rebuild because that will result in an infinite loop.
           if (files.length === 1 && files[0] === args['--output']) return
 
+          using I = new Instrumentation()
+          DEBUG && I.start('[@tailwindcss/cli] (watcher)')
+
+          // Re-compile the input
+          let start = process.hrtime.bigint()
+
           let changedFiles: ChangedContent[] = []
           let rebuildStrategy: 'incremental' | 'full' = 'incremental'
 
@@ -206,9 +216,6 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
             } satisfies ChangedContent)
           }
 
-          // Re-compile the input
-          let start = process.hrtime.bigint()
-
           // Track the compiled CSS
           let compiledCss = ''
 
@@ -226,32 +233,36 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
             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 && console.time('[@tailwindcss/cli] Scan for candidates')
+            DEBUG && I.start('Scan for candidates')
             let candidates = scanner.scan()
-            env.DEBUG && console.timeEnd('[@tailwindcss/cli] Scan for candidates')
+            DEBUG && I.end('Scan for candidates')
 
             // Setup new watchers
+            DEBUG && I.start('Setup new watchers')
             let newCleanupWatchers = await createWatchers(watchDirectories(scanner), handle)
+            DEBUG && I.end('Setup new watchers')
 
             // Clear old watchers
+            DEBUG && I.start('Cleanup old watchers')
             await cleanupWatchers()
+            DEBUG && I.end('Cleanup old watchers')
 
             cleanupWatchers = newCleanupWatchers
 
             // Re-compile the CSS
-            env.DEBUG && console.time('[@tailwindcss/cli] Build CSS')
+            DEBUG && I.start('Build CSS')
             compiledCss = compiler.build(candidates)
-            env.DEBUG && console.timeEnd('[@tailwindcss/cli] Build CSS')
+            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')
+            DEBUG && I.start('Scan for candidates')
             let newCandidates = scanner.scanFiles(changedFiles)
-            env.DEBUG && console.timeEnd('[@tailwindcss/cli] Scan for candidates')
+            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,12 +272,12 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
               return
             }
 
-            env.DEBUG && console.time('[@tailwindcss/cli] Build CSS')
+            DEBUG && I.start('Build CSS')
             compiledCss = compiler.build(newCandidates)
-            env.DEBUG && console.timeEnd('[@tailwindcss/cli] Build CSS')
+            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)}`)
@@ -295,13 +306,13 @@ export async function handle(args: Result<ReturnType<typeof options>>) {
     process.stdin.resume()
   }
 
-  env.DEBUG && console.time('[@tailwindcss/cli] Scan for candidates')
+  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')
+  DEBUG && I.end('Scan for candidates')
+  DEBUG && I.start('Build CSS')
   let output = await handleError(() => compiler.build(candidates))
-  env.DEBUG && console.timeEnd('[@tailwindcss/cli] Build CSS')
-  await write(output, args)
+  DEBUG && I.end('Build CSS')
+  await write(output, args, I)
 
   let end = process.hrtime.bigint()
   eprintln(header())

packages/@tailwindcss-node/src/index.cts

@@ -2,6 +2,7 @@ import * as Module from 'node:module'
 import { pathToFileURL } from 'node:url'
 import * as env from './env'
 export * from './compile'
+export * from './instrumentation'
 export * from './normalize-path'
 export { env }
 

packages/@tailwindcss-node/src/index.ts

@@ -2,6 +2,7 @@ import * as Module from 'node:module'
 import { pathToFileURL } from 'node:url'
 import * as env from './env'
 export { __unstable__loadDesignSystem, compile, compileAst, Features } from './compile'
+export * from './instrumentation'
 export * from './normalize-path'
 export { env }
 

packages/@tailwindcss-node/src/instrumentation.test.ts

@@ -0,0 +1,61 @@
+import { stripVTControlCharacters } from 'util'
+import { expect, it } from 'vitest'
+import { Instrumentation } from './instrumentation'
+
+it('should add instrumentation', () => {
+  let I = new Instrumentation()
+
+  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', () => {
+  let I = new Instrumentation()
+
+  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
+      "
+    `)
+  })
+})

packages/@tailwindcss-node/src/instrumentation.ts

@@ -0,0 +1,105 @@
+import { DefaultMap } from '../../tailwindcss/src/utils/default-map'
+import * as env from './env'
+
+export class Instrumentation implements Disposable {
+  #hits = new DefaultMap(() => ({ value: 0 }))
+  #timers = new DefaultMap(() => ({ value: 0n }))
+  #timerStack: { id: string; label: string; namespace: string; value: bigint }[] = []
+
+  constructor(private defaultFlush = (message: string) => process.stderr.write(`${message}\n`)) {}
+
+  hit(label: string) {
+    this.#hits.get(label).value++
+  }
+
+  start(label: string) {
+    let namespace = this.#timerStack.map((t) => t.label).join('//')
+    let id = `${namespace}${namespace.length === 0 ? '' : '//'}${label}`
+
+    this.#hits.get(id).value++
+
+    // Create the timer if it doesn't exist yet
+    this.#timers.get(id)
+
+    this.#timerStack.push({ id, label, namespace, value: process.hrtime.bigint() })
+  }
+
+  end(label: string) {
+    let end = process.hrtime.bigint()
+
+    if (this.#timerStack[this.#timerStack.length - 1].label !== label) {
+      throw new Error(
+        `Mismatched timer label: \`${label}\`, expected \`${
+          this.#timerStack[this.#timerStack.length - 1].label
+        }\``,
+      )
+    }
+
+    let parent = this.#timerStack.pop()!
+    let elapsed = end - parent.value
+    this.#timers.get(parent.id).value += elapsed
+  }
+
+  reset() {
+    this.#hits.clear()
+    this.#timers.clear()
+    this.#timerStack.splice(0)
+  }
+
+  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)
+    }
+
+    for (let [label, { value: count }] of this.#hits.entries()) {
+      if (this.#timers.has(label)) continue
+      if (output.length === 0) {
+        hasHits = true
+        output.push('Hits:')
+      }
+
+      let depth = label.split('//').length
+      output.push(`${'  '.repeat(depth)}${label} ${dim(blue(`× ${count}`))}`)
+    }
+
+    if (this.#timers.size > 0 && hasHits) {
+      output.push('\nTimers:')
+    }
+
+    let max = -Infinity
+    let computed = new Map<string, string>()
+    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)
+    }
+
+    for (let label of this.#timers.keys()) {
+      let depth = label.split('//').length
+      output.push(
+        `${dim(`[${computed.get(label)!.padStart(max, ' ')}]`)}${'  '.repeat(depth - 1)}${depth === 1 ? ' ' : dim(' ↳ ')}${label.split('//').pop()} ${
+          this.#hits.get(label).value === 1 ? '' : dim(blue(`× ${this.#hits.get(label).value}`))
+        }`.trimEnd(),
+      )
+    }
+
+    flush(`\n${output.join('\n')}\n`)
+    this.reset()
+  }
+
+  [Symbol.dispose]() {
+    env.DEBUG && this.report()
+  }
+}
+
+function dim(input: string) {
+  return `\u001b[2m${input}\u001b[22m`
+}
+
+function blue(input: string) {
+  return `\u001b[34m${input}\u001b[39m`
+}