lkml.org 
[lkml]   [2004]   [Aug]   [13]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    SubjectRe: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6
    From
    Date
    On Fri, 2004-08-13 at 06:31, Ingo Molnar wrote:
    > * Lee Revell <rlrevell@joe-job.com> 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@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

    \
     
     \ /
      Last update: 2005-03-22 14:05    [W:2.547 / U:0.032 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site