diff --git a/src/install/PackageManager/PackageManagerLifecycle.rs b/src/install/PackageManager/PackageManagerLifecycle.rs index 730d18f94fa4..561a8daf9ceb 100644 --- a/src/install/PackageManager/PackageManagerLifecycle.rs +++ b/src/install/PackageManager/PackageManagerLifecycle.rs @@ -34,7 +34,12 @@ pub struct LifecycleScriptTimeLog { list: Vec, } -pub struct LifecycleScriptTimeLogEntry {} +pub struct LifecycleScriptTimeLogEntry { + pub(crate) package_name: Box<[u8]>, + pub(crate) script_id: u8, + /// nanoseconds + pub(crate) duration: u64, +} impl LifecycleScriptTimeLog { pub(crate) fn append_concurrent(&mut self, entry: LifecycleScriptTimeLogEntry) { @@ -42,6 +47,28 @@ impl LifecycleScriptTimeLog { self.list.push(entry); self.mutex.unlock(); } + + pub(crate) fn print_and_clear(&mut self) { + #[cfg(debug_assertions)] + { + assert!( + self.mutex.try_lock(), + "LifecycleScriptTimeLog.print is not intended to be thread-safe" + ); + self.mutex.unlock(); + } + + if let Some(longest) = self.list.iter().max_by_key(|e| e.duration) { + bun_core::warn!( + "{}'s {} script took {}", + BStr::new(&longest.package_name), + lockfile::Scripts::NAMES[longest.script_id as usize], + bun_fmt::fmt_duration_one_decimal(longest.duration), + ); + Output::flush(); + } + self.list.clear(); + } } impl PackageManager { diff --git a/src/install/PackageManager/install_with_manager.rs b/src/install/PackageManager/install_with_manager.rs index a06d651a152c..06b82376bf1c 100644 --- a/src/install/PackageManager/install_with_manager.rs +++ b/src/install/PackageManager/install_with_manager.rs @@ -1034,6 +1034,8 @@ fn print_install_summary( if this.options.do_.summary() { print_summary_tree(this, install_summary, log_level)?; + this.lifecycle_script_time_log.print_and_clear(); + if !did_meta_hash_change { this.summary.remove = 0; this.summary.add = 0; diff --git a/src/install/lifecycle_script_runner.rs b/src/install/lifecycle_script_runner.rs index c323f1bb12fa..ccb57a767d9b 100644 --- a/src/install/lifecycle_script_runner.rs +++ b/src/install/lifecycle_script_runner.rs @@ -676,6 +676,7 @@ impl<'a> LifecycleScriptSubprocess<'a> { (*this).remaining_fds = 0; (*this).started_at = bun_core::Timespec::now(bun_core::TimespecMockMode::AllowMockedTime).ns(); + (*this).timer = Some(Timer::start()); // Store the allocation-rooted `this` in the intrusive heap — not a `&mut self` // reborrow, whose SB tag would be invalidated by the field accesses below. (*manager) @@ -909,14 +910,20 @@ impl<'a> LifecycleScriptSubprocess<'a> { } } - if let Some(nanos) = maybe_duration { - if nanos > MIN_MILLISECONDS_TO_LOG * bun_core::time::NS_PER_MS { - let entry = LifecycleScriptTimeLogEntry {}; - // SAFETY: see [`Self::manager_mut`]. - unsafe { self.manager_mut() } - .lifecycle_script_time_log - .append_concurrent(entry); - } + // Foreground (root-package) scripts were already echoed live; warn only for background deps. + if !self.foreground + && let Some(nanos) = maybe_duration + && nanos > MIN_MILLISECONDS_TO_LOG * bun_core::time::NS_PER_MS + { + let entry = LifecycleScriptTimeLogEntry { + package_name: self.package_name.clone(), + script_id: self.current_script_index, + duration: nanos, + }; + // SAFETY: see [`Self::manager_mut`]. + unsafe { self.manager_mut() } + .lifecycle_script_time_log + .append_concurrent(entry); } if let Some(ctx) = &self.ctx { diff --git a/test/cli/install/bun-install-lifecycle-scripts.test.ts b/test/cli/install/bun-install-lifecycle-scripts.test.ts index 8123acc24bdf..f01e5274e736 100644 --- a/test/cli/install/bun-install-lifecycle-scripts.test.ts +++ b/test/cli/install/bun-install-lifecycle-scripts.test.ts @@ -2135,6 +2135,50 @@ for (const forceWaiterThread of isLinux ? [false, true] : [false]) { return dependenciesList; } + test("slow lifecycle script prints a warning", async () => { + using ctx = await setupTest(); + const { packageDir, packageJson, env } = ctx; + const testEnv = forceWaiterThread ? { ...env, BUN_FEATURE_FLAG_FORCE_WAITER_THREAD: "1" } : env; + + await mkdir(join(packageDir, "slow-pkg")); + await writeFile( + join(packageDir, "slow-pkg", "package.json"), + JSON.stringify({ + name: "slow-pkg", + version: "1.0.0", + scripts: { + postinstall: `${bunExe()} -e 'Bun.sleepSync(750)'`, + }, + }), + ); + await writeFile( + packageJson, + JSON.stringify({ + name: "foo", + version: "1.0.0", + dependencies: { + "slow-pkg": "file:./slow-pkg", + }, + trustedDependencies: ["slow-pkg"], + }), + ); + + const { stdout, stderr, exited } = spawn({ + cmd: [bunExe(), "install"], + cwd: packageDir, + stdout: "pipe", + stdin: "ignore", + stderr: "pipe", + env: testEnv, + }); + + const [err, out, exitCode] = await Promise.all([stderr.text(), stdout.text(), exited]); + expect(err).not.toContain("error:"); + expect(err).toMatch(/warn: slow-pkg's postinstall script took \d/); + expect(out).toContain("1 package installed"); + expect(exitCode).toBe(0); + }); + test("reach max concurrent scripts", async () => { using ctx = await setupTest(); const { packageDir, packageJson, env } = ctx; diff --git a/test/harness.ts b/test/harness.ts index 9ee228e80515..3e9a27aaf8aa 100644 --- a/test/harness.ts +++ b/test/harness.ts @@ -1511,9 +1511,10 @@ export async function runBunInstall( return { out, err, exited }; } -// stderr with `slow filesystem` warning removed +// stderr with timing-dependent warnings removed (debug/ASAN builds can push any +// lifecycle script over the 500ms slow-script threshold) export function stderrForInstall(err: string) { - return err.replace(/warn: Slow filesystem.*/g, ""); + return err.replace(/warn: Slow filesystem.*/g, "").replace(/warn: .*'s \S+ script took .*\n?\n?/g, ""); } export async function runBunUpdate(