当前位置: 首页 > 科技观察

一步步教你分析Trace,你学会了吗?

时间:2023-03-12 06:45:17 科技观察

博主的例子使用RK3399,运行Android8.1。为了方便大家捕捉踪迹,博主写了一个bat脚本。Windows环境下直接双击运行,根据提示回车三次即可。捕获的轨迹将输出到名为SYS_TRACE的当前文件中。my_trace.bat@echooffrem在/sys/kernel/debug/tracing/或/sys/kernel/tracing/中,请自行确认adbrootadbshell"echo65536>/sys/kernel/debug/tracing/buffer_size_kb"echo"buffer_size_kb(每个cpu):"adbshell"cat/sys/kernel/debug/tracing/buffer_size_kb"adbshell"echonop>/sys/kernel/debug/tracing/current_tracer">nul2>&1adbshell"echo'noprint-tgid'>/sys/kernel/tracing/trace_options">nul2>&1remclearftraceeventsadbshell"echo>/sys/kernel/debug/tracing/set_event"remenableprofilingeventshere,withloopfor%%xin(sched_switchsched_wakeupsched_wakeup_newsched_migrate_tasksoftirq_raisesoftirq_entrysoftirq_exitipiirqirq_handler_entryirq_handler_exitcpu_frequencyworkqueue_execute_startworkqueue_execute_end定时器clksuspend_resumedevice_pm_callback_startdevice_pm_callback_endcpu_idlepm_qos_update_requesti2cf2fssuspend_resume)do(adbshell"echo%%x>>/sys/kernel/debug/tracing/set_event")rem以防tracing_enabled被用户或其他调试tooladbshell禁用"echo1>/sys/kernel/debug/tracing/tracing_enabled">nul2>&1adbshell"echo0>/sys/kernel/debug/tracing/tracing_on"rem擦除之前记录的traceadbshell"echo>/sys/kernel/debug/tracing/trace"echopressanykeytostartcapture...pauseadbshell"echo1>/sys/kernel/debug/tracing/tracing_on"echo"开始记录ftrace数据"echo"按任意键停止..."pauseadbwait-for-deviceadbshell"echo0>/sys/kernel/debug/tracing/tracing_on"echo"记录停止..."adbshell"ps-AT">ps_1.txtadbshellcat/sys/kernel/debug/tracing/trace>SYS_FTRACEadbshell"ps-AT">ps_2.txtadbshell"echonoprint-tgid>/sys/kernel/debug/tracing/trace_options">nul2>&1remdefaultsizeadbshell"echo4096>/sys/kernel/debug/tracing/buffer_size_kb"pause这个脚本重要的地方都有说明,rem开头的都是注释,请注意第一条注释。大体的框架是先将每个CPU的buffer设置为65536,然后通过for循环设置你要捕获的事件,然后开始捕获。这时您可以在设备上操作重现问题。问题复现后,停止抓取,拉出抓取的trace。运行后目录如下:SYS_TRACE如下:本次我们只分析i2c的问题,所以使用grep工具将i2c相关的提取出来。博主在i2c4上挂载了三个设备,通过cat/proc/interrputs确认i2c4的软件中断号为41,则提取命令如下:grep-e"irq=41"-e"i2c-4"SYS_FTRACE>i2c4-20221106.txt只提取i2c4部分,截取一部分分析:i2c_readtoirq_handler_entryisslow:此路I2C4挂载设备过多,同时发起通信会被抢占。发起i2c传输的用户线程优先级较低。当多个设备同时发起i2c传输,或者已经有几个设备在你前面等待时,你的设备将得不到锁,一直排在后面。硬件传输时间长:比如从机有问题,或者i2crate设置不正确,用示波器可以捕捉到。irq_handler_exittoi2c_reply慢:发起i2c传输的用户线程优先级低,i2c中断后调用用户线程,但被高优先级线程抢占,用户线程未被调度中央处理器。很多时候,为了功耗,i2c中断会设置为唤醒CPU失败。比如CPU0发起一次i2c通信,CPU0不等它返回,无事可做就进入空闲状态。i2c中断来后,CPU0无法唤醒,导致变慢。【这个原因也跟调度策略有关。当其他CPU空闲时,应该将用户线程调度到其他CPU处理]总结一下:如果用户线程的优先级低,那么你观察到的i2c传输时间是整体慢的。如果CPU进入idle导致你的i2c传输耗时,那是概率性的,耗时偶尔会出现15-25ms的水平,让人难以忍受。