Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6
From: Lee Revell
Date: Fri Aug 13 2004 - 14:58:49 EST
On Fri, 2004-08-13 at 06:31, Ingo Molnar wrote:
> * Lee Revell <rlrevell@xxxxxxxxxxx> wrote:
>
> > > > http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> >
> > Ugh, this is a bad one:
> >
> > preemption latency trace v1.0
> > -----------------------------
> > latency: 506 us, entries: 157 (157)
> > process: evolution/3461, uid: 1000
> > nice: 0, policy: 0, rt_priority: 0
> > =======>
> > 0.000ms (+0.000ms): get_random_bytes (__check_and_rekey)
> [...]
> > 0.493ms (+0.001ms): local_bh_enable (__check_and_rekey)
>
> indeed this is a new one. Entropy rekeying every 300 seconds. Most of
> the overhead comes from the memcpy's - 10 usecs a pop!
Here's another case where those memcpy's hurt. This was the biggest
latency reported last night:
preemption latency trace v1.0
-----------------------------
latency: 683 us, entries: 329 (329)
process: ksoftirqd/0/2, uid: 0
nice: -10, policy: 0, rt_priority: 0
=======>
0.000ms (+0.000ms): process_backlog (net_rx_action)
0.000ms (+0.000ms): netif_receive_skb (process_backlog)
0.002ms (+0.002ms): packet_rcv_spkt (netif_receive_skb)
0.003ms (+0.000ms): skb_clone (packet_rcv_spkt)
0.003ms (+0.000ms): kmem_cache_alloc (skb_clone)
0.004ms (+0.000ms): memcpy (skb_clone)
0.006ms (+0.001ms): strlcpy (packet_rcv_spkt)
0.007ms (+0.001ms): sk_run_filter (packet_rcv_spkt)
0.010ms (+0.002ms): __kfree_skb (packet_rcv_spkt)
0.010ms (+0.000ms): kfree_skbmem (__kfree_skb)
0.010ms (+0.000ms): skb_release_data (kfree_skbmem)
0.011ms (+0.000ms): kmem_cache_free (kfree_skbmem)
0.011ms (+0.000ms): ip_rcv (netif_receive_skb)
0.013ms (+0.001ms): ip_route_input (ip_rcv)
0.014ms (+0.000ms): rt_hash_code (ip_route_input)
0.015ms (+0.001ms): ip_route_input_slow (ip_rcv)
0.017ms (+0.001ms): rt_hash_code (ip_route_input_slow)
0.018ms (+0.001ms): fn_hash_lookup (ip_route_input_slow)
0.020ms (+0.001ms): fib_semantic_match (fn_hash_lookup)
0.022ms (+0.002ms): fib_validate_source (ip_route_input_slow)
0.023ms (+0.001ms): fn_hash_lookup (fib_validate_source)
0.024ms (+0.001ms): fn_hash_lookup (fib_validate_source)
0.026ms (+0.001ms): fib_semantic_match (fn_hash_lookup)
0.027ms (+0.000ms): __fib_res_prefsrc (fib_validate_source)
0.027ms (+0.000ms): inet_select_addr (__fib_res_prefsrc)
0.030ms (+0.002ms): do_IRQ (common_interrupt)
0.030ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
0.034ms (+0.003ms): generic_redirect_hardirq (do_IRQ)
0.034ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
0.034ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
0.035ms (+0.000ms): mark_offset_tsc (timer_interrupt)
0.041ms (+0.005ms): do_timer (timer_interrupt)
0.041ms (+0.000ms): update_process_times (do_timer)
0.041ms (+0.000ms): update_one_process (update_process_times)
0.042ms (+0.000ms): run_local_timers (update_process_times)
0.042ms (+0.000ms): raise_softirq (update_process_times)
0.043ms (+0.000ms): scheduler_tick (update_process_times)
0.043ms (+0.000ms): sched_clock (scheduler_tick)
0.044ms (+0.001ms): task_timeslice (scheduler_tick)
0.045ms (+0.000ms): update_wall_time (do_timer)
0.045ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
0.046ms (+0.000ms): generic_note_interrupt (do_IRQ)
0.046ms (+0.000ms): end_8259A_irq (do_IRQ)
0.046ms (+0.000ms): enable_8259A_irq (do_IRQ)
0.048ms (+0.001ms): dst_alloc (ip_route_input_slow)
0.049ms (+0.000ms): kmem_cache_alloc (dst_alloc)
0.050ms (+0.000ms): cache_alloc_refill (kmem_cache_alloc)
0.055ms (+0.005ms): rt_intern_hash (ip_route_input_slow)
0.056ms (+0.001ms): local_bh_enable (rt_intern_hash)
0.058ms (+0.001ms): ip_local_deliver (ip_rcv)
0.059ms (+0.001ms): tcp_v4_rcv (ip_local_deliver)
0.060ms (+0.000ms): tcp_v4_checksum_init (tcp_v4_rcv)
0.060ms (+0.000ms): skb_checksum (tcp_v4_checksum_init)
0.065ms (+0.004ms): tcp_v4_do_rcv (tcp_v4_rcv)
0.066ms (+0.000ms): tcp_v4_hnd_req (tcp_v4_do_rcv)
0.066ms (+0.000ms): tcp_v4_search_req (tcp_v4_hnd_req)
0.068ms (+0.002ms): tcp_rcv_state_process (tcp_v4_do_rcv)
0.069ms (+0.001ms): tcp_v4_conn_request (tcp_rcv_state_process)
0.070ms (+0.000ms): kmem_cache_alloc (tcp_v4_conn_request)
0.071ms (+0.000ms): cache_alloc_refill (kmem_cache_alloc)
0.072ms (+0.001ms): cache_grow (cache_alloc_refill)
0.073ms (+0.000ms): kmem_flagcheck (cache_grow)
0.073ms (+0.000ms): kmem_getpages (cache_grow)
0.073ms (+0.000ms): __get_free_pages (kmem_getpages)
0.074ms (+0.000ms): __alloc_pages (__get_free_pages)
0.074ms (+0.000ms): buffered_rmqueue (__alloc_pages)
0.075ms (+0.000ms): bad_range (buffered_rmqueue)
0.076ms (+0.000ms): prep_new_page (buffered_rmqueue)
0.076ms (+0.000ms): zone_statistics (__alloc_pages)
0.077ms (+0.000ms): alloc_slabmgmt (cache_grow)
0.077ms (+0.000ms): set_slab_attr (cache_grow)
0.078ms (+0.000ms): cache_init_objs (cache_grow)
0.084ms (+0.005ms): tcp_parse_options (tcp_v4_conn_request)
0.087ms (+0.003ms): secure_tcp_sequence_number (tcp_v4_conn_request)
0.087ms (+0.000ms): do_gettimeofday (secure_tcp_sequence_number)
0.088ms (+0.000ms): get_offset_tsc (do_gettimeofday)
0.089ms (+0.000ms): __check_and_rekey (secure_tcp_sequence_number)
0.089ms (+0.000ms): get_random_bytes (__check_and_rekey)
0.090ms (+0.000ms): extract_entropy (get_random_bytes)
0.091ms (+0.001ms): extract_entropy (extract_entropy)
0.093ms (+0.001ms): SHATransform (extract_entropy)
0.093ms (+0.000ms): memcpy (SHATransform)
0.103ms (+0.009ms): add_entropy_words (extract_entropy)
[...]
0.572ms (+0.000ms): SHATransform (extract_entropy)
0.572ms (+0.000ms): memcpy (SHATransform)
0.581ms (+0.008ms): add_entropy_words (extract_entropy)
0.582ms (+0.001ms): local_bh_enable (__check_and_rekey)
0.583ms (+0.000ms): halfMD4Transform (secure_tcp_sequence_number)
0.584ms (+0.001ms): tcp_v4_send_synack (tcp_v4_conn_request)
0.585ms (+0.000ms): tcp_v4_route_req (tcp_v4_send_synack)
0.586ms (+0.001ms): do_IRQ (common_interrupt)
0.587ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
0.591ms (+0.004ms): generic_redirect_hardirq (do_IRQ)
0.592ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
0.592ms (+0.000ms): rtc_interrupt (generic_handle_IRQ_event)
0.592ms (+0.000ms): is_hpet_enabled (rtc_interrupt)
0.596ms (+0.004ms): mod_timer (rtc_interrupt)
0.597ms (+0.000ms): __mod_timer (rtc_interrupt)
0.597ms (+0.000ms): internal_add_timer (__mod_timer)
0.598ms (+0.000ms): __wake_up (rtc_interrupt)
0.598ms (+0.000ms): __wake_up_common (__wake_up)
0.599ms (+0.000ms): kill_fasync (rtc_interrupt)
0.599ms (+0.000ms): generic_note_interrupt (do_IRQ)
0.599ms (+0.000ms): end_8259A_irq (do_IRQ)
0.600ms (+0.000ms): enable_8259A_irq (do_IRQ)
0.601ms (+0.001ms): ip_route_output_flow (tcp_v4_route_req)
0.602ms (+0.000ms): __ip_route_output_key (ip_route_output_flow)
0.602ms (+0.000ms): rt_hash_code (__ip_route_output_key)
0.603ms (+0.000ms): ip_route_output_slow (ip_route_output_flow)
0.604ms (+0.001ms): ip_dev_find (ip_route_output_slow)
0.604ms (+0.000ms): fn_hash_lookup (ip_dev_find)
0.605ms (+0.000ms): fib_semantic_match (fn_hash_lookup)
0.606ms (+0.000ms): fn_hash_lookup (ip_route_output_slow)
0.607ms (+0.000ms): fn_hash_lookup (ip_route_output_slow)
0.607ms (+0.000ms): fib_semantic_match (fn_hash_lookup)
0.608ms (+0.000ms): fn_hash_select_default (ip_route_output_slow)
0.610ms (+0.001ms): dst_alloc (ip_route_output_slow)
0.610ms (+0.000ms): kmem_cache_alloc (dst_alloc)
0.613ms (+0.002ms): rt_set_nexthop (ip_route_output_slow)
0.613ms (+0.000ms): memcpy (rt_set_nexthop)
0.614ms (+0.000ms): rt_hash_code (ip_route_output_slow)
0.614ms (+0.000ms): rt_intern_hash (ip_route_output_slow)
0.615ms (+0.000ms): arp_bind_neighbour (rt_intern_hash)
0.615ms (+0.000ms): neigh_lookup (arp_bind_neighbour)
0.616ms (+0.000ms): arp_hash (neigh_lookup)
0.618ms (+0.001ms): local_bh_enable (neigh_lookup)
0.618ms (+0.000ms): local_bh_enable (rt_intern_hash)
0.619ms (+0.001ms): tcp_make_synack (tcp_v4_send_synack)
0.619ms (+0.000ms): sock_wmalloc (tcp_make_synack)
0.620ms (+0.000ms): alloc_skb (sock_wmalloc)
0.620ms (+0.000ms): kmem_cache_alloc (alloc_skb)
0.621ms (+0.000ms): __kmalloc (alloc_skb)
0.626ms (+0.005ms): ip_build_and_send_pkt (tcp_v4_send_synack)
0.628ms (+0.001ms): ip_output (ip_build_and_send_pkt)
0.628ms (+0.000ms): ip_finish_output (ip_build_and_send_pkt)
0.629ms (+0.000ms): neigh_resolve_output (ip_finish_output)
0.630ms (+0.000ms): neigh_hh_init (neigh_resolve_output)
0.631ms (+0.001ms): eth_header (neigh_resolve_output)
0.632ms (+0.001ms): local_bh_enable (neigh_resolve_output)
0.633ms (+0.000ms): dev_queue_xmit (neigh_resolve_output)
0.634ms (+0.001ms): pfifo_fast_enqueue (dev_queue_xmit)
0.635ms (+0.000ms): qdisc_restart (dev_queue_xmit)
0.635ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart)
0.636ms (+0.000ms): dev_queue_xmit_nit (qdisc_restart)
0.637ms (+0.000ms): skb_clone (dev_queue_xmit_nit)
0.637ms (+0.000ms): kmem_cache_alloc (skb_clone)
0.638ms (+0.000ms): memcpy (skb_clone)
0.639ms (+0.001ms): packet_rcv_spkt (dev_queue_xmit_nit)
0.639ms (+0.000ms): strlcpy (packet_rcv_spkt)
0.640ms (+0.000ms): sk_run_filter (packet_rcv_spkt)
0.641ms (+0.001ms): __kfree_skb (packet_rcv_spkt)
0.642ms (+0.000ms): kfree_skbmem (__kfree_skb)
0.642ms (+0.000ms): skb_release_data (kfree_skbmem)
0.642ms (+0.000ms): kmem_cache_free (kfree_skbmem)
0.643ms (+0.000ms): rhine_start_tx (qdisc_restart)
0.646ms (+0.003ms): qdisc_restart (dev_queue_xmit)
0.646ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart)
0.647ms (+0.000ms): local_bh_enable (dev_queue_xmit)
0.648ms (+0.001ms): tcp_v4_synq_add (tcp_v4_conn_request)
0.649ms (+0.000ms): tcp_reset_keepalive_timer (tcp_v4_synq_add)
0.649ms (+0.000ms): sk_reset_timer (tcp_reset_keepalive_timer)
0.650ms (+0.000ms): mod_timer (sk_reset_timer)
0.650ms (+0.000ms): __mod_timer (sk_reset_timer)
0.651ms (+0.000ms): internal_add_timer (__mod_timer)
0.652ms (+0.001ms): init_westwood (tcp_rcv_state_process)
0.652ms (+0.000ms): init_bictcp (tcp_rcv_state_process)
0.653ms (+0.000ms): __kfree_skb (tcp_rcv_state_process)
0.654ms (+0.000ms): kfree_skbmem (__kfree_skb)
0.654ms (+0.000ms): skb_release_data (kfree_skbmem)
0.654ms (+0.000ms): kfree (kfree_skbmem)
0.656ms (+0.001ms): do_IRQ (common_interrupt)
0.656ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
0.660ms (+0.004ms): generic_redirect_hardirq (do_IRQ)
0.661ms (+0.000ms): wake_up_process (generic_redirect_hardirq)
0.661ms (+0.000ms): try_to_wake_up (wake_up_process)
0.661ms (+0.000ms): task_rq_lock (try_to_wake_up)
0.662ms (+0.000ms): activate_task (try_to_wake_up)
0.662ms (+0.000ms): sched_clock (activate_task)
0.662ms (+0.000ms): recalc_task_prio (activate_task)
0.663ms (+0.000ms): effective_prio (recalc_task_prio)
0.663ms (+0.000ms): enqueue_task (activate_task)
0.664ms (+0.001ms): kmem_cache_free (kfree_skbmem)
0.666ms (+0.001ms): check_preempt_timing (touch_preempt_timing)
Lee
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/