authorgravatar for andrew@ziglang.orgAndrew Kelley <andrew@ziglang.org> 2017-04-25 12:29:25-04:00
committergravatar for andrew@ziglang.orgAndrew Kelley <andrew@ziglang.org> 2017-04-25 12:29:25-04:00
loge0050af293146a38e2122413196e66f73d90f2e0
tree3da86e1e696d8452e3af47e0cad2e218b5d094c6
parent4cc2ea14214434297d01c1c89e9308c5c332b0fb

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 ```

7 files changed, 89 insertions(+), 0 deletions(-)

src/all_types.hpp+7
......@@ -1285,6 +1285,11 @@ struct ZigLLVMFnKey {
12851285uint32_t zig_llvm_fn_key_hash(ZigLLVMFnKey);
12861286bool zig_llvm_fn_key_eql(ZigLLVMFnKey a, ZigLLVMFnKey b);
12871287
1288struct TimeEvent {
1289 double time;
1290 const char *name;
1291};
1292
12881293struct CodeGen {
12891294 LLVMModuleRef module;
12901295 ZigList<ErrorMsg*> errors;
......@@ -1468,6 +1473,8 @@ struct CodeGen {
14681473
14691474 Buf *test_filter;
14701475 Buf *test_name_prefix;
1476
1477 ZigList<TimeEvent> timing_events;
14711478};
14721479
14731480enum VarLinkage {
src/codegen.cpp+30
......@@ -57,6 +57,9 @@ PackageTableEntry *new_package(const char *root_src_dir, const char *root_src_pa
5757
5858CodeGen *codegen_create(Buf *root_source_dir, const ZigTarget *target) {
5959 CodeGen *g = allocate<CodeGen>(1);
60
61 codegen_add_time_event(g, "Initialize");
62
6063 g->import_table.init(32);
6164 g->builtin_fn_table.init(32);
6265 g->primitive_type_table.init(32);
......@@ -3654,6 +3657,8 @@ static LLVMValueRef build_alloca(CodeGen *g, TypeTableEntry *type_entry, const c
36543657static void do_code_gen(CodeGen *g) {
36553658 assert(!g->errors.length);
36563659
3660 codegen_add_time_event(g, "Code Generation");
3661
36573662 delete_unused_builtin_fns(g);
36583663 generate_error_name_table(g);
36593664 generate_enum_name_tables(g);
......@@ -3977,6 +3982,8 @@ static void do_code_gen(CodeGen *g) {
39773982 LLVMVerifyModule(g->module, LLVMAbortProcessAction, &error);
39783983#endif
39793984
3985 codegen_add_time_event(g, "LLVM Emit Object");
3986
39803987 char *err_msg = nullptr;
39813988 Buf *out_file_o = buf_create_from_buf(g->root_out_name);
39823989 const char *o_ext = target_o_file_ext(&g->zig_target);
......@@ -4730,6 +4737,8 @@ static PackageTableEntry *create_zigrt_pkg(CodeGen *g) {
47304737}
47314738
47324739void codegen_add_root_code(CodeGen *g, Buf *src_dir, Buf *src_basename, Buf *source_code) {
4740 codegen_add_time_event(g, "Semantic Analysis");
4741
47334742 Buf source_path = BUF_INIT;
47344743 os_path_join(src_dir, src_basename, &source_path);
47354744
......@@ -5020,3 +5029,24 @@ void codegen_generate_h_file(CodeGen *g) {
50205029 if (fclose(out_h))
50215030 zig_panic("unable to close h file: %s", strerror(errno));
50225031}
5032
5033void codegen_print_timing_report(CodeGen *g, FILE *f) {
5034 double start_time = g->timing_events.at(0).time;
5035 double end_time = g->timing_events.last().time;
5036 double total = end_time - start_time;
5037 fprintf(f, "%20s%12s%12s%12s%12s\n", "Name", "Start", "End", "Duration", "Percent");
5038 for (size_t i = 0; i < g->timing_events.length - 1; i += 1) {
5039 TimeEvent *te = &g->timing_events.at(i);
5040 TimeEvent *next_te = &g->timing_events.at(i + 1);
5041 fprintf(f, "%20s%12.4f%12.4f%12.4f%12.4f\n", te->name,
5042 te->time - start_time,
5043 next_te->time - start_time,
5044 next_te->time - te->time,
5045 (next_te->time - te->time) / total);
5046 }
5047 fprintf(f, "%20s%12.4f%12.4f%12.4f%12.4f\n", "Total", 0.0, total, total, 1.0);
5048}
5049
5050void codegen_add_time_event(CodeGen *g, const char *name) {
5051 g->timing_events.append({os_get_time(), name});
5052}
src/codegen.hpp+2
......@@ -47,6 +47,8 @@ void codegen_set_omit_zigrt(CodeGen *g, bool omit_zigrt);
4747void codegen_set_test_filter(CodeGen *g, Buf *filter);
4848void codegen_set_test_name_prefix(CodeGen *g, Buf *prefix);
4949void codegen_set_lib_version(CodeGen *g, size_t major, size_t minor, size_t patch);
50void codegen_add_time_event(CodeGen *g, const char *name);
51void codegen_print_timing_report(CodeGen *g, FILE *f);
5052
5153PackageTableEntry *new_package(const char *root_src_dir, const char *root_src_path);
5254void codegen_add_root_code(CodeGen *g, Buf *source_dir, Buf *source_basename, Buf *source_code);
src/link.cpp+6
......@@ -732,6 +732,8 @@ static void construct_linker_job(LinkJob *lj) {
732732}
733733
734734void codegen_link(CodeGen *g, const char *out_file) {
735 codegen_add_time_event(g, "Build Dependencies");
736
735737 LinkJob lj = {0};
736738
737739 // 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) {
808810
809811 Buf diag = BUF_INIT;
810812
813 codegen_add_time_event(g, "LLVM Link");
811814 if (!ZigLLDLink(g->zig_target.oformat, lj.args.items, lj.args.length, &diag)) {
812815 fprintf(stderr, "%s\n", buf_ptr(&diag));
813816 exit(1);
814817 }
818 codegen_add_time_event(g, "Generate .h");
815819
816820 if (g->out_type == OutTypeLib ||
817821 g->out_type == OutTypeObj)
......@@ -819,6 +823,8 @@ void codegen_link(CodeGen *g, const char *out_file) {
819823 codegen_generate_h_file(g);
820824 }
821825
826 codegen_add_time_event(g, "Done");
827
822828 if (g->verbose) {
823829 fprintf(stderr, "OK\n");
824830 }
src/main.cpp+14
......@@ -64,6 +64,7 @@ static int usage(const char *arg0) {
6464 " -mwindows (windows only) --subsystem windows to the linker\n"
6565 " -rdynamic add all symbols to the dynamic symbol table\n"
6666 " -rpath [path] add directory to the runtime library search path\n"
67 " --enable-timing-info print timing diagnostics\n"
6768 "Test Options:\n"
6869 " --test-filter [text] skip tests that do not match filter\n"
6970 " --test-name-prefix [text] add prefix to all tests\n"
......@@ -163,6 +164,7 @@ int main(int argc, char **argv) {
163164 size_t ver_major = 0;
164165 size_t ver_minor = 0;
165166 size_t ver_patch = 0;
167 bool timing_info = false;
166168
167169 if (argc >= 2 && strcmp(argv[1], "build") == 0) {
168170 const char *zig_exe_path = arg0;
......@@ -292,6 +294,8 @@ int main(int argc, char **argv) {
292294 rdynamic = true;
293295 } else if (strcmp(arg, "--each-lib-rpath") == 0) {
294296 each_lib_rpath = true;
297 } else if (strcmp(arg, "--enable-timing-info") == 0) {
298 timing_info = true;
295299 } else if (arg[1] == 'L' && arg[2] != 0) {
296300 // alias for --library-path
297301 lib_dirs.append(&arg[2]);
......@@ -596,20 +600,28 @@ int main(int argc, char **argv) {
596600 if (cmd == CmdBuild) {
597601 codegen_add_root_code(g, &root_source_dir, &root_source_name, &root_source_code);
598602 codegen_link(g, out_file);
603 if (timing_info)
604 codegen_print_timing_report(g, stderr);
599605 return EXIT_SUCCESS;
600606 } else if (cmd == CmdLink) {
601607 for (size_t i = 0; i < objects.length; i += 1) {
602608 codegen_add_object(g, buf_create_from_str(objects.at(i)));
603609 }
604610 codegen_link(g, out_file);
611 if (timing_info)
612 codegen_print_timing_report(g, stderr);
605613 return EXIT_SUCCESS;
606614 } else if (cmd == CmdAsm) {
607615 codegen_add_root_assembly(g, &root_source_dir, &root_source_name, &root_source_code);
608616 codegen_link(g, out_file);
617 if (timing_info)
618 codegen_print_timing_report(g, stderr);
609619 return EXIT_SUCCESS;
610620 } else if (cmd == CmdParseH) {
611621 codegen_parseh(g, &root_source_dir, &root_source_name, &root_source_code);
612622 ast_render_decls(g, stdout, 4, g->root_import);
623 if (timing_info)
624 codegen_print_timing_report(g, stderr);
613625 return EXIT_SUCCESS;
614626 } else if (cmd == CmdTest) {
615627 codegen_add_root_code(g, &root_source_dir, &root_source_name, &root_source_code);
......@@ -620,6 +632,8 @@ int main(int argc, char **argv) {
620632 if (term.how != TerminationIdClean || term.code != 0) {
621633 fprintf(stderr, "\nTests failed. Use the following command to reproduce the failure:\n");
622634 fprintf(stderr, "./test\n");
635 } else if (timing_info) {
636 codegen_print_timing_report(g, stderr);
623637 }
624638 return (term.how == TerminationIdClean) ? term.code : -1;
625639 } else {
src/os.cpp+29
......@@ -38,6 +38,11 @@
3838
3939#endif
4040
41#if defined(__MACH__)
42#include <mach/clock.h>
43#include <mach/mach.h>
44#endif
45
4146#include <stdlib.h>
4247#include <errno.h>
4348#include <time.h>
......@@ -690,3 +695,27 @@ int os_rename(Buf *src_path, Buf *dest_path) {
690695 }
691696 return 0;
692697}
698
699double os_get_time(void) {
700#if defined(ZIG_OS_WINDOWS)
701 unsigned __int64 time;
702 QueryPerformanceCounter((LARGE_INTEGER*) &time);
703 return time * win32_time_resolution;
704#elif defined(__MACH__)
705 mach_timespec_t mts;
706
707 kern_return_t err = clock_get_time(cclock, &mts);
708 assert(!err);
709
710 double seconds = (double)mts.tv_sec;
711 seconds += ((double)mts.tv_nsec) / 1000000000.0;
712
713 return seconds;
714#else
715 struct timespec tms;
716 clock_gettime(CLOCK_MONOTONIC, &tms);
717 double seconds = (double)tms.tv_sec;
718 seconds += ((double)tms.tv_nsec) / 1000000000.0;
719 return seconds;
720#endif
721}
src/os.hpp+1
......@@ -56,6 +56,7 @@ int os_delete_file(Buf *path);
5656int os_file_exists(Buf *full_path, bool *result);
5757
5858int os_rename(Buf *src_path, Buf *dest_path);
59double os_get_time(void);
5960
6061#if defined(__APPLE__)
6162#define ZIG_OS_DARWIN