diff --git a/bootstrap/compiler.zig b/bootstrap/compiler.zig index 8ffd774..f46097f 100644 --- a/bootstrap/compiler.zig +++ b/bootstrap/compiler.zig @@ -3617,6 +3617,16 @@ const Thread = struct{ discard_count: u64 = 0, handle: std.Thread = undefined, generate_debug_information: bool = true, + timestamp: std.time.Instant = std.mem.zeroes(std.time.Instant), + timers: Timers = Timers.initFill(std.mem.zeroes(TimeRange)), + const Timers = std.EnumArray(Timer, TimeRange); + + const Timer = enum{ + setup, + analysis, + llvm_build_ir, + llvm_emit_object, + }; fn add_thread_work(thread: *Thread, job: Job) void { @atomicStore(@TypeOf(thread.task_system.state), &thread.task_system.state, .running, .seq_cst); @@ -3700,7 +3710,6 @@ const TaskSystem = struct{ c_source_file, c_source_file_done, analysis, - analysis_resolution, llvm_generate_ir, llvm_emit_object, llvm_finished_object, @@ -3803,6 +3812,19 @@ const Instance = struct{ } }; +const TimeRange = struct{ + start: std.time.Instant, + end: std.time.Instant, +}; + +const TimeUnion = union(enum){ + range: TimeRange, + accumulating: struct{ + sum: u64, + previous: std.time.Instant, + }, +}; + const File = struct{ global_declaration: GlobalDeclaration, scope: File.Scope, @@ -3812,7 +3834,7 @@ const File = struct{ .start = 0, .end = 0, }, - state: State = .queued, + state: State, thread: u32 = 0, interested_threads: PinnedArray(u32) = .{}, interested_files: PinnedArray(*File) = .{}, @@ -3820,6 +3842,15 @@ const File = struct{ values_per_import: PinnedArray(PinnedArray(*Value)) = .{}, resolved_import_count: u32 = 0, local_lazy_expressions: PinnedArray(*LocalLazyExpression) = .{}, + timestamp: std.time.Instant, + timers: Timers = Timers.initFill(.{ .range = std.mem.zeroes(TimeRange) }), + const Timers = std.EnumArray(Timer, TimeUnion); + const Timer = enum{ + queue, + read, + analysis, + wait_for_dependencies, + }; pub fn get_index(file: *File) u32 { return instance.files.get_index(file); @@ -3831,7 +3862,10 @@ const File = struct{ const State = enum{ queued, + reading, analyzing, + waiting_for_dependencies, + analyzed, }; const Scope = struct { @@ -3879,6 +3913,8 @@ fn add_file(file_absolute_path: []const u8, interested_threads: []const u32) u32 }, .source_code = &.{}, .path = file_absolute_path, + .state = .queued, + .timestamp = std.time.Instant.now() catch unreachable, }; new_file.interested_threads.append_slice(interested_threads); @@ -4127,6 +4163,7 @@ fn control_thread(unit: *Unit, lati: u32) void { assert(objects.length > 0); + link_start = std.time.Instant.now() catch unreachable; link(.{ .output_file_path = unit.descriptor.executable_path, .extra_arguments = &.{}, @@ -4135,8 +4172,12 @@ fn control_thread(unit: *Unit, lati: u32) void { .link_libc = true, .link_libcpp = false, }); + link_end = std.time.Instant.now() catch unreachable; } +var link_start: std.time.Instant = undefined; +var link_end: std.time.Instant = undefined; + fn command_exe(arguments: []const []const u8) void { if (arguments.len == 0) { error_insufficient_arguments_command("exe"); @@ -4300,6 +4341,7 @@ fn command_exe(arguments: []const []const u8) void { } pub fn main() void { + const program_start = std.time.Instant.now() catch fail(); instance.arena = library.Arena.init(4 * 1024 * 1024) catch unreachable; const executable_path = library.self_exe_path(instance.arena) catch unreachable; const executable_directory = std.fs.path.dirname(executable_path).?; @@ -4352,6 +4394,47 @@ pub fn main() void { } else { fail_message("Unrecognized command"); } + + const program_end = std.time.Instant.now() catch unreachable; + + const print_timers = configuration.timers; + if (print_timers) { + for (instance.files.slice()) |*file| { + std.debug.print("File {s}:\n", .{file.path}); + var it = file.timers.iterator(); + while (it.next()) |timer_entry| { + const ns = switch (timer_entry.value.*) { + .accumulating => |t| t.sum, + .range => |range| range.end.since(range.start), + }; + const ms = @as(f64, @floatFromInt(ns)) / 1000_000.0; + std.debug.print("- {s}: {d} ns ({d:.02} ms)\n", .{@tagName(timer_entry.key), ns, ms}); + } + } + + for (instance.threads) |*thread| { + std.debug.print("Thread {}:\n", .{thread.get_index()}); + var it = thread.timers.iterator(); + while (it.next()) |timer_entry| { + const ns = timer_entry.value.end.since(timer_entry.value.start); + const ms = @as(f64, @floatFromInt(ns)) / 1000_000.0; + std.debug.print("- {s}: {d} ns ({d:.02} ms)\n", .{@tagName(timer_entry.key), ns, ms}); + } + } + + { + const ns = link_end.since(link_start); + const ms = @as(f64, @floatFromInt(ns)) / 1000_000.0; + std.debug.print("Link time: {} ns ({d:.02} ms)\n", .{ns, ms}); + } + + { + const ns = program_end.since(program_start); + const ms = @as(f64, @floatFromInt(ns)) / 1000_000.0; + + std.debug.print("Program took {} ns ({d:.02} ms) to execute!\n", .{ns, ms}); + } + } } const LinkerOptions = struct { @@ -4574,6 +4657,7 @@ fn try_end_analyzing_file(file: *File) void { } fn worker_thread(thread_index: u32, cpu_count: *u32) void { + const thread_start = std.time.Instant.now() catch unreachable; while (true) { const local_cpu_count = cpu_count.*; if (local_cpu_count == 0) { @@ -4596,17 +4680,42 @@ fn worker_thread(thread_index: u32, cpu_count: *u32) void { thread.void.sema.thread = @intCast(thread_index); thread.noreturn.sema.thread = @intCast(thread_index); + const thread_setup_end = std.time.Instant.now() catch unreachable; + thread.timers.set(.setup, .{ .start = thread_start, .end = thread_setup_end }); + while (true) { while (thread.get_worker_job()) |job| { const c = thread.task_system.job.worker.completed; switch (job.id) { .analyze_file => { - thread.assigned_file_count += 1; + const t = thread.timers.get(.analysis); + if (t.end.order(t.start) == .eq) { + thread.timers.getPtr(.analysis).start = std.time.Instant.now() catch unreachable; + } const file_index = job.offset; const file = &instance.files.slice()[file_index]; - file.state = .analyzing; - file.source_code = library.read_file(thread.arena, std.fs.cwd(), file.path); file.thread = thread_index; + thread.assigned_file_count += 1; + const queue_start = file.timestamp; + const queue_end = std.time.Instant.now() catch unreachable; + file.timers.set(.queue, .{ + .range = .{ + .start = queue_start, + .end = queue_end, + }, + }); + const read_start = queue_end; + file.state = .reading; + file.source_code = library.read_file(thread.arena, std.fs.cwd(), file.path); + const read_end = std.time.Instant.now() catch unreachable; + file.timers.set(.read, .{ + .range = .{ + .start = read_start, + .end = read_end, + }, + }); + file.timestamp = read_end; + file.state = .analyzing; analyze_file(thread, file_index); }, .notify_file_resolved => { @@ -4718,6 +4827,7 @@ fn worker_thread(thread_index: u32, cpu_count: *u32) void { }, .llvm_generate_ir => { if (thread.functions.length > 0 or thread.global_variables.length > 0) { + const llvm_start = std.time.Instant.now() catch unreachable; const context = LLVM.Context.create(); const module_name: []const u8 = "thread"; const module = LLVM.Module.create(module_name.ptr, module_name.len, context); @@ -5300,7 +5410,7 @@ fn worker_thread(thread_index: u32, cpu_count: *u32) void { } } - const verify_module = true; + const verify_module = builtin.mode == .Debug; const print_module_at_failure = true; const print_module = false; @@ -5326,21 +5436,36 @@ fn worker_thread(thread_index: u32, cpu_count: *u32) void { write("\n"); } + const llvm_end = std.time.Instant.now() catch unreachable; + + thread.timers.set(.llvm_build_ir, .{ + .start = llvm_start, + .end = llvm_end, + }); + thread.add_control_work(.{ .id = .llvm_notify_ir_done, }); } }, .llvm_emit_object => { + const llvm_start = std.time.Instant.now() catch unreachable; const timestamp = std.time.nanoTimestamp(); const thread_object = std.fmt.allocPrint(std.heap.page_allocator, "nat/o/{s}_thread{}_{}.o", .{std.fs.path.basename(std.fs.path.dirname(instance.files.get(@enumFromInt(0)).path).?), thread.get_index(), timestamp}) catch unreachable; thread.llvm.object = thread_object; - const disable_verify = false; + const disable_verify = builtin.mode != .Debug; const result = thread.llvm.module.addPassesToEmitFile(thread.llvm.target_machine, thread_object.ptr, thread_object.len, LLVM.CodeGenFileType.object, disable_verify); if (!result) { @panic("can't generate machine code"); } + const llvm_end = std.time.Instant.now() catch unreachable; + + thread.timers.set(.llvm_emit_object, .{ + .start = llvm_start, + .end = llvm_end, + }); + thread.add_control_work(.{ .id = .llvm_notify_object_done, }); @@ -8904,11 +9029,30 @@ pub fn analyze_file(thread: *Thread, file_index: u32) void { } fn try_resolve_file(thread: *Thread, file: *File) void { + const analysis_end = std.time.Instant.now() catch unreachable; + const analysis_start = file.timestamp; + file.timestamp = analysis_end; + const timer_tag: File.Timer = switch (file.state) { + .analyzing => .analysis, + .waiting_for_dependencies => .wait_for_dependencies, + else => unreachable, + }; + if (file.imports.length == file.resolved_import_count) { + file.timers.set(timer_tag, .{ + .range = .{ + .start = analysis_start, + .end = analysis_end, + }, + }); + file.state = .analyzed; thread.analyzed_file_count += 1; + // If the thread has analyzed the same files it has been assigned, tell the control thread + // that the thread has finished file analysis so it can proceed to the next step if (thread.analyzed_file_count == thread.assigned_file_count) { if (@atomicLoad(@TypeOf(thread.task_system.job.queuer.to_do), &thread.task_system.job.queuer.to_do, .seq_cst) == thread.task_system.job.worker.completed + 1) { + thread.timers.getPtr(.analysis).end = std.time.Instant.now() catch unreachable; thread.add_control_work(.{ .id = .notify_analysis_complete, }); @@ -8924,6 +9068,23 @@ fn try_resolve_file(thread: *Thread, file: *File) void { .count = @intCast(ti), }); } + } else { + file.state = .waiting_for_dependencies; + switch (file.timers.get(timer_tag)) { + .range => |range| { + const order = range.end.order(range.start); + switch (order) { + .eq => file.timers.set(timer_tag, .{ + .range = .{ + .start = analysis_start, + .end = analysis_end, + }, + }), + else => |t| @panic(@tagName(t)), + } + }, + .accumulating => unreachable, + } } } diff --git a/bootstrap/library.zig b/bootstrap/library.zig index b9fb5ba..a8ee07f 100644 --- a/bootstrap/library.zig +++ b/bootstrap/library.zig @@ -803,12 +803,12 @@ pub fn read_file(arena: *Arena, directory: std.fs.Dir, file_relative_path: []con } pub fn self_exe_path(arena: *Arena) ![]const u8 { - var buffer: [std.fs.MAX_PATH_BYTES]u8 = undefined; + var buffer: [std.fs.max_path_bytes]u8 = undefined; return try arena.duplicate_bytes(try std.fs.selfExePath(&buffer)); } pub fn realpath(arena: *Arena, dir: std.fs.Dir, relative_path: []const u8) ![]const u8 { - var buffer: [std.fs.MAX_PATH_BYTES]u8 = undefined; + var buffer: [std.fs.max_path_bytes]u8 = undefined; const stack_realpath = try dir.realpath(relative_path, &buffer); const heap_realpath = try arena.new_array(u8, stack_realpath.len); @memcpy(heap_realpath, stack_realpath); diff --git a/build.zig b/build.zig index 26a1e7e..516c912 100644 --- a/build.zig +++ b/build.zig @@ -36,6 +36,7 @@ pub fn build(b: *std.Build) !void { .windows => true, // .macos => true, }; + const timers = b.option(bool, "timers", "This option enables to make and print timers") orelse !is_ci; const fetcher = b.addExecutable(.{ .name = "llvm_fetcher", @@ -467,7 +468,7 @@ pub fn build(b: *std.Build) !void { unreachable; } - var tokenizer = std.mem.tokenize(u8, result.stdout, " "); + var tokenizer = std.mem.tokenizeScalar(u8, result.stdout, ' '); const cxx_version = while (tokenizer.next()) |chunk| { if (std.ascii.isDigit(chunk[0])) { if (std.SemanticVersion.parse(chunk)) |sema_version| { @@ -565,6 +566,7 @@ pub fn build(b: *std.Build) !void { compiler_options.addOption(bool, "editor", use_editor); compiler_options.addOption(bool, "sleep_on_thread_hot_loops", sleep_on_thread_hot_loops); compiler_options.addOption([]const []const u8, "include_paths", include_paths.items); + compiler_options.addOption(bool, "timers", timers); compiler.root_module.addOptions("configuration", compiler_options); if (target.result.os.tag == .windows) {