Initial tracing implementation #4966

sokra · 2023-05-16T03:32:09Z

Description

adds a raw_trace subscriber that will emit the raw trace events into .turbopack/trace.log (resp. .next/trace.log for next.js)
adds a CLI script which converts the raw trace into a chrome trace json file -> https://ui.perfetto.dev/
adds a TURBOPACK_TRACING (resp. NEXT_TURBOPACK_TRACING) env var to enable tracing
adds some presets e. g. turbopack or next to enable tracing for certain things.
add tracing for invalidations

There are three different visualization modes:

`--single`

Shows all cpu time as it would look like when a single cpu would execute the workload.

(10 concurrent tasks that take 1s are shown as 10 tasks that take 1s with total time of 10s)

Pro:

Concurrency is visualized by bar filling (dark filled bars -> too few concurrency)
It injects pseudo bars with "cpus idle" for low concurrency (with --idle)

Con:

Total time won't be represented correctly, since a single CPU would take longer

Use Case: Gives a good overview of slow tasks in a build.

`--merged`

Shows all cpu time scaled by the concurrency.

(10 concurrent tasks that take 1s are shown as 10 tasks that take 0.1s with total time of 1s)

Pro:

Total time is represented correctly
Low concurrent tasks are bigger
Concurrency is visualized by bar filling (dark filled bars -> too few concurrency)
It injects pseudo bars with "cpus idle" for low concurrency (with --idle)

Con:

Individual tasks time won't be represented correctly.

Use Case: Gives a good overview why a build is slow overall.

`--threads`

Shows cpu time distributed on infinite virtual cpus/threads.

(10 concurrent tasks that take 1s are shown as 10 concurrent tasks that take 1s with total time of 1s)

Pro:

Concurrency is shown via multiple CPU
Most realistic visualization

Con:

Hard to read

vercel · 2023-05-16T03:32:22Z

The latest updates on your projects. Learn more about Vercel for Git ↗︎

Name	Status	Preview	Comments	Updated (UTC)
examples-basic-web	🔄 Building (Inspect)	Visit Preview	💬 Add feedback	May 22, 2023 2:17pm
examples-tailwind-web	🔄 Building (Inspect)	Visit Preview	💬 Add feedback	May 22, 2023 2:17pm
examples-vite-web	🔄 Building (Inspect)	Visit Preview	💬 Add feedback	May 22, 2023 2:17pm

8 Ignored Deployments

Name	Status	Preview	Updated (UTC)
examples-cra-web	⬜️ Ignored (Inspect)	Visit Preview	May 22, 2023 2:17pm
examples-designsystem-docs	⬜️ Ignored (Inspect)	Visit Preview	May 22, 2023 2:17pm
examples-gatsby-web	⬜️ Ignored (Inspect)	Visit Preview	May 22, 2023 2:17pm
examples-kitchensink-blog	⬜️ Ignored (Inspect)	Visit Preview	May 22, 2023 2:17pm
examples-native-web	⬜️ Ignored (Inspect)		May 22, 2023 2:17pm
examples-nonmonorepo	⬜️ Ignored (Inspect)		May 22, 2023 2:17pm
examples-svelte-web	⬜️ Ignored (Inspect)		May 22, 2023 2:17pm
turbo-site	⬜️ Ignored (Inspect)	Visit Preview	May 22, 2023 2:17pm

github-actions · 2023-05-16T03:33:15Z

✅ This change can build next-swc

github-actions · 2023-05-16T03:36:37Z

⚠️ CI failed ⚠️

The following steps have failed in CI:

Turbopack Rust tests (mac/win, non-blocking)

See workflow summary for details

github-actions · 2023-05-16T06:22:39Z

Linux Benchmark for `05f1b16`

Click to view benchmark

Test	Base	PR	%
bench_hmr_to_commit/Turbopack CSR/1000 modules	8767.42µs ± 59.28µs	8785.33µs ± 37.04µs	+0.20%
bench_hmr_to_eval/Turbopack CSR/1000 modules	7907.63µs ± 55.48µs	7927.13µs ± 35.02µs	+0.25%
bench_startup/Turbopack CSR/1000 modules	930.93ms ± 1.78ms	933.80ms ± 5.94ms	+0.31%

github-actions · 2023-05-16T07:12:13Z

MacOS Benchmark for `05f1b16`

Test	Base	PR	%	Significant %
bench_startup/Turbopack CSR/1000 modules	2981.95ms ± 10.48ms	3082.18ms ± 39.10ms	+3.36%	+0.04%

Click to view full benchmark

Test	Base	PR	%	Significant %
bench_hmr_to_commit/Turbopack CSR/1000 modules	26.58ms ± 0.19ms	26.52ms ± 0.20ms	-0.24%
bench_hmr_to_eval/Turbopack CSR/1000 modules	25.70ms ± 0.19ms	25.78ms ± 0.24ms	+0.29%
bench_startup/Turbopack CSR/1000 modules	2981.95ms ± 10.48ms	3082.18ms ± 39.10ms	+3.36%	+0.04%

github-actions · 2023-05-17T09:01:38Z

Linux Benchmark for d510489

Click to view benchmark

Test	Base	PR	%
bench_hmr_to_commit/Turbopack CSR/1000 modules	9385.29µs ± 54.82µs	9267.48µs ± 67.07µs	-1.26%
bench_hmr_to_eval/Turbopack CSR/1000 modules	8329.60µs ± 69.29µs	8787.06µs ± 613.97µs	+5.49%
bench_startup/Turbopack CSR/1000 modules	923.52ms ± 2.33ms	921.17ms ± 3.20ms	-0.25%

github-actions · 2023-05-17T09:48:37Z

MacOS Benchmark for d510489

Test	Base	PR	%	Significant %
bench_hmr_to_commit/Turbopack CSR/1000 modules	52.31ms ± 2.49ms	25.84ms ± 0.30ms	-50.61%	-44.13%

Click to view full benchmark

Test	Base	PR	%	Significant %
bench_hmr_to_commit/Turbopack CSR/1000 modules	52.31ms ± 2.49ms	25.84ms ± 0.30ms	-50.61%	-44.13%
bench_hmr_to_eval/Turbopack CSR/1000 modules	25.60ms ± 0.15ms	26.15ms ± 0.34ms	+2.15%
bench_startup/Turbopack CSR/1000 modules	2620.24ms ± 34.04ms	2625.13ms ± 34.96ms	+0.19%

alexkirsz

Change the level of all spans and events here from Level::Info to Level::Trace.

alexkirsz · 2023-05-17T10:21:34Z

crates/turbo-tasks-macros/src/func.rs

+ turbo_tasks::macro_helpers::tracing::Instrument::instrument(
+ async {
+ let turbo_tasks_result = #original_function(#(#input_arguments),*).await;
+ turbo_tasks::macro_helpers::notify_scheduled_tasks();
+ turbo_tasks_result
+ },
+ turbo_tasks::macro_helpers::tracing::info_span!(#name_code)
+ ).await


Can we expose a turbo tasks API for this instead of doing this in the macro itself? We should strive to keep the macro output minimal.

e.g. turbo_tasks::macro_helpers::instrument!(#name_code, #original_function(#(#input_arguments),*))

crates/turbo-tasks-macros/src/func.rs

crates/turbo-tasks-memory/src/memory_backend.rs

crates/turbopack-cli-utils/src/raw_trace.rs

crates/turbopack-cli-utils/src/tracing.rs

crates/turbopack-convert-trace/src/main.rs

crates/turbopack-node/src/source_map/mod.rs

github-actions · 2023-05-17T15:16:44Z

Linux Benchmark for `8d89006`

Click to view benchmark

Test	Base	PR	%
bench_hmr_to_commit/Turbopack CSR/1000 modules	8839.20µs ± 39.84µs	8842.99µs ± 23.71µs	+0.04%
bench_hmr_to_eval/Turbopack CSR/1000 modules	7805.89µs ± 55.21µs	7937.47µs ± 227.94µs	+1.69%
bench_startup/Turbopack CSR/1000 modules	887.39ms ± 1.78ms	891.75ms ± 3.59ms	+0.49%

crates/turbopack-cli/src/main.rs

github-actions · 2023-05-22T14:39:59Z

Linux Benchmark for 53a3b34

Click to view benchmark

Test	Base	PR	%
bench_hmr_to_commit/Turbopack CSR/1000 modules	8310.34µs ± 42.10µs	8231.38µs ± 75.45µs	-0.95%
bench_hmr_to_eval/Turbopack CSR/1000 modules	7413.13µs ± 33.32µs	7462.04µs ± 173.39µs	+0.66%
bench_startup/Turbopack CSR/1000 modules	876.29ms ± 0.53ms	874.75ms ± 3.11ms	-0.18%

github-actions · 2023-05-22T15:42:03Z

MacOS Benchmark for 53a3b34

Test	Base	PR	%	Significant %
bench_hmr_to_commit/Turbopack CSR/1000 modules	24.53ms ± 0.75ms	56.57ms ± 2.77ms	+130.57%	+95.98%

Click to view full benchmark

Test	Base	PR	%	Significant %
bench_hmr_to_commit/Turbopack CSR/1000 modules	24.53ms ± 0.75ms	56.57ms ± 2.77ms	+130.57%	+95.98%
bench_hmr_to_eval/Turbopack CSR/1000 modules	25.82ms ± 0.33ms	26.27ms ± 0.21ms	+1.75%
bench_startup/Turbopack CSR/1000 modules	2925.11ms ± 100.59ms	2755.90ms ± 43.19ms	-5.78%

### What? adds `NEXT_TURBOPACK_TRACING` env var to enable tracing. Writes into `.next/trace.log` There are 4 presets: * `NEXT_TURBOPACK_TRACING=overview` gives a overview of requests and modules processed. * `NEXT_TURBOPACK_TRACING=next` above plus details for next.js * `NEXT_TURBOPACK_TRACING=turbopack` above plus details for turbopack * `NEXT_TURBOPACK_TRACING=turbo-tasks` above plus details for turbo-tasks Published release builds will only allow `overview` to work, since all detailed instrumentation is statically disabled. see vercel/turborepo#4966 for more details ### Why? get more insight into build times ### Turbopack changes * vercel/turborepo#4995 * vercel/turborepo#5049 * vercel/turborepo#5053 * vercel/turborepo#4966

### Description * adds a raw_trace subscriber that will emit the raw trace events into `.turbopack/trace.log` (resp. `.next/trace.log` for next.js) * adds a CLI script which converts the raw trace into a chrome trace json file -> https://ui.perfetto.dev/ * adds a `TURBOPACK_TRACING` (resp. `NEXT_TURBOPACK_TRACING`) env var to enable tracing * adds some presets e. g. `turbopack` or `next` to enable tracing for certain things. * add tracing for invalidations There are three different visualization modes: #### `--single` Shows all cpu time as it would look like when a single cpu would execute the workload. (10 concurrent tasks that take 1s are shown as 10 tasks that take 1s with total time of 10s) Pro: * Concurrency is visualized by bar filling (dark filled bars -> too few concurrency) * It injects pseudo bars with "cpus idle" for low concurrency (with `--idle`) Con: * Total time won't be represented correctly, since a single CPU would take longer Use Case: Gives a good overview of slow tasks in a build. #### `--merged` Shows all cpu time scaled by the concurrency. (10 concurrent tasks that take 1s are shown as 10 tasks that take 0.1s with total time of 1s) Pro: * Total time is represented correctly * Low concurrent tasks are bigger * Concurrency is visualized by bar filling (dark filled bars -> too few concurrency) * It injects pseudo bars with "cpus idle" for low concurrency (with `--idle`) Con: * Individual tasks time won't be represented correctly. Use Case: Gives a good overview why a build is slow overall. #### `--threads` Shows cpu time distributed on infinite virtual cpus/threads. (10 concurrent tasks that take 1s are shown as 10 concurrent tasks that take 1s with total time of 1s) Pro: * Concurrency is shown via multiple CPU * Most realistic visualization Con: * Hard to read

turbo-orchestrator bot added team: turbopack labels May 16, 2023

sokra force-pushed the sokra/tracing branch from b466390 to 665af9e Compare May 16, 2023 04:48

vercel bot deployed to Preview – turbo-site May 16, 2023 04:50 View deployment

sokra force-pushed the sokra/tracing branch from 665af9e to 919ba47 Compare May 16, 2023 05:58

sokra force-pushed the sokra/tracing branch from b284856 to 70f2861 Compare May 17, 2023 07:28

vercel bot deployed to Preview – turbo-site May 17, 2023 07:29 View deployment

sokra marked this pull request as ready for review May 17, 2023 09:03

sokra requested review from a team as code owners May 17, 2023 09:03

sokra requested review from mehulkar and arlyon May 17, 2023 09:03

sokra mentioned this pull request May 17, 2023

add tracing for turbopack vercel/next.js#49920

Merged

alexkirsz suggested changes May 17, 2023

View reviewed changes

ForsakenHarmony reviewed May 17, 2023

View reviewed changes

crates/turbopack-node/src/source_map/mod.rs Outdated Show resolved Hide resolved

sokra force-pushed the sokra/tracing branch from 6dd44f1 to f193afb Compare May 17, 2023 14:53

sokra requested review from alexkirsz and ForsakenHarmony May 17, 2023 14:56

ForsakenHarmony reviewed May 17, 2023

View reviewed changes

crates/turbopack-cli/src/main.rs Outdated Show resolved Hide resolved

mehulkar removed their request for review May 19, 2023 03:04

sokra force-pushed the sokra/tracing branch from 3c28306 to ffad3c4 Compare May 19, 2023 18:02

vercel bot deployed to Preview – turbo-site May 19, 2023 18:03 View deployment

sokra added 20 commits May 22, 2023 12:50

improve handling of spans from events

ffdd510

optimize

d2dfba6

review

6bfcda0

avoid crashing when writer is closing or closed

75440c4

use postcard for serialization

fe36bf3

use really non-blocking trace writer

3d79b4d

update to conver-trace for changed format

1a7812c

buffer writes

c8efce6

move span from control flow to visit trait

a38c93f

use static lists for presets for readablility

e5adb64

instrument chunk item code generation

a852033

update lockfile

5c4e2a2

update turbopack-cli with new writer

44b245b

remove tracing-appender

751e567

remove typo

3b2765d

review

c401cef

review

9a01c35

deduplicate tracing presets

ce0c7cc

lint

6a501d4

update lockfile

79386f4

sokra force-pushed the sokra/tracing branch from d934146 to 79386f4 Compare May 22, 2023 14:16

sokra merged commit cee02be into main May 22, 2023

sokra deleted the sokra/tracing branch May 22, 2023 15:39

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Initial tracing implementation #4966

Initial tracing implementation #4966

sokra commented May 16, 2023 •

edited

Loading

vercel bot commented May 16, 2023 •

edited

Loading

github-actions bot commented May 16, 2023

github-actions bot commented May 16, 2023 •

edited

Loading

github-actions bot commented May 16, 2023

github-actions bot commented May 16, 2023

github-actions bot commented May 17, 2023

github-actions bot commented May 17, 2023

alexkirsz left a comment

alexkirsz May 17, 2023

github-actions bot commented May 17, 2023

github-actions bot commented May 22, 2023

github-actions bot commented May 22, 2023

Initial tracing implementation #4966

Initial tracing implementation #4966

Conversation

sokra commented May 16, 2023 • edited Loading

Description

--single

--merged

--threads

vercel bot commented May 16, 2023 • edited Loading

github-actions bot commented May 16, 2023

github-actions bot commented May 16, 2023 • edited Loading

⚠️ CI failed ⚠️

github-actions bot commented May 16, 2023

Linux Benchmark for 05f1b16

github-actions bot commented May 16, 2023

MacOS Benchmark for 05f1b16

github-actions bot commented May 17, 2023

Linux Benchmark for d510489

github-actions bot commented May 17, 2023

MacOS Benchmark for d510489

alexkirsz left a comment

Choose a reason for hiding this comment

alexkirsz May 17, 2023

Choose a reason for hiding this comment

github-actions bot commented May 17, 2023

Linux Benchmark for 8d89006

github-actions bot commented May 22, 2023

Linux Benchmark for 53a3b34

github-actions bot commented May 22, 2023

MacOS Benchmark for 53a3b34

sokra commented May 16, 2023 •

edited

Loading

`--single`

`--merged`

`--threads`

vercel bot commented May 16, 2023 •

edited

Loading

github-actions bot commented May 16, 2023 •

edited

Loading

Linux Benchmark for `05f1b16`

MacOS Benchmark for `05f1b16`

Linux Benchmark for `8d89006`