como usar o ftrace para function_trace uma interrupção de módulos do kernel?

Question

Eu tenho um dispositivo Banana Pi Arm com 2 núcleos (1.2 GHz) rodando um kernel Debian que eu habilitei as opções de debug do kernel ftrace. Eu quero determinar a quantidade de tempo gasto em uma função de módulo do kernel. A função é da forma

static irq_handler_t vtgpio_irq_handler(unsigned int irq, void *dev_id, struct pt_regs *regs);

No meu sistema de arquivos de depuração depois de carregar o módulo, vejo o nome exposto como um filtro. Eu estou rastreando todas as funções. Eu tentei ativar as instruções trace_printk , mas não consigo vê-lo impresso no meu arquivo de rastreamento. Aqui está a implementação da função:

/** @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                                                                                                                               
}

Eu sei que a função está sendo chamada porque vejo a instrução printk em dmesg | tail se eu substituir trace_printk por printk . Também sei que algumas das funções dos módulos são rastreáveis como gravar em funções de armazenamento sysfs. Por exemplo, posso ver

static struct kobj_attribute mode_attr = __ATTR(mode, 0660, mode_show, mode_store);

O ftrace escreve para 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  |  }

O mode_store neste rastreio grava HIGH ou LOW em um pino no qual o manipulador de IRQ está registrado. Qualquer dica será muito útil, estou tentando medir a sobrecarga do manipulador de IRQ.