Merge pull request #1346 from bjorn3/self_profile_cleanup

Improve -Ztime-passes and -Zself-profile output

Author: bjorn3

src/base.rs

@@ -21,23 +21,6 @@ pub(crate) struct CodegenedFunction {
     func_debug_cx: Option<FunctionDebugContext>,
 }
 
-#[cfg_attr(not(feature = "jit"), allow(dead_code))]
-pub(crate) fn codegen_and_compile_fn<'tcx>(
-    tcx: TyCtxt<'tcx>,
-    cx: &mut crate::CodegenCx,
-    cached_context: &mut Context,
-    module: &mut dyn Module,
-    instance: Instance<'tcx>,
-) {
-    let _inst_guard =
-        crate::PrintOnPanic(|| format!("{:?} {}", instance, tcx.symbol_name(instance).name));
-
-    let cached_func = std::mem::replace(&mut cached_context.func, Function::new());
-    let codegened_func = codegen_fn(tcx, cx, cached_func, module, instance);
-
-    compile_fn(cx, cached_context, module, codegened_func);
-}
-
 pub(crate) fn codegen_fn<'tcx>(
     tcx: TyCtxt<'tcx>,
     cx: &mut crate::CodegenCx,
@@ -47,6 +30,9 @@ pub(crate) fn codegen_fn<'tcx>(
 ) -> CodegenedFunction {
     debug_assert!(!instance.substs.needs_infer());
 
+    let symbol_name = tcx.symbol_name(instance).name.to_string();
+    let _timer = tcx.prof.generic_activity_with_arg("codegen fn", &*symbol_name);
+
     let mir = tcx.instance_mir(instance.def);
     let _mir_guard = crate::PrintOnPanic(|| {
         let mut buf = Vec::new();
@@ -58,7 +44,6 @@ pub(crate) fn codegen_fn<'tcx>(
     });
 
     // Declare function
-    let symbol_name = tcx.symbol_name(instance).name.to_string();
     let sig = get_function_sig(tcx, module.target_config().default_call_conv, instance);
     let func_id = module.declare_function(&symbol_name, Linkage::Local, &sig).unwrap();
 
@@ -112,7 +97,7 @@ pub(crate) fn codegen_fn<'tcx>(
         next_ssa_var: 0,
     };
 
-    tcx.sess.time("codegen clif ir", || codegen_fn_body(&mut fx, start_block));
+    tcx.prof.generic_activity("codegen clif ir").run(|| codegen_fn_body(&mut fx, start_block));
     fx.bcx.seal_all_blocks();
     fx.bcx.finalize();
 
@@ -146,6 +131,9 @@ pub(crate) fn compile_fn(
     module: &mut dyn Module,
     codegened_func: CodegenedFunction,
 ) {
+    let _timer =
+        cx.profiler.generic_activity_with_arg("compile function", &*codegened_func.symbol_name);
+
     let clif_comments = codegened_func.clif_comments;
 
     // Store function in context
@@ -191,9 +179,30 @@ pub(crate) fn compile_fn(
     };
 
     // Define function
-    cx.profiler.verbose_generic_activity("define function").run(|| {
+    cx.profiler.generic_activity("define function").run(|| {
         context.want_disasm = cx.should_write_ir;
         module.define_function(codegened_func.func_id, context).unwrap();
+
+        if cx.profiler.enabled() {
+            let mut recording_args = false;
+            cx.profiler
+                .generic_activity_with_arg_recorder(
+                    "define function (clif pass timings)",
+                    |recorder| {
+                        let pass_times = cranelift_codegen::timing::take_current();
+                        // Replace newlines with | as measureme doesn't allow control characters like
+                        // newlines inside strings.
+                        recorder.record_arg(format!("{}", pass_times).replace("\n", " | "));
+                        recording_args = true;
+                    },
+                )
+                .run(|| {
+                    if recording_args {
+                        // Wait a tiny bit to ensure chrome's profiler doesn't hide the event
+                        std::thread::sleep(std::time::Duration::from_nanos(2))
+                    }
+                });
+        }
     });
 
     if cx.should_write_ir {
@@ -220,7 +229,7 @@ pub(crate) fn compile_fn(
     let isa = module.isa();
     let debug_context = &mut cx.debug_context;
     let unwind_context = &mut cx.unwind_context;
-    cx.profiler.verbose_generic_activity("generate debug info").run(|| {
+    cx.profiler.generic_activity("generate debug info").run(|| {
         if let Some(debug_context) = debug_context {
             codegened_func.func_debug_cx.unwrap().finalize(
                 debug_context,
@@ -237,7 +246,7 @@ pub(crate) fn verify_func(
     writer: &crate::pretty_clif::CommentWriter,
     func: &Function,
 ) {
-    tcx.sess.time("verify clif ir", || {
+    tcx.prof.generic_activity("verify clif ir").run(|| {
         let flags = cranelift_codegen::settings::Flags::new(cranelift_codegen::settings::builder());
         match cranelift_codegen::verify_function(&func, &flags) {
             Ok(_) => {}
@@ -273,7 +282,10 @@ fn codegen_fn_body(fx: &mut FunctionCx<'_, '_, '_>, start_block: Block) {
         fx.bcx.ins().trap(TrapCode::UnreachableCodeReached);
         return;
     }
-    fx.tcx.sess.time("codegen prelude", || crate::abi::codegen_fn_prelude(fx, start_block));
+    fx.tcx
+        .prof
+        .generic_activity("codegen prelude")
+        .run(|| crate::abi::codegen_fn_prelude(fx, start_block));
 
     for (bb, bb_data) in fx.mir.basic_blocks.iter_enumerated() {
         let block = fx.get_block(bb);
@@ -434,7 +446,7 @@ fn codegen_fn_body(fx: &mut FunctionCx<'_, '_, '_>, start_block: Block) {
                 cleanup: _,
                 from_hir_call: _,
             } => {
-                fx.tcx.sess.time("codegen call", || {
+                fx.tcx.prof.generic_activity("codegen call").run(|| {
                     crate::abi::codegen_terminator_call(
                         fx,
                         mir::SourceInfo { span: *fn_span, ..source_info },

src/config.rs

@@ -42,12 +42,6 @@ pub struct BackendConfig {
     /// Defaults to the value of `CG_CLIF_JIT_ARGS`.
     pub jit_args: Vec<String>,
 
-    /// Display the time it took to perform codegen for a crate.
-    ///
-    /// Defaults to true when the `CG_CLIF_DISPLAY_CG_TIME` env var is set to 1 or false otherwise.
-    /// Can be set using `-Cllvm-args=display_cg_time=...`.
-    pub display_cg_time: bool,
-
     /// Enable the Cranelift ir verifier for all compilation passes. If not set it will only run
     /// once before passing the clif ir to Cranelift for compilation.
     ///
@@ -73,7 +67,6 @@ impl Default for BackendConfig {
                 let args = std::env::var("CG_CLIF_JIT_ARGS").unwrap_or_else(|_| String::new());
                 args.split(' ').map(|arg| arg.to_string()).collect()
             },
-            display_cg_time: bool_env_var("CG_CLIF_DISPLAY_CG_TIME"),
             enable_verifier: cfg!(debug_assertions) || bool_env_var("CG_CLIF_ENABLE_VERIFIER"),
             disable_incr_cache: bool_env_var("CG_CLIF_DISABLE_INCR_CACHE"),
         }
@@ -92,7 +85,6 @@ impl BackendConfig {
             if let Some((name, value)) = opt.split_once('=') {
                 match name {
                     "mode" => config.codegen_mode = value.parse()?,
-                    "display_cg_time" => config.display_cg_time = parse_bool(name, value)?,
                     "enable_verifier" => config.enable_verifier = parse_bool(name, value)?,
                     "disable_incr_cache" => config.disable_incr_cache = parse_bool(name, value)?,
                     _ => return Err(format!("Unknown option `{}`", name)),

src/driver/aot.rs

@@ -272,25 +272,25 @@ fn module_codegen(
         ConcurrencyLimiterToken,
     ),
 ) -> OngoingModuleCodegen {
-    let (cgu_name, mut cx, mut module, codegened_functions) = tcx.sess.time("codegen cgu", || {
-        let cgu = tcx.codegen_unit(cgu_name);
-        let mono_items = cgu.items_in_deterministic_order(tcx);
-
-        let mut module = make_module(tcx.sess, &backend_config, cgu_name.as_str().to_string());
-
-        let mut cx = crate::CodegenCx::new(
-            tcx,
-            backend_config.clone(),
-            module.isa(),
-            tcx.sess.opts.debuginfo != DebugInfo::None,
-            cgu_name,
-        );
-        super::predefine_mono_items(tcx, &mut module, &mono_items);
-        let mut codegened_functions = vec![];
-        for (mono_item, _) in mono_items {
-            match mono_item {
-                MonoItem::Fn(inst) => {
-                    tcx.sess.time("codegen fn", || {
+    let (cgu_name, mut cx, mut module, codegened_functions) =
+        tcx.prof.verbose_generic_activity_with_arg("codegen cgu", cgu_name.as_str()).run(|| {
+            let cgu = tcx.codegen_unit(cgu_name);
+            let mono_items = cgu.items_in_deterministic_order(tcx);
+
+            let mut module = make_module(tcx.sess, &backend_config, cgu_name.as_str().to_string());
+
+            let mut cx = crate::CodegenCx::new(
+                tcx,
+                backend_config.clone(),
+                module.isa(),
+                tcx.sess.opts.debuginfo != DebugInfo::None,
+                cgu_name,
+            );
+            super::predefine_mono_items(tcx, &mut module, &mono_items);
+            let mut codegened_functions = vec![];
+            for (mono_item, _) in mono_items {
+                match mono_item {
+                    MonoItem::Fn(inst) => {
                         let codegened_function = crate::base::codegen_fn(
                             tcx,
                             &mut cx,
@@ -299,53 +299,68 @@ fn module_codegen(
                             inst,
                         );
                         codegened_functions.push(codegened_function);
-                    });
-                }
-                MonoItem::Static(def_id) => {
-                    crate::constant::codegen_static(tcx, &mut module, def_id)
-                }
-                MonoItem::GlobalAsm(item_id) => {
-                    crate::global_asm::codegen_global_asm_item(tcx, &mut cx.global_asm, item_id);
+                    }
+                    MonoItem::Static(def_id) => {
+                        crate::constant::codegen_static(tcx, &mut module, def_id)
+                    }
+                    MonoItem::GlobalAsm(item_id) => {
+                        crate::global_asm::codegen_global_asm_item(
+                            tcx,
+                            &mut cx.global_asm,
+                            item_id,
+                        );
+                    }
                 }
             }
-        }
-        crate::main_shim::maybe_create_entry_wrapper(
-            tcx,
-            &mut module,
-            &mut cx.unwind_context,
-            false,
-            cgu.is_primary(),
-        );
+            crate::main_shim::maybe_create_entry_wrapper(
+                tcx,
+                &mut module,
+                &mut cx.unwind_context,
+                false,
+                cgu.is_primary(),
+            );
 
-        let cgu_name = cgu.name().as_str().to_owned();
+            let cgu_name = cgu.name().as_str().to_owned();
 
-        (cgu_name, cx, module, codegened_functions)
-    });
+            (cgu_name, cx, module, codegened_functions)
+        });
 
     OngoingModuleCodegen::Async(std::thread::spawn(move || {
-        cx.profiler.clone().verbose_generic_activity("compile functions").run(|| {
-            let mut cached_context = Context::new();
-            for codegened_func in codegened_functions {
-                crate::base::compile_fn(&mut cx, &mut cached_context, &mut module, codegened_func);
-            }
-        });
+        cx.profiler.clone().verbose_generic_activity_with_arg("compile functions", &*cgu_name).run(
+            || {
+                let mut cached_context = Context::new();
+                for codegened_func in codegened_functions {
+                    crate::base::compile_fn(
+                        &mut cx,
+                        &mut cached_context,
+                        &mut module,
+                        codegened_func,
+                    );
+                }
+            },
+        );
 
-        let global_asm_object_file =
-            cx.profiler.verbose_generic_activity("compile assembly").run(|| {
+        let global_asm_object_file = cx
+            .profiler
+            .verbose_generic_activity_with_arg("compile assembly", &*cgu_name)
+            .run(|| {
                 crate::global_asm::compile_global_asm(&global_asm_config, &cgu_name, &cx.global_asm)
             })?;
 
-        let codegen_result = cx.profiler.verbose_generic_activity("write object file").run(|| {
-            emit_cgu(
-                &global_asm_config.output_filenames,
-                &cx.profiler,
-                cgu_name,
-                module,
-                cx.debug_context,
-                cx.unwind_context,
-                global_asm_object_file,
-            )
-        });
+        let codegen_result = cx
+            .profiler
+            .verbose_generic_activity_with_arg("write object file", &*cgu_name)
+            .run(|| {
+                emit_cgu(
+                    &global_asm_config.output_filenames,
+                    &cx.profiler,
+                    cgu_name,
+                    module,
+                    cx.debug_context,
+                    cx.unwind_context,
+                    global_asm_object_file,
+                )
+            });
         std::mem::drop(token);
         codegen_result
     }))
@@ -375,7 +390,7 @@ pub(crate) fn run_aot(
 
     let mut concurrency_limiter = ConcurrencyLimiter::new(tcx.sess, cgus.len());
 
-    let modules = super::time(tcx, backend_config.display_cg_time, "codegen mono items", || {
+    let modules = tcx.sess.time("codegen mono items", || {
         cgus.iter()
             .map(|cgu| {
                 let cgu_reuse = if backend_config.disable_incr_cache {
@@ -437,7 +452,6 @@ pub(crate) fn run_aot(
     };
 
     let metadata_module = if need_metadata_module {
-        let _timer = tcx.prof.generic_activity("codegen crate metadata");
         let (metadata_cgu_name, tmp_file) = tcx.sess.time("write compressed metadata", || {
             use rustc_middle::mir::mono::CodegenUnitNameBuilder;