From 626cfe01bbb87bf4bed24374616859e9c92b5bc1 Mon Sep 17 00:00:00 2001 From: Bill Thiede Date: Thu, 24 Oct 2019 14:08:03 -0700 Subject: [PATCH] Add function calls to understand detached results. --- src/flamegraph.svg | 4 ++-- src/main.rs | 26 ++++++++++++++++++++++++++ 2 files changed, 28 insertions(+), 2 deletions(-) diff --git a/src/flamegraph.svg b/src/flamegraph.svg index 22be3af..cebdb96 100644 --- a/src/flamegraph.svg +++ b/src/flamegraph.svg @@ -1,4 +1,4 @@ -Flame Graph Reset ZoomSearch perf_4.19 (4 samples, 0.20%)[unknown] (4 samples, 0.20%)entry_SYSCALL_64_after_hwframe (4 samples, 0.20%)do_syscall_64 (4 samples, 0.20%)__x64_sys_execve (4 samples, 0.20%)__do_execve_file.isra.34 (4 samples, 0.20%)search_binary_handler (4 samples, 0.20%)load_elf_binary (4 samples, 0.20%)setup_new_exec (4 samples, 0.20%)perf_event_exec (4 samples, 0.20%)__intel_pmu_enable_all.constprop.23 (4 samples, 0.20%)native_write_msr (4 samples, 0.20%)[unknown] (1 samples, 0.05%)entry_SYSCALL_64_after_hwframe (1 samples, 0.05%)do_syscall_64 (1 samples, 0.05%)__x64_sys_execve (1 samples, 0.05%)__do_execve_file.isra.34 (1 samples, 0.05%)search_binary_handler (1 samples, 0.05%)load_elf_binary (1 samples, 0.05%)elf_map (1 samples, 0.05%)vm_mmap_pgoff (1 samples, 0.05%)do_mmap (1 samples, 0.05%)mmap_region (1 samples, 0.05%)vm_area_alloc (1 samples, 0.05%)kmem_cache_alloc (1 samples, 0.05%)memcg_kmem_get_cache (1 samples, 0.05%)get_mem_cgroup_from_mm (1 samples, 0.05%)<std::time::Instant as core::ops::arith::Sub>::sub (43 samples, 2.18%)<..std::sys::unix::time::Timespec::sub_timespec (36 samples, 1.82%)rustperf::four (187 samples, 9.48%)rustperf::fourstd::time::Instant::now (144 samples, 7.30%)std::time:..__clock_gettime (139 samples, 7.05%)__clock_g..__vdso_clock_gettime (132 samples, 6.69%)__vdso_cl..[[vdso]] (81 samples, 4.11%)[[vd..<std::time::Instant as core::ops::arith::Sub>::sub (119 samples, 6.03%)<std::ti..std::sys::unix::time::Timespec::sub_timespec (86 samples, 4.36%)std::..apic_timer_interrupt (1 samples, 0.05%)smp_apic_timer_interrupt (1 samples, 0.05%)hrtimer_interrupt (1 samples, 0.05%)__hrtimer_run_queues (1 samples, 0.05%)tick_sched_timer (1 samples, 0.05%)tick_sched_do_timer (1 samples, 0.05%)timekeeping_advance (1 samples, 0.05%)timekeeping_update (1 samples, 0.05%)notifier_call_chain (1 samples, 0.05%)pvclock_gtod_notify (1 samples, 0.05%)rustperf::four (581 samples, 29.45%)rustperf::fourstd::time::Instant::now (442 samples, 22.40%)std::time::Instant::now__clock_gettime (423 samples, 21.44%)__clock_gettime__vdso_clock_gettime (374 samples, 18.96%)__vdso_clock_gettime[[vdso]] (229 samples, 11.61%)[[vdso]]<std::time::Instant as core::ops::arith::Sub>::sub (46 samples, 2.33%)<..std::sys::unix::time::Timespec::sub_timespec (36 samples, 1.82%)rustperf::one (197 samples, 9.98%)rustperf::onestd::time::Instant::now (142 samples, 7.20%)std::time:..__clock_gettime (137 samples, 6.94%)__clock_g..__vdso_clock_gettime (127 samples, 6.44%)__vdso_c..[[vdso]] (84 samples, 4.26%)[[vds..<std::time::Instant as core::ops::arith::Sub>::sub (130 samples, 6.59%)<std::tim..std::sys::unix::time::Timespec::sub_timespec (96 samples, 4.87%)std::s..rustperf::three (594 samples, 30.11%)rustperf::threestd::time::Instant::now (434 samples, 22.00%)std::time::Instant::now__clock_gettime (412 samples, 20.88%)__clock_gettime__vdso_clock_gettime (375 samples, 19.01%)__vdso_clock_gettime[[vdso]] (247 samples, 12.52%)[[vdso]]<std::time::Instant as core::ops::arith::Sub>::sub (86 samples, 4.36%)<std:..std::sys::unix::time::Timespec::sub_timespec (72 samples, 3.65%)std:.._start (1,967 samples, 99.70%)_start__libc_start_main (1,967 samples, 99.70%)__libc_start_mainmain (1,967 samples, 99.70%)mainstd::rt::lang_start_internal (1,967 samples, 99.70%)std::rt::lang_start_internal__rust_maybe_catch_panic (1,967 samples, 99.70%)__rust_maybe_catch_panicstd::panicking::try::do_call (1,967 samples, 99.70%)std::panicking::try::do_callstd::rt::lang_start::_$u7b$$u7b$closure$u7d$$u7d$::h80d40c3a4e341551 (1,967 samples, 99.70%)std::rt::lang_start::_$u7b$$u7b$closure$u7d$$u7d$::h80d40c3a4e341551rustperf::main (1,780 samples, 90.22%)rustperf::mainrustperf::two (397 samples, 20.12%)rustperf::twostd::time::Instant::now (295 samples, 14.95%)std::time::Instant::now__clock_gettime (288 samples, 14.60%)__clock_gettime__vdso_clock_gettime (267 samples, 13.53%)__vdso_clock_gettime[[vdso]] (164 samples, 8.31%)[[vdso]]all (1,973 samples, 100%)rustperf (1,969 samples, 99.80%)rustperfentry_SYSCALL_64_after_hwframe (1 samples, 0.05%)do_syscall_64 (1 samples, 0.05%)__x64_sys_exit_group (1 samples, 0.05%)do_group_exit (1 samples, 0.05%)do_exit (1 samples, 0.05%)mmput (1 samples, 0.05%)exit_mmap (1 samples, 0.05%)unmap_vmas (1 samples, 0.05%)unmap_page_range (1 samples, 0.05%) \ No newline at end of file +]]>Flame Graph Reset ZoomSearch perf_4.19 (4 samples, 0.17%)[unknown] (4 samples, 0.17%)entry_SYSCALL_64_after_hwframe (4 samples, 0.17%)do_syscall_64 (4 samples, 0.17%)__x64_sys_execve (4 samples, 0.17%)__do_execve_file.isra.34 (4 samples, 0.17%)search_binary_handler (4 samples, 0.17%)load_elf_binary (4 samples, 0.17%)setup_new_exec (4 samples, 0.17%)perf_event_exec (4 samples, 0.17%)__intel_pmu_enable_all.constprop.23 (4 samples, 0.17%)native_write_msr (4 samples, 0.17%)[unknown] (1 samples, 0.04%)entry_SYSCALL_64_after_hwframe (1 samples, 0.04%)do_syscall_64 (1 samples, 0.04%)__x64_sys_execve (1 samples, 0.04%)__do_execve_file.isra.34 (1 samples, 0.04%)search_binary_handler (1 samples, 0.04%)load_elf_binary (1 samples, 0.04%)__clear_user (1 samples, 0.04%)page_fault (1 samples, 0.04%)__do_page_fault (1 samples, 0.04%)handle_mm_fault (1 samples, 0.04%)__handle_mm_fault (1 samples, 0.04%)__do_fault (1 samples, 0.04%)ext4_filemap_fault (1 samples, 0.04%)filemap_fault (1 samples, 0.04%)irq_entries_start (1 samples, 0.04%)<std::time::Instant as core::ops::arith::Sub>::sub (39 samples, 1.65%)std::sys::unix::time::Timespec::sub_timespec (30 samples, 1.27%)rustperf::last (194 samples, 8.19%)rustperf::l..std::time::Instant::now (155 samples, 6.54%)std::time..__clock_gettime (149 samples, 6.29%)__clock_..__vdso_clock_gettime (140 samples, 5.91%)__vdso_..[[vdso]] (86 samples, 3.63%)[[vd..<std::time::Instant as core::ops::arith::Sub>::sub (41 samples, 1.73%)std::sys::unix::time::Timespec::sub_timespec (30 samples, 1.27%)rustperf::first (186 samples, 7.85%)rustperf::..std::time::Instant::now (142 samples, 5.99%)std::ti..__clock_gettime (125 samples, 5.28%)__cloc..__vdso_clock_gettime (111 samples, 4.69%)__vds..[[vdso]] (63 samples, 2.66%)[[..<std::time::Instant as core::ops::arith::Sub>::sub (149 samples, 6.29%)<std::ti..std::sys::unix::time::Timespec::sub_timespec (111 samples, 4.69%)std::..apic_timer_interrupt (1 samples, 0.04%)smp_apic_timer_interrupt (1 samples, 0.04%)irq_enter (1 samples, 0.04%)rcu_nmi_enter (1 samples, 0.04%)[[vdso]] (351 samples, 14.82%)[[vdso]]rustperf::four (794 samples, 33.52%)rustperf::fourstd::time::Instant::now (620 samples, 26.17%)std::time::Instant::now__clock_gettime (590 samples, 24.91%)__clock_gettime__vdso_clock_gettime (539 samples, 22.75%)__vdso_clock_gettimeapic_timer_interrupt (1 samples, 0.04%)smp_apic_timer_interrupt (1 samples, 0.04%)irq_exit (1 samples, 0.04%)__softirqentry_text_start (1 samples, 0.04%)run_timer_softirq (1 samples, 0.04%)call_timer_fn (1 samples, 0.04%)tcp_keepalive_timer (1 samples, 0.04%)__tcp_transmit_skb (1 samples, 0.04%)ip_output (1 samples, 0.04%)ip_finish_output2 (1 samples, 0.04%)<std::time::Instant as core::ops::arith::Sub>::sub (53 samples, 2.24%)<..std::sys::unix::time::Timespec::sub_timespec (33 samples, 1.39%)__vdso_clock_gettime (116 samples, 4.90%)__vdso..[[vdso]] (78 samples, 3.29%)[[v..rustperf::one (199 samples, 8.40%)rustperf::o..std::time::Instant::now (142 samples, 5.99%)std::tim..__clock_gettime (129 samples, 5.45%)__clock..apic_timer_interrupt (1 samples, 0.04%)smp_apic_timer_interrupt (1 samples, 0.04%)hrtimer_interrupt (1 samples, 0.04%)__hrtimer_run_queues (1 samples, 0.04%)tick_sched_timer (1 samples, 0.04%)tick_sched_handle (1 samples, 0.04%)update_process_times (1 samples, 0.04%)scheduler_tick (1 samples, 0.04%)perf_event_task_tick (1 samples, 0.04%)<std::time::Instant as core::ops::arith::Sub>::sub (121 samples, 5.11%)<std::..std::sys::unix::time::Timespec::sub_timespec (89 samples, 3.76%)std:..[[vdso]] (258 samples, 10.89%)[[vdso]]apic_timer_interrupt (1 samples, 0.04%)smp_apic_timer_interrupt (1 samples, 0.04%)irq_exit (1 samples, 0.04%)__softirqentry_text_start (1 samples, 0.04%)rcu_process_callbacks (1 samples, 0.04%)note_gp_changes (1 samples, 0.04%)rustperf::three (592 samples, 24.99%)rustperf::threestd::time::Instant::now (452 samples, 19.08%)std::time::Instant::now__clock_gettime (419 samples, 17.69%)__clock_gettime__vdso_clock_gettime (380 samples, 16.04%)__vdso_clock_gettimeret_from_intr (1 samples, 0.04%)do_IRQ (1 samples, 0.04%)irq_exit (1 samples, 0.04%)__softirqentry_text_start (1 samples, 0.04%)net_rx_action (1 samples, 0.04%)igb_poll (1 samples, 0.04%)ret_from_intr (1 samples, 0.04%)do_IRQ (1 samples, 0.04%)irq_exit (1 samples, 0.04%)__softirqentry_text_start (1 samples, 0.04%)net_rx_action (1 samples, 0.04%)process_backlog (1 samples, 0.04%)__netif_receive_skb_one_core (1 samples, 0.04%)ip_rcv (1 samples, 0.04%)ip_local_deliver (1 samples, 0.04%)ip_local_deliver_finish (1 samples, 0.04%)tcp_v4_rcv (1 samples, 0.04%)tcp_v4_do_rcv (1 samples, 0.04%)tcp_rcv_established (1 samples, 0.04%)tcp_data_queue (1 samples, 0.04%)sock_def_readable (1 samples, 0.04%)__wake_up_common_lock (1 samples, 0.04%)__wake_up_common (1 samples, 0.04%)ep_poll_callback (1 samples, 0.04%)_raw_spin_lock_irqsave (1 samples, 0.04%)<std::time::Instant as core::ops::arith::Sub>::sub (83 samples, 3.50%)<st..std::sys::unix::time::Timespec::sub_timespec (56 samples, 2.36%)s..[[vdso]] (184 samples, 7.77%)[[vdso]]ret_from_intr (1 samples, 0.04%)do_IRQ (1 samples, 0.04%)irq_exit (1 samples, 0.04%)__softirqentry_text_start (1 samples, 0.04%)net_rx_action (1 samples, 0.04%)igb_poll (1 samples, 0.04%)napi_gro_receive (1 samples, 0.04%)netif_receive_skb_internal (1 samples, 0.04%)__netif_receive_skb_one_core (1 samples, 0.04%)ip_rcv (1 samples, 0.04%)nf_hook_slow (1 samples, 0.04%)nf_conntrack_in (1 samples, 0.04%)all (2,369 samples, 100%)rustperf (2,365 samples, 99.83%)rustperf_start (2,364 samples, 99.79%)_start__libc_start_main (2,364 samples, 99.79%)__libc_start_mainmain (2,364 samples, 99.79%)mainstd::rt::lang_start_internal (2,364 samples, 99.79%)std::rt::lang_start_internal__rust_maybe_catch_panic (2,364 samples, 99.79%)__rust_maybe_catch_panicstd::panicking::try::do_call (2,364 samples, 99.79%)std::panicking::try::do_callstd::rt::lang_start::_$u7b$$u7b$closure$u7d$$u7d$::h80d40c3a4e341551 (2,364 samples, 99.79%)std::rt::lang_start::_$u7b$$u7b$closure$u7d$$u7d$::h80d40c3a4e341551rustperf::main (2,170 samples, 91.60%)rustperf::mainrustperf::two (395 samples, 16.67%)rustperf::twostd::time::Instant::now (306 samples, 12.92%)std::time::Instant:..__clock_gettime (288 samples, 12.16%)__clock_gettime__vdso_clock_gettime (264 samples, 11.14%)__vdso_clock_get..ret_from_intr (1 samples, 0.04%)do_IRQ (1 samples, 0.04%)irq_exit (1 samples, 0.04%)__softirqentry_text_start (1 samples, 0.04%)net_rx_action (1 samples, 0.04%)process_backlog (1 samples, 0.04%)__netif_receive_skb_one_core (1 samples, 0.04%)__netif_receive_skb_core (1 samples, 0.04%)br_handle_frame (1 samples, 0.04%)nf_hook_slow (1 samples, 0.04%)br_nf_pre_routing (1 samples, 0.04%)nf_hook_slow (1 samples, 0.04%) \ No newline at end of file diff --git a/src/main.rs b/src/main.rs index 10a3054..f17baee 100644 --- a/src/main.rs +++ b/src/main.rs @@ -48,9 +48,34 @@ fn four(runtime: Duration) { } } +#[inline(never)] +fn first(runtime: Duration) { + println!("Starting first"); + let start = Instant::now(); + loop { + let diff = Instant::now() - start; + if diff > runtime { + return; + } + } +} + +#[inline(never)] +fn last(runtime: Duration) { + println!("Starting last"); + let start = Instant::now(); + loop { + let diff = Instant::now() - start; + if diff > runtime { + return; + } + } +} + fn main() { let runtime = Duration::new(2, 0); + first(runtime); four(runtime); three(runtime); two(runtime); @@ -61,4 +86,5 @@ fn main() { three(runtime); one(runtime); four(runtime); + last(runtime); }