feat(turbopack): Attempt to detect and warn about slow file IO (#66057)

We'd like to warn users if they have particularly slow file IO, so that they can correct the problem themselves, and don't send us reports of poor performance.

- Feature request: https://vercel.slack.com/archives/C03KAR5DCKC/p1716051650641529
- Tweet about how Bun does this: https://x.com/jarredsumner/status/1637549427677364224
- Bun implementation: 06a9aa80c3/src/install/install.zig (L3038)

**Why 100ms?** Bun used to use 10ms, found it too noisy, and switched to 100ms.

This benchmark should run non-blocking in the background and should not meaningfully slow down server startup (even on slow disks).

## Simulated Testing

I looked around and found https://github.com/schoentoon/slowpokefs/. It hasn't been updated in 10 years, but still seems to build fine.

In a nextjs project directory, turn `.next` into an artifically slow mount point:

```
fusermount -uz .next; rm -rf .next .next.real && mkdir .next .next.real && ~/slowpokefs/slowpokefs -m 50 -M 50 --no-slow-read -F .next.real .next
```

<img width="695" alt="Screenshot 2024-05-21 at 4 14 58 PM" src="https://github.com/vercel/next.js/assets/180404/217d7692-33cf-42b7-bbf7-5a530b9e0df1">

Run `pnpm dev --turbo` and see that the warning is generated.

## "Real World" Testing

The following tests are from a linux VM using virtiofs to connect to a 5400 RPM USB 2.0 HDD with APFS:

Only the .next is on an HDD (bind mount):
Otherwise idle disk: `4.86ms 4.44ms 5.31ms`
Otherwise busy disk (copying files): `69.34ms 53.75ms 25.12ms`

The whole project directory is on the HDD (more realistic):
Otherwise idle disk: `20.29ms 35.61ms 48.12ms`
Otherwise busy disk (copying files): `131.40ms 21.71ms 87.33ms`

Most of the time the threshold was not reached, but the 131.40ms test did trigger the warning!

Fixes PACK-3087
This commit is contained in:
Benjamin Woodruff 2024-05-23 09:52:33 -07:00 committed by GitHub
parent e62bc11358
commit 5017a41c75
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
3 changed files with 74 additions and 5 deletions

1
Cargo.lock generated
View file

@ -3082,6 +3082,7 @@ dependencies = [
"next-build",
"next-core",
"next-custom-transforms",
"rand",
"serde",
"serde_json",
"shadow-rs",

View file

@ -85,6 +85,7 @@ napi = { version = "2", default-features = false, features = [
] }
napi-derive = "2"
next-custom-transforms = { workspace = true }
rand = { workspace = true }
serde = "1"
serde_json = "1"
shadow-rs = { workspace = true }

View file

@ -18,14 +18,14 @@ use next_core::tracing_presets::{
TRACING_NEXT_OVERVIEW_TARGETS, TRACING_NEXT_TARGETS, TRACING_NEXT_TURBOPACK_TARGETS,
TRACING_NEXT_TURBO_TASKS_TARGETS,
};
use rand::Rng;
use tokio::{io::AsyncWriteExt, time::Instant};
use tracing::Instrument;
use tracing_subscriber::{
prelude::__tracing_subscriber_SubscriberExt, util::SubscriberInitExt, EnvFilter, Registry,
};
use turbo_tasks::{ReadRef, TransientInstance, TurboTasks, UpdateInfo, Vc};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Registry};
use turbo_tasks::{Completion, ReadRef, TransientInstance, TurboTasks, UpdateInfo, Vc};
use turbopack_binding::{
turbo::{
tasks_fs::{FileContent, FileSystem},
tasks_fs::{DiskFileSystem, FileContent, FileSystem, FileSystemPath},
tasks_memory::MemoryBackend,
},
turbopack::{
@ -56,6 +56,10 @@ use super::{
};
use crate::register;
/// Used by [`benchmark_file_io`]. This is a noisy benchmark, so set the
/// threshold high.
const SLOW_FILESYSTEM_THRESHOLD: Duration = Duration::from_millis(100);
#[napi(object)]
#[derive(Clone, Debug)]
pub struct NapiEnvVar {
@ -328,6 +332,12 @@ pub async fn project_new(
})
.await
.map_err(|e| napi::Error::from_reason(PrettyPrintError(&e).to_string()))?;
turbo_tasks.spawn_once_task(async move {
benchmark_file_io(container.project().node_root())
.await
.inspect_err(|err| tracing::warn!(%err, "failed to benchmark file IO"))
});
Ok(External::new_with_size_hint(
ProjectInstance {
turbo_tasks,
@ -338,6 +348,63 @@ pub async fn project_new(
))
}
/// A very simple and low-overhead, but potentially noisy benchmark to detect
/// very slow disk IO. Warns the user (via `println!`) if the benchmark takes
/// more than `SLOW_FILESYSTEM_THRESHOLD`.
///
/// This idea is copied from Bun:
/// - https://x.com/jarredsumner/status/1637549427677364224
/// - https://github.com/oven-sh/bun/blob/06a9aa80c38b08b3148bfeabe560/src/install/install.zig#L3038
#[tracing::instrument]
async fn benchmark_file_io(directory: Vc<FileSystemPath>) -> Result<Vc<Completion>> {
let temp_path = directory.join(format!(
"tmp_file_io_benchmark_{:x}",
rand::random::<u128>()
));
// try to get the real file path on disk so that we can use it with tokio
let fs = Vc::try_resolve_downcast_type::<DiskFileSystem>(directory.fs())
.await?
.context(anyhow!(
"expected node_root to be a DiskFileSystem, cannot benchmark"
))?
.await?;
let temp_path = fs.to_sys_path(temp_path).await?;
let mut random_buffer = [0u8; 512];
rand::thread_rng().fill(&mut random_buffer[..]);
// perform IO directly with tokio (skipping `tokio_tasks_fs`) to avoid the
// additional noise/overhead of tasks caching, invalidation, file locks,
// etc.
let start = Instant::now();
async move {
for _ in 0..3 {
// create a new empty file
let mut file = tokio::fs::File::create(&temp_path).await?;
file.write_all(&random_buffer).await?;
file.sync_all().await?;
drop(file);
// remove the file
tokio::fs::remove_file(&temp_path).await?;
}
anyhow::Ok(())
}
.instrument(tracing::info_span!("benchmark file IO (measurement)"))
.await?;
if Instant::now().duration_since(start) > SLOW_FILESYSTEM_THRESHOLD {
println!(
"Slow filesystem detected. If {} is a network drive, consider moving it to a local \
folder. If you have an antivirus enabled, consider excluding your project directory.",
fs.to_sys_path(directory).await?.to_string_lossy(),
);
}
Ok(Completion::new())
}
#[napi(ts_return_type = "{ __napiType: \"Project\" }")]
pub async fn project_update(
#[napi(ts_arg_type = "{ __napiType: \"Project\" }")] project: External<ProjectInstance>,