Continuation:
“Where is my money time lebowski kernel?”
Docs: Linux timing and scheduling granularity | Frits Hoogland Weblog
$ cd /sys/kernel/debug/tracing
$ echo __arm64_sys_ppoll | sudo tee set_ftrace_filter
# serialq thread pid
$ echo 17906 | sudo tee set_ftrace_pid
$ echo function_graph | sudo tee current_tracer
$ echo 1 | sudo tee tracing_on
$ sudo cat ./trace | less
0) ! 750.870 us | __arm64_sys_ppoll();
0) 0.814 us | __arm64_sys_ppoll();
0) + 60.130 us | __arm64_sys_ppoll();
0) 0.760 us | __arm64_sys_ppoll();
0) + 85.426 us | __arm64_sys_ppoll();
0) 0.777 us | __arm64_sys_ppoll();
0) + 54.389 us | __arm64_sys_ppoll();
0) 0.740 us | __arm64_sys_ppoll();
0) ! 767.296 us | __arm64_sys_ppoll();
0) 0.778 us | __arm64_sys_ppoll();
# Hmmm
$ echo __arm64_sys_ppoll | sudo tee set_graph_function
$ echo | sudo tee set_ftrace_filter
$ echo | sudo tee trace
$ sudo cat ./trace | less
3) | __arm64_sys_ppoll() {
3) 0.259 us | get_timespec64();
3) | ktime_get_ts64() {
3) 0.259 us | arch_counter_read();
3) 0.759 us | }
3) 0.259 us | timespec64_add_safe();
3) 0.259 us | set_user_sigmask();
3) | do_sys_poll() {
3) | select_estimate_accuracy() {
3) | ktime_get_ts64() {
3) 0.259 us | arch_counter_read();
3) 0.741 us | }
3) 0.259 us | set_normalized_timespec64();
3) 2.000 us | }
3) | fdget() {
3) 0.241 us | __rcu_read_lock();
3) 0.259 us | __rcu_read_unlock();
3) 1.389 us | }
3) | tty_poll() {
3) | tty_ldisc_ref_wait() {
3) 0.426 us | ldsem_down_read();
3) 0.908 us | }
3) | n_tty_poll() {
3) | __pollwait() {
3) | add_wait_queue() {
3) 0.278 us | _raw_spin_lock_irqsave();
3) 0.240 us | _raw_spin_unlock_irqrestore();
3) 1.204 us | }
3) 1.685 us | }
3) | __pollwait() {
3) | add_wait_queue() {
3) 0.259 us | _raw_spin_lock_irqsave();
3) 0.241 us | _raw_spin_unlock_irqrestore();
3) 1.204 us | }
3) 1.666 us | }
3) | tty_buffer_flush_work() {
3) | flush_work() {
3) | __flush_work() {
3) 0.259 us | __rcu_read_lock();
3) 0.259 us | _raw_spin_lock_irq();
3) 0.241 us | _raw_spin_unlock_irq();
3) 0.241 us | __rcu_read_unlock();
3) 2.167 us | }
3) 2.648 us | }
3) 3.130 us | }
3) 0.241 us | tty_hung_up_p();
3) 0.241 us | mutex_is_locked();
3) | tty_chars_in_buffer() {
3) | acm_tty_chars_in_buffer [cdc_acm]() {
3) 0.259 us | _raw_spin_lock_irqsave();
3) 0.260 us | _raw_spin_unlock_irqrestore();
3) 1.222 us | }
3) 1.704 us | }
3) + 10.426 us | }
3) | tty_ldisc_deref() {
3) 0.259 us | ldsem_up_read();
3) 0.815 us | }
3) + 13.240 us | }
3) 0.352 us | fput();
3) | fdget() {
3) 0.259 us | __rcu_read_lock();
3) 0.241 us | __rcu_read_unlock();
3) 1.444 us | }
3) | pipe_poll() {
3) | __pollwait() {
3) | add_wait_queue() {
3) 0.241 us | _raw_spin_lock_irqsave();
3) 0.259 us | _raw_spin_unlock_irqrestore();
3) 1.778 us | }
3) 2.259 us | }
3) 2.760 us | }
3) 0.352 us | fput();
3) | schedule_hrtimeout_range() {
3) | schedule_hrtimeout_range_clock() {
3) | hrtimer_init_sleeper() {
3) 0.389 us | __hrtimer_init();
3) 0.870 us | }
3) | hrtimer_start_range_ns() {
3) 0.259 us | _raw_spin_lock_irqsave();
3) | get_nohz_timer_target() {
3) 0.259 us | idle_cpu();
3) 0.722 us | }
3) 0.315 us | enqueue_hrtimer();
3) 0.241 us | _raw_spin_unlock_irqrestore();
3) 3.167 us | }
3) | schedule() {
3) | rcu_note_context_switch() {
3) 0.240 us | rcu_qs();
3) 0.722 us | }
3) 0.241 us | _raw_spin_lock();
3) 0.278 us | update_rq_clock();
3) | dequeue_task_fair() {
3) | dequeue_entities() {
3) | dequeue_entity() {
3) | update_curr() {
3) 0.260 us | update_curr_se();
3) 0.241 us | update_min_vruntime();
3) 0.260 us | cpuacct_charge();
3) | __cgroup_account_cputime() {
3) 0.278 us | cgroup_base_stat_cputime_account_begin();
3) 0.259 us | cgroup_rstat_updated();
3) 1.241 us | }
3) | dl_server_update() {
3) | update_curr_dl_se() {
3) 0.259 us | dl_scaled_delta_exec();
3) 0.741 us | }
3) 1.222 us | }
3) 4.667 us | }
3) 0.260 us | vruntime_eligible();
3) 0.278 us | __update_load_avg_se();
3) 0.278 us | __update_load_avg_cfs_rq();
3) | update_entity_lag() {
3) 0.259 us | avg_vruntime();
3) 0.723 us | }
3) 0.259 us | update_cfs_group();
3) 0.259 us | update_min_vruntime();
3) 8.648 us | }
3) | dequeue_entity() {
3) | update_curr() {
3) 0.259 us | update_curr_se();
3) 0.259 us | __calc_delta.constprop.0();
3) 0.259 us | update_min_vruntime();
3) 1.685 us | }
3) 0.259 us | vruntime_eligible();
3) 0.259 us | __update_load_avg_se();
3) 0.240 us | __update_load_avg_cfs_rq();
3) | update_entity_lag() {
3) 0.334 us | avg_vruntime();
3) 0.352 us | __calc_delta.constprop.0();
3) 1.370 us | }
3) 0.259 us | update_cfs_group();
3) 0.259 us | update_min_vruntime();
3) 6.759 us | }
3) | dequeue_entity() {
3) | update_curr() {
3) 0.240 us | update_curr_se();
3) 0.241 us | __calc_delta.constprop.0();
3) 0.259 us | update_min_vruntime();
3) 1.797 us | }
3) 0.259 us | vruntime_eligible();
3) 0.260 us | __update_load_avg_se();
3) 0.259 us | __update_load_avg_cfs_rq();
3) | update_entity_lag() {
3) 0.260 us | avg_vruntime();
3) 0.334 us | __calc_delta.constprop.0();
3) 1.407 us | }
3) 0.259 us | update_cfs_group();
3) 0.260 us | update_min_vruntime();
3) 6.926 us | }
3) | dl_server_stop() {
3) 0.241 us | __dequeue_dl_entity();
3) | task_non_contending() {
3) 0.259 us | hrtimer_active();
3) | hrtimer_start_range_ns() {
3) 0.259 us | _raw_spin_lock_irqsave();
3) | ktime_get() {
3) 0.260 us | arch_counter_read();
3) 0.759 us | }
3) | get_nohz_timer_target() {
3) 0.241 us | idle_cpu();
3) 0.814 us | }
3) 0.333 us | enqueue_hrtimer();
3) 0.241 us | _raw_spin_unlock_irqrestore();
3) 4.018 us | }
3) 5.148 us | }
3) | hrtimer_try_to_cancel() {
3) 0.259 us | hrtimer_active();
3) | hrtimer_try_to_cancel.part.0() {
3) 0.259 us | _raw_spin_lock_irqsave();
3) 0.278 us | __remove_hrtimer();
3) 0.240 us | _raw_spin_unlock_irqrestore();
3) 1.834 us | }
3) 2.982 us | }
3) 9.463 us | }
3) + 33.000 us | }
3) 0.259 us | hrtick_update();
3) + 33.981 us | }
3) | pick_next_task_fair() {
3) 0.352 us | pick_task_fair();
3) | sched_balance_newidle() {
3) 0.241 us | __rcu_read_lock();
3) 0.241 us | __msecs_to_jiffies();
3) 0.240 us | __rcu_read_unlock();
3) 1.889 us | }
3) 2.944 us | }
3) 0.259 us | pick_task_idle();
3) | put_prev_task_fair() {
3) 0.260 us | put_prev_entity();
3) 0.259 us | put_prev_entity();
3) 0.241 us | put_prev_entity();
3) 1.685 us | }
3) 0.259 us | set_next_task_idle();
3) | psi_task_switch() {
3) 0.241 us | psi_flags_change();
3) | psi_group_change() {
3) 0.259 us | record_times();
3) 0.797 us | }
3) | psi_group_change() {
3) 0.259 us | record_times();
3) 0.778 us | }
3) | psi_group_change() {
3) 0.259 us | record_times();
3) 0.778 us | }
3) 3.796 us | }
3) 0.352 us | _raw_spin_lock_irqsave();
3) 0.240 us | _raw_spin_unlock_irqrestore();
3) | finish_task_switch.isra.0() {
3) 0.259 us | _raw_spin_unlock();
3) 0.778 us | }
3) ! 726.240 us | }
3) | hrtimer_try_to_cancel.part.0() {
3) 0.352 us | _raw_spin_lock_irqsave();
3) 0.352 us | __remove_hrtimer();
3) 0.389 us | _raw_spin_unlock_irqrestore();
3) 2.000 us | }
3) ! 733.481 us | }
3) ! 734.074 us | }
3) | fdget() {
3) 0.259 us | __rcu_read_lock();
3) 0.259 us | __rcu_read_unlock();
3) 1.407 us | }
3) | tty_poll() {
3) | tty_ldisc_ref_wait() {
3) 0.296 us | ldsem_down_read();
3) 0.981 us | }
3) | n_tty_poll() {
3) 0.241 us | tty_hung_up_p();
3) 0.333 us | mutex_is_locked();
3) | tty_chars_in_buffer() {
3) | acm_tty_chars_in_buffer [cdc_acm]() {
3) 0.296 us | _raw_spin_lock_irqsave();
3) 0.334 us | _raw_spin_unlock_irqrestore();
3) 1.407 us | }
3) 1.981 us | }
3) | tty_write_room() {
3) | acm_tty_write_room [cdc_acm]() {
3) 0.260 us | _raw_spin_lock_irqsave();
3) 0.260 us | _raw_spin_unlock_irqrestore();
3) 1.222 us | }
3) 1.704 us | }
3) 5.833 us | }
3) | tty_ldisc_deref() {
3) 0.259 us | ldsem_up_read();
3) 0.722 us | }
3) 8.685 us | }
3) 0.278 us | fput();
3) | fdget() {
3) 0.259 us | __rcu_read_lock();
3) 0.241 us | __rcu_read_unlock();
3) 1.296 us | }
3) 0.259 us | pipe_poll();
3) 0.260 us | fput();
3) | poll_freewait() {
3) | remove_wait_queue() {
3) 0.297 us | _raw_spin_lock_irqsave();
3) 0.259 us | _raw_spin_unlock_irqrestore();
3) 1.537 us | }
3) 0.352 us | fput();
3) | remove_wait_queue() {
3) 0.296 us | _raw_spin_lock_irqsave();
3) 0.241 us | _raw_spin_unlock_irqrestore();
3) 1.500 us | }
3) 0.259 us | fput();
3) | remove_wait_queue() {
3) 0.259 us | _raw_spin_lock_irqsave();
3) 0.352 us | _raw_spin_unlock_irqrestore();
3) 1.426 us | }
3) 0.260 us | fput();
3) 7.148 us | }
3) ! 779.593 us | }
3) | poll_select_finish() {
3) | ktime_get_ts64() {
3) 0.277 us | arch_counter_read();
3) 0.889 us | }
3) 0.259 us | set_normalized_timespec64();
3) 0.259 us | put_timespec64();
3) 2.611 us | }
3) ! 785.482 us | }
For me, who is not very familiar with kernel tracing,
It looks like it really wastes time on block + switching task + rescheduling.
(I rebooted the machine)
Well, rt and priority tricks do not help to reduce RTT or make it react faster on average.
Hope someone finds this curious.
Thanks.
I’ve reused/updated the branch to print data from serialqueue sent/recv and reactor separately: Klipper: communication bus tests
Well, to spam the pings and get the average latency.