I have a Banana Pi Arm device with 2 cores (1.2 GHz) running a Debian kernel which I enabled ftrace kernel debug options. I want to determine the amount of time spent in a kernel module function. The function is of the form
static irq_handler_t vtgpio_irq_handler(unsigned int irq, void *dev_id, struct pt_regs *regs);
In my debug file system after I load the module I see the name exposed as a filter. I am tracing all functions. I tried to enable the trace_printk statements but I can not see it printed in my trace file. Here is the implementation of the function:
/** @brief handler for rising signal */
static irq_handler_t vtgpio_irq_handler(unsigned int irq, void *dev_id, struct pt_regs *regs) {
trace_printk(KERN_INFO "rise\n");
pause();
return (irq_handler_t) IRQ_HANDLED; // return that we all good
}
I know that the function is being called because I see the printk statement in dmesg | tail if I replace trace_printk with printk. Also I know that some of the modules functions are traceable like writing to sysfs store functions. For example I can see
static struct kobj_attribute mode_attr = __ATTR(mode, 0660, mode_show, mode_store);
The ftrace from writing to mode_store.
1) | sys_write() {
1) 0.708 us | fget_light();
1) | vfs_write() {
1) 0.875 us | rw_verify_area();
1) | sysfs_write_file() {
1) 0.459 us | mutex_lock();
1) | get_zeroed_page() {
1) | __get_free_pages() {
1) | __alloc_pages_nodemask() {
1) 0.708 us | next_zones_zonelist();
1) | get_page_from_freelist() {
1) 0.458 us | next_zones_zonelist();
1) 1.000 us | __zone_watermark_ok();
1) | kmap_atomic() {
1) 0.625 us | add_preempt_count();
1) 0.625 us | page_address();
1) 9.250 us | }
1) | __kunmap_atomic() {
1) 0.750 us | sub_preempt_count();
1) 5.459 us | }
1) + 41.000 us | }
1) + 53.209 us | }
1) 0.542 us | page_address();
1) + 62.541 us | }
1) + 66.958 us | }
1) 0.917 us | sysfs_get_active();
1) | mode_store() {
1) | /* <6>VT-GPIO_TEST: resume */
1) | gpio_direction_output() {
1) | _raw_spin_lock_irqsave() {
1) | __raw_spin_lock_irqsave() {
1) 0.834 us | add_preempt_count();
1) 5.375 us | }
1) 9.458 us | }
1) 0.834 us | gpio_ensure_requested();
1) | _raw_spin_unlock_irqrestore() {
1) 0.708 us | sub_preempt_count();
1) 5.125 us | }
1) | sunxi_gpio_direction_out() {
1) 1.125 us | gpio_set_one_pin_io_status();
1) 1.167 us | gpio_write_one_pin_value();
1) + 12.333 us | }
1) + 47.250 us | }
1) | gpio_direction_input() {
1) | _raw_spin_lock_irqsave() {
1) | __raw_spin_lock_irqsave() {
1) 0.625 us | add_preempt_count();
1) 5.167 us | }
1) 9.667 us | }
1) 0.583 us | gpio_ensure_requested();
1) | _raw_spin_unlock_irqrestore() {
1) 0.708 us | sub_preempt_count();
1) 5.166 us | }
1) | sunxi_gpio_direction_in() {
1) 0.667 us | gpio_set_one_pin_io_status();
1) 5.208 us | }
1) + 38.833 us | }
1) ! 105.833 us | }
1) 0.875 us | sysfs_put_active();
1) 0.875 us | mutex_unlock();
1) ! 204.500 us | }
1) 0.416 us | __fsnotify_parent();
1) | fsnotify() {
1) | __srcu_read_lock() {
1) 0.583 us | add_preempt_count();
1) 0.667 us | sub_preempt_count();
1) 9.542 us | }
1) | __srcu_read_unlock() {
1) 0.584 us | add_preempt_count();
1) 0.667 us | sub_preempt_count();
1) 9.041 us | }
1) + 30.125 us | }
1) ! 252.708 us | }
1) ! 262.292 us | }
The mode_store in this trace actually writes HIGH or LOW to a pin that the IRQ handler is registered to. Any tips will be very helpful, I am trying to measure the overhead of the IRQ handler.
