Skip to content

Commit

Permalink
Log slow lifecycle scripts
Browse files Browse the repository at this point in the history
  • Loading branch information
@Jarred-Sumner
Jarred-Sumner committed Dec 28, 2024
1 parent 7b06872 commit ee31a53
Show file tree
Hide file tree
Showing 3 changed files with 92 additions and 14 deletions.
7 changes: 7 additions & 0 deletions src/bun.js/event_loop.zig
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2051,6 +2051,13 @@ pub const AnyEventLoop = union(enum) {

pub const Task = AnyTaskWithExtraContext;

pub fn iterationNumber(this: *const AnyEventLoop) u64 {
return switch (this.*) {
.js => this.js.usocketsLoop().iterationNumber(),
.mini => this.mini.loop.iterationNumber(),
};
}

pub fn wakeup(this: *AnyEventLoop) void {
this.loop().wakeup();
}
Expand Down
68 changes: 54 additions & 14 deletions src/install/install.zig
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2757,6 +2757,44 @@ pub const PackageManager = struct {

patched_dependencies_to_remove: std.ArrayHashMapUnmanaged(PackageNameAndVersionHash, void, ArrayIdentityContext.U64, false) = .{},

active_lifecycle_scripts: LifecycleScriptSubprocess.List,
last_reported_slow_lifecycle_script_at: u64 = 0,
cached_tick_for_slow_lifecycle_script_logging: u64 = 0,

pub fn reportSlowLifecycleScripts(this: *PackageManager, log_level: Options.LogLevel) void {
if (log_level == .silent) return;
if (bun.getRuntimeFeatureFlag("BUN_DISABLE_SLOW_LIFECYCLE_SCRIPT_LOGGING")) {
return;
}

if (this.active_lifecycle_scripts.peek()) |active_lifecycle_script_running_for_the_longest_amount_of_time| {
if (this.cached_tick_for_slow_lifecycle_script_logging == this.event_loop.iterationNumber()) {
return;
}
this.cached_tick_for_slow_lifecycle_script_logging = this.event_loop.iterationNumber();
const current_time = bun.timespec.now().ns();
const time_running = current_time -| active_lifecycle_script_running_for_the_longest_amount_of_time.started_at;
const interval: u64 = if (log_level.isVerbose()) std.time.ns_per_s * 5 else std.time.ns_per_s * 30;
if (time_running > interval and current_time -| this.last_reported_slow_lifecycle_script_at > interval) {
this.last_reported_slow_lifecycle_script_at = current_time;
const package_name = active_lifecycle_script_running_for_the_longest_amount_of_time.package_name;

if (!(package_name.len > 1 and package_name[package_name.len - 1] == 's')) {
Output.warn("{s}'s postinstall has costed you {}\n", .{
package_name,
bun.fmt.fmtDurationOneDecimal(time_running),
});
} else {
Output.warn("{s}' postinstall has costed you {}\n", .{
package_name,
bun.fmt.fmtDurationOneDecimal(time_running),
});
}
Output.flush();
}
}
}

pub const PackageUpdateInfo = struct {
original_version_literal: string,
is_alias: bool,
Expand Down Expand Up @@ -3116,6 +3154,7 @@ pub const PackageManager = struct {
}

fn hasNoMorePendingLifecycleScripts(this: *PackageManager) bool {
this.reportSlowLifecycleScripts(this.options.log_level);
return this.pending_lifecycle_script_tasks.load(.monotonic) == 0;
}

Expand All @@ -3129,6 +3168,7 @@ pub const PackageManager = struct {
}

pub fn sleep(this: *PackageManager) void {
this.reportSlowLifecycleScripts(this.options.log_level);
Output.flush();
this.event_loop.tick(this, hasNoMorePendingLifecycleScripts);
}
Expand Down Expand Up @@ -8789,6 +8829,9 @@ pub const PackageManager = struct {
// var node = progress.start(name: []const u8, estimated_total_items: usize)
manager.* = PackageManager{
.options = options,
.active_lifecycle_scripts = .{
.context = manager,
},
.network_task_fifo = NetworkQueue.init(),
.patch_task_fifo = PatchTaskFifo.init(),
.allocator = ctx.allocator,
Expand Down Expand Up @@ -8955,6 +8998,9 @@ pub const PackageManager = struct {
.options = .{
.max_concurrent_lifecycle_scripts = cli.concurrent_scripts orelse cpu_count * 2,
},
.active_lifecycle_scripts = .{
.context = manager,
},
.network_task_fifo = NetworkQueue.init(),
.allocator = allocator,
.log = log,
Expand Down Expand Up @@ -12574,10 +12620,6 @@ pub const PackageManager = struct {
for (this.pending_lifecycle_scripts.items) |entry| {
const package_name = entry.list.package_name;
while (LifecycleScriptSubprocess.alive_count.load(.monotonic) >= this.manager.options.max_concurrent_lifecycle_scripts) {
if (PackageManager.verbose_install) {
if (PackageManager.hasEnoughTimePassedBetweenWaitingMessages()) Output.prettyErrorln("<d>[PackageManager]<r> waiting for {d} scripts\n", .{LifecycleScriptSubprocess.alive_count.load(.monotonic)});
}

this.manager.sleep();
}

Expand Down Expand Up @@ -12609,9 +12651,7 @@ pub const PackageManager = struct {
}

while (this.manager.pending_lifecycle_script_tasks.load(.monotonic) > 0) {
if (PackageManager.verbose_install) {
if (PackageManager.hasEnoughTimePassedBetweenWaitingMessages()) Output.prettyErrorln("<d>[PackageManager]<r> waiting for {d} scripts\n", .{LifecycleScriptSubprocess.alive_count.load(.monotonic)});
}
this.manager.reportSlowLifecycleScripts(log_level);

if (comptime log_level.showProgress()) {
if (this.manager.scripts_node) |scripts_node| {
Expand Down Expand Up @@ -14003,8 +14043,8 @@ pub const PackageManager = struct {
);
if (!installer.options.do.install_packages) return error.InstallFailed;
}

this.tickLifecycleScripts();
this.reportSlowLifecycleScripts(log_level);
}

for (remaining) |dependency_id| {
Expand All @@ -14027,6 +14067,7 @@ pub const PackageManager = struct {
if (!installer.options.do.install_packages) return error.InstallFailed;

this.tickLifecycleScripts();
this.reportSlowLifecycleScripts(log_level);
}

while (this.pendingTaskCount() > 0 and installer.options.do.install_packages) {
Expand Down Expand Up @@ -14056,6 +14097,8 @@ pub const PackageManager = struct {
return true;
}

closure.manager.reportSlowLifecycleScripts(log_level);

if (PackageManager.verbose_install and closure.manager.pendingTaskCount() > 0) {
const pending_task_count = closure.manager.pendingTaskCount();
if (pending_task_count > 0 and PackageManager.hasEnoughTimePassedBetweenWaitingMessages()) {
Expand All @@ -14082,6 +14125,7 @@ pub const PackageManager = struct {
}
} else {
this.tickLifecycleScripts();
this.reportSlowLifecycleScripts(log_level);
}

for (installer.trees) |tree| {
Expand All @@ -14107,9 +14151,7 @@ pub const PackageManager = struct {
installer.completeRemainingScripts(log_level);

while (this.pending_lifecycle_script_tasks.load(.monotonic) > 0) {
if (PackageManager.verbose_install) {
if (PackageManager.hasEnoughTimePassedBetweenWaitingMessages()) Output.prettyErrorln("<d>[PackageManager]<r> waiting for {d} scripts\n", .{this.pending_lifecycle_script_tasks.load(.monotonic)});
}
this.reportSlowLifecycleScripts(log_level);

this.sleep();
}
Expand Down Expand Up @@ -14972,9 +15014,7 @@ pub const PackageManager = struct {
try manager.spawnPackageLifecycleScripts(ctx, scripts, optional, log_level, output_in_foreground);

while (manager.pending_lifecycle_script_tasks.load(.monotonic) > 0) {
if (PackageManager.verbose_install) {
if (PackageManager.hasEnoughTimePassedBetweenWaitingMessages()) Output.prettyErrorln("<d>[PackageManager]<r> waiting for {d} scripts\n", .{manager.pending_lifecycle_script_tasks.load(.monotonic)});
}
manager.reportSlowLifecycleScripts(log_level);

manager.sleep();
}
Expand Down
31 changes: 31 additions & 0 deletions src/install/lifecycle_script_runner.zig
View file
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,15 @@ pub const LifecycleScriptSubprocess = struct {

foreground: bool = false,
optional: bool = false,
started_at: u64 = 0,

heap: bun.io.heap.IntrusiveField(LifecycleScriptSubprocess) = .{},

pub const List = bun.io.heap.Intrusive(LifecycleScriptSubprocess, *PackageManager, sortByStartedAt);

fn sortByStartedAt(_: *PackageManager, a: *LifecycleScriptSubprocess, b: *LifecycleScriptSubprocess) bool {
return a.started_at < b.started_at;
}

pub usingnamespace bun.New(@This());

Expand Down Expand Up @@ -92,6 +101,12 @@ pub const LifecycleScriptSubprocess = struct {
// This is only used on the main thread.
var cwd_z_buf: bun.PathBuffer = undefined;

fn ensureNotInHeap(this: *LifecycleScriptSubprocess) void {
if (this.heap.child != null or this.heap.next != null or this.heap.prev != null or this.manager.active_lifecycle_scripts.root == this) {
this.manager.active_lifecycle_scripts.remove(this);
}
}

pub fn spawnNextScript(this: *LifecycleScriptSubprocess, next_script_index: u8) !void {
bun.Analytics.Features.lifecycle_scripts += 1;

Expand All @@ -105,6 +120,8 @@ pub const LifecycleScriptSubprocess = struct {
this.has_incremented_alive_count = false;
_ = alive_count.fetchSub(1, .monotonic);
}

this.ensureNotInHeap();
}

const manager = this.manager;
Expand All @@ -114,6 +131,8 @@ pub const LifecycleScriptSubprocess = struct {
this.stdout.setParent(this);
this.stderr.setParent(this);

this.ensureNotInHeap();

this.current_script_index = next_script_index;
this.has_called_process_exit = false;

Expand Down Expand Up @@ -197,6 +216,8 @@ pub const LifecycleScriptSubprocess = struct {
};

this.remaining_fds = 0;
this.started_at = bun.timespec.now().ns();
this.manager.active_lifecycle_scripts.insert(this);
var spawned = try (try bun.spawn.spawnProcess(&spawn_options, @ptrCast(&argv), this.envp)).unwrap();

if (comptime Environment.isPosix) {
Expand Down Expand Up @@ -299,6 +320,8 @@ pub const LifecycleScriptSubprocess = struct {
_ = alive_count.fetchSub(1, .monotonic);
}

this.ensureNotInHeap();

switch (status) {
.exited => |exit| {
const maybe_duration = if (this.timer) |*t| t.read() else null;
Expand Down Expand Up @@ -355,8 +378,15 @@ pub const LifecycleScriptSubprocess = struct {
}
}

if (PackageManager.verbose_install) {
Output.prettyErrorln("<r><d>[Scripts]<r> Finished scripts for <b>{}<r>", .{
bun.fmt.quote(this.package_name),
});
}

// the last script finished
_ = this.manager.pending_lifecycle_script_tasks.fetchSub(1, .monotonic);

this.deinit();
},
.signaled => |signal| {
Expand Down Expand Up @@ -426,6 +456,7 @@ pub const LifecycleScriptSubprocess = struct {

pub fn deinit(this: *LifecycleScriptSubprocess) void {
this.resetPolls();
this.ensureNotInHeap();

if (!this.manager.options.log_level.isVerbose()) {
this.stdout.deinit();
Expand Down

0 comments on commit ee31a53

Please sign in to comment.