1

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.

  • You'd probably be better off asking on Stack Overflow – roaima Jul 27 '18 at 17:33
  • @roaima - now that it has the bounty we cannot move it. – slm Jul 28 '18 at 0:19

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.