Improve debug logs #15303

RobinMalfait · 2024-12-04T20:47:39Z

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

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

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

RobinMalfait · 2024-12-05T11:08:57Z

packages/@tailwindcss-cli/src/commands/build/index.ts

@@ -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()


Ideally this is only created when DEBUG is true but I don't think that's possible

TIL about this feature 😮 I think it's cool but haven't really used this before. Is there any way to only conditionally create an instance of Instrumentation? 🤔

I'm not sure yet what to think about it, probably just takes some getting used to haha. It seems like it's the same as defer in Go but the fact that it requires an object with a dispose symbol seems a little extra verbose.

If you look at the compiled output (because we can't use the native version just yet), what it essentially does is it wraps the code in a try/catch/finally and calls the dispose function in the finally block.

E.g.: https://www.typescriptlang.org/play/?#code/DYUwLgBAZg9jEF4IG8BQEJhAZzACgEoUIBfAGnQgG0BlATwFsAjGYAOgBMBLbABxmwgAuoRSUMAYxgA7bKxBtgMAOZ4A5Bxkg1BSiVT7UUAK7SJYLjIgALEMCWi0GY9i7TlEAB6JocSp7YsXEIDIA

The cool part is that you don't have to worry about all the spots where you used an early return to flush the changes to the terminal because the moment you return, the finally block is executed as well.

But yeah, I don't know/think you can create one conditionally because of this try/catch setup 😬

I think it's fine. It's like a few objects and closures being created. The overhead for this is massively dwarfed by everything else. And reporting doesn't happen unless in debug mode either so that code does nothing.

RobinMalfait · 2024-12-05T11:11:04Z

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"))),


When using DEBUG=1 it also shows a lot of oxide related tracing logs. This change only shows them if you are using DEBUG=* or DEBUG=tailwindcss:oxide by following the DEBUG conventions.

RobinMalfait · 2024-12-05T11:11:53Z

packages/@tailwindcss-cli/src/commands/build/index.ts


            // Scan the directory for candidates
-            env.DEBUG && console.time('[@tailwindcss/cli] Scan for candidates')
+            DEBUG && I.start('Scan for candidates')


These are called after the initial I.start('[@tailwincss/cli]'), this allows us to remove the prefix because these logs will be indented.

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

RobinMalfait · 2024-12-05T11:12:58Z

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

+              DEBUG && I.start('Optimization')
+
+              DEBUG && I.start('AST -> CSS')
+              let css = toCss(tailwindCssAst)
+              DEBUG && I.end('AST -> CSS')
+
+              DEBUG && I.start('Lightning CSS')
+              let ast = optimizeCss(css, {
+                minify: typeof optimize === 'object' ? optimize.minify : true,
+              })
+              DEBUG && I.end('Lightning CSS')
+
+              DEBUG && I.start('CSS -> PostCSS AST')
+              context.optimizedPostCssAst = postcss.parse(ast, result.opts)
+              DEBUG && I.end('CSS -> PostCSS AST')
+
+              DEBUG && I.end('Optimization')


Same as before, but split up explicitly

RobinMalfait · 2024-12-05T11:13:18Z

packages/tsconfig.base.json

+    "target": "es2022",
+    "lib": ["es2022", "esnext.disposable", "dom"],


These are needed to compile the new using keyword

CHANGELOG.md

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.

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.

This is only the case for when we are automatically disposing the `Instrumentation`.

This prevents `env.DEBUG` property access over and over again

thecrypticace

yay

We recently introduced some better instrumentation (#15303) which uses the new `using` keyword. I made sure that this was compiled correctly for environments where `using` is not available yet. The issue is that this also relies on `Symbol.dispose` being available. In my testing on our minimal required Node.js version (18) it did work fine. However, turns out that I was using `18.20.x` locally where `Symbol.dispose` **_is_** available, but on older version of Node.js 18 (e.g.: `18.17.x`) it is **_not_** available. This now results in some completely broken builds, e.g.: when running on Cloudflare Pages. See: #15399 I could reproduce this error in CI, by temporarily downgrading the used Node.js version to `18.17.0`. See: <img width="1142" alt="image" src="https://github.com/user-attachments/assets/5bf30f80-9ca0-40d9-ad02-d1ffb4e0e5dd" /> Implementing the proper polyfill, as recommended by the TypeScript docs ( see: https://www.typescriptlang.org/docs/handbook/release-notes/typescript-5-2.html#:~:text=Symbol.dispose,-??=%20Symbol(%22Symbol.dispose ), the error goes away. (If you look at CI after the polyfill, it still fails but for different reasons unrelated to this change) Fixes: #15399 --- ## Test plan 1. I reproduced it in CI, and I kept the commits so that you can take a look where it fails with the `Object not disposable`. 2. Using the provided reproduction from #15399: ### Before It works on Node.js v18.20.x, but switching to Node.js v18.17.x you can see it fail: <img width="1607" alt="image" src="https://github.com/user-attachments/assets/cb6ab73a-8eb2-4003-bab7-b2390f1c879d" /> ### After Using pnpm's overrides, we can apply the fix from this PR and test it in the reproduction. You'll notice that it now works in both Node.js v18.20.x and v18.17.x <img width="1604" alt="image" src="https://github.com/user-attachments/assets/b3a65557-0658-4cb0-a2f9-e3079c7936d5" />

RobinMalfait force-pushed the feat/improve-debug-logs branch from 776e646 to 0430e9d Compare December 4, 2024 23:11

philipp-spiess reviewed Dec 5, 2024

View reviewed changes

packages/@tailwindcss-node/src/instrumentation.test.ts Outdated Show resolved Hide resolved

packages/@tailwindcss-postcss/src/index.ts Outdated Show resolved Hide resolved

RobinMalfait commented Dec 5, 2024

View reviewed changes

RobinMalfait marked this pull request as ready for review December 5, 2024 11:15

RobinMalfait requested a review from a team as a code owner December 5, 2024 11:15

RobinMalfait force-pushed the feat/improve-debug-logs branch from 0049ab7 to ab99449 Compare December 5, 2024 13:22

RobinMalfait commented Dec 6, 2024

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

RobinMalfait changed the title ~~Improve debug logs + small improvements~~ Improve debug logs Dec 9, 2024

RobinMalfait force-pushed the feat/improve-debug-logs branch from 410bb2e to e317a2c Compare December 9, 2024 10:53

RobinMalfait added 16 commits December 9, 2024 12:00

fix missing console.timeEnd(…)

2b08a29

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.

splitup steps, and add a few more timing logs

7076c9b

add used file to the debug logs

1b7c979

only enable oxide logs using DEBUG=tailwindcss:oxide or DEBUG=*

31a5e67

add instrumentation

f6229ca

use custom intstrumentation

562018f

add a few more logs

5e885dc

use custom instrumentation in @tailwindcss/cli

903fc26

implement Instrumentation as a class

b1c02ad

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.

ensure using keyword is being compiled

7c13e79

use new Instrumentation

d458ae1

only report when env.DEBUG is true

94f823e

This is only the case for when we are automatically disposing the `Instrumentation`.

use the Instrumentation in the Vite plugin

9f59085

use shared DEBUG constant

8fd41e5

This prevents `env.DEBUG` property access over and over again

fix import

35a5ee0

update changelog

d9aa08d

RobinMalfait force-pushed the feat/improve-debug-logs branch from e317a2c to d9aa08d Compare December 9, 2024 11:06

RobinMalfait added 4 commits December 9, 2024 13:17

Merge branch 'next' into feat/improve-debug-logs

4e51d0b

add debug logs for the quick bail check

8d683ed

reset after reporting

b2ef631

Merge branch 'next' into feat/improve-debug-logs

3f12e3e

RobinMalfait added 2 commits December 11, 2024 15:06

remove explicit white() calls

8fb7eb3

use process.stderr.write

2f26215

thecrypticace approved these changes Dec 11, 2024

View reviewed changes

RobinMalfait merged commit bcf7099 into next Dec 11, 2024
1 check passed

RobinMalfait deleted the feat/improve-debug-logs branch December 11, 2024 14:27

RobinMalfait mentioned this pull request Dec 16, 2024

Ensure Symbol.dispose and Symbol.asyncDispose are available #15404

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve debug logs #15303

Improve debug logs #15303

RobinMalfait commented Dec 4, 2024 •

edited

Loading

RobinMalfait Dec 5, 2024

philipp-spiess Dec 9, 2024

RobinMalfait Dec 9, 2024

thecrypticace Dec 11, 2024

RobinMalfait Dec 5, 2024

RobinMalfait Dec 5, 2024

RobinMalfait Dec 5, 2024

RobinMalfait Dec 5, 2024

thecrypticace left a comment

		"target": "es2022",
		"lib": ["es2022", "esnext.disposable", "dom"],

Improve debug logs #15303

Improve debug logs #15303

Conversation

RobinMalfait commented Dec 4, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thecrypticace left a comment

Choose a reason for hiding this comment

RobinMalfait commented Dec 4, 2024 •

edited

Loading