From ee31a538d80794d3b9696b2185fa7df3b06bc023 Mon Sep 17 00:00:00 2001 From: Jarred Sumner Date: Fri, 27 Dec 2024 22:44:33 -0800 Subject: [PATCH] Log slow lifecycle scripts --- src/bun.js/event_loop.zig | 7 +++ src/install/install.zig | 68 ++++++++++++++++++++----- src/install/lifecycle_script_runner.zig | 31 +++++++++++ 3 files changed, 92 insertions(+), 14 deletions(-) diff --git a/src/bun.js/event_loop.zig b/src/bun.js/event_loop.zig index 03e24fe55bc5ac..1b4c3a1b78acc4 100644 --- a/src/bun.js/event_loop.zig +++ b/src/bun.js/event_loop.zig @@ -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(); } diff --git a/src/install/install.zig b/src/install/install.zig index 5ba0da5b3a0c93..07bc1a8955ed39 100644 --- a/src/install/install.zig +++ b/src/install/install.zig @@ -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, @@ -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; } @@ -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); } @@ -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, @@ -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, @@ -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("[PackageManager] waiting for {d} scripts\n", .{LifecycleScriptSubprocess.alive_count.load(.monotonic)}); - } - this.manager.sleep(); } @@ -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("[PackageManager] 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| { @@ -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| { @@ -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) { @@ -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()) { @@ -14082,6 +14125,7 @@ pub const PackageManager = struct { } } else { this.tickLifecycleScripts(); + this.reportSlowLifecycleScripts(log_level); } for (installer.trees) |tree| { @@ -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("[PackageManager] waiting for {d} scripts\n", .{this.pending_lifecycle_script_tasks.load(.monotonic)}); - } + this.reportSlowLifecycleScripts(log_level); this.sleep(); } @@ -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("[PackageManager] waiting for {d} scripts\n", .{manager.pending_lifecycle_script_tasks.load(.monotonic)}); - } + manager.reportSlowLifecycleScripts(log_level); manager.sleep(); } diff --git a/src/install/lifecycle_script_runner.zig b/src/install/lifecycle_script_runner.zig index c2b2a089e5c1d7..6b054644a0f0c6 100644 --- a/src/install/lifecycle_script_runner.zig +++ b/src/install/lifecycle_script_runner.zig @@ -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()); @@ -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; @@ -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; @@ -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; @@ -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) { @@ -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; @@ -355,8 +378,15 @@ pub const LifecycleScriptSubprocess = struct { } } + if (PackageManager.verbose_install) { + Output.prettyErrorln("[Scripts] Finished scripts for {}", .{ + bun.fmt.quote(this.package_name), + }); + } + // the last script finished _ = this.manager.pending_lifecycle_script_tasks.fetchSub(1, .monotonic); + this.deinit(); }, .signaled => |signal| { @@ -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();