add --trace-compile-timing arg to add compile timing comments (#54662)

NEWS.md

@@ -43,6 +43,8 @@ Command-line option changes
 [`NO_COLOR`](https://no-color.org/) or [`FORCE_COLOR`](https://force-color.org/) environment
 variables. ([#53742]).
 * `--project=@temp` starts Julia with a temporary environment.
+* New `--trace-compile-timing` option to report how long each method reported by `--trace-compile` took
+ to compile, in ms. ([#54662])
 
 Multi-threading changes
 -----------------------

base/options.jl

@@ -57,6 +57,7 @@ struct JLOptions
  strip_ir::Int8
  permalloc_pkgimg::Int8
  heap_size_hint::UInt64
+ trace_compile_timing::Int8
 end
 
 # This runs early in the sysimage != is not defined yet

doc/man/julia.1

@@ -285,6 +285,10 @@ Generate an incremental output file (rather than complete)
 --trace-compile={stderr|name}
 Print precompile statements for methods compiled during execution or save to a path
 
+.TP
+--trace-compile-timing=
+If --trace-compile is enabled show how long each took to compile in ms
+
 .TP
 -image-codegen
 Force generate code in imaging mode

doc/src/manual/command-line-interface.md

@@ -215,6 +215,7 @@ The following is a complete list of command-line switches available when launchi
 |`--output-asm <name>` |Generate an assembly file (.s)|
 |`--output-incremental={yes\|no*}` |Generate an incremental output file (rather than complete)|
 |`--trace-compile={stderr\|name}` |Print precompile statements for methods compiled during execution or save to a path|
+|`--trace-compile-timing` |If --trace-compile is enabled show how long each took to compile in ms|
 |`--image-codegen` |Force generate code in imaging mode|
 |`--permalloc-pkgimg={yes\|no*}` |Copy the data section of package images into memory|
 

src/gf.c

@@ -2474,7 +2474,7 @@ jl_code_instance_t *jl_method_inferred_with_abi(jl_method_instance_t *mi JL_PROP
 
 jl_mutex_t precomp_statement_out_lock;
 
-static void record_precompile_statement(jl_method_instance_t *mi)
+static void record_precompile_statement(jl_method_instance_t *mi, double compilation_time)
 {
  static ios_t f_precompile;
  static JL_STREAM* s_precompile = NULL;
@@ -2497,6 +2497,8 @@ static void record_precompile_statement(jl_method_instance_t *mi)
  }
  }
  if (!jl_has_free_typevars(mi->specTypes)) {
+ if (jl_options.trace_compile_timing)
+ jl_printf(s_precompile, "#= %6.1f ms =# ", compilation_time / 1e6);
  jl_printf(s_precompile, "precompile(");
  jl_static_show(s_precompile, mi->specTypes);
  jl_printf(s_precompile, ")\n");
@@ -2595,7 +2597,7 @@ jl_code_instance_t *jl_compile_method_internal(jl_method_instance_t *mi, size_t
  codeinst->rettype_const = unspec->rettype_const;
  jl_atomic_store_release(&codeinst->invoke, unspec_invoke);
  jl_mi_cache_insert(mi, codeinst);
- record_precompile_statement(mi);
+ record_precompile_statement(mi, 0);
  return codeinst;
  }
  }
@@ -2612,7 +2614,7 @@ jl_code_instance_t *jl_compile_method_internal(jl_method_instance_t *mi, size_t
  0, 1, ~(size_t)0, 0, jl_nothing, 0, NULL);
  jl_atomic_store_release(&codeinst->invoke, jl_fptr_interpret_call);
  jl_mi_cache_insert(mi, codeinst);
- record_precompile_statement(mi);
+ record_precompile_statement(mi, 0);
  return codeinst;
  }
  if (compile_option == JL_OPTIONS_COMPILE_OFF) {
@@ -2650,13 +2652,15 @@ jl_code_instance_t *jl_compile_method_internal(jl_method_instance_t *mi, size_t
  }
 
  JL_GC_PUSH1(&codeinst);
+ double compile_time = jl_hrtime();
  int did_compile = jl_compile_codeinst(codeinst);
+ compile_time = jl_hrtime() - compile_time;
 
  if (jl_atomic_load_relaxed(&codeinst->invoke) == NULL) {
  // Something went wrong. Bail to the fallback path.
  codeinst = NULL;
  } else if (did_compile) {
- record_precompile_statement(mi);
+ record_precompile_statement(mi, compile_time);
  }
  JL_GC_POP();
  }

src/jloptions.c

@@ -100,6 +100,7 @@ JL_DLLEXPORT void jl_init_options(void)
  0, // strip-ir
  0, // permalloc_pkgimg
  0, // heap-size-hint
+ 0, // trace_compile_timing
  };
  jl_options_initialized = 1;
 }
@@ -258,6 +259,8 @@ static const char opts_hidden[] =
  " complete)\n"
  " --trace-compile={stderr|name} Print precompile statements for methods compiled\n"
  " during execution or save to a path\n"
+ " --trace-compile-timing If --trace-compile is enabled show how long each took to\n"
+ " compile in ms\n"
  " --image-codegen Force generate code in imaging mode\n"
  " --permalloc-pkgimg={yes|no*} Copy the data section of package images into memory\n"
 ;
@@ -280,6 +283,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
  opt_inline,
  opt_polly,
  opt_trace_compile,
+ opt_trace_compile_timing,
  opt_math_mode,
  opt_worker,
  opt_bind_to,
@@ -356,6 +360,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
  { "inline", required_argument, 0, opt_inline },
  { "polly", required_argument, 0, opt_polly },
  { "trace-compile", required_argument, 0, opt_trace_compile },
+ { "trace-compile-timing", no_argument, 0, opt_trace_compile_timing },
  { "math-mode", required_argument, 0, opt_math_mode },
  { "handle-signals", required_argument, 0, opt_handle_signals },
  // hidden command line options
@@ -794,7 +799,7 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
  jl_errorf("julia: invalid argument to --inline (%s)", optarg);
  }
  break;
- case opt_polly:
+  case opt_polly:
  if (!strcmp(optarg,"yes"))
  jl_options.polly = JL_OPTIONS_POLLY_ON;
  else if (!strcmp(optarg,"no"))
@@ -803,11 +808,14 @@ JL_DLLEXPORT void jl_parse_opts(int *argcp, char ***argvp)
  jl_errorf("julia: invalid argument to --polly (%s)", optarg);
  }
  break;
-  case opt_trace_compile:
+ case opt_trace_compile:
  jl_options.trace_compile = strdup(optarg);
  if (!jl_options.trace_compile)
  jl_errorf("fatal error: failed to allocate memory: %s", strerror(errno));
  break;
+ case opt_trace_compile_timing:
+ jl_options.trace_compile_timing = 1;
+ break;
  case opt_math_mode:
  if (!strcmp(optarg,"ieee"))
  jl_options.fast_math = JL_OPTIONS_FAST_MATH_OFF;

src/jloptions.h

@@ -61,6 +61,7 @@ typedef struct {
  int8_t strip_ir;
  int8_t permalloc_pkgimg;
  uint64_t heap_size_hint;
+ int8_t trace_compile_timing;
 } jl_options_t;
 
 #endif

test/cmdlineargs.jl

@@ -793,6 +793,17 @@ let exename = `$(Base.julia_cmd()) --startup-file=no --color=no`
  # tested in test/parallel.jl)
  @test errors_not_signals(`$exename --worker=true`)
 
+ # --trace-compile-timing
+ let
+ io = IOBuffer()
+ v = writereadpipeline(
+ "foo(x) = begin Base.Experimental.@force_compile; x; end; foo(1)",
+ `$exename --trace-compile=stderr --trace-compile-timing -i`,
+ stderr=io)
+ _stderr = String(take!(io))
+ @test occursin(" ms =# precompile(Tuple{typeof(Main.foo), Int", _stderr)
+ end
+
  # test passing arguments
  mktempdir() do dir
  testfile, io = mktemp(dir)