Skip to content
Open
Show file tree
Hide file tree
Changes from 2 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
32 changes: 31 additions & 1 deletion src/install/PackageManager/PackageManagerLifecycle.rs
Original file line number Diff line number Diff line change
Expand Up @@ -34,14 +34,44 @@
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();
}

/// Print the single slowest entry as a warning. Safe to call when no
/// entries were recorded.
Comment thread
robobun marked this conversation as resolved.
Outdated
pub(crate) fn print(&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) {
// extra \n prints a blank line after this one
bun_core::warn!(
"{}'s {} script took {}\n",
BStr::new(&longest.package_name),
lockfile::Scripts::NAMES[longest.script_id as usize],
bun_fmt::fmt_duration_one_decimal(longest.duration),
);

Check warning on line 70 in src/install/PackageManager/PackageManagerLifecycle.rs

View check run for this annotation

Claude / Claude Code Review

Trailing \n in warn! does not produce the intended blank line

The comment says "extra \\n prints a blank line after this one", but `bun_core::warn!` expands to `pretty_errorln!`, whose `_needs_nl()` helper returns `""` when the format string already ends in `\n` (the `ln_macros_suppress_double_newline` unit test in output.rs pins this exact case). So exactly one newline is emitted and the intended blank-line separator before "N packages installed" doesn't appear. Either drop the trailing `\n` and the misleading comment (matching the sibling `report_slow_li
Comment thread
robobun marked this conversation as resolved.
Outdated
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();

if !did_meta_hash_change {
this.summary.remove = 0;
this.summary.add = 0;
Expand Down
7 changes: 6 additions & 1 deletion 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 @@ -911,7 +912,11 @@ 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 {};
let entry = LifecycleScriptTimeLogEntry {
package_name: self.package_name.clone(),
script_id: self.current_script_index,
duration: nanos,
};
Comment thread
coderabbitai[bot] marked this conversation as resolved.
Outdated
// SAFETY: see [`Self::manager_mut`].
unsafe { self.manager_mut() }
.lifecycle_script_time_log
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