Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
29 changes: 28 additions & 1 deletion src/install/PackageManager/PackageManagerLifecycle.rs
Original file line number Diff line number Diff line change
Expand Up @@ -34,14 +34,41 @@ pub struct LifecycleScriptTimeLog {
list: Vec<LifecycleScriptTimeLogEntry>,
}

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) {
self.mutex.lock();
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 {
Expand Down
2 changes: 2 additions & 0 deletions src/install/PackageManager/install_with_manager.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
23 changes: 15 additions & 8 deletions src/install/lifecycle_script_runner.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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 {
Expand Down
44 changes: 44 additions & 0 deletions test/cli/install/bun-install-lifecycle-scripts.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Comment thread
coderabbitai[bot] marked this conversation as resolved.
});

test("reach max concurrent scripts", async () => {
using ctx = await setupTest();
const { packageDir, packageJson, env } = ctx;
Expand Down
5 changes: 3 additions & 2 deletions test/harness.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand Down
Loading