msm: camera: common: Enhance timestamp printing in camera

Add precision to nanosecond part of monotonic timestamps.
Update delimiters between second and nanosecond values.

CRs-Fixed: 3307225
Change-Id: I4e7aab0ea9256c2ff769a87c3873002d715ed3c9
Signed-off-by: Mukund Madhusudan Atre <[email protected]>

drivers/cam_cre/cam_cre_hw_mgr/cam_cre_hw_mgr.c

@@ -2559,7 +2559,8 @@ static int cam_cre_mgr_hw_dump(void *hw_priv, void *hw_dump_args)
 	req_ts = ktime_to_timespec64(ctx_data->req_list[idx]->submit_timestamp);
 
 	if (diff < (CRE_REQUEST_TIMEOUT * 1000)) {
-		CAM_INFO(CAM_CRE, "No Error req %llu %ld:%06ld %ld:%06ld",
+		CAM_INFO(CAM_CRE,
+			"No Error req %llu req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 			dump_args->request_id,
 			req_ts.tv_sec,
 			req_ts.tv_nsec/NSEC_PER_USEC,
@@ -2570,7 +2571,7 @@ static int cam_cre_mgr_hw_dump(void *hw_priv, void *hw_dump_args)
 		return 0;
 	}
 
-	CAM_ERR(CAM_CRE, "Error req %llu %ld:%06ld %ld:%06ld",
+	CAM_ERR(CAM_CRE, "Error req %llu req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 		dump_args->request_id,
 		req_ts.tv_sec,
 		req_ts.tv_nsec/NSEC_PER_USEC,

drivers/cam_fd/fd_hw_mgr/cam_fd_hw_mgr.c

@@ -1595,7 +1595,8 @@ hw_dump:
 	cur_ts = ktime_to_timespec64(cur_time);
 	req_ts = ktime_to_timespec64(frame_req->submit_timestamp);
 	if (diff < CAM_FD_RESPONSE_TIME_THRESHOLD) {
-		CAM_INFO(CAM_FD, "No Error req %lld %ld:%06ld %ld:%06ld",
+		CAM_INFO(CAM_FD,
+			"No Error req %lld req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 			dump_args->request_id,
 			req_ts.tv_sec,
 			req_ts.tv_nsec/NSEC_PER_USEC,
@@ -1603,7 +1604,7 @@ hw_dump:
 			cur_ts.tv_nsec/NSEC_PER_USEC);
 		return 0;
 	}
-	CAM_INFO(CAM_FD, "Error req %lld %ld:%06ld %ld:%06ld",
+	CAM_INFO(CAM_FD, "Error req %lld req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 		dump_args->request_id,
 		req_ts.tv_sec,
 		req_ts.tv_nsec/NSEC_PER_USEC,

drivers/cam_icp/icp_hw/icp_hw_mgr/cam_icp_hw_mgr.c

@@ -5938,7 +5938,7 @@ static int cam_icp_mgr_hw_dump(void *hw_priv, void *hw_dump_args)
 		req_ts = ktime_to_timespec64(frm_process->submit_timestamp[i]);
 	}
 
-	CAM_INFO(CAM_ICP, "Error req %lld %ld:%06ld %ld:%06ld",
+	CAM_INFO(CAM_ICP, "Error req %lld req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 		dump_args->request_id,
 		req_ts.tv_sec,
 		req_ts.tv_nsec/NSEC_PER_USEC,

drivers/cam_isp/isp_hw_mgr/isp_hw/ife_csid_hw/cam_ife_csid_hw_ver2.c

@@ -144,7 +144,8 @@ static void cam_ife_csid_ver2_print_camif_timestamps(
 	}
 
 	if (found && path_cfg)
-		CAM_INFO(CAM_ISP, "CSID[%u] %s SOF[%lld:%lld] EPOCH[%lld:%lld] EOF[%lld:%lld]",
+		CAM_INFO(CAM_ISP,
+			"CSID[%u] %s SOF timestamp:[%lld.%09lld] EPOCH timestamp:[%lld.%09lld] EOF timestamp:[%lld.%09lld]",
 			csid_hw->hw_intf->hw_idx, res->res_name,
 			path_cfg->sof_ts.tv_sec, path_cfg->sof_ts.tv_nsec,
 			path_cfg->epoch_ts.tv_sec, path_cfg->epoch_ts.tv_nsec,
@@ -1138,7 +1139,7 @@ static int cam_ife_csid_ver2_handle_event_err(
 			path_cfg = (struct cam_ife_csid_ver2_path_cfg *)res->res_priv;
 			evt.res_id   = res->res_id;
 			CAM_ERR(CAM_ISP,
-				"csid[%u] Res:%s Err 0x%x status 0x%x time_stamp: %lld:%lld",
+				"csid[%u] Res:%s Err 0x%x status 0x%x time_stamp: %lld.%09lld",
 				csid_hw->hw_intf->hw_idx, res->res_name, err_type,
 				irq_status, path_cfg->error_ts.tv_sec,
 				path_cfg->error_ts.tv_nsec);
@@ -1613,7 +1614,7 @@ static int cam_ife_csid_ver2_parse_path_irq_status(
 	bit_pos = 0;
 	while (status) {
 		if (status & 0x1)
-			CAM_INFO(CAM_ISP, "CSID[%d] IRQ %s %s timestamp:[%lld:%lld]",
+			CAM_INFO(CAM_ISP, "CSID[%d] IRQ %s %s timestamp:[%lld.%09lld]",
 				csid_hw->hw_intf->hw_idx, irq_reg_tag[index],
 				csid_reg->path_irq_desc[bit_pos].desc,
 				evt_payload->timestamp.tv_sec,
@@ -1662,20 +1663,20 @@ static int cam_ife_csid_ver2_top_info_irq_bottom_half(
 
 	if (irq_status & IFE_CSID_VER2_TOP_INFO_VOTE_UP) {
 		cam_cpas_log_votes(true);
-		CAM_INFO(CAM_ISP, "CSID:%d INFO_VOTE_UP timestamp:[%lld:%lld]",
+		CAM_INFO(CAM_ISP, "CSID:%d INFO_VOTE_UP timestamp:[%lld.%09lld]",
 			csid_hw->hw_intf->hw_idx, payload->timestamp.tv_sec,
 			payload->timestamp.tv_nsec);
 	}
 
 	if (irq_status & IFE_CSID_VER2_TOP_INFO_VOTE_DN) {
 		cam_cpas_log_votes(true);
-		CAM_INFO(CAM_ISP, "CSID:%d INFO_VOTE_DN timestamp:[%lld:%lld]",
+		CAM_INFO(CAM_ISP, "CSID:%d INFO_VOTE_DN timestamp:[%lld.%09lld]",
 			csid_hw->hw_intf->hw_idx, payload->timestamp.tv_sec,
 			payload->timestamp.tv_nsec);
 	}
 
 	if (irq_status & IFE_CSID_VER2_TOP_ERR_NO_VOTE_DN) {
-		CAM_INFO(CAM_ISP, "CSID:%d ERR_NO_VOTE_DN timestamp:[%lld:%lld]",
+		CAM_INFO(CAM_ISP, "CSID:%d ERR_NO_VOTE_DN timestamp:[%lld.%09lld]",
 			csid_hw->hw_intf->hw_idx, payload->timestamp.tv_sec,
 			payload->timestamp.tv_nsec);
 

drivers/cam_isp/isp_hw_mgr/isp_hw/tfe_hw/cam_tfe_core.c

@@ -329,10 +329,10 @@ static void cam_tfe_log_error_irq_status(
 	soc_info = top_priv->common_data.soc_info;
 	soc_private = top_priv->common_data.soc_info->soc_private;
 
-	CAM_INFO(CAM_ISP, "current monotonic time stamp seconds %lld:%lld",
+	CAM_INFO(CAM_ISP, "current monotonic timestamp:[%lld.%06lld]",
 		ts.tv_sec, ts.tv_nsec/1000);
 	CAM_INFO(CAM_ISP,
-		"ERROR time %lld:%lld SOF %lld:%lld EPOCH %lld:%lld EOF %lld:%lld",
+		"ERROR timestamp:[%lld.%06lld] SOF timestamp:[%lld.%06lld] EPOCH timestamp:[%lld.%06lld] EOF timestamp:[%lld.%06lld]",
 		top_priv->error_ts.tv_sec,
 		top_priv->error_ts.tv_nsec/1000,
 		top_priv->sof_ts.tv_sec,

drivers/cam_isp/isp_hw_mgr/isp_hw/vfe_hw/vfe_top/cam_vfe_camif_lite_ver2.c

@@ -557,10 +557,10 @@ static int cam_vfe_camif_lite_handle_irq_bottom_half(
 
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 		CAM_INFO(CAM_ISP,
-			"ERROR time %lld:%lld",
+			"ERROR timestamp:[%lld.%09lld]",
 			camif_lite_priv->error_ts.tv_sec,
 			camif_lite_priv->error_ts.tv_nsec);
 		CAM_INFO(CAM_ISP, "ife_clk_src:%lld",

drivers/cam_isp/isp_hw_mgr/isp_hw/vfe_hw/vfe_top/cam_vfe_camif_lite_ver3.c

@@ -1173,16 +1173,16 @@ static int cam_vfe_camif_lite_handle_irq_bottom_half(
 		evt_info.event_data = (void *)&err_evt_info;
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 		CAM_INFO(CAM_ISP,
-			"ERROR time %lld:%lld",
+			"ERROR timestamp:[%lld.%09lld]",
 			camif_lite_priv->error_ts.tv_sec,
 			camif_lite_priv->error_ts.tv_nsec);
 
 		if (camif_lite_node->is_rdi_primary_res)
 			CAM_INFO(CAM_ISP,
-				"SOF %lld:%lld EPOCH %lld:%lld EOF %lld:%lld",
+				"SOF timestamp:[%lld.%09lld] EPOCH timestamp:[%lld.%09lld] EOF timestamp:[%lld.%09lld]",
 				camif_lite_priv->sof_ts.tv_sec,
 				camif_lite_priv->sof_ts.tv_nsec,
 				camif_lite_priv->epoch_ts.tv_sec,

drivers/cam_isp/isp_hw_mgr/isp_hw/vfe_hw/vfe_top/cam_vfe_camif_ver2.c

@@ -668,7 +668,7 @@ int cam_vfe_camif_dump_timestamps(
 		(struct cam_vfe_mux_camif_data *)rsrc_node->res_priv;
 
 	CAM_INFO(CAM_ISP,
-		"CAMIF ERROR time %lld:%lld SOF %lld:%lld EPOCH %lld:%lld EOF %lld:%lld",
+		"CAMIF ERROR timestamp:[%lld.%09lld] SOF timestamp:[%lld.%09lld] EPOCH timestamp:[%lld.%09lld] EOF timestamp:[%lld.%09lld]",
 		camif_priv->error_ts.tv_sec,
 		camif_priv->error_ts.tv_nsec,
 		camif_priv->sof_ts.tv_sec,
@@ -889,7 +889,7 @@ static int cam_vfe_camif_handle_irq_bottom_half(void *handler_priv,
 		evt_info.event_data = (void *)&err_evt_info;
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 
 		if (camif_priv->event_cb)
@@ -917,7 +917,7 @@ static int cam_vfe_camif_handle_irq_bottom_half(void *handler_priv,
 		evt_info.event_data = (void *)&err_evt_info;
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 
 		if (camif_priv->event_cb)

drivers/cam_isp/isp_hw_mgr/isp_hw/vfe_hw/vfe_top/cam_vfe_camif_ver3.c

@@ -820,7 +820,7 @@ int cam_vfe_camif_ver3_dump_timestamps(
 		(struct cam_vfe_mux_camif_ver3_data *)rsrc_node->res_priv;
 
 	CAM_INFO(CAM_ISP,
-		"CAMIF ERROR time %lld:%lld SOF %lld:%lld EPOCH %lld:%lld EOF %lld:%lld",
+		"CAMIF ERROR timestamp:[%lld.%09lld] SOF timestamp:[%lld.%09lld] EPOCH timestamp:[%lld.%09lld] EOF timestamp:[%lld.%09lld]",
 		camif_priv->error_ts.tv_sec,
 		camif_priv->error_ts.tv_nsec,
 		camif_priv->sof_ts.tv_sec,
@@ -1470,7 +1470,7 @@ static int cam_vfe_camif_ver3_handle_irq_bottom_half(void *handler_priv,
 
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 
 		ret = CAM_VFE_IRQ_STATUS_OVERFLOW;
@@ -1504,7 +1504,7 @@ static int cam_vfe_camif_ver3_handle_irq_bottom_half(void *handler_priv,
 
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 
 		ret = CAM_VFE_IRQ_STATUS_VIOLATION;

drivers/cam_isp/isp_hw_mgr/isp_hw/vfe_hw/vfe_top/cam_vfe_rdi.c

@@ -536,7 +536,7 @@ static int cam_vfe_rdi_handle_irq_bottom_half(void *handler_priv,
 	if (irq_rdi_status) {
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 
 		cam_vfe_rdi_cpas_reg_dump(rdi_priv);
@@ -544,7 +544,7 @@ static int cam_vfe_rdi_handle_irq_bottom_half(void *handler_priv,
 		CAM_INFO(CAM_ISP, "ife_clk_src:%lld",
 			soc_private->ife_clk_src);
 		CAM_INFO(CAM_ISP,
-			"ERROR time %lld:%lld SOF %lld:%lld",
+			"ERROR timestamp:[%lld.%09lld] SOF timestamp:[%lld.%09lld]",
 			rdi_priv->error_ts.tv_sec,
 			rdi_priv->error_ts.tv_nsec,
 			rdi_priv->sof_ts.tv_sec,

drivers/cam_isp/isp_hw_mgr/isp_hw/vfe_hw/vfe_top/cam_vfe_top_ver4.c

@@ -500,11 +500,11 @@ int cam_vfe_top_ver4_dump_timestamps(
 	ktime_get_boottime_ts64(&ts);
 
 	CAM_INFO(CAM_ISP,
-		"VFE[%u] current monotonic time stamp seconds %lld:%lld",
+		"VFE[%u] current monotonic timestamp:[%lld.%09lld]",
 		vfe_priv->hw_intf->hw_idx, ts.tv_sec, ts.tv_nsec);
 
 	CAM_INFO(CAM_ISP,
-		"CAMIF Error time %lld:%lld SOF %lld:%lld EPOCH %lld:%lld EOF %lld:%lld",
+		"CAMIF Error timestamp:[%lld.%09lld] SOF timestamp:[%lld.%09lld] EPOCH timestamp:[%lld.%09lld] EOF timestamp:[%lld.%09lld]",
 		vfe_priv->error_ts.tv_sec,
 		vfe_priv->error_ts.tv_nsec,
 		vfe_priv->sof_ts.tv_sec,
@@ -1438,7 +1438,7 @@ static int cam_vfe_handle_irq_bottom_half(void *handler_priv,
 		evt_info.event_data = (void *)&err_evt_info;
 		ktime_get_boottime_ts64(&ts);
 		CAM_INFO(CAM_ISP,
-			"current monotonic time stamp seconds %lld:%lld",
+			"current monotonic timestamp:[%lld.%09lld]",
 			ts.tv_sec, ts.tv_nsec);
 
 		if (vfe_priv->event_cb)

drivers/cam_jpeg/jpeg_hw/cam_jpeg_hw_mgr.c

@@ -1863,7 +1863,7 @@ hw_dump:
 
 	if (diff < CAM_JPEG_RESPONSE_TIME_THRESHOLD) {
 		CAM_INFO(CAM_JPEG,
-			"No error req %lld %ld:%06ld %ld:%06ld",
+			"No error req %lld req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 			dump_args->request_id,
 			req_ts.tv_sec,
 			req_ts.tv_nsec/NSEC_PER_USEC,
@@ -1874,7 +1874,7 @@ hw_dump:
 	}
 
 	CAM_INFO(CAM_JPEG,
-		"Error req %lld %ld:%06ld %ld:%06ld",
+		"Error req %lld req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 		dump_args->request_id,
 		req_ts.tv_sec,
 		req_ts.tv_nsec/NSEC_PER_USEC,

drivers/cam_lrme/lrme_hw_mgr/lrme_hw/cam_lrme_hw_core.c

@@ -1,6 +1,7 @@
 // SPDX-License-Identifier: GPL-2.0-only
 /*
  * Copyright (c) 2017-2021, The Linux Foundation. All rights reserved.
+ * Copyright (c) 2022 Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include <linux/timer.h>
@@ -120,7 +121,8 @@ static int cam_lrme_hw_dump(
 	req_ts = ktime_to_timespec64(req->submit_timestamp);
 
 	if (diff < CAM_LRME_RESPONSE_TIME_THRESHOLD) {
-		CAM_INFO(CAM_LRME, "No error req %lld %ld:%06ld %ld:%06ld",
+		CAM_INFO(CAM_LRME,
+			"No error req %lld req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 			dump_args->request_id,
 			req_ts.tv_sec,
 			req_ts.tv_nsec/NSEC_PER_USEC,
@@ -130,7 +132,8 @@ static int cam_lrme_hw_dump(
 		return 0;
 	}
 
-	CAM_INFO(CAM_LRME, "Error req %lld %ld:%06ld %ld:%06ld",
+	CAM_INFO(CAM_LRME,
+		"Error req %lld req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 		dump_args->request_id,
 		req_ts.tv_sec,
 		req_ts.tv_nsec/NSEC_PER_USEC,

drivers/cam_ope/ope_hw_mgr/cam_ope_hw_mgr.c

@@ -3650,7 +3650,8 @@ static int cam_ope_mgr_hw_dump(void *hw_priv, void *hw_dump_args)
 	req_ts = ktime_to_timespec64(ctx_data->req_list[idx]->submit_timestamp);
 
 	if (diff < (ctx_data->req_timer_timeout * 1000)) {
-		CAM_INFO(CAM_OPE, "No Error req %llu %ld:%06ld %ld:%06ld",
+		CAM_INFO(CAM_OPE,
+			"No Error req %llu req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 			dump_args->request_id,
 			req_ts.tv_sec,
 			req_ts.tv_nsec/NSEC_PER_USEC,
@@ -3661,7 +3662,7 @@ static int cam_ope_mgr_hw_dump(void *hw_priv, void *hw_dump_args)
 		return 0;
 	}
 
-	CAM_ERR(CAM_OPE, "Error req %llu %ld:%06ld %ld:%06ld",
+	CAM_ERR(CAM_OPE, "Error req %llu req timestamp:[%lld.%06lld] curr timestamp:[%lld.%06lld]",
 		dump_args->request_id,
 		req_ts.tv_sec,
 		req_ts.tv_nsec/NSEC_PER_USEC,

drivers/cam_utils/cam_common_util.c

@@ -157,7 +157,7 @@ void cam_common_util_thread_switch_delay_detect(
 		scheduled_ts  = ktime_to_timespec64(scheduled_time);
 		cur_ts = ktime_to_timespec64(cur_time);
 		CAM_WARN_RATE_LIMIT_CUSTOM(CAM_UTIL, 1, 1,
-			"%s delay detected %ld:%06ld cur %ld:%06ld diff %ld: threshold %d",
+			"%s delay detected sched timestamp:[%lld.%06lld] cur timestamp:[%lld.%06lld] diff %ld: threshold %d",
 			token, scheduled_ts.tv_sec,
 			scheduled_ts.tv_nsec/NSEC_PER_USEC,
 			cur_ts.tv_sec, cur_ts.tv_nsec/NSEC_PER_USEC,

drivers/cam_utils/cam_common_util.h

@@ -74,7 +74,8 @@
 	rem_jiffies = cam_common_wait_for_completion_timeout((complete), (timeout_jiffies)); \
 	if (!rem_jiffies) {                                                                  \
 		end_time = ktime_to_timespec64(ktime_get());                                 \
-		CAM_ERR(module_id, fmt " (timeout: %ums start: %llu.%llu end: %llu.%llu)",   \
+		CAM_ERR(module_id,                                                           \
+		fmt " (timeout: %ums start: timestamp:[%lld.%06lld] end: timestamp:[%lld.%06lld])",\
 		##args, jiffies_to_msecs(timeout_jiffies),                                   \
 		start_time.tv_sec, (start_time.tv_nsec/NSEC_PER_USEC),                       \
 		end_time.tv_sec, (end_time.tv_nsec/NSEC_PER_USEC));                          \