preemption latency trace v1.0.2
-------------------------------
 latency: 152 us, entries: 66 (66)
    -----------------
    | task: ksoftirqd/0/2, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: scsi_request_fn+0x239/0x490
 => ended at:   scsi_request_fn+0x25e/0x490
=======>
00000001 0.000ms (+0.000ms): scsi_request_fn (blk_run_queue)
00000001 0.000ms (+0.000ms): elv_next_request (scsi_request_fn)
00000001 0.000ms (+0.000ms): as_next_request (elv_next_request)
00000001 0.001ms (+0.000ms): as_dispatch_request (as_next_request)
00000001 0.002ms (+0.001ms): as_fifo_expired (as_dispatch_request)
00000001 0.004ms (+0.001ms): as_move_to_dispatch (as_dispatch_request)
00000001 0.005ms (+0.001ms): as_antic_stop (as_move_to_dispatch)
00000001 0.006ms (+0.001ms): as_find_next_arq (as_move_to_dispatch)
00000001 0.007ms (+0.000ms): rb_next (as_find_next_arq)
00000001 0.008ms (+0.001ms): rb_prev (as_find_next_arq)
00000001 0.009ms (+0.001ms): as_choose_req (as_find_next_arq)
00000001 0.011ms (+0.001ms): as_remove_queued_request (as_move_to_dispatch)
00000001 0.012ms (+0.001ms): as_remove_merge_hints (as_remove_queued_request)
00000001 0.014ms (+0.001ms): rb_erase (as_remove_queued_request)
00000001 0.015ms (+0.001ms): __rb_erase_color (rb_erase)
00000001 0.017ms (+0.002ms): __rb_rotate_left (__rb_erase_color)
00000001 0.019ms (+0.002ms): scsi_prep_fn (elv_next_request)
00000001 0.021ms (+0.001ms): scsi_get_command (scsi_prep_fn)
00000001 0.022ms (+0.000ms): __scsi_get_command (scsi_get_command)
00000001 0.023ms (+0.000ms): kmem_cache_alloc (__scsi_get_command)
00000001 0.025ms (+0.002ms): scsi_init_io (scsi_prep_fn)
00000001 0.025ms (+0.000ms): scsi_alloc_sgtable (scsi_init_io)
00000001 0.027ms (+0.001ms): mempool_alloc (scsi_alloc_sgtable)
00000001 0.029ms (+0.001ms): mempool_alloc_slab (mempool_alloc)
00000001 0.029ms (+0.000ms): kmem_cache_alloc (mempool_alloc)
00000001 0.031ms (+0.001ms): cache_alloc_refill (kmem_cache_alloc)
00000001 0.034ms (+0.003ms): cache_grow (cache_alloc_refill)
00000001 0.035ms (+0.001ms): kmem_flagcheck (cache_grow)
00000001 0.037ms (+0.001ms): kmem_getpages (cache_grow)
00000001 0.037ms (+0.000ms): __get_free_pages (kmem_getpages)
00000001 0.038ms (+0.001ms): __alloc_pages (__get_free_pages)
00000001 0.040ms (+0.002ms): buffered_rmqueue (__alloc_pages)
00000001 0.043ms (+0.002ms): bad_range (buffered_rmqueue)
00000001 0.044ms (+0.001ms): prep_new_page (buffered_rmqueue)
00000001 0.046ms (+0.001ms): zone_statistics (__alloc_pages)
00000001 0.047ms (+0.001ms): page_address (__get_free_pages)
00000001 0.049ms (+0.001ms): alloc_slabmgmt (cache_grow)
00000001 0.049ms (+0.000ms): kmem_cache_alloc (alloc_slabmgmt)
00000001 0.051ms (+0.001ms): set_slab_attr (cache_grow)
00000001 0.051ms (+0.000ms): cache_init_objs (cache_grow)
00000001 0.054ms (+0.002ms): blk_rq_map_sg (scsi_init_io)
00000001 0.107ms (+0.052ms): sd_init_command (scsi_prep_fn)
00010001 0.111ms (+0.004ms): do_IRQ (scsi_request_fn)
00010002 0.112ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
00010002 0.116ms (+0.003ms): generic_redirect_hardirq (do_IRQ)
00010001 0.117ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010001 0.118ms (+0.001ms): timer_interrupt (generic_handle_IRQ_event)
00010002 0.119ms (+0.001ms): mark_offset_tsc (timer_interrupt)
00010002 0.131ms (+0.011ms): do_timer (timer_interrupt)
00010002 0.132ms (+0.001ms): update_process_times (do_timer)
00010002 0.132ms (+0.000ms): update_one_process (update_process_times)
00010002 0.133ms (+0.000ms): run_local_timers (update_process_times)
00010002 0.134ms (+0.000ms): raise_softirq (update_process_times)
00010002 0.134ms (+0.000ms): scheduler_tick (update_process_times)
00010002 0.135ms (+0.000ms): sched_clock (scheduler_tick)
00010003 0.139ms (+0.004ms): task_timeslice (scheduler_tick)
00010002 0.141ms (+0.002ms): update_wall_time (do_timer)
00010002 0.142ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010002 0.143ms (+0.001ms): profile_hook (timer_interrupt)
00010003 0.144ms (+0.001ms): notifier_call_chain (profile_hook)
00010002 0.147ms (+0.002ms): generic_note_interrupt (do_IRQ)
00010002 0.147ms (+0.000ms): end_8259A_irq (do_IRQ)
00010002 0.148ms (+0.000ms): enable_8259A_irq (do_IRQ)
00000002 0.150ms (+0.001ms): do_softirq (do_IRQ)
00000002 0.150ms (+0.000ms): __do_softirq (do_softirq)
00000001 0.153ms (+0.002ms): sub_preempt_count (scsi_request_fn)