From e0050af293146a38e2122413196e66f73d90f2e0 Mon Sep 17 00:00:00 2001 From: Andrew Kelley Date: Tue, 25 Apr 2017 12:29:25 -0400 Subject: [PATCH] add some timing diagnostics pass --enable-timing-info to print a nice table like this: ``` Name Start End Duration Percent Initialize 0.0000 0.0000 0.0000 0.0001 Semantic Analysis 0.0000 0.0421 0.0420 0.2109 Code Generation 0.0421 0.0620 0.0200 0.1003 LLVM Emit Object 0.0620 0.1852 0.1231 0.6180 Build Dependencies 0.1852 0.1974 0.0122 0.0615 LLVM Link 0.1974 0.1993 0.0018 0.0093 Generate .h 0.1993 0.1993 0.0000 0.0000 Total 0.0000 0.1993 0.1993 1.0000 ``` --- src/all_types.hpp | 7 +++++++ src/codegen.cpp | 30 ++++++++++++++++++++++++++++++ src/codegen.hpp | 2 ++ src/link.cpp | 6 ++++++ src/main.cpp | 14 ++++++++++++++ src/os.cpp | 29 +++++++++++++++++++++++++++++ src/os.hpp | 1 + 7 files changed, 89 insertions(+) diff --git a/src/all_types.hpp b/src/all_types.hpp index 5a26e79740..607efbdf68 100644 --- a/src/all_types.hpp +++ b/src/all_types.hpp @@ -1285,6 +1285,11 @@ struct ZigLLVMFnKey { uint32_t zig_llvm_fn_key_hash(ZigLLVMFnKey); bool zig_llvm_fn_key_eql(ZigLLVMFnKey a, ZigLLVMFnKey b); +struct TimeEvent { + double time; + const char *name; +}; + struct CodeGen { LLVMModuleRef module; ZigList errors; @@ -1468,6 +1473,8 @@ struct CodeGen { Buf *test_filter; Buf *test_name_prefix; + + ZigList timing_events; }; enum VarLinkage { diff --git a/src/codegen.cpp b/src/codegen.cpp index 01b763d5b0..12cff60a17 100644 --- a/src/codegen.cpp +++ b/src/codegen.cpp @@ -57,6 +57,9 @@ PackageTableEntry *new_package(const char *root_src_dir, const char *root_src_pa CodeGen *codegen_create(Buf *root_source_dir, const ZigTarget *target) { CodeGen *g = allocate(1); + + codegen_add_time_event(g, "Initialize"); + g->import_table.init(32); g->builtin_fn_table.init(32); g->primitive_type_table.init(32); @@ -3654,6 +3657,8 @@ static LLVMValueRef build_alloca(CodeGen *g, TypeTableEntry *type_entry, const c static void do_code_gen(CodeGen *g) { assert(!g->errors.length); + codegen_add_time_event(g, "Code Generation"); + delete_unused_builtin_fns(g); generate_error_name_table(g); generate_enum_name_tables(g); @@ -3977,6 +3982,8 @@ static void do_code_gen(CodeGen *g) { LLVMVerifyModule(g->module, LLVMAbortProcessAction, &error); #endif + codegen_add_time_event(g, "LLVM Emit Object"); + char *err_msg = nullptr; Buf *out_file_o = buf_create_from_buf(g->root_out_name); const char *o_ext = target_o_file_ext(&g->zig_target); @@ -4730,6 +4737,8 @@ static PackageTableEntry *create_zigrt_pkg(CodeGen *g) { } void codegen_add_root_code(CodeGen *g, Buf *src_dir, Buf *src_basename, Buf *source_code) { + codegen_add_time_event(g, "Semantic Analysis"); + Buf source_path = BUF_INIT; os_path_join(src_dir, src_basename, &source_path); @@ -5020,3 +5029,24 @@ void codegen_generate_h_file(CodeGen *g) { if (fclose(out_h)) zig_panic("unable to close h file: %s", strerror(errno)); } + +void codegen_print_timing_report(CodeGen *g, FILE *f) { + double start_time = g->timing_events.at(0).time; + double end_time = g->timing_events.last().time; + double total = end_time - start_time; + fprintf(f, "%20s%12s%12s%12s%12s\n", "Name", "Start", "End", "Duration", "Percent"); + for (size_t i = 0; i < g->timing_events.length - 1; i += 1) { + TimeEvent *te = &g->timing_events.at(i); + TimeEvent *next_te = &g->timing_events.at(i + 1); + fprintf(f, "%20s%12.4f%12.4f%12.4f%12.4f\n", te->name, + te->time - start_time, + next_te->time - start_time, + next_te->time - te->time, + (next_te->time - te->time) / total); + } + fprintf(f, "%20s%12.4f%12.4f%12.4f%12.4f\n", "Total", 0.0, total, total, 1.0); +} + +void codegen_add_time_event(CodeGen *g, const char *name) { + g->timing_events.append({os_get_time(), name}); +} diff --git a/src/codegen.hpp b/src/codegen.hpp index d5d7bd0644..4646f5008e 100644 --- a/src/codegen.hpp +++ b/src/codegen.hpp @@ -47,6 +47,8 @@ void codegen_set_omit_zigrt(CodeGen *g, bool omit_zigrt); void codegen_set_test_filter(CodeGen *g, Buf *filter); void codegen_set_test_name_prefix(CodeGen *g, Buf *prefix); void codegen_set_lib_version(CodeGen *g, size_t major, size_t minor, size_t patch); +void codegen_add_time_event(CodeGen *g, const char *name); +void codegen_print_timing_report(CodeGen *g, FILE *f); PackageTableEntry *new_package(const char *root_src_dir, const char *root_src_path); void codegen_add_root_code(CodeGen *g, Buf *source_dir, Buf *source_basename, Buf *source_code); diff --git a/src/link.cpp b/src/link.cpp index 5c73c2134e..59aa19e5db 100644 --- a/src/link.cpp +++ b/src/link.cpp @@ -732,6 +732,8 @@ static void construct_linker_job(LinkJob *lj) { } void codegen_link(CodeGen *g, const char *out_file) { + codegen_add_time_event(g, "Build Dependencies"); + LinkJob lj = {0}; // even though we're calling LLD as a library it thinks the first @@ -808,10 +810,12 @@ void codegen_link(CodeGen *g, const char *out_file) { Buf diag = BUF_INIT; + codegen_add_time_event(g, "LLVM Link"); if (!ZigLLDLink(g->zig_target.oformat, lj.args.items, lj.args.length, &diag)) { fprintf(stderr, "%s\n", buf_ptr(&diag)); exit(1); } + codegen_add_time_event(g, "Generate .h"); if (g->out_type == OutTypeLib || g->out_type == OutTypeObj) @@ -819,6 +823,8 @@ void codegen_link(CodeGen *g, const char *out_file) { codegen_generate_h_file(g); } + codegen_add_time_event(g, "Done"); + if (g->verbose) { fprintf(stderr, "OK\n"); } diff --git a/src/main.cpp b/src/main.cpp index 8576bb6b42..542606c9a1 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -64,6 +64,7 @@ static int usage(const char *arg0) { " -mwindows (windows only) --subsystem windows to the linker\n" " -rdynamic add all symbols to the dynamic symbol table\n" " -rpath [path] add directory to the runtime library search path\n" + " --enable-timing-info print timing diagnostics\n" "Test Options:\n" " --test-filter [text] skip tests that do not match filter\n" " --test-name-prefix [text] add prefix to all tests\n" @@ -163,6 +164,7 @@ int main(int argc, char **argv) { size_t ver_major = 0; size_t ver_minor = 0; size_t ver_patch = 0; + bool timing_info = false; if (argc >= 2 && strcmp(argv[1], "build") == 0) { const char *zig_exe_path = arg0; @@ -292,6 +294,8 @@ int main(int argc, char **argv) { rdynamic = true; } else if (strcmp(arg, "--each-lib-rpath") == 0) { each_lib_rpath = true; + } else if (strcmp(arg, "--enable-timing-info") == 0) { + timing_info = true; } else if (arg[1] == 'L' && arg[2] != 0) { // alias for --library-path lib_dirs.append(&arg[2]); @@ -596,20 +600,28 @@ int main(int argc, char **argv) { if (cmd == CmdBuild) { codegen_add_root_code(g, &root_source_dir, &root_source_name, &root_source_code); codegen_link(g, out_file); + if (timing_info) + codegen_print_timing_report(g, stderr); return EXIT_SUCCESS; } else if (cmd == CmdLink) { for (size_t i = 0; i < objects.length; i += 1) { codegen_add_object(g, buf_create_from_str(objects.at(i))); } codegen_link(g, out_file); + if (timing_info) + codegen_print_timing_report(g, stderr); return EXIT_SUCCESS; } else if (cmd == CmdAsm) { codegen_add_root_assembly(g, &root_source_dir, &root_source_name, &root_source_code); codegen_link(g, out_file); + if (timing_info) + codegen_print_timing_report(g, stderr); return EXIT_SUCCESS; } else if (cmd == CmdParseH) { codegen_parseh(g, &root_source_dir, &root_source_name, &root_source_code); ast_render_decls(g, stdout, 4, g->root_import); + if (timing_info) + codegen_print_timing_report(g, stderr); return EXIT_SUCCESS; } else if (cmd == CmdTest) { codegen_add_root_code(g, &root_source_dir, &root_source_name, &root_source_code); @@ -620,6 +632,8 @@ int main(int argc, char **argv) { if (term.how != TerminationIdClean || term.code != 0) { fprintf(stderr, "\nTests failed. Use the following command to reproduce the failure:\n"); fprintf(stderr, "./test\n"); + } else if (timing_info) { + codegen_print_timing_report(g, stderr); } return (term.how == TerminationIdClean) ? term.code : -1; } else { diff --git a/src/os.cpp b/src/os.cpp index e8ee2a155b..472a572e3b 100644 --- a/src/os.cpp +++ b/src/os.cpp @@ -38,6 +38,11 @@ #endif +#if defined(__MACH__) +#include +#include +#endif + #include #include #include @@ -690,3 +695,27 @@ int os_rename(Buf *src_path, Buf *dest_path) { } return 0; } + +double os_get_time(void) { +#if defined(ZIG_OS_WINDOWS) + unsigned __int64 time; + QueryPerformanceCounter((LARGE_INTEGER*) &time); + return time * win32_time_resolution; +#elif defined(__MACH__) + mach_timespec_t mts; + + kern_return_t err = clock_get_time(cclock, &mts); + assert(!err); + + double seconds = (double)mts.tv_sec; + seconds += ((double)mts.tv_nsec) / 1000000000.0; + + return seconds; +#else + struct timespec tms; + clock_gettime(CLOCK_MONOTONIC, &tms); + double seconds = (double)tms.tv_sec; + seconds += ((double)tms.tv_nsec) / 1000000000.0; + return seconds; +#endif +} diff --git a/src/os.hpp b/src/os.hpp index 1d29362d59..6187d0aca0 100644 --- a/src/os.hpp +++ b/src/os.hpp @@ -56,6 +56,7 @@ int os_delete_file(Buf *path); int os_file_exists(Buf *full_path, bool *result); int os_rename(Buf *src_path, Buf *dest_path); +double os_get_time(void); #if defined(__APPLE__) #define ZIG_OS_DARWIN