Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Initial tracing implementation #4966

Merged
merged 50 commits into from
May 22, 2023
Merged

Initial tracing implementation #4966

merged 50 commits into from
May 22, 2023

Conversation

sokra
Copy link
Member

@sokra sokra commented May 16, 2023

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
Copy link

vercel bot commented May 16, 2023

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 Comments 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
Copy link
Contributor

✅ This change can build next-swc

@github-actions
Copy link
Contributor

github-actions bot commented May 16, 2023

⚠️ CI failed ⚠️

The following steps have failed in CI:

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

See workflow summary for details

@github-actions
Copy link
Contributor

Linux Benchmark for 05f1b16

Click to view benchmark
Test Base PR % Significant %
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
Copy link
Contributor

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
Copy link
Contributor

Linux Benchmark for d510489

Click to view benchmark
Test Base PR % Significant %
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%

@sokra sokra marked this pull request as ready for review May 17, 2023 09:03
@sokra sokra requested review from a team as code owners May 17, 2023 09:03
@sokra sokra requested review from mehulkar and arlyon May 17, 2023 09:03
@github-actions
Copy link
Contributor

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%

Copy link
Contributor

@alexkirsz alexkirsz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Comment on lines 158 to 165
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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 Outdated Show resolved Hide resolved
crates/turbo-tasks-memory/src/memory_backend.rs Outdated Show resolved Hide resolved
crates/turbo-tasks-memory/src/memory_backend.rs Outdated Show resolved Hide resolved
crates/turbopack-cli-utils/src/raw_trace.rs Outdated Show resolved Hide resolved
crates/turbopack-cli-utils/src/raw_trace.rs Show resolved Hide resolved
crates/turbopack-cli-utils/src/raw_trace.rs Show resolved Hide resolved
crates/turbopack-cli-utils/src/tracing.rs Outdated Show resolved Hide resolved
crates/turbopack-convert-trace/src/main.rs Outdated Show resolved Hide resolved
@github-actions
Copy link
Contributor

Linux Benchmark for 8d89006

Click to view benchmark
Test Base PR % Significant %
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%

@github-actions
Copy link
Contributor

Linux Benchmark for 53a3b34

Click to view benchmark
Test Base PR % Significant %
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%

@sokra sokra merged commit cee02be into main May 22, 2023
@sokra sokra deleted the sokra/tracing branch May 22, 2023 15:39
@github-actions
Copy link
Contributor

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%

kodiakhq bot pushed a commit to vercel/next.js that referenced this pull request May 23, 2023
### 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
hydRAnger pushed a commit to hydRAnger/next.js that referenced this pull request Jun 12, 2023
### 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
ForsakenHarmony pushed a commit to vercel/next.js that referenced this pull request Jul 25, 2024
### 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
ForsakenHarmony pushed a commit to vercel/next.js that referenced this pull request Jul 29, 2024
### 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
ForsakenHarmony pushed a commit to vercel/next.js that referenced this pull request Aug 1, 2024
### 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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants