CamX ISP Hardware Event日志分析|极客笔记

要分析高通ISP Hardware Event（IRQ）的日志，首先要打开ISP Debug log。

打开ISP的Debug log

adb shell "echo 0x8 > /sys/module/camera/parameters/debug_mdl"
adb shell "echo 0x8 > /sys/module/cam_debug_util/parameters/debug_mdl"

ISP Hardware Event Log

Log搜索Pattern：

logcat -b kernel |grep -iE "__cam_isp_ctx_handle_irq_in_activated.*Enter"

Log输出：

10-09 06:05:15.083     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 1
10-09 06:05:15.083     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 2
10-09 06:05:15.099     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 3
10-09 06:05:15.104     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 4
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.155     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 1
10-09 06:05:15.171     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[SOF], evt id 3
10-09 06:05:15.186     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 4
10-09 06:05:15.226     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 1
10-09 06:05:15.226     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 2
10-09 06:05:15.242     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 3

Event ID定义在techpack/camera/drivers/cam_isp/isp_hw_mgr/include/cam_isp_hw_mgr_intf.h，具体如下:

/**
 *  enum cam_isp_hw_event_type - Collection of the ISP hardware events
 */
enum cam_isp_hw_event_type {
    CAM_ISP_HW_EVENT_ERROR,         // 0
    CAM_ISP_HW_EVENT_SOF,           // 1 
    CAM_ISP_HW_EVENT_REG_UPDATE,    // 2
    CAM_ISP_HW_EVENT_EPOCH,         // 3
    CAM_ISP_HW_EVENT_EOF,           // 4
    CAM_ISP_HW_EVENT_DONE,          // 5
    CAM_ISP_HW_EVENT_MAX            // 6
};

ISP Buffer Done Log

以TFE为例，每个Output port 都会有Buffer Done Event发生，定义在techpack/camera/include/uapi/camera/media/cam_isp_tfe.h，Output port resource ID具体如下

/* TFE output port resource id number */
#define CAM_ISP_TFE_OUT_RES_BASE               0x1

#define CAM_ISP_TFE_OUT_RES_FULL               (CAM_ISP_TFE_OUT_RES_BASE + 0)  // 0x1
#define CAM_ISP_TFE_OUT_RES_RAW_DUMP           (CAM_ISP_TFE_OUT_RES_BASE + 1)  // 0x2
#define CAM_ISP_TFE_OUT_RES_PDAF               (CAM_ISP_TFE_OUT_RES_BASE + 2)  // 0x3
#define CAM_ISP_TFE_OUT_RES_RDI_0              (CAM_ISP_TFE_OUT_RES_BASE + 3)  // 0x4
#define CAM_ISP_TFE_OUT_RES_RDI_1              (CAM_ISP_TFE_OUT_RES_BASE + 4)  // 0x5
#define CAM_ISP_TFE_OUT_RES_RDI_2              (CAM_ISP_TFE_OUT_RES_BASE + 5)  // 0x6
#define CAM_ISP_TFE_OUT_RES_STATS_HDR_BE       (CAM_ISP_TFE_OUT_RES_BASE + 6)  // 0x7
#define CAM_ISP_TFE_OUT_RES_STATS_HDR_BHIST    (CAM_ISP_TFE_OUT_RES_BASE + 7)  // 0x8
#define CAM_ISP_TFE_OUT_RES_STATS_TL_BG        (CAM_ISP_TFE_OUT_RES_BASE + 8)  // 0x9
#define CAM_ISP_TFE_OUT_RES_STATS_BF           (CAM_ISP_TFE_OUT_RES_BASE + 9)  // 0xa
#define CAM_ISP_TFE_OUT_RES_STATS_AWB_BG       (CAM_ISP_TFE_OUT_RES_BASE + 10) // 0xb
#define CAM_ISP_TFE_OUT_RES_MAX                (CAM_ISP_TFE_OUT_RES_BASE + 11) // 0xc

Log搜索 Pattern：

logcat -b kernel |grep -iE "__cam_isp_ctx_handle_irq_in_activated.*evt id 5|Buf done for out_res"

Log输出：

10-09 06:05:15.104     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.104     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0xa
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0x7
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0xb
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0x1
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0x2
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0x5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0x9
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 5
10-09 06:05:15.115     0     0 I CAM_DBG : CAM-ISP: cam_tfe_hw_mgr_handle_hw_buf_done: 5692: Buf done for out_res->res_id: 0x8
10-09 06:05:15.247     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 5

ISP SOF Log

Sensor送给ISP的每帧数据会有一个SOF和一个EOF与之对应。

Log搜索 Pattern：

logcat -b kernel |grep -iE "__cam_isp_ctx_handle_irq_in_activated.*evt id 1|Notify CRM  SOF frame"

Log输出：

10-09 06:05:15.083     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 1
10-09 06:05:15.099     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_notify_sof_in_activated_state: 1958: Notify CRM  SOF frame 1 ctx 2
10-09 06:05:15.155     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[EPOCH], evt id 1
10-09 06:05:15.171     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_notify_sof_in_activated_state: 1958: Notify CRM  SOF frame 2 ctx 2
10-09 06:05:15.226     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 1
10-09 06:05:15.242     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_notify_sof_in_activated_state: 1958: Notify CRM  SOF frame 3 ctx 2
10-09 06:05:15.298     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 1
10-09 06:05:15.313     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_notify_sof_in_activated_state: 1958: Notify CRM  SOF frame 4 ctx 2
10-09 06:05:15.369     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 1
10-09 06:05:15.385     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_notify_sof_in_activated_state: 1958: Notify CRM  SOF frame 5 ctx 2
10-09 06:05:15.441     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 1
10-09 06:05:15.456     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_notify_sof_in_activated_state: 1958: Notify CRM  SOF frame 6 ctx 2
10-09 06:05:15.512     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 1
10-09 06:05:15.528     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_notify_sof_in_activated_state: 1958: Notify CRM  SOF frame 7 ctx 2
10-09 06:05:15.583     0     0 I CAM_DBG : CAM-ISP: __cam_isp_ctx_handle_irq_in_activated: 5984: Enter: State 5, Substate[APPLIED], evt id 1