From 3bd53e2a80c2ed728276b5696a9655ed0878f56c Mon Sep 17 00:00:00 2001 From: gingerBill Date: Sat, 3 Oct 2026 16:26:58 +0100 Subject: [PATCH] Improve the parsing for tokenizing + parsing speeds under `-show-more-timings -show-debug-messages` --- src/main.cpp | 164 +++++++++++++++++++++++++++++++++++++----------- src/parser.cpp | 28 ++++++++- src/parser.hpp | 10 ++- src/timings.cpp | 35 +++++++++++ 4 files changed, 197 insertions(+), 40 deletions(-) diff --git a/src/main.cpp b/src/main.cpp index b541dc0aa..29fcfc899 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -2383,6 +2383,132 @@ gb_internal void show_import_graph(Checker *c) { gb_printf("}\n\n"); } +gb_internal void add_time_to_tokenize_only(AstFile *f, f64 *time, u64 *cpu_time) { + isize size = f->tokenizer.end - f->tokenizer.start; + if (size <= 0) { + return; + } + Tokenizer t = {}; + t.curr_file_id = f->id; + init_tokenizer_with_data(&t, f->fullpath, f->tokenizer.start, size); + + u64 start = time_stamp_time_now(); + u64 cpu_start = thread_cpu_time_now(); + Token token = {}; + do { + tokenizer_get_token(&t, &token); + } while (token.kind != Token_EOF && token.kind != Token_Invalid); + *cpu_time += thread_cpu_time_now()-cpu_start; + *time += cast(f64)(time_stamp_time_now()-start)/cast(f64)time_stamp__freq(); +} + +gb_internal GB_COMPARE_PROC(file_cpu_time_to_parse_cmp) { + AstFile *x = *(AstFile **)a; + AstFile *y = *(AstFile **)b; + if (x->cpu_time_to_parse != y->cpu_time_to_parse) { + return x->cpu_time_to_parse > y->cpu_time_to_parse ? -1 : +1; + } + return string_compare(x->fullpath, y->fullpath); +} + +gb_internal void show_parse_timings(Parser *p, Timings *t) { + auto all_files = array_make(heap_allocator(), 0, p->packages.count*8); + defer (array_free(&all_files)); + for (AstPackage *pkg : p->packages) { + for (AstFile *file : pkg->files) { + array_add(&all_files, file); + } + } + + f64 cpu_freq = thread_cpu_time_freq(); + + isize tokens = p->total_token_count; + isize lines = p->total_line_count; + isize total_file_size = 0; + + f64 load_time = 0; + f64 load_cpu_time = 0; + f64 parse_time = 0; + f64 parse_cpu_time = 0; + f64 setup_time = 0; + f64 setup_cpu_time = 0; + f64 tokenize_time = 0; + u64 tokenize_cpu_ticks = 0; + + for (AstFile *file : all_files) { + total_file_size += file->tokenizer.end - file->tokenizer.start; + load_time += file->time_to_load; + parse_time += file->time_to_parse; + setup_time += file->time_to_setup_decls; + load_cpu_time += cast(f64)file->cpu_time_to_load/cpu_freq; + parse_cpu_time += cast(f64)file->cpu_time_to_parse/cpu_freq; + setup_cpu_time += cast(f64)file->cpu_time_to_setup_decls/cpu_freq; + + add_time_to_tokenize_only(file, &tokenize_time, &tokenize_cpu_ticks); + } + + f64 tokenize_cpu_time = cast(f64)tokenize_cpu_ticks/cpu_freq; + + f64 wall_time = 0; + for (TimeStamp const &s : t->sections) { + if (s.label == "parse files") { + wall_time = time_stamp_as_s(s, t->freq); + break; + } + } + + isize thread_count = gb_max(global_thread_pool.threads.count, 1); + f64 task_time = load_time + parse_time + setup_time; + f64 task_cpu_time = load_cpu_time + parse_cpu_time + setup_cpu_time; + f64 mib = cast(f64)total_file_size/(1024.0*1024.0); + + auto const &row = [&](char const *label, f64 time, f64 cpu_time, bool rates) { + gb_printf_err(" %s - %9.3f ms %9.3f ms", label, 1.0e3*time, 1.0e3*cpu_time); + if (rates) { + f64 lines_per_second = cast(f64)lines/cpu_time; + char const *loc = " LOC/s"; + if (lines_per_second >= 1.0e6) { + lines_per_second /= 1.0e6; + loc = " MLOC/s"; + } else if (lines_per_second >= 1.0e3) { + lines_per_second /= 1.0e3; + loc = " kLOC/s"; + } + gb_printf_err(" %7.3f us/token %7.3f us/line %8.2f MiB/s %7.2f%s", + 1.0e6*cpu_time/cast(f64)tokens, 1.0e6*cpu_time/cast(f64)lines, mib/cpu_time, lines_per_second, loc); + } + gb_printf_err("\n"); + }; + + gb_printf_err("Parsing (%td files, %td lines, %td tokens, %.2f MiB, %td threads)\n", all_files.count, lines, tokens, mib, thread_count); + gb_printf_err(" parse files - %9.3f ms (wall time)\n", 1.0e3*wall_time); + gb_printf_err(" wall time CPU time (rates from the CPU time)\n"); + row( "file tasks ", task_time, task_cpu_time, false); + row( " loading files ", load_time, load_cpu_time, false); + row( " tokenizing and parsing ", parse_time, parse_cpu_time, true); + row( " setting up decls and imports ", setup_time, setup_cpu_time, false); + row( "tokenizing alone, 1 thread ", tokenize_time, tokenize_cpu_time, true); + if (build_context.thread_count == 1) { + row( "parsing alone (estimated) ", parse_time-tokenize_time, parse_cpu_time-tokenize_cpu_time, true); + } else { + gb_printf_err(" parsing alone - estimated with -thread-count:1\n"); + } + gb_printf_err(" the file tasks kept the threads %.0f%% busy and %.0f%% of their time was spent running\n", + 100.0*task_time/(wall_time*cast(f64)thread_count), 100.0*task_cpu_time/task_time); + gb_printf_err("\n"); + + array_sort(all_files, file_cpu_time_to_parse_cmp); + gb_printf_err("Slowest files to tokenize and parse, by CPU time\n"); + for (isize i = 0; i < gb_min(all_files.count, 8); i++) { + AstFile *file = all_files[i]; + f64 cpu_time = cast(f64)file->cpu_time_to_parse/cpu_freq; + gb_printf_err(" %9.3f ms %9.3f ms (wall) %8td tokens %7.3f us/token %.*s\n", + 1.0e3*cpu_time, 1.0e3*file->time_to_parse, file->token_count, + 1.0e6*cpu_time/cast(f64)gb_max(file->token_count, 1), LIT(file->fullpath)); + } + gb_printf_err("\n"); +} + gb_internal void show_timings(Checker *c, Timings *t) { Parser *p = c->parser; isize lines = p->total_line_count; @@ -2390,11 +2516,9 @@ gb_internal void show_timings(Checker *c, Timings *t) { isize files = 0; isize packages = p->packages.count; isize total_file_size = 0; - f64 total_parsing_time = 0; for (AstPackage *pkg : p->packages) { files += pkg->files.count; for (AstFile *file : pkg->files) { - total_parsing_time += file->time_to_parse; total_file_size += file->tokenizer.end - file->tokenizer.start; } } @@ -2417,41 +2541,7 @@ gb_internal void show_timings(Checker *c, Timings *t) { gb_printf_err("Total File Size - %td\n", total_file_size); gb_printf_err("\n"); } - { - f64 time = total_parsing_time; - gb_printf_err("Tokenizing and Parsing Only\n"); - gb_printf_err("LOC/s - %.3f\n", cast(f64)lines/time); - gb_printf_err("us/LOC - %.3f\n", 1.0e6*time/cast(f64)lines); - gb_printf_err("Tokens/s - %.3f\n", cast(f64)tokens/time); - gb_printf_err("us/Token - %.3f\n", 1.0e6*time/cast(f64)tokens); - gb_printf_err("bytes/s - %.3f\n", cast(f64)total_file_size/time); - gb_printf_err("MiB/s - %.3f\n", cast(f64)(total_file_size/time)/(1024*1024)); - gb_printf_err("us/bytes - %.3f\n", 1.0e6*time/cast(f64)total_file_size); - - gb_printf_err("\n"); - } - { - TimeStamp ts = {}; - for (TimeStamp const &s : t->sections) { - if (s.label == "parse files") { - ts = s; - break; - } - } - GB_ASSERT(ts.label == "parse files"); - - f64 parse_time = time_stamp_as_s(ts, t->freq); - gb_printf_err("Parse pass\n"); - gb_printf_err("LOC/s - %.3f\n", cast(f64)lines/parse_time); - gb_printf_err("us/LOC - %.3f\n", 1.0e6*parse_time/cast(f64)lines); - gb_printf_err("Tokens/s - %.3f\n", cast(f64)tokens/parse_time); - gb_printf_err("us/Token - %.3f\n", 1.0e6*parse_time/cast(f64)tokens); - gb_printf_err("bytes/s - %.3f\n", cast(f64)total_file_size/parse_time); - gb_printf_err("MiB/s - %.3f\n", cast(f64)(total_file_size/parse_time)/(1024*1024)); - gb_printf_err("us/bytes - %.3f\n", 1.0e6*parse_time/cast(f64)total_file_size); - - gb_printf_err("\n"); - } + show_parse_timings(p, t); { TimeStamp ts = {}; TimeStamp ts_end = {}; diff --git a/src/parser.cpp b/src/parser.cpp index 31561f39c..5b8329ba6 100644 --- a/src/parser.cpp +++ b/src/parser.cpp @@ -6399,6 +6399,15 @@ gb_internal Array parse_stmt_list(AstFile *f) { } +// Only the report of `-show-more-timings -show-debug-messages` uses a file's CPU time, +// and getting a thread's CPU time is a system call +gb_internal u64 parse_thread_cpu_time_now(void) { + if (build_context.show_debug_messages && build_context.show_more_timings) { + return thread_cpu_time_now(); + } + return 0; +} + gb_internal ParseFileError init_ast_file(AstFile *f, String const &fullpath) { GB_ASSERT(f != nullptr); f->fullpath = string_trim_whitespace(fullpath); // Just in case @@ -6412,7 +6421,11 @@ gb_internal ParseFileError init_ast_file(AstFile *f, String const &fullpath) { gb_zero_item(&f->tokenizer); f->tokenizer.curr_file_id = f->id; + u64 load_start = time_stamp_time_now(); + u64 load_cpu_start = parse_thread_cpu_time_now(); TokenizerInitError err = init_tokenizer_from_fullpath(&f->tokenizer, f->fullpath, build_context.copy_file_contents); + f->cpu_time_to_load = parse_thread_cpu_time_now()-load_cpu_start; + f->time_to_load = cast(f64)(time_stamp_time_now()-load_start)/cast(f64)time_stamp__freq(); if (err != TokenizerInit_None) { switch (err) { case TokenizerInit_Empty: @@ -7493,6 +7506,9 @@ gb_internal bool parse_file(Parser *p, AstFile *f) { } u64 start = time_stamp_time_now(); + u64 cpu_start = parse_thread_cpu_time_now(); + u64 setup_start = 0; + u64 setup_cpu_start = 0; String filepath = f->tokenizer.fullpath; String base_dir = dir_from_path(filepath); @@ -7593,11 +7609,19 @@ gb_internal bool parse_file(Parser *p, AstFile *f) { f->decls = slice_from_array(decls); + setup_start = time_stamp_time_now(); + setup_cpu_start = parse_thread_cpu_time_now(); parse_setup_file_decls(p, f, base_dir, f->decls); } - u64 end = time_stamp_time_now(); - f->time_to_parse = cast(f64)(end-start)/cast(f64)time_stamp__freq(); + u64 end = time_stamp_time_now(); + u64 cpu_end = parse_thread_cpu_time_now(); + u64 setup_ticks = setup_start != 0 ? end-setup_start : 0; + u64 setup_cpu_ticks = setup_cpu_start != 0 ? cpu_end-setup_cpu_start : 0; + f->time_to_parse = cast(f64)(end-start-setup_ticks)/cast(f64)time_stamp__freq(); + f->time_to_setup_decls = cast(f64)setup_ticks/cast(f64)time_stamp__freq(); + f->cpu_time_to_parse = cpu_end-cpu_start-setup_cpu_ticks; + f->cpu_time_to_setup_decls = setup_cpu_ticks; for (int i = 0; i < AstDelayQueue_COUNT; i++) { array_init(f->delayed_decls_queues+i, ast_allocator(f), 0, f->delayed_decl_count); diff --git a/src/parser.hpp b/src/parser.hpp index 1f5869883..65d0cde3a 100644 --- a/src/parser.hpp +++ b/src/parser.hpp @@ -155,7 +155,6 @@ struct AstFile { Ast * curr_proc; isize error_count; ParseFileError last_error; - f64 time_to_parse; // seconds, including tokenizing CommentGroup *lead_comment; // Comment (block) before the decl CommentGroup *line_comment; // Comment after the semicolon @@ -173,6 +172,15 @@ struct AstFile { struct LLVMOpaqueMetadata *llvm_metadata; struct LLVMOpaqueMetadata *llvm_metadata_scope; + + //// Profiling ///// + + f64 time_to_load; // seconds + f64 time_to_parse; // seconds, tokenizing included, setting up the decls excluded + f64 time_to_setup_decls; // seconds, mostly finding and adding the imported packages + u64 cpu_time_to_load; + u64 cpu_time_to_parse; + u64 cpu_time_to_setup_decls; }; enum AstForeignFileKind { diff --git a/src/timings.cpp b/src/timings.cpp index f6e86867f..f1d6e5eb3 100644 --- a/src/timings.cpp +++ b/src/timings.cpp @@ -32,6 +32,7 @@ gb_internal u64 win32_time_stamp__freq(void) { #elif defined(GB_SYSTEM_OSX) #include +#include gb_internal mach_timebase_info_data_t osx_init_timebase_info(void) { mach_timebase_info_data_t data; @@ -105,6 +106,40 @@ gb_internal u64 time_stamp__freq(void) { #endif } +gb_internal u64 thread_cpu_time_now(void) { +#if defined(GB_SYSTEM_WINDOWS) + ULONG64 cycles = 0; + QueryThreadCycleTime(GetCurrentThread(), &cycles); + return cycles; +#else + struct timespec ts; + clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts); + return (cast(u64)ts.tv_sec * 1000000000ull) + cast(u64)ts.tv_nsec; +#endif +} + +gb_internal f64 thread_cpu_time_freq(void) { +#if defined(GB_SYSTEM_WINDOWS) + gb_local_persist f64 freq = 0; + if (freq == 0) { + for (isize i = 0; i < 5; i++) { + u64 start = time_stamp_time_now(); + u64 start_cycles = thread_cpu_time_now(); + u64 end = start; + while (end-start < time_stamp__freq()/100) { + end = time_stamp_time_now(); + } + u64 end_cycles = thread_cpu_time_now(); + f64 measured = cast(f64)(end_cycles-start_cycles) * cast(f64)time_stamp__freq() / cast(f64)(end-start); + freq = gb_max(freq, measured); + } + } + return freq; +#else + return 1.0e9; +#endif +} + gb_internal TimeStamp make_time_stamp(String const &label) { TimeStamp ts = {0}; ts.start = time_stamp_time_now();