mirror of
https://github.com/torvalds/linux
synced 2024-11-05 18:23:50 +00:00
8b2a5dac78
Disabling interrupts in trace_clock_local takes quite a performance
hit to the recording of traces. Using perf top we see:
------------------------------------------------------------------------------
PerfTop: 244 irqs/sec kernel:100.0% [1000Hz cpu-clock-msecs], (all, 4 CPUs)
------------------------------------------------------------------------------
samples pcnt kernel function
_______ _____ _______________
2842.00 - 40.4% : trace_clock_local
1043.00 - 14.8% : rb_reserve_next_event
784.00 - 11.1% : ring_buffer_lock_reserve
600.00 - 8.5% : __rb_reserve_next
579.00 - 8.2% : rb_end_commit
440.00 - 6.3% : ring_buffer_unlock_commit
290.00 - 4.1% : ring_buffer_producer_thread [ring_buffer_benchmark]
155.00 - 2.2% : debug_smp_processor_id
117.00 - 1.7% : trace_recursive_unlock
103.00 - 1.5% : ring_buffer_event_data
28.00 - 0.4% : do_gettimeofday
22.00 - 0.3% : _spin_unlock_irq
14.00 - 0.2% : native_read_tsc
11.00 - 0.2% : getnstimeofday
Where trace_clock_local is 40% of the tracing, and the time for recording
a trace according to ring_buffer_benchmark is 210ns. After converting
the interrupts to preemption disabling we have from perf top:
------------------------------------------------------------------------------
PerfTop: 1084 irqs/sec kernel:99.9% [1000Hz cpu-clock-msecs], (all, 4 CPUs)
------------------------------------------------------------------------------
samples pcnt kernel function
_______ _____ _______________
1277.00 - 16.8% : native_read_tsc
1148.00 - 15.1% : rb_reserve_next_event
896.00 - 11.8% : ring_buffer_lock_reserve
688.00 - 9.1% : __rb_reserve_next
664.00 - 8.8% : rb_end_commit
563.00 - 7.4% : ring_buffer_unlock_commit
508.00 - 6.7% : _spin_unlock_irq
365.00 - 4.8% : debug_smp_processor_id
321.00 - 4.2% : trace_clock_local
303.00 - 4.0% : ring_buffer_producer_thread [ring_buffer_benchmark]
273.00 - 3.6% : native_sched_clock
122.00 - 1.6% : trace_recursive_unlock
113.00 - 1.5% : sched_clock
101.00 - 1.3% : ring_buffer_event_data
53.00 - 0.7% : tick_nohz_stop_sched_tick
Where trace_clock_local drops from 40% to only taking 4% of the total time.
The trace time also goes from 210ns down to 179ns (31ns).
I talked with Peter Zijlstra about the impact that sched_clock may have
without having interrupts disabled, and he told me that if a timer interrupt
comes in, sched_clock may report a wrong time.
Balancing a seldom incorrect timestamp with a 15% performance boost, I'll
take the performance boost.
Acked-by: Peter Zijlstra <peterz@infradead.org>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
|
||
|---|---|---|
| .. | ||
| gcov | ||
| irq | ||
| power | ||
| time | ||
| trace | ||
| .gitignore | ||
| acct.c | ||
| async.c | ||
| audit.c | ||
| audit.h | ||
| audit_tree.c | ||
| audit_watch.c | ||
| auditfilter.c | ||
| auditsc.c | ||
| backtracetest.c | ||
| bounds.c | ||
| capability.c | ||
| cgroup.c | ||
| cgroup_freezer.c | ||
| compat.c | ||
| configs.c | ||
| cpu.c | ||
| cpuset.c | ||
| cred-internals.h | ||
| cred.c | ||
| delayacct.c | ||
| dma.c | ||
| exec_domain.c | ||
| exit.c | ||
| extable.c | ||
| fork.c | ||
| freezer.c | ||
| futex.c | ||
| futex_compat.c | ||
| groups.c | ||
| hrtimer.c | ||
| hung_task.c | ||
| itimer.c | ||
| kallsyms.c | ||
| Kconfig.freezer | ||
| Kconfig.hz | ||
| Kconfig.preempt | ||
| kexec.c | ||
| kfifo.c | ||
| kgdb.c | ||
| kmod.c | ||
| kprobes.c | ||
| ksysfs.c | ||
| kthread.c | ||
| latencytop.c | ||
| lockdep.c | ||
| lockdep_internals.h | ||
| lockdep_proc.c | ||
| lockdep_states.h | ||
| Makefile | ||
| module.c | ||
| mutex-debug.c | ||
| mutex-debug.h | ||
| mutex.c | ||
| mutex.h | ||
| notifier.c | ||
| ns_cgroup.c | ||
| nsproxy.c | ||
| panic.c | ||
| params.c | ||
| perf_event.c | ||
| pid.c | ||
| pid_namespace.c | ||
| pm_qos_params.c | ||
| posix-cpu-timers.c | ||
| posix-timers.c | ||
| printk.c | ||
| profile.c | ||
| ptrace.c | ||
| rcupdate.c | ||
| rcutorture.c | ||
| rcutree.c | ||
| rcutree.h | ||
| rcutree_plugin.h | ||
| rcutree_trace.c | ||
| relay.c | ||
| res_counter.c | ||
| resource.c | ||
| rtmutex-debug.c | ||
| rtmutex-debug.h | ||
| rtmutex-tester.c | ||
| rtmutex.c | ||
| rtmutex.h | ||
| rtmutex_common.h | ||
| rwsem.c | ||
| sched.c | ||
| sched_clock.c | ||
| sched_cpupri.c | ||
| sched_cpupri.h | ||
| sched_debug.c | ||
| sched_fair.c | ||
| sched_features.h | ||
| sched_idletask.c | ||
| sched_rt.c | ||
| sched_stats.h | ||
| seccomp.c | ||
| semaphore.c | ||
| signal.c | ||
| slow-work.c | ||
| smp.c | ||
| softirq.c | ||
| softlockup.c | ||
| spinlock.c | ||
| srcu.c | ||
| stacktrace.c | ||
| stop_machine.c | ||
| sys.c | ||
| sys_ni.c | ||
| sysctl.c | ||
| sysctl_check.c | ||
| taskstats.c | ||
| test_kprobes.c | ||
| time.c | ||
| timeconst.pl | ||
| timer.c | ||
| tracepoint.c | ||
| tsacct.c | ||
| uid16.c | ||
| up.c | ||
| user.c | ||
| user_namespace.c | ||
| utsname.c | ||
| utsname_sysctl.c | ||
| wait.c | ||
| workqueue.c | ||