msm: camera: common: Append timestamp in INFO LOGS

Use Kernel time to obtain the current time when IFE is acquired
/released and when sensor is streamed on/off. Convert the Ktime
to a timestamp format and log it in existing info prints. This
will help to co-relate timestamp between user-space and kernel
logs. The change also replaces the current usage of direct calls
to ktime_get_real_ts64 with macro across all drivers.

CRs-Fixed: 2987320
Change-Id: I87c4790164d222fc1ed6ff41ad00eeb1ed8c8867
Signed-off-by: Sokchetra Eung <[email protected]>

drivers/cam_cpas/cam_cpas_hw.c

@@ -2041,7 +2041,7 @@ static void cam_cpas_update_monitor_array(struct cam_hw_info *cpas_hw,
 
 	entry = &cpas_core->monitor_entries[iterator];
 
-	ktime_get_real_ts64(&entry->timestamp);
+	CAM_GET_TIMESTAMP(entry->timestamp);
 	strlcpy(entry->identifier_string, identifier_string,
 		sizeof(entry->identifier_string));
 
@@ -2128,7 +2128,7 @@ static void cam_cpas_dump_monitor_array(
 	int i = 0, j = 0;
 	int64_t state_head = 0;
 	uint32_t index, num_entries, oldest_entry;
-	uint64_t ms, tmp, hrs, min, sec;
+	uint64_t ms, hrs, min, sec;
 	struct cam_cpas_monitor *entry;
 	struct timespec64 curr_timestamp;
 	char log_buf[CAM_CPAS_LOG_BUF_LEN];
@@ -2151,13 +2151,8 @@ static void cam_cpas_dump_monitor_array(
 			CAM_CPAS_MONITOR_MAX_ENTRIES, &oldest_entry);
 	}
 
-
-	ktime_get_real_ts64(&curr_timestamp);
-	tmp = curr_timestamp.tv_sec;
-	ms = (curr_timestamp.tv_nsec) / 1000000;
-	sec = do_div(tmp, 60);
-	min = do_div(tmp, 60);
-	hrs = do_div(tmp, 24);
+	CAM_GET_TIMESTAMP(curr_timestamp);
+	CAM_CONVERT_TIMESTAMP_FORMAT(curr_timestamp, hrs, min, sec, ms);
 
 	CAM_INFO(CAM_CPAS,
 		"**** %llu:%llu:%llu.%llu : ======== Dumping monitor information ===========",
@@ -2167,11 +2162,7 @@ static void cam_cpas_dump_monitor_array(
 
 	for (i = 0; i < num_entries; i++) {
 		entry = &cpas_core->monitor_entries[index];
-		tmp = entry->timestamp.tv_sec;
-		ms = (entry->timestamp.tv_nsec) / 1000000;
-		sec = do_div(tmp, 60);
-		min = do_div(tmp, 60);
-		hrs = do_div(tmp, 24);
+		CAM_CONVERT_TIMESTAMP_FORMAT(entry->timestamp, hrs, min, sec, ms);
 		memset(log_buf, 0, sizeof(log_buf));
 		len = 0;
 

drivers/cam_isp/isp_hw_mgr/cam_ife_hw_mgr.c

@@ -1241,6 +1241,7 @@ static void cam_ife_hw_mgr_print_acquire_info(
 	int hw_idx[CAM_ISP_HW_SPLIT_MAX] = {-1, -1};
 	int sfe_hw_idx[CAM_ISP_HW_SPLIT_MAX] = {-1, -1};
 	int i, len = 0;
+	uint64_t ms, sec, min, hrs;
 
 	if (!list_empty(&hw_mgr_ctx->res_list_ife_src)) {
 		hw_mgr_res = list_first_entry(&hw_mgr_ctx->res_list_ife_src,
@@ -1296,8 +1297,12 @@ static void cam_ife_hw_mgr_print_acquire_info(
 	if (hw_mgr_ctx->flags.is_offline)
 		len += scnprintf(log_info + len, (128 - len), " OFFLINE: Y");
 
+	CAM_GET_TIMESTAMP(hw_mgr_ctx->ts);
+	CAM_CONVERT_TIMESTAMP_FORMAT(hw_mgr_ctx->ts, hrs, min, sec, ms);
+
 	CAM_INFO(CAM_ISP,
-		"Acquired %s with [%u pix] [%u pd] [%u rdi] ports for ctx:%u",
+		"%llu:%llu:%llu.%llu Acquired %s with [%u pix] [%u pd] [%u rdi] ports for ctx:%u",
+		hrs, min, sec, ms,
 		log_info,
 		num_pix_port, num_pd_port, num_rdi_port,
 		hw_mgr_ctx->ctx_index);
@@ -1351,16 +1356,10 @@ static void cam_ife_hw_mgr_dump_acq_data(
 	struct cam_isp_hw_mgr_res    *hw_mgr_res = NULL;
 	struct cam_isp_hw_mgr_res    *hw_mgr_res_temp = NULL;
 	struct cam_isp_resource_node *hw_res = NULL;
-	struct timespec64            *ts = NULL;
-	uint64_t ms, tmp, hrs, min, sec;
+	uint64_t ms, hrs, min, sec;
 	int i = 0, j = 0;
 
-	ts = &hwr_mgr_ctx->ts;
-	tmp = ts->tv_sec;
-	ms = (ts->tv_nsec) / 1000000;
-	sec = do_div(tmp, 60);
-	min = do_div(tmp, 60);
-	hrs = do_div(tmp, 24);
+	CAM_CONVERT_TIMESTAMP_FORMAT(hwr_mgr_ctx->ts, hrs, min, sec, ms);
 
 	CAM_INFO(CAM_ISP,
 		"**** %llu:%llu:%llu.%llu ctx_idx: %u rdi_only: %s is_dual: %s acquired ****",
@@ -4885,8 +4884,6 @@ static int cam_ife_mgr_acquire_hw(void *hw_mgr_priv, void *acquire_hw_args)
 	acquire_args->op_params.param_list[1] =
 		ife_hw_mgr->isp_bus_caps.max_sfe_out_res_type;
 
-	ktime_get_real_ts64(&ife_ctx->ts);
-
 	cam_ife_hw_mgr_print_acquire_info(ife_ctx, total_pix_port,
 		total_pd_port, total_rdi_port, rc);
 
@@ -6662,6 +6659,7 @@ static int cam_ife_mgr_release_hw(void *hw_mgr_priv,
 	struct cam_ife_hw_mgr            *hw_mgr       = hw_mgr_priv;
 	struct cam_ife_hw_mgr_ctx        *ctx;
 	uint32_t                          i;
+	uint64_t                          ms, sec, min, hrs;
 
 	if (!hw_mgr_priv || !release_hw_args) {
 		CAM_ERR(CAM_ISP, "Invalid arguments");
@@ -6715,7 +6713,12 @@ static int cam_ife_mgr_release_hw(void *hw_mgr_priv,
 	}
 
 	cam_ife_mgr_free_cdm_cmd(&ctx->cdm_cmd);
-	CAM_INFO(CAM_ISP, "Release HW success ctx id: %u",
+
+	CAM_GET_TIMESTAMP(ctx->ts);
+	CAM_CONVERT_TIMESTAMP_FORMAT(ctx->ts, hrs, min, sec, ms);
+
+	CAM_INFO(CAM_ISP, "%llu:%llu:%llu.%llu Release HW success ctx id: %u",
+		hrs, min, sec, ms,
 		ctx->ctx_index);
 
 	memset(&ctx->ts, 0, sizeof(struct timespec64));

drivers/cam_req_mgr/cam_mem_mgr.c

@@ -36,27 +36,17 @@ static int cam_mem_mgr_get_dma_heaps(void);
 static void cam_mem_mgr_print_tbl(void)
 {
 	int i;
-	uint64_t ms, tmp, hrs, min, sec;
-	struct timespec64 *ts =  NULL;
+	uint64_t ms, hrs, min, sec;
 	struct timespec64 current_ts;
 
-	ktime_get_real_ts64(&(current_ts));
-	tmp = current_ts.tv_sec;
-	ms = (current_ts.tv_nsec) / 1000000;
-	sec = do_div(tmp, 60);
-	min = do_div(tmp, 60);
-	hrs = do_div(tmp, 24);
+	CAM_GET_TIMESTAMP(current_ts);
+	CAM_CONVERT_TIMESTAMP_FORMAT(current_ts, hrs, min, sec, ms);
 
 	CAM_INFO(CAM_MEM, "***%llu:%llu:%llu:%llu Mem mgr table dump***",
 		hrs, min, sec, ms);
 	for (i = 1; i < CAM_MEM_BUFQ_MAX; i++) {
 		if (tbl.bufq[i].active) {
-			ts = &tbl.bufq[i].timestamp;
-			tmp = ts->tv_sec;
-			ms = (ts->tv_nsec) / 1000000;
-			sec = do_div(tmp, 60);
-			min = do_div(tmp, 60);
-			hrs = do_div(tmp, 24);
+			CAM_CONVERT_TIMESTAMP_FORMAT((tbl.bufq[i].timestamp), hrs, min, sec, ms);
 			CAM_INFO(CAM_MEM,
 				"%llu:%llu:%llu:%llu idx %d fd %d i_ino %lu size %llu",
 				hrs, min, sec, ms, i, tbl.bufq[i].fd, tbl.bufq[i].i_ino,
@@ -235,7 +225,7 @@ static int32_t cam_mem_get_slot(void)
 
 	set_bit(idx, tbl.bitmap);
 	tbl.bufq[idx].active = true;
-	ktime_get_real_ts64(&(tbl.bufq[idx].timestamp));
+	CAM_GET_TIMESTAMP((tbl.bufq[idx].timestamp));
 	mutex_init(&tbl.bufq[idx].q_lock);
 	mutex_unlock(&tbl.m_lock);
 

drivers/cam_sensor_module/cam_sensor/cam_sensor_core.c

@@ -750,6 +750,9 @@ int32_t cam_sensor_driver_cmd(struct cam_sensor_ctrl_t *s_ctrl,
 	struct cam_control *cmd = (struct cam_control *)arg;
 	struct cam_sensor_power_ctrl_t *power_info =
 		&s_ctrl->sensordata->power_info;
+	struct timespec64 ts;
+	uint64_t ms, sec, min, hrs;
+
 	if (!s_ctrl || !arg) {
 		CAM_ERR(CAM_SENSOR, "s_ctrl is NULL");
 		return -EINVAL;
@@ -1043,8 +1046,12 @@ int32_t cam_sensor_driver_cmd(struct cam_sensor_ctrl_t *s_ctrl,
 			}
 		}
 
+		CAM_GET_TIMESTAMP(ts);
+		CAM_CONVERT_TIMESTAMP_FORMAT(ts, hrs, min, sec, ms);
+
 		CAM_INFO(CAM_SENSOR,
-			"CAM_START_DEV Success for %s sensor_id:0x%x,sensor_slave_addr:0x%x",
+			"%llu:%llu:%llu.%llu CAM_START_DEV Success for %s sensor_id:0x%x,sensor_slave_addr:0x%x",
+			hrs, min, sec, ms,
 			s_ctrl->sensor_name,
 			s_ctrl->sensordata->slave_info.sensor_id,
 			s_ctrl->sensordata->slave_info.sensor_slave_addr);
@@ -1073,8 +1080,13 @@ int32_t cam_sensor_driver_cmd(struct cam_sensor_ctrl_t *s_ctrl,
 		cam_sensor_release_per_frame_resource(s_ctrl);
 		s_ctrl->last_flush_req = 0;
 		s_ctrl->sensor_state = CAM_SENSOR_ACQUIRE;
+
+		CAM_GET_TIMESTAMP(ts);
+		CAM_CONVERT_TIMESTAMP_FORMAT(ts, hrs, min, sec, ms);
+
 		CAM_INFO(CAM_SENSOR,
-			"CAM_STOP_DEV Success for %s sensor_id:0x%x,sensor_slave_addr:0x%x",
+			"%llu:%llu:%llu.%llu CAM_STOP_DEV Success for %s sensor_id:0x%x,sensor_slave_addr:0x%x",
+			hrs, min, sec, ms,
 			s_ctrl->sensor_name,
 			s_ctrl->sensordata->slave_info.sensor_id,
 			s_ctrl->sensordata->slave_info.sensor_slave_addr);

drivers/cam_smmu/cam_smmu_api.c

@@ -314,7 +314,7 @@ static void cam_smmu_update_monitor_array(
 
 	CAM_SMMU_INC_MONITOR_HEAD(&cb_info->monitor_head, &iterator);
 
-	ktime_get_real_ts64(&cb_info->monitor_entries[iterator].timestamp);
+	CAM_GET_TIMESTAMP(cb_info->monitor_entries[iterator].timestamp);
 
 	cb_info->monitor_entries[iterator].is_map = is_map;
 	cb_info->monitor_entries[iterator].ion_fd = mapping_info->ion_fd;
@@ -330,8 +330,7 @@ static void cam_smmu_dump_monitor_array(
 	int i = 0;
 	int64_t state_head = 0;
 	uint32_t index, num_entries, oldest_entry;
-	uint64_t ms, tmp, hrs, min, sec;
-	struct timespec64 *ts = NULL;
+	uint64_t ms, hrs, min, sec;
 
 	state_head = atomic64_read(&cb_info->monitor_head);
 
@@ -353,12 +352,8 @@ static void cam_smmu_dump_monitor_array(
 	index = oldest_entry;
 
 	for (i = 0; i < num_entries; i++) {
-		ts = &cb_info->monitor_entries[index].timestamp;
-		tmp = ts->tv_sec;
-		ms = (ts->tv_nsec) / 1000000;
-		sec = do_div(tmp, 60);
-		min = do_div(tmp, 60);
-		hrs = do_div(tmp, 24);
+		CAM_CONVERT_TIMESTAMP_FORMAT(cb_info->monitor_entries[index].timestamp,
+			hrs, min, sec, ms);
 
 		CAM_INFO(CAM_SMMU,
 		"**** %llu:%llu:%llu.%llu : Index[%d] [%s] : ion_fd=%d i_ino=%lu start=0x%llx end=0x%llx len=%zu region=%d",
@@ -543,8 +538,7 @@ static void cam_smmu_dump_cb_info(int idx)
 	size_t shared_reg_len = 0, io_reg_len = 0;
 	size_t shared_free_len = 0, io_free_len = 0;
 	uint32_t i = 0;
-	uint64_t ms, tmp, hrs, min, sec;
-	struct timespec64 *ts = NULL;
+	uint64_t ms, hrs, min, sec;
 	struct timespec64 current_ts;
 	struct cam_context_bank_info *cb_info =
 		&iommu_cb_set.cb_info[idx];
@@ -559,12 +553,9 @@ static void cam_smmu_dump_cb_info(int idx)
 		io_free_len = io_reg_len - cb_info->io_mapping_size;
 	}
 
-	ktime_get_real_ts64(&(current_ts));
-	tmp = current_ts.tv_sec;
-	ms = (current_ts.tv_nsec) / 1000000;
-	sec = do_div(tmp, 60);
-	min = do_div(tmp, 60);
-	hrs = do_div(tmp, 24);
+	CAM_GET_TIMESTAMP(current_ts);
+	CAM_CONVERT_TIMESTAMP_FORMAT(current_ts, hrs, min, sec, ms);
+
 	CAM_ERR(CAM_SMMU,
 		"********** %llu:%llu:%llu:%llu Context bank dump for %s **********",
 		hrs, min, sec, ms, cb_info->name[0]);
@@ -579,12 +570,7 @@ static void cam_smmu_dump_cb_info(int idx)
 		list_for_each_entry_safe(mapping, mapping_temp,
 			&iommu_cb_set.cb_info[idx].smmu_buf_list, list) {
 			i++;
-			ts = &mapping->ts;
-			tmp = ts->tv_sec;
-			ms = (ts->tv_nsec) / 1000000;
-			sec = do_div(tmp, 60);
-			min = do_div(tmp, 60);
-			hrs = do_div(tmp, 24);
+			CAM_CONVERT_TIMESTAMP_FORMAT(mapping->ts, hrs, min, sec, ms);
 			CAM_ERR(CAM_SMMU,
 				"%llu:%llu:%llu:%llu: %u ion_fd=%d i_ino=%lu start=0x%x end=0x%x len=%u region=%d",
 				hrs, min, sec, ms, i, mapping->ion_fd, mapping->i_ino,
@@ -2283,7 +2269,7 @@ static int cam_smmu_map_buffer_and_add_to_list(int idx, int ion_fd,
 	mapping_info->ion_fd = ion_fd;
 	mapping_info->i_ino = file_inode(buf->file)->i_ino;
 	mapping_info->is_internal = is_internal;
-	ktime_get_real_ts64(&mapping_info->ts);
+	CAM_GET_TIMESTAMP(mapping_info->ts);
 	/* add to the list */
 	list_add(&mapping_info->list,
 		&iommu_cb_set.cb_info[idx].smmu_buf_list);
@@ -2314,7 +2300,8 @@ static int cam_smmu_map_kernel_buffer_and_add_to_list(int idx,
 
 	mapping_info->ion_fd = -1;
 	mapping_info->i_ino = file_inode(buf->file)->i_ino;
-	ktime_get_real_ts64(&mapping_info->ts);
+	CAM_GET_TIMESTAMP(mapping_info->ts);
+
 	/* add to the list */
 	list_add(&mapping_info->list,
 		&iommu_cb_set.cb_info[idx].smmu_buf_kernel_list);
@@ -3239,15 +3226,10 @@ int cam_smmu_map_user_iova(int handle, int ion_fd, struct dma_buf *dmabuf,
 	buf_state = cam_smmu_user_reuse_fd_in_list(idx, ion_fd, dmabuf, paddr_ptr,
 		len_ptr, &ts);
 	if (buf_state == CAM_SMMU_BUFF_EXIST) {
-		uint64_t ms = 0, tmp = 0, hrs = 0, min = 0, sec = 0;
-
-		if (ts) {
-			tmp = ts->tv_sec;
-			ms = (ts->tv_nsec) / 1000000;
-			sec = do_div(tmp, 60);
-			min = do_div(tmp, 60);
-			hrs = do_div(tmp, 24);
-		}
+		uint64_t ms = 0, hrs = 0, min = 0, sec = 0;
+
+		if (ts)
+			CAM_CONVERT_TIMESTAMP_FORMAT((*ts), hrs, min, sec, ms);
 		CAM_ERR(CAM_SMMU,
 			"fd=%d already in list [%llu:%llu:%lu:%llu] cb=%s idx=%d handle=%d len=%llu,give same addr back",
 			ion_fd, hrs, min, sec, ms,

drivers/cam_utils/cam_common_util.h

@@ -17,21 +17,30 @@
 #define U64_TO_PTR(ptr) ((void *)(uintptr_t)ptr)
 
 #define CAM_GET_TIMESTAMP(timestamp) ktime_get_real_ts64(&(timestamp))
-#define CAM_GET_TIMESTAMP_DIFF_IN_MICRO(ts_start, ts_end, diff_microsec)       \
-({                                                                             \
-	diff_microsec = 0;                                                     \
-	if (ts_end.tv_nsec >= ts_start.tv_nsec) {                              \
-		diff_microsec =                                                \
-			(ts_end.tv_nsec - ts_start.tv_nsec) / 1000;            \
-		diff_microsec +=                                               \
-			(ts_end.tv_sec - ts_start.tv_sec) * 1000 * 1000;       \
-	} else {                                                               \
-		diff_microsec =                                                \
-			(ts_end.tv_nsec +                                      \
-			(1000*1000*1000 - ts_start.tv_nsec)) / 1000;           \
-		diff_microsec +=                                               \
-			(ts_end.tv_sec - ts_start.tv_sec - 1) * 1000 * 1000;   \
-	}                                                                      \
+#define CAM_GET_TIMESTAMP_DIFF_IN_MICRO(ts_start, ts_end, diff_microsec)         \
+({                                                                               \
+	diff_microsec = 0;                                                       \
+	if (ts_end.tv_nsec >= ts_start.tv_nsec) {                                \
+		diff_microsec =                                                  \
+			(ts_end.tv_nsec - ts_start.tv_nsec) / 1000;              \
+		diff_microsec +=                                                 \
+			(ts_end.tv_sec - ts_start.tv_sec) * 1000 * 1000;         \
+	} else {                                                                 \
+		diff_microsec =                                                  \
+			(ts_end.tv_nsec +                                        \
+			(1000*1000*1000 - ts_start.tv_nsec)) / 1000;             \
+		diff_microsec +=                                                 \
+			(ts_end.tv_sec - ts_start.tv_sec - 1) * 1000 * 1000;     \
+	}                                                                        \
+})
+
+#define CAM_CONVERT_TIMESTAMP_FORMAT(ts, hrs, min, sec, ms)                      \
+({                                                                               \
+	uint64_t tmp = ((ts).tv_sec);                                            \
+	(ms) = ((ts).tv_nsec) / 1000000;                                         \
+	(sec) = do_div(tmp, 60);                                                 \
+	(min) = do_div(tmp, 60);                                                 \
+	(hrs) = do_div(tmp, 24);                                                 \
 })