preemption latency trace v1.0.3 ------------------------------- latency: 82 us, entries: 109 (109) ----------------- | task: in.telnetd/3486, uid:0 nice:0 policy:0 rt_prio:0 ----------------- => started at: release_sock+0x1c/0xa0 => ended at: tcp_write_xmit+0x249/0x330 =======> 00000100 0.000ms (+0.000ms): release_sock (tcp_sendmsg) 00000101 0.000ms (+0.000ms): __release_sock (release_sock) 00010100 0.002ms (+0.001ms): do_IRQ (tcp_v4_do_rcv) 00010101 0.002ms (+0.000ms): mask_and_ack_8259A (do_IRQ) 00010101 0.005ms (+0.002ms): generic_redirect_hardirq (do_IRQ) 00010100 0.005ms (+0.000ms): generic_handle_IRQ_event (do_IRQ) 00010100 0.006ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event) 00010101 0.006ms (+0.000ms): mark_offset_tsc (timer_interrupt) 00010101 0.013ms (+0.006ms): do_timer (timer_interrupt) 00010101 0.013ms (+0.000ms): update_process_times (do_timer) 00010101 0.014ms (+0.000ms): update_one_process (update_process_times) 00010101 0.014ms (+0.000ms): run_local_timers (update_process_times) 00010101 0.015ms (+0.000ms): raise_softirq (update_process_times) 00010101 0.015ms (+0.000ms): scheduler_tick (update_process_times) 00010101 0.015ms (+0.000ms): sched_clock (scheduler_tick) 00010102 0.017ms (+0.001ms): task_timeslice (scheduler_tick) 00010101 0.018ms (+0.000ms): update_wall_time (do_timer) 00010101 0.018ms (+0.000ms): update_wall_time_one_tick (update_wall_time) 00010101 0.019ms (+0.000ms): profile_tick (timer_interrupt) 00010101 0.020ms (+0.000ms): profile_hook (profile_tick) 00010102 0.020ms (+0.000ms): notifier_call_chain (profile_hook) 00010101 0.021ms (+0.000ms): profile_hit (timer_interrupt) 00010101 0.021ms (+0.000ms): generic_note_interrupt (do_IRQ) 00010101 0.022ms (+0.000ms): end_8259A_irq (do_IRQ) 00010101 0.022ms (+0.000ms): enable_8259A_irq (do_IRQ) 00000100 0.024ms (+0.001ms): tcp_v4_do_rcv (__release_sock) 00000100 0.025ms (+0.000ms): tcp_rcv_established (tcp_v4_do_rcv) 00000100 0.026ms (+0.001ms): tcp_ack (tcp_rcv_established) 00000100 0.026ms (+0.000ms): tcp_clean_rtx_queue (tcp_ack) 00000100 0.027ms (+0.000ms): __kfree_skb (tcp_clean_rtx_queue) 00000100 0.028ms (+0.000ms): kfree_skbmem (__kfree_skb) 00000100 0.028ms (+0.000ms): skb_release_data (kfree_skbmem) 00000100 0.029ms (+0.000ms): kfree (kfree_skbmem) 00000100 0.029ms (+0.000ms): kmem_cache_free (kfree_skbmem) 00000100 0.030ms (+0.000ms): tcp_ack_saw_tstamp (tcp_clean_rtx_queue) 00000100 0.030ms (+0.000ms): tcp_rtt_estimator (tcp_ack_saw_tstamp) 00000100 0.032ms (+0.001ms): __kfree_skb (tcp_rcv_established) 00000100 0.032ms (+0.000ms): kfree_skbmem (__kfree_skb) 00000100 0.032ms (+0.000ms): skb_release_data (kfree_skbmem) 00000100 0.033ms (+0.000ms): kfree (kfree_skbmem) 00000100 0.033ms (+0.000ms): kmem_cache_free (kfree_skbmem) 00000100 0.034ms (+0.000ms): __tcp_data_snd_check (tcp_rcv_established) 00000100 0.034ms (+0.000ms): tcp_write_xmit (__tcp_data_snd_check) 00000100 0.035ms (+0.000ms): skb_clone (tcp_write_xmit) 00000100 0.036ms (+0.000ms): kmem_cache_alloc (skb_clone) 00000100 0.036ms (+0.000ms): memcpy (skb_clone) 00000100 0.037ms (+0.000ms): tcp_transmit_skb (tcp_write_xmit) 00000100 0.038ms (+0.001ms): __tcp_select_window (tcp_transmit_skb) 00000100 0.040ms (+0.001ms): tcp_v4_send_check (tcp_transmit_skb) 00000100 0.041ms (+0.001ms): ip_queue_xmit (tcp_transmit_skb) 00000100 0.044ms (+0.002ms): nf_hook_slow (ip_queue_xmit) 00000101 0.044ms (+0.000ms): nf_iterate (nf_hook_slow) 00000101 0.045ms (+0.000ms): ipt_local_out_hook (nf_iterate) 00000101 0.045ms (+0.000ms): ipt_do_table (ipt_local_out_hook) 00000201 0.047ms (+0.001ms): local_bh_enable (ipt_do_table) 00000101 0.048ms (+0.000ms): dst_output (nf_hook_slow) 00000101 0.048ms (+0.000ms): ip_output (dst_output) 00000101 0.049ms (+0.000ms): ip_finish_output (dst_output) 00000201 0.049ms (+0.000ms): local_bh_enable (ip_finish_output) 00000101 0.050ms (+0.000ms): dev_queue_xmit (ip_finish_output) 00000203 0.051ms (+0.000ms): pfifo_fast_enqueue (dev_queue_xmit) 00000203 0.051ms (+0.000ms): qdisc_restart (dev_queue_xmit) 00000203 0.052ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart) 00000203 0.052ms (+0.000ms): e100_xmit_frame (qdisc_restart) 00000204 0.053ms (+0.000ms): e100_xmit_prepare (e100_xmit_frame) 00010204 0.055ms (+0.002ms): do_IRQ (e100_xmit_frame) 00010205 0.056ms (+0.000ms): mask_and_ack_8259A (do_IRQ) 00010205 0.060ms (+0.003ms): generic_redirect_hardirq (do_IRQ) 00010205 0.060ms (+0.000ms): wake_up_process (generic_redirect_hardirq) 00010205 0.061ms (+0.000ms): try_to_wake_up (wake_up_process) 00010205 0.061ms (+0.000ms): task_rq_lock (try_to_wake_up) 00010206 0.062ms (+0.000ms): activate_task (try_to_wake_up) 00010206 0.062ms (+0.000ms): sched_clock (activate_task) 00010206 0.062ms (+0.000ms): recalc_task_prio (activate_task) 00010206 0.063ms (+0.000ms): effective_prio (recalc_task_prio) 00010206 0.064ms (+0.000ms): enqueue_task (activate_task) 00010205 0.064ms (+0.000ms): preempt_schedule (try_to_wake_up) 00010204 0.065ms (+0.000ms): preempt_schedule (do_IRQ) 00010204 0.067ms (+0.001ms): do_IRQ (e100_xmit_frame) 00010205 0.067ms (+0.000ms): mask_and_ack_8259A (do_IRQ) 00010205 0.070ms (+0.002ms): preempt_schedule (do_IRQ) 00010205 0.070ms (+0.000ms): generic_redirect_hardirq (do_IRQ) 00010205 0.071ms (+0.000ms): wake_up_process (generic_redirect_hardirq) 00010205 0.071ms (+0.000ms): try_to_wake_up (wake_up_process) 00010205 0.071ms (+0.000ms): task_rq_lock (try_to_wake_up) 00010206 0.071ms (+0.000ms): activate_task (try_to_wake_up) 00010206 0.072ms (+0.000ms): sched_clock (activate_task) 00010206 0.072ms (+0.000ms): recalc_task_prio (activate_task) 00010206 0.072ms (+0.000ms): effective_prio (recalc_task_prio) 00010206 0.073ms (+0.000ms): enqueue_task (activate_task) 00010205 0.073ms (+0.000ms): preempt_schedule (try_to_wake_up) 00010204 0.074ms (+0.000ms): preempt_schedule (do_IRQ) 00000203 0.074ms (+0.000ms): preempt_schedule (e100_xmit_frame) 00000202 0.075ms (+0.000ms): preempt_schedule (qdisc_restart) 00000203 0.075ms (+0.000ms): qdisc_restart (dev_queue_xmit) 00000203 0.076ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart) 00000202 0.076ms (+0.000ms): preempt_schedule (dev_queue_xmit) 00000202 0.076ms (+0.000ms): local_bh_enable (dev_queue_xmit) 00000102 0.077ms (+0.000ms): preempt_schedule (dev_queue_xmit) 00000101 0.077ms (+0.000ms): preempt_schedule (dev_queue_xmit) 00000100 0.078ms (+0.000ms): preempt_schedule (nf_hook_slow) 00000100 0.079ms (+0.001ms): sk_reset_timer (tcp_write_xmit) 00000100 0.079ms (+0.000ms): mod_timer (sk_reset_timer) 00000100 0.080ms (+0.000ms): __mod_timer (sk_reset_timer) 00000102 0.081ms (+0.000ms): internal_add_timer (__mod_timer) 00000101 0.081ms (+0.000ms): preempt_schedule (__mod_timer) 00000100 0.082ms (+0.000ms): preempt_schedule (__mod_timer) 00000100 0.083ms (+0.001ms): touch_preempt_timing (tcp_write_xmit) 00000100 0.083ms (+0.000ms): update_max_trace (check_preempt_timing)