一次使用 ftrace function tracer 的野经历

------------------------------------------------------

 也是简单回忆一下。

------------------------------------------------------

 多年前，公司开发一个新升级的产品（__嵌入式无线AP），新的硬件板，使用新的PowerPC CPU，新的无线radio 和 全新版本的radio driver（__当然，都是从某vendor那里买的）。

 可能软硬件上步子跨得太大，出现了这样的问题:

        在跑某个压力测试时，无征兆地莫名其妙地突然重启。        # 压力大也会重启，压力小也会重启，只是频率小一些。

 

        也不是 crash。没有任何 crash log。 

        也不是因为 硬件watchdog没有及时得到feed 而超时reset CPU。

 

 缺少进一步分析的信息。无法得知，在莫名其妙重启时，是在执行什么逻辑。但应该是 内核态的逻辑（__用户态的逻辑应该没有这么大杀伤力吧）。
 

 

 于是，去找有没有手段，来获取重启之前执行的是什么函数。当时第1次遇到这种问题，也完全没有方向。

 

 当时使用的 kernel version 是 2.6.32。        # 嗯，这个新产品中，所用的内核版本也升级了，不然，之前的更老版本还真没有下面的 ftrace 这个东西。
 

 凑巧看到，kernel source tree 中有:

        
        Documentation\trace\

            ftrace.txt

 囫囵吞枣地读了一下，也试验了下。

 

 感觉，可以用其中 function tracer 来跟踪内核的函数调用。

------------------------------------------------------

 但直接使用 ftrace 的话，会有一些问题:

        直接使用，是在运行时，从 debugfs 去读取 trace 的内容

                cat /sys/kernel/debug/tracing/trace

 

        但是，遇到的问题是，无征兆地重启。

        
        因为预先不知道任何时候，也不太好 在运行时，不断去读取trace内容。

        
        并且，压力测试时，CPU usage很高，在shell下会很慢，直接读取会卡很久，看到的也可能是老的内容。

 

------------------------------------------------------

 于是，想出了这么一个trick:

 

        #1. 在 RAM 中想办法 reserve 一块 memory block，其中内容是一个简单的 circular buffer:

                    unsigned long ip[128];
                    unsigned long parent_ip[128];
                    unsigned long cur_idx;

            这块 memory block 在 bootloader 启动时，并不清0。在 kernel 启动的 早期阶段，也以 bootm_reserve() 来保留（__这样，后续不会被 kernel 所使用）。

 

 

        #2.    在 kernel function tracer 中插入自定义的记录代码:

                 -1124,22 +1164,26 @@ trace_function(struct trace_array *tr,
                         return;
        
                     event = trace_buffer_lock_reserve(buffer, TRACE_FN, sizeof(*entry),
                                       flags, pc);
                     if (!event)
                         return;
                     entry    = ring_buffer_event_data(event);
                     entry->ip            = ip;
                     entry->parent_ip        = parent_ip;
        
                -    if (!filter_check_discard(call, entry, buffer, event))
                +    if (!filter_check_discard(call, entry, buffer, event)) {

                +#if defined(MY_KDBG_TRACING)        //here we know CONFIG_FUNCTION_TRACER is set
                +        my_trace_function(ip, parent_ip, flags, pc);                        # !!__这里是自己插入的记录代码。
                +#endif

                         ring_buffer_unlock_commit(buffer, event);
                +    }
                 }

        
            将每次跟踪到的 parent_ip 和 ip，记录到 reserved memory block 的 circular buffer 中。

 

 

        #3. 发生了异常重启之后，下一次启动之后，将那块 reserved memory block 的内容，dump 出来到本地。

            
            再写一段小的离线对比程序，对比 其中的记录下的 ip 值，和 上一次保存的 /proc/kallsyms 中的 symbol 地址。就可以确定记录下的 ip 属于 那个 symbol。

            这样，就可以大致看出，系统异常重启之前的最后时刻，执行的是哪些functions。

 

 

 用了几次，看到的都是 最后时刻 执行的是 WIFI driver 中的 functions（__并且大多都是访问 WIFI radio 的 HW registers 的）。

------------------------------------------------------

 后续:

    将调查结果，说与 负责radio driver的组。他们去向 radio driver vendor 提support问题单，请求支援。

    但 vendor 的 support，回应的内容，也没什么有用的信息。问题的处理停留了一段时间。

    然后，好像是 vendor 发过来一些没什么解释的 patch，或者 有几个 driver 的小版本升级，merge 了进来。

    然后，就莫名其妙地 不重启了。        # 我不懂 radio driver，当时也有其他一堆事，没有紧密去跟这个。
                                                               # 只是听QA 说不重启了，就好了。

    所以，后续就是，不了了之。

------------------------------------------------------

--- 现在回想起来，在调查过程中，可以改进的地方:
 

    #1. 当时是 对所有 kernel functions 进行 tracing。

        实际上，可以限制为 只对 radio driver 的 function 进行 tracing 的。         # 因为，大致猜测到应该是 radio driver 中有问题。

        通过: 

                 echo 'hrtimer_*' > set_ftrace_filter

        不过，好像在当时 kernel version 2.6.32 中，只能这样指定 function name 或者 wildcard。并不支持 指定 某个 kernel module 的所有 symbols。

 

        更后续的kernel version 才支持 指定 某个 kernel module 的所有 symbols:

               echo 'write*:mod:ext3' > set_ftrace_filter        # 对 ext3 module 中的所有 write* function，进行 tracing。
    

        而 对于当时的 version 2.6.32，因为 radio driver 比较大，包含了很多 function symbols，也无法以简单的 wildcard 来设置。

        
        所以，干脆是设置为 所有 kernel functions 进行 tracing。

        #
        # --- 现在回想，如果当时脑子灵活一点，写一段小程序，从 /proc/kallsyms 中提取 radio driver 的 所有 symbols，
        #        然后一个一个输入到 set_ftrace_filter 中，应该也可以。
        #

 

    #2. ftrace的开销方面。

        因为是 设置为 所有 kernel functions 进行 tracing。

        所以，开销就比较大。在跑压力测试时，throughput 直接减半。

        因为 throughput 下去了，于是 可能radio driver 对 radio HW registers 的访问，也没那么频繁了。所以，异常重启的频率，少了很多。

        所以，体会到，工具本身的开销，也会影响到观测。

 

    #3. 记录到 memory block 中的内容，可能受到 cache 不及时刷新的影响。因为突然的异常重启时，cache 的内容不一定能够刷到 RAM 中。

        虽然，也有添加了 flush_cache()的逻辑，但突然异常重启，flush_cache()也不一定会及时执行到。 --- 也不能每记录一次ip，都flush cache一次，虽然没有比对，但是感觉频繁的flush cache 会带来更大开销。
    

        所以，观测结果也不一定是完全精确。

        #
        # --- 现在回想，是不是可以将 reserved memory block 的 page table entries，设置为 "Uncached" （__" write-through" ?） 。
        #
        #        这样访问其时就不经过 cache。
        #
        #
        #        但是，开销还是有很大，只不过可能没有频繁 flush_cache() 那么大。
        #
        #        
        #        以 在其他CPU 上的体验，比如说，在 MIPS CPU 上，写同一块16MB的 memory，通过 MIPS uncached region 指针来访写，比
        #        通过 MIPS cached region 来写，直观体验上，时间多花7、8倍？
        #

 

    #4. 嵌入式产品上，内存太小（256MB），多年前的嵌入式CPU和kernel也并不一定支持一些fancy的 debug feature （__比如 kdump ）。

        所以，只能做一些粗糙的野路子。

 
------------------------------------------------------