Re: Random abnormal high CPU sys usage related to timer
From: Mac Lin
Date: Mon Aug 29 2016 - 12:27:06 EST
On Mon, Aug 29, 2016 at 6:45 PM, Thomas Gleixner <tglx@xxxxxxxxxxxxx> wrote:
> Tracing will tell you exactly what's going on in the system.
Will, it seems that I lost my direction. But anyway, there are some
gains to revisit the old tests.
>>> I've checked the /proc/timer_stats, /proc/interrupts, and perf, all
>>> the irq counter, timer counter, timer/irq event didn't show any
>>> abnormal value or useful clue.
I have to take that back. The above result is with another test code
which is harder to reproduce the issue.
Attached the debug info get with and without the issue. Comparing the
two got the following:
* The /proc/timer_stats is almost the same, but perf events shows
extra softirq/timer events.
* The perf sample of the failed case is much more than the good case,
but the ratio of the sampled functions are basically the same.
On Mon, Aug 29, 2016 at 6:45 PM, Thomas Gleixner <tglx@xxxxxxxxxxxxx> wrote:
> On Sat, 27 Aug 2016, Mac Lin wrote:
>> Hi Vegard,
>> Thanks for the prompt response.
>> The commit is introduced since 4.6, but the issue can be reproduced at
>> 3.10 (earliest I have ever test). And testing on buildroot+4.7 with
>> the commit reverted, the issue still happen.
>>
>> In fact, I did a test that ran a script that keep increase a counter
>> for 10 seconds on the same CPU. If I ran 2 of it, the number is half
>> of running 1. But if I ran it while the issue happened, the counter
>> reported is around the same value as the 1 process case. So I doubt
>> that it might be an issue of reported number.
>>
>> Is there other way to ensure the CPU is "really" doing something?
>
> Tracing will tell you exactly what's going on in the system.
>
> Thanks,
>
> tglx
# echo 1 > /proc/timer_stats;sleep 10;
# echo 0 > /proc/timer_stats; cat /proc/timer_stats | sort -t ',' -b -k 2 -n | grep test
6, 25294 test-host do_nanosleep (hrtimer_wakeup)
99717, 25294 test-host hrtimer_start (it_real_fn)
# sudo perf stat -e irq:*,timer:* -p $(pidof test-host) sleep 10
Warning: unknown op '{'
Warning: unknown op '{'
Performance counter stats for process id '25294':
0 irq:irq_handler_entry
0 irq:irq_handler_exit
2,706 irq:softirq_entry
2,712 irq:softirq_exit
2,716 irq:softirq_raise
0 timer:timer_init
5 timer:timer_start
648 timer:timer_expire_entry
649 timer:timer_expire_exit
650 timer:timer_cancel
101,175 timer:hrtimer_init
204,365 timer:hrtimer_start
1,865 timer:hrtimer_expire_entry
1,867 timer:hrtimer_expire_exit
103,351 timer:hrtimer_cancel
0 timer:itimer_state
5 timer:itimer_expire
0 timer:tick_stop
10.000852806 seconds time elapsed
# sudo perf stat -p $(pidof test-host) sleep 10
Performance counter stats for process id '25294':
786.097515 task-clock (msec) # 0.079 CPUs utilized
100,425 context-switches # 0.128 M/sec
0 cpu-migrations # 0.000 K/sec
<not counted> page-faults
614,752,853 cycles # 0.782 GHz [100.00%]
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
708,966,076 instructions # 1.15 insns per cycle
132,275,374 branches # 168.268 M/sec
901,980 branch-misses # 0.68% of all branches
10.001767161 seconds time elapsed
# sudo perf record -p $(pidof test-host) -s -T -R sleep 10
[ perf record: Woken up 8 times to write data ]
[ perf record: Captured and wrote 1.865 MB perf.data (~81471 samples) ]
# sudo perf report -I -n | grep xxxxxxxxxxa -v
# ========
# captured on: Mon Aug 29 23:13:13 2016
# hostname : test-Vostro-5470
# os release : 3.13.0-45-generic
# perf version : 3.13.11-ckt13
# arch : x86_64
# nrcpus online : 4
# nrcpus avail : 4
# cpudesc : Intel(R) Core(TM) i5-4200U CPU @ 1.60GHz
# cpuid : GenuineIntel,6,69,1
# total memory : 3953448 kB
# cmdline : /usr/lib/linux-tools-3.13.0-45/perf record -p 25294 -s -T -R sleep 10
# event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap = 1, attr_mmap_data = 0
# sibling cores : 0-3
# sibling threads : 0-1
# sibling threads : 2-3
# node0 meminfo : total = 3953448 kB, free = 207796 kB
# node0 cpu list : 0-3
# pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5
# ========
#
# Samples: 34K of event 'cycles'
# Event count (approx.): 597604549
#
# Overhead Samples Command Shared Object Symbol
# ........ ............ ......... ................. ..........................................
#
11.12% 3641 test-host [kernel.kallsyms] [k] native_write_msr_safe
7.20% 2443 test-host test-host [.] timer_handler
6.88% 2426 test-host libc-2.19.so [.] __GI___libc_nanosleep
4.06% 1417 test-host [kernel.kallsyms] [k] update_cfs_shares
3.54% 1243 test-host [kernel.kallsyms] [k] do_signal
2.41% 747 test-host [kernel.kallsyms] [k] __restore_xstate_sig
2.33% 761 test-host [kernel.kallsyms] [k] do_nanosleep
2.13% 772 test-host [kernel.kallsyms] [k] update_curr
2.06% 730 test-host [kernel.kallsyms] [k] save_xstate_sig
2.05% 744 test-host [kernel.kallsyms] [k] dequeue_entity
1.96% 718 test-host [kernel.kallsyms] [k] __calc_delta
1.87% 600 test-host [kernel.kallsyms] [k] hrtimer_nanosleep
1.83% 638 test-host [kernel.kallsyms] [k] _raw_spin_lock_irq
1.58% 561 test-host [kernel.kallsyms] [k] cpuacct_charge
1.58% 568 test-host [kernel.kallsyms] [k] __schedule
1.58% 486 test-host [kernel.kallsyms] [k] _raw_spin_lock_irqsave
1.57% 571 test-host [kernel.kallsyms] [k] native_read_tsc
1.57% 496 test-host [kernel.kallsyms] [k] __hrtimer_start_range_ns
1.41% 497 test-host [kernel.kallsyms] [k] copy_user_enhanced_fast_string
1.34% 485 test-host [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore
1.32% 487 test-host [kernel.kallsyms] [k] timerqueue_add
1.28% 462 test-host [kernel.kallsyms] [k] system_call
1.25% 443 test-host [kernel.kallsyms] [k] _raw_spin_lock
1.22% 444 test-host [kernel.kallsyms] [k] setup_sigcontext
1.17% 408 test-host [kernel.kallsyms] [k] system_call_after_swapgs
1.15% 329 test-host test-host [.] main
1.14% 420 test-host [kernel.kallsyms] [k] recalc_sigpending
1.11% 410 test-host [kernel.kallsyms] [k] dequeue_task_fair
1.00% 367 test-host [kernel.kallsyms] [k] kmem_cache_free
0.92% 340 test-host [kernel.kallsyms] [k] free_uid
0.89% 318 test-host [kernel.kallsyms] [k] ktime_get
0.85% 305 test-host [kernel.kallsyms] [k] get_signal_to_deliver
0.84% 300 test-host [kernel.kallsyms] [k] account_entity_dequeue
0.83% 301 test-host [kernel.kallsyms] [k] clockevents_program_event
0.82% 299 test-host [kernel.kallsyms] [k] update_min_vruntime
0.76% 276 test-host libc-2.19.so [.] __restore_rt
0.71% 176 test-host [kernel.kallsyms] [k] __dequeue_signal
0.66% 160 test-host [kernel.kallsyms] [k] perf_event_context_sched_in
0.60% 212 test-host libc-2.19.so [.] usleep
0.59% 224 test-host [kernel.kallsyms] [k] hrtimer_init
0.58% 200 test-host [kernel.kallsyms] [k] schedule
0.56% 207 test-host [kernel.kallsyms] [k] sys_nanosleep
0.55% 204 test-host [kernel.kallsyms] [k] _atomic_dec_and_lock
0.54% 200 test-host [kernel.kallsyms] [k] rb_insert_color
0.54% 205 test-host [kernel.kallsyms] [k] put_prev_task_fair
0.54% 190 test-host [kernel.kallsyms] [k] system_call_fastpath
0.54% 189 test-host [kernel.kallsyms] [k] __sigqueue_free.part.11
0.52% 189 test-host [kernel.kallsyms] [k] sched_clock_cpu
0.51% 185 test-host [kernel.kallsyms] [k] local_clock
0.48% 174 test-host [kernel.kallsyms] [k] do_sigaltstack
0.46% 155 test-host [kernel.kallsyms] [k] finish_task_switch
0.44% 155 test-host [kernel.kallsyms] [k] dequeue_signal
0.43% 158 test-host [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.39
0.40% 149 test-host [kernel.kallsyms] [k] native_sched_clock
0.40% 142 test-host [kernel.kallsyms] [k] update_cfs_rq_blocked_load
0.38% 140 test-host [kernel.kallsyms] [k] __set_current_blocked
0.38% 131 test-host [kernel.kallsyms] [k] enqueue_hrtimer
0.38% 132 test-host [kernel.kallsyms] [k] pick_next_task_stop
0.36% 51 test-host [kernel.kallsyms] [k] int_with_check
0.36% 133 test-host [kernel.kallsyms] [k] ctx_sched_out
0.35% 120 test-host [kernel.kallsyms] [k] recalc_sigpending_tsk
0.35% 124 test-host [kernel.kallsyms] [k] restore_sigcontext
0.33% 124 test-host [kernel.kallsyms] [k] hrtimer_try_to_cancel
0.32% 117 test-host [kernel.kallsyms] [k] __clear_user
0.32% 39 test-host [kernel.kallsyms] [k] uprobe_deny_signal
0.31% 112 test-host [kernel.kallsyms] [k] perf_pmu_disable
0.31% 111 test-host [kernel.kallsyms] [k] lock_hrtimer_base.isra.19
0.31% 102 test-host [kernel.kallsyms] [k] _cond_resched
0.30% 102 test-host [kernel.kallsyms] [k] __remove_hrtimer
0.29% 107 test-host [kernel.kallsyms] [k] account_entity_enqueue
0.28% 105 test-host [kernel.kallsyms] [k] sysret_signal
0.26% 90 test-host [kernel.kallsyms] [k] read_tsc
0.25% 91 test-host [kernel.kallsyms] [k] pick_next_task_fair
0.24% 88 test-host [kernel.kallsyms] [k] hrtimer_force_reprogram
0.24% 89 test-host [kernel.kallsyms] [k] sys_rt_sigreturn
0.24% 86 test-host [kernel.kallsyms] [k] __perf_event_task_sched_out
0.24% 83 test-host [kernel.kallsyms] [k] stub_rt_sigreturn
0.23% 83 test-host [kernel.kallsyms] [k] __set_task_blocked
0.23% 85 test-host [kernel.kallsyms] [k] dequeue_task
0.23% 82 test-host [kernel.kallsyms] [k] tick_program_event
0.22% 82 test-host [kernel.kallsyms] [k] _raw_spin_unlock
0.22% 79 test-host [kernel.kallsyms] [k] ctx_sched_in
0.20% 75 test-host [kernel.kallsyms] [k] lapic_next_deadline
0.20% 78 test-host [kernel.kallsyms] [k] ret_from_sys_call
0.19% 67 test-host [kernel.kallsyms] [k] hrtimer_forward
0.18% 64 test-host [kernel.kallsyms] [k] signal_delivered
0.17% 61 test-host [kernel.kallsyms] [k] do_notify_resume
0.17% 63 test-host [kernel.kallsyms] [k] __perf_event_task_sched_in
0.17% 63 test-host [kernel.kallsyms] [k] idle_cpu
0.16% 56 test-host [kernel.kallsyms] [k] idle_balance
0.16% 55 test-host [kernel.kallsyms] [k] rb_erase
0.15% 58 test-host [kernel.kallsyms] [k] clear_buddies
0.15% 50 test-host [kernel.kallsyms] [k] x86_pmu_enable
0.14% 50 test-host [kernel.kallsyms] [k] int_check_syscall_exit_work
0.13% 51 test-host [kernel.kallsyms] [k] apic_timer_interrupt
0.12% 42 test-host [kernel.kallsyms] [k] pick_next_task_rt
0.11% 40 test-host [kernel.kallsyms] [k] perf_event_sched_in
0.11% 41 test-host [kernel.kallsyms] [k] retint_swapgs
0.11% 40 test-host [kernel.kallsyms] [k] perf_pmu_enable
0.10% 36 test-host [kernel.kallsyms] [k] restore_args
0.10% 37 test-host [kernel.kallsyms] [k] update_rq_clock.part.63
0.10% 35 test-host [kernel.kallsyms] [k] restore_altstack
0.10% 33 test-host [kernel.kallsyms] [k] perf_pmu_nop_void
0.09% 33 test-host [kernel.kallsyms] [k] timerqueue_del
0.08% 31 test-host [kernel.kallsyms] [k] rcu_note_context_switch
0.08% 27 test-host [kernel.kallsyms] [k] rb_next
0.08% 29 test-host [kernel.kallsyms] [k] perf_event_task_sched_out
0.08% 28 test-host [kernel.kallsyms] [k] int_restore_rest
0.07% 27 test-host [kernel.kallsyms] [k] signal_setup_done
0.07% 23 test-host [kernel.kallsyms] [k] x86_pmu_disable
0.07% 24 test-host [kernel.kallsyms] [k] task_tick_fair
0.06% 23 test-host [kernel.kallsyms] [k] intel_pmu_enable_all
0.06% 22 test-host [kernel.kallsyms] [k] intel_pmu_disable_all
0.06% 19 test-host [kernel.kallsyms] [k] hrtimer_start_range_ns
0.06% 21 test-host [kernel.kallsyms] [k] sysret_check
0.06% 21 test-host [kernel.kallsyms] [k] update_wall_time
0.05% 16 test-host [kernel.kallsyms] [k] native_irq_return_iret
0.05% 17 test-host [kernel.kallsyms] [k] __do_softirq
0.05% 19 test-host [kernel.kallsyms] [k] run_timer_softirq
0.04% 15 test-host [kernel.kallsyms] [k] set_current_blocked
0.04% 15 test-host [kernel.kallsyms] [k] cpu_needs_another_gp
0.04% 14 test-host [kernel.kallsyms] [k] rcu_check_callbacks
0.04% 15 test-host [kernel.kallsyms] [k] pick_next_task_idle
0.04% 15 test-host [kernel.kallsyms] [k] irq_exit
0.04% 12 test-host [kernel.kallsyms] [k] trigger_load_balance
0.03% 13 test-host [kernel.kallsyms] [k] deactivate_task
0.03% 11 test-host [kernel.kallsyms] [k] sched_clock
0.03% 11 test-host [kernel.kallsyms] [k] int_ret_from_sys_call
0.03% 8 test-host [kernel.kallsyms] [k] _copy_from_user
0.03% 11 test-host [kernel.kallsyms] [k] rcu_irq_enter
0.03% 10 test-host [kernel.kallsyms] [k] perf_event_task_tick
0.03% 7 test-host [kernel.kallsyms] [k] enqueue_task_fair
0.02% 9 test-host [kernel.kallsyms] [k] account_system_time
0.02% 9 test-host [kernel.kallsyms] [k] hrtick_update
0.02% 8 test-host [kernel.kallsyms] [k] notifier_call_chain
0.02% 8 test-host [kernel.kallsyms] [k] int_signal
0.02% 7 test-host [kernel.kallsyms] [k] check_preempt_wakeup
0.02% 8 test-host [kernel.kallsyms] [k] nohz_balance_exit_idle.part.53
0.02% 8 test-host [kernel.kallsyms] [k] calc_global_load
0.02% 8 test-host [kernel.kallsyms] [k] enqueue_entity
0.02% 7 test-host [kernel.kallsyms] [k] account_process_tick
0.02% 4 test-host [kernel.kallsyms] [k] wq_worker_waking_up
0.02% 7 test-host test-host [.] usleep@plt
0.02% 7 test-host [kernel.kallsyms] [k] sysret_careful
0.02% 7 test-host [kernel.kallsyms] [k] hrtimer_interrupt
0.02% 7 test-host [kernel.kallsyms] [k] __update_cpu_load
0.02% 7 test-host [kernel.kallsyms] [k] pvclock_gtod_notify
0.02% 6 test-host [kernel.kallsyms] [k] update_cpu_load_active
0.02% 6 test-host [kernel.kallsyms] [k] tick_do_update_jiffies64
0.02% 6 test-host [kernel.kallsyms] [k] raise_softirq
0.02% 6 test-host [kernel.kallsyms] [k] cpumask_clear_cpu
0.02% 6 test-host [kernel.kallsyms] [k] update_vsyscall
0.02% 6 test-host [kernel.kallsyms] [k] rcu_irq_exit
0.01% 6 test-host [kernel.kallsyms] [k] kthread_data
0.01% 3 test-host [kernel.kallsyms] [k] msecs_to_jiffies
0.01% 5 test-host [kernel.kallsyms] [k] rcu_process_callbacks
0.01% 5 test-host [kernel.kallsyms] [k] __acct_update_integrals
0.01% 5 test-host [kernel.kallsyms] [k] profile_tick
0.01% 5 test-host [kernel.kallsyms] [k] run_posix_cpu_timers
0.01% 4 test-host [kernel.kallsyms] [k] insert_work
0.01% 4 test-host [kernel.kallsyms] [k] __irq_work_run
0.01% 4 test-host [kernel.kallsyms] [k] cpuacct_account_field
0.01% 4 test-host [kernel.kallsyms] [k] perf_adjust_freq_unthr_context.part.79
0.01% 4 test-host [kernel.kallsyms] [k] ret_from_intr
0.01% 4 test-host [kernel.kallsyms] [k] rcu_bh_qs
0.01% 2 test-host [kernel.kallsyms] [k] wake_up_process
0.01% 4 test-host [kernel.kallsyms] [k] update_process_times
0.01% 4 test-host [kernel.kallsyms] [k] update_blocked_averages
0.01% 3 test-host [kernel.kallsyms] [k] scheduler_tick
0.01% 3 test-host [kernel.kallsyms] [k] fget_light
0.01% 3 test-host [kernel.kallsyms] [k] __local_bh_enable
0.01% 3 test-host [kernel.kallsyms] [k] timekeeping_update.constprop.9
0.01% 3 test-host [kernel.kallsyms] [k] local_apic_timer_interrupt
0.01% 3 test-host [kernel.kallsyms] [k] ktime_get_update_offsets
0.01% 3 test-host [kernel.kallsyms] [k] native_apic_mem_write
0.01% 3 test-host [kernel.kallsyms] [k] hrtimer_run_pending
0.01% 2 test-host [kernel.kallsyms] [k] invoke_rcu_core
0.01% 2 test-host [kernel.kallsyms] [k] note_gp_changes
0.01% 2 test-host [kernel.kallsyms] [k] find_busiest_group
0.01% 2 test-host [kernel.kallsyms] [k] tty_write
0.01% 2 test-host [kernel.kallsyms] [k] check_preempt_curr
0.01% 1 test-host [kernel.kallsyms] [k] tick_sched_do_timer
0.01% 2 test-host [kernel.kallsyms] [k] __queue_work
0.01% 2 test-host [kernel.kallsyms] [k] hrtimer_run_queues
0.01% 2 test-host [kernel.kallsyms] [k] ntp_tick_length
0.01% 2 test-host [kernel.kallsyms] [k] fetch_task_cputime
0.01% 2 test-host libc-2.19.so [.] _IO_file_write@@GLIBC_2.2.5
0.01% 2 test-host [kernel.kallsyms] [k] irq_enter
0.01% 2 test-host [kernel.kallsyms] [k] __enqueue_entity
0.01% 2 test-host [kernel.kallsyms] [k] load_balance
0.01% 2 test-host [kernel.kallsyms] [k] tick_sched_handle.isra.17
0.01% 2 test-host [kernel.kallsyms] [k] rcu_report_qs_rnp
0.00% 2 test-host [kernel.kallsyms] [k] set_next_buddy
0.00% 2 test-host [kernel.kallsyms] [k] __run_hrtimer
0.00% 2 test-host [kernel.kallsyms] [k] get_work_pool
0.00% 1 test-host [kernel.kallsyms] [k] prepare_signal
0.00% 1 test-host [kernel.kallsyms] [k] retint_careful
0.00% 1 test-host [kernel.kallsyms] [k] smp_apic_timer_interrupt
0.00% 1 test-host libc-2.19.so [.] _IO_do_write@@GLIBC_2.2.5
0.00% 1 test-host [kernel.kallsyms] [k] _raw_spin_trylock
0.00% 1 test-host [kernel.kallsyms] [k] raw_notifier_call_chain
0.00% 1 test-host [kernel.kallsyms] [k] update_stats_wait_end
0.00% 1 test-host [kernel.kallsyms] [k] int_careful
0.00% 1 test-host [kernel.kallsyms] [k] tty_insert_flip_string_fixed_flag
0.00% 1 test-host [kernel.kallsyms] [k] update_group_power
0.00% 1 test-host [kernel.kallsyms] [k] rcu_sysidle_exit
0.00% 1 test-host [kernel.kallsyms] [k] kmem_cache_alloc
0.00% 1 test-host [kernel.kallsyms] [k] wakeup_gran.isra.47
0.00% 1 test-host [kernel.kallsyms] [k] account_user_time
0.00% 1 test-host [kernel.kallsyms] [k] acct_account_cputime
0.00% 1 test-host [kernel.kallsyms] [k] __note_gp_changes
0.00% 1 test-host [kernel.kallsyms] [k] wake_up_worker
0.00% 1 test-host [kernel.kallsyms] [k] resched_task
0.00% 1 test-host [kernel.kallsyms] [k] find_next_bit
0.00% 1 test-host [kernel.kallsyms] [k] rcu_sysidle_enter
0.00% 1 test-host [kernel.kallsyms] [k] ttwu_stat
0.00% 1 test-host [kernel.kallsyms] [k] do_timer
0.00% 1 test-host [kernel.kallsyms] [k] set_next_entity
0.00% 1 test-host [kernel.kallsyms] [k] rebalance_domains
0.00% 1 test-host [kernel.kallsyms] [k] delayed_work_timer_fn
0.00% 1 test-host [kernel.kallsyms] [k] set_normalized_timespec
0.00% 1 test-host [kernel.kallsyms] [k] schedule_user
0.00% 1 test-host [kernel.kallsyms] [k] tick_sched_timer
0.00% 1 test-host [kernel.kallsyms] [k] place_entity
0.00% 1 test-host libc-2.19.so [.] vfprintf
#
# (For a higher level overview, try: perf report --sort comm,dso)
#
# echo 1 > /proc/timer_stats;sleep 10;
# echo 0 > /proc/timer_stats; cat /proc/timer_stats | sort -t ',' -b -k 2 -n | grep test
6, 25115 test-host do_nanosleep (hrtimer_wakeup)
99867, 25115 test-host hrtimer_start (it_real_fn)
# sudo perf stat -e irq:*,timer:* -p $(pidof test-host) sleep 10
Warning: unknown op '{'
Warning: unknown op '{'
Performance counter stats for process id '25115':
0 irq:irq_handler_entry
0 irq:irq_handler_exit
0 irq:softirq_entry
0 irq:softirq_exit
0 irq:softirq_raise
0 timer:timer_init
0 timer:timer_start
0 timer:timer_expire_entry
0 timer:timer_expire_exit
0 timer:timer_cancel
100,745 timer:hrtimer_init
201,652 timer:hrtimer_start
4 timer:hrtimer_expire_entry
4 timer:hrtimer_expire_exit
101,065 timer:hrtimer_cancel
0 timer:itimer_state
2 timer:itimer_expire
0 timer:tick_stop
10.000763356 seconds time elapsed
# sudo perf stat -p $(pidof test-host) sleep 10
Performance counter stats for process id '25115':
847.348719 task-clock (msec) # 0.085 CPUs utilized
99,981 context-switches # 0.118 M/sec
0 cpu-migrations # 0.000 K/sec
0 page-faults # 0.000 K/sec
607,782,792 cycles # 0.717 GHz
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
700,673,778 instructions # 1.15 insns per cycle
130,516,259 branches # 154.029 M/sec
887,230 branch-misses # 0.68% of all branches
10.000683870 seconds time elapsed
# sudo perf record -p $(pidof test-host) -s -T -R sleep 10
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.039 MB perf.data (~1685 samples) ]
# sudo perf report -I -n | grep xxxxxxxxxxa -v
# ========
# captured on: Mon Aug 29 23:09:44 2016
# hostname : test-Vostro-5470
# os release : 3.13.0-45-generic
# perf version : 3.13.11-ckt13
# arch : x86_64
# nrcpus online : 4
# nrcpus avail : 4
# cpudesc : Intel(R) Core(TM) i5-4200U CPU @ 1.60GHz
# cpuid : GenuineIntel,6,69,1
# total memory : 3953448 kB
# cmdline : /usr/lib/linux-tools-3.13.0-45/perf record -p 25115 -s -T -R sleep 10
# event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap = 1, attr_mmap_data = 0
# sibling cores : 0-3
# sibling threads : 0-1
# sibling threads : 2-3
# node0 meminfo : total = 3953448 kB, free = 182324 kB
# node0 cpu list : 0-3
# pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5
# ========
#
# Samples: 442 of event 'cycles'
# Event count (approx.): 534240571
#
# Overhead Samples Command Shared Object Symbol
# ........ ............ ......... ................. ..................................
#
11.78% 68 test-host [kernel.kallsyms] [k] native_write_msr_safe
5.29% 22 test-host test-host [.] timer_handler
5.29% 22 test-host libc-2.19.so [.] __GI___libc_nanosleep
3.85% 16 test-host [kernel.kallsyms] [k] do_signal
3.60% 15 test-host [kernel.kallsyms] [k] update_cfs_shares
2.88% 12 test-host [kernel.kallsyms] [k] dequeue_entity
2.40% 10 test-host [kernel.kallsyms] [k] __restore_xstate_sig
2.40% 10 test-host [kernel.kallsyms] [k] hrtimer_nanosleep
2.40% 10 test-host [kernel.kallsyms] [k] kmem_cache_free
2.16% 9 test-host [kernel.kallsyms] [k] hrtimer_init
2.16% 9 test-host [kernel.kallsyms] [k] do_nanosleep
1.92% 8 test-host [kernel.kallsyms] [k] save_xstate_sig
1.70% 7 test-host [kernel.kallsyms] [k] system_call_after_swapgs
1.68% 7 test-host [kernel.kallsyms] [k] recalc_sigpending
1.68% 7 test-host [kernel.kallsyms] [k] __hrtimer_start_range_ns
1.68% 7 test-host [kernel.kallsyms] [k] __calc_delta
1.68% 7 test-host [kernel.kallsyms] [k] update_curr
1.68% 7 test-host [kernel.kallsyms] [k] dequeue_task_fair
1.68% 7 test-host [kernel.kallsyms] [k] ktime_get
1.44% 6 test-host [kernel.kallsyms] [k] timerqueue_add
1.44% 6 test-host [kernel.kallsyms] [k] _raw_spin_lock
1.44% 6 test-host [kernel.kallsyms] [k] _raw_spin_lock_irq
1.20% 5 test-host libc-2.19.so [.] usleep
1.20% 5 test-host [kernel.kallsyms] [k] setup_sigcontext
1.20% 5 test-host [kernel.kallsyms] [k] native_read_tsc
1.20% 5 test-host [kernel.kallsyms] [k] do_sigaltstack
1.20% 5 test-host [kernel.kallsyms] [k] update_min_vruntime
1.20% 5 test-host [kernel.kallsyms] [k] cpuacct_charge
1.20% 5 test-host [kernel.kallsyms] [k] ctx_sched_out
1.20% 5 test-host [kernel.kallsyms] [k] copy_user_enhanced_fast_string
1.20% 5 test-host [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore
1.20% 5 test-host [kernel.kallsyms] [k] int_check_syscall_exit_work
1.20% 5 test-host [kernel.kallsyms] [k] __schedule
0.96% 7 test-host [kernel.kallsyms] [k] perf_event_context_sched_in
0.96% 4 test-host [kernel.kallsyms] [k] get_signal_to_deliver
0.96% 4 test-host [kernel.kallsyms] [k] sched_clock_cpu
0.96% 4 test-host [kernel.kallsyms] [k] finish_task_switch
0.96% 4 test-host [kernel.kallsyms] [k] system_call
0.72% 4 test-host [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.39
0.72% 3 test-host [kernel.kallsyms] [k] hrtimer_try_to_cancel
0.72% 3 test-host [kernel.kallsyms] [k] sys_nanosleep
0.72% 3 test-host [kernel.kallsyms] [k] account_entity_dequeue
0.72% 3 test-host [kernel.kallsyms] [k] put_prev_task_fair
0.72% 3 test-host [kernel.kallsyms] [k] perf_event_sched_in
0.72% 3 test-host [kernel.kallsyms] [k] _raw_spin_lock_irqsave
0.72% 3 test-host [kernel.kallsyms] [k] stub_rt_sigreturn
0.48% 2 test-host test-host [.] main
0.48% 2 test-host libc-2.19.so [.] __restore_rt
0.48% 2 test-host [kernel.kallsyms] [k] sys_rt_sigreturn
0.48% 2 test-host [kernel.kallsyms] [k] read_tsc
0.48% 2 test-host [kernel.kallsyms] [k] native_sched_clock
0.48% 2 test-host [kernel.kallsyms] [k] free_uid
0.48% 2 test-host [kernel.kallsyms] [k] __sigqueue_free.part.11
0.48% 2 test-host [kernel.kallsyms] [k] restore_altstack
0.48% 2 test-host [kernel.kallsyms] [k] pick_next_task_fair
0.48% 2 test-host [kernel.kallsyms] [k] perf_pmu_disable
0.48% 2 test-host [kernel.kallsyms] [k] __perf_event_task_sched_in
0.48% 2 test-host [kernel.kallsyms] [k] __perf_event_task_sched_out
0.48% 2 test-host [kernel.kallsyms] [k] schedule
0.48% 2 test-host [kernel.kallsyms] [k] system_call_fastpath
0.48% 2 test-host [kernel.kallsyms] [k] sysret_signal
0.48% 2 test-host [kernel.kallsyms] [k] __set_current_blocked
0.48% 2 test-host [kernel.kallsyms] [k] __remove_hrtimer
0.48% 2 test-host [kernel.kallsyms] [k] clockevents_program_event
0.25% 2 test-host [kernel.kallsyms] [k] _atomic_dec_and_lock
0.24% 1 test-host [kernel.kallsyms] [k] restore_sigcontext
0.24% 1 test-host [kernel.kallsyms] [k] do_notify_resume
0.24% 1 test-host [kernel.kallsyms] [k] x86_pmu_disable
0.24% 1 test-host [kernel.kallsyms] [k] intel_pmu_disable_all
0.24% 1 test-host [kernel.kallsyms] [k] __dequeue_signal
0.24% 1 test-host [kernel.kallsyms] [k] dequeue_signal
0.24% 1 test-host [kernel.kallsyms] [k] __set_task_blocked
0.24% 1 test-host [kernel.kallsyms] [k] enqueue_hrtimer
0.24% 1 test-host [kernel.kallsyms] [k] idle_cpu
0.24% 1 test-host [kernel.kallsyms] [k] local_clock
0.24% 1 test-host [kernel.kallsyms] [k] pick_next_task_idle
0.24% 1 test-host [kernel.kallsyms] [k] update_cfs_rq_blocked_load
0.24% 1 test-host [kernel.kallsyms] [k] clear_buddies
0.24% 1 test-host [kernel.kallsyms] [k] pick_next_task_rt
0.24% 1 test-host [kernel.kallsyms] [k] pick_next_task_stop
0.24% 1 test-host [kernel.kallsyms] [k] perf_pmu_enable
0.24% 1 test-host [kernel.kallsyms] [k] rb_insert_color
0.24% 1 test-host [kernel.kallsyms] [k] __clear_user
0.24% 1 test-host [kernel.kallsyms] [k] retint_swapgs
0.24% 1 test-host [kernel.kallsyms] [k] sysret_check
0.24% 1 test-host [kernel.kallsyms] [k] hrtimer_start_range_ns
0.00% 1 test-host [kernel.kallsyms] [k] _raw_spin_unlock
0.00% 1 test-host [kernel.kallsyms] [k] x86_pmu_enable
#
# (For a higher level overview, try: perf report --sort comm,dso)
#