echo irqsoff >| current_tracer
--(ROOT:/sys/kernel/debug/tracing)---------------------------------------------------------------------------------------------------------------------------------(pts/4@firefox)--
echo latency-format >| trace_options
--(ROOT:/sys/kernel/debug/tracing)---------------------------------------------------------------------------------------------------------------------------------(pts/4@firefox)--
echo 0 >| tracing_max_latency
--(ROOT:/sys/kernel/debug/tracing)---------------------------------------------------------------------------------------------------------------------------------(pts/4@firefox)--
echo 1 >| tracing_on
--(ROOT:/sys/kernel/debug/tracing)---------------------------------------------------------------------------------------------------------------------------------(pts/4@firefox)--
cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 2.6.38.8-rtai
# --------------------------------------------------------------------
# latency: 72 us, #57/57, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
# -----------------
# | task: sshd-390 (uid:102 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: scsi_dispatch_cmd
# => ended at: scsi_dispatch_cmd
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| /_--=> lock-depth
# |||||/ delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
sshd-390 0d.s.. 0us : ata_scsi_queuecmd <-scsi_dispatch_cmd
sshd-390 0d.s1. 0us : ata_scsi_find_dev <-ata_scsi_queuecmd
sshd-390 0d.s1. 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
sshd-390 0d.s1. 1us : ata_scsi_translate <-ata_scsi_queuecmd
sshd-390 0d.s1. 2us : ata_qc_new_init <-ata_scsi_translate
sshd-390 0d.s1. 3us : ata_sg_init <-ata_scsi_translate
sshd-390 0d.s1. 3us : ata_scsi_rw_xlat <-ata_scsi_translate
sshd-390 0d.s1. 3us : scsi_10_lba_len <-ata_scsi_rw_xlat
sshd-390 0d.s1. 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
sshd-390 0d.s1. 5us : ata_rwcmd_protocol <-ata_build_rw_tf
sshd-390 0d.s1. 6us : ata_qc_issue <-ata_scsi_translate
sshd-390 0d.s1. 7us : _rtai_apic_timer_handler <-rtai_apic_timer_handler
sshd-390 0d.s1. 7us : native_apic_mem_write <-_rtai_apic_timer_handler
sshd-390 0d.s1. 7us+: rt_timer_handler <-_rtai_apic_timer_handler
sshd-390 0d.s1. 10us : switch_rtai_tasks.clone.4 <-rt_timer_handler
sshd-390 0dN... 11us : rt_get_time <-fun
sshd-390 0dN... 12us : count2nano <-fun
sshd-390 0dN... 12us : rt_sleep <-fun
sshd-390 0dN... 12us : rt_schedule <-rt_sleep
sshd-390 0dN... 13us : native_apic_mem_write <-rt_schedule
sshd-390 0dN... 13us : switch_rtai_tasks.clone.4 <-rt_schedule
sshd-390 0d.s1. 13us : page_address <-ata_qc_issue
sshd-390 0d.s1. 14us : nommu_map_sg <-ata_qc_issue
sshd-390 0d.s1. 14us : check_addr <-nommu_map_sg
sshd-390 0d.s1. 15us : ata_bmdma_qc_prep <-ata_qc_issue
sshd-390 0d.s1. 16us : ata_bmdma_qc_issue <-ata_qc_issue
sshd-390 0d.s1. 16us : ata_dev_select.clone.14 <-ata_bmdma_qc_issue
sshd-390 0d.s1. 16us : __const_udelay <-ata_dev_select.clone.14
sshd-390 0d.s1. 17us+: delay_tsc <-__const_udelay
sshd-390 0d.s2. 26us : _rtai_apic_timer_handler <-rtai_apic_timer_handler
sshd-390 0d.s2. 26us : native_apic_mem_write <-_rtai_apic_timer_handler
sshd-390 0d.s2. 27us+: rt_timer_handler <-_rtai_apic_timer_handler
sshd-390 0d.s2. 30us : __ipipe_set_irq_pending <-rt_timer_handler
sshd-390 0d.s2. 31us : native_apic_mem_write <-rt_timer_handler
sshd-390 0d.s1. 31us : ata_sff_check_status <-ata_dev_select.clone.14
sshd-390 0d.s1. 32us : ata_sff_dev_select <-ata_dev_select.clone.14
sshd-390 0d.s1. 33us : ata_sff_pause <-ata_sff_dev_select
sshd-390 0d.s1. 34us : ata_sff_sync <-ata_sff_pause
sshd-390 0d.s1. 35us : __const_udelay <-ata_sff_pause
sshd-390 0d.s1. 35us : delay_tsc <-__const_udelay
sshd-390 0d.s1. 36us : __const_udelay <-ata_dev_select.clone.14
sshd-390 0d.s1. 36us+: delay_tsc <-__const_udelay
sshd-390 0d.s1. 46us : ata_sff_check_status <-ata_dev_select.clone.14
sshd-390 0d.s1. 47us+: ata_sff_tf_load <-ata_bmdma_qc_issue
sshd-390 0d.s1. 54us : __const_udelay <-ata_sff_tf_load
sshd-390 0d.s1. 54us+: delay_tsc <-__const_udelay
sshd-390 0d.s1. 64us : ata_sff_check_status <-ata_sff_tf_load
sshd-390 0d.s1. 65us+: ata_bmdma_setup <-ata_bmdma_qc_issue
sshd-390 0d.s1. 67us : ata_sff_exec_command <-ata_bmdma_setup
sshd-390 0d.s1. 69us : ata_sff_pause <-ata_sff_exec_command
sshd-390 0d.s1. 69us : ata_sff_sync <-ata_sff_pause
sshd-390 0d.s1. 70us : __const_udelay <-ata_sff_pause
sshd-390 0d.s1. 70us : delay_tsc <-__const_udelay
sshd-390 0d.s1. 71us : ata_bmdma_start <-ata_bmdma_qc_issue
sshd-390 0d.s1. 72us : ata_scsi_queuecmd <-scsi_dispatch_cmd
sshd-390 0d.s1. 72us : trace_hardirqs_on <-scsi_dispatch_cmd
sshd-390 0d.s1. 73us : <stack trace>
=> ata_scsi_queuecmd
=> scsi_dispatch_cmd
=> scsi_request_fn
=> __blk_run_queue
=> blk_run_queue
=> scsi_run_queue
=> scsi_next_command
=> scsi_io_completion
--(ROOT:/sys/kernel/debug/tracing)----------