使用ftrace的事件加强其他的追踪器输出

ftrace的追踪事件可以与其他插件追踪器组合输出。这样就可以更清晰地查看输出量较多的函数追踪器的结果等。

例如,尝试同时使用进程调度程序的相关事件和函数追踪器,就可以得知进程的切换处理和函数调用关系等。在下例中实际显示了从发生sched_switch事件到进程切换为止的步骤,可以更加详细地了解事件前后发生的情况。


[tracing]#echo'sched:*'>set_event

[tracing]#echo'function'>current_tracer

[tracing]#cat trace

……

less-3569[001]16957.997983:sched_stat_wait:comm=events/1 pid=10

delay=53796[ns]

less-3569[001]16957.997984:task_of<-pick_next_task_fair

less-3569[001]16957.997984:hrtickstart_fair<-pick_next

task_fair

less-3569[001]16957.997985:_raw_local_save_flags<-ftrace

raw_event_sched_switch

less-3569[001]16957.997985:sched_switch:prev_comm=less

prev_pid=3569 prev_prio=120 prev_state=R==>next_comm=events/1 next_pid=10 next_prio=120

less-3569[001]16957.997985:atomic_inc<-schedule

less-3569[001]16957.997986:enter_lazy_tlb.clone.16

<-schedule

less-3569[001]16957.997986:native_load_sp0<-__switch_to

less-3569[001]16957.997987:load_TLS<-__switch_to

less-3569[001]16957.997987:native_load_tls<-load_TLS

less-3569[001]16957.997988:unlazy_fpu<-switch_to

less-3569[001]16957.997988:read_cr0<-__unlazy_fpu

less-3569[001]16957.997988:native_read_cr0<-read_cr0

less-3569[001]16957.997989:native_write_cr0<-__unlazy_fpu

events/1-10[001]16957.997995:finish_task_switch<-schedule

events/1-10[001]16957.997999:rawlocal_irq_enable<-finish_task

switch


另外,还可以使用事件的参数,研究函数调用的终点实际进行的处理和处理所花费的时间之间的关系。


[tracing]#echo do_IRQ>set_ftrace_flter

[tracing]#echo 1>events/irq/irq_handler_entry/enable

[tracing]#echo function_graph>current_tracer

[tracing]#cat trace

……

0)==========>|

0)|do_IRQ(){

0)|/irq_handler_entry:irq=19 name=ehci_hcd:usb1/

0)|/irq_handler_entry:irq=19 name=virtio0/

0)!244.859 us|}

0)<==========|

0)==========>|

0)|do_IRQ(){

0)|/irq_handler_entry:irq=21 name=ahci/

0)|/irq_handler_entry:irq=21 name=Intel 82801AA-ICH/

0)==========>|

0

)|do_IRQ(){

0)|/irq_handler_entry:irq=21 name=ahci/

0)|/irq_handler_entry:irq=21 name=Intel 82801AA-ICH/

0)!286.214 us|}

0)<==========|

0)!620.506 us|}

0)<==========|


例如,这里就使用do_IRQ的函数调用图表显示了处理所花费的时间(出现了超过100微秒的数值,因此数值前面显示了‘!’),但是仅使用函数调用图表难以调查出哪个中断进行了什么处理。但是事件会显示各个中断的处理方式,这样就可以很简单地得知启动了哪个中断处理程序,以及此时花费了多少时间。