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 : => 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)----------