msm: camera: common: workq delay debug

Added log to print wq_name and callback info to understand
which task is delayed and to aid in debugging.

CRs-Fixed: 3381768
Change-Id: I74f1f5d3312c9163cfbafa4bc15a96c973ef2ba5
Signed-off-by: Karthik Dillibabu <[email protected]>

drivers/cam_cdm/cam_cdm_hw_core.c

@@ -1,7 +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.
+ * Copyright (c) 2022-2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include <linux/delay.h>
@@ -1320,7 +1320,7 @@ static void cam_hw_cdm_work(struct work_struct *work)
 	}
 
 	cam_common_util_thread_switch_delay_detect(
-		"CDM workq schedule",
+		"cam_cdm_workq", "schedule", cam_hw_cdm_work,
 		payload->workq_scheduled_ts,
 		CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
 

drivers/cam_cdm/cam_cdm_virtual_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) 2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include <linux/delay.h>
@@ -36,7 +37,7 @@ static void cam_virtual_cdm_work(struct work_struct *work)
 		core = (struct cam_cdm *)cdm_hw->core_info;
 
 		cam_common_util_thread_switch_delay_detect(
-			"Virtual CDM workq schedule",
+			"virtual_cdm_workq", "schedule", cam_virtual_cdm_work,
 			payload->workq_scheduled_ts,
 			CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
 

drivers/cam_cpas/cpas_top/cam_cpastop_hw.c

@@ -1,7 +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.
+ * Copyright (c) 2022-2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include <linux/delay.h>
@@ -677,7 +677,7 @@ static void cam_cpastop_work(struct work_struct *work)
 	}
 
 	cam_common_util_thread_switch_delay_detect(
-		"CPAS workq schedule",
+		"cam_cpas_workq", "schedule", cam_cpastop_work,
 		payload->workq_scheduled_ts,
 		CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
 

drivers/cam_isp/isp_hw_mgr/hw_utils/cam_tasklet_util.c

@@ -1,6 +1,7 @@
 // SPDX-License-Identifier: GPL-2.0-only
 /*
  * Copyright (c) 2017-2021, The Linux Foundation. All rights reserved.
+ * Copyright (c) 2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include <linux/slab.h>
@@ -334,12 +335,13 @@ static void cam_tasklet_action(unsigned long data)
 	struct cam_tasklet_info          *tasklet_info = NULL;
 	struct cam_tasklet_queue_cmd     *tasklet_cmd = NULL;
 	ktime_t                           tasklet_exec_start_time;
-
+	void                             *cb = NULL;
 	tasklet_info = (struct cam_tasklet_info *)data;
 
 	while (!cam_tasklet_dequeue_cmd(tasklet_info, &tasklet_cmd)) {
+		cb = (void *)tasklet_cmd->bottom_half_handler;
 		cam_common_util_thread_switch_delay_detect(
-			"Tasklet schedule",
+			"ISP Tasklet", "schedule", cb,
 			tasklet_cmd->tasklet_enqueue_ts,
 			CAM_TASKLET_SCHED_TIME_THRESHOLD);
 		tasklet_exec_start_time = ktime_get();
@@ -348,9 +350,9 @@ static void cam_tasklet_action(unsigned long data)
 			tasklet_cmd->payload);
 
 		cam_common_util_thread_switch_delay_detect(
-			"Tasklet execution",
+			"ISP Tasklet", "execution", cb,
 			tasklet_exec_start_time,
-			CAM_TASKLET_EXE_TIME_THRESHOLD);
+			CAM_TASKLET_SCHED_TIME_THRESHOLD);
 		cam_tasklet_put_cmd(tasklet_info, (void **)(&tasklet_cmd));
 	}
 }

drivers/cam_req_mgr/cam_req_mgr_workq.c

@@ -1,6 +1,7 @@
 // SPDX-License-Identifier: GPL-2.0-only
 /*
  * Copyright (c) 2016-2021, The Linux Foundation. All rights reserved.
+ * Copyright (c) 2022-2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include "cam_req_mgr_workq.h"
@@ -108,6 +109,7 @@ void cam_req_mgr_process_workq(struct work_struct *w)
 	int32_t                        i = CRM_TASK_PRIORITY_0;
 	unsigned long                  flags = 0;
 	ktime_t                        sched_start_time;
+	void                          *cb = NULL;
 
 	if (!w) {
 		CAM_ERR(CAM_CRM, "NULL task pointer can not schedule");
@@ -116,21 +118,26 @@ void cam_req_mgr_process_workq(struct work_struct *w)
 	workq = (struct cam_req_mgr_core_workq *)
 		container_of(w, struct cam_req_mgr_core_workq, work);
 
-	cam_common_util_thread_switch_delay_detect(
-		"CRM workq schedule",
-		workq->workq_scheduled_ts,
-		CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
-	sched_start_time = ktime_get();
 	while (i < CRM_TASK_PRIORITY_MAX) {
 		WORKQ_ACQUIRE_LOCK(workq, flags);
 		while (!list_empty(&workq->task.process_head[i])) {
 			task = list_first_entry(&workq->task.process_head[i],
 				struct crm_workq_task, entry);
+			cb = (void *)task->process_cb;
+			cam_common_util_thread_switch_delay_detect(
+				workq->workq_name, "schedule", cb,
+				task->task_scheduled_ts,
+				CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
+			sched_start_time = ktime_get();
 			atomic_sub(1, &workq->task.pending_cnt);
 			list_del_init(&task->entry);
 			WORKQ_RELEASE_LOCK(workq, flags);
 			if (!unlikely(atomic_read(&workq->flush)))
 				cam_req_mgr_process_task(task);
+			cam_common_util_thread_switch_delay_detect(
+				workq->workq_name, "execution", cb,
+				sched_start_time,
+				CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
 			CAM_DBG(CAM_CRM, "processed task %pK free_cnt %d",
 				task, atomic_read(&workq->task.free_cnt));
 			WORKQ_ACQUIRE_LOCK(workq, flags);
@@ -138,10 +145,6 @@ void cam_req_mgr_process_workq(struct work_struct *w)
 		WORKQ_RELEASE_LOCK(workq, flags);
 		i++;
 	}
-	cam_common_util_thread_switch_delay_detect(
-		"CRM workq execution",
-		sched_start_time,
-		CAM_WORKQ_EXE_TIME_THRESHOLD);
 }
 
 int cam_req_mgr_workq_enqueue_task(struct crm_workq_task *task,
@@ -169,6 +172,7 @@ int cam_req_mgr_workq_enqueue_task(struct crm_workq_task *task,
 	task->priority =
 		(prio < CRM_TASK_PRIORITY_MAX && prio >= CRM_TASK_PRIORITY_0)
 		? prio : CRM_TASK_PRIORITY_0;
+	task->task_scheduled_ts = ktime_get();
 
 	WORKQ_ACQUIRE_LOCK(workq, flags);
 	if (!workq->job) {
@@ -184,7 +188,6 @@ int cam_req_mgr_workq_enqueue_task(struct crm_workq_task *task,
 	CAM_DBG(CAM_CRM, "enq task %pK pending_cnt %d",
 		task, atomic_read(&workq->task.pending_cnt));
 
-	workq->workq_scheduled_ts = ktime_get();
 	queue_work(workq->job, &workq->work);
 	WORKQ_RELEASE_LOCK(workq, flags);
 

drivers/cam_req_mgr/cam_req_mgr_workq.h

@@ -1,6 +1,7 @@
 /* SPDX-License-Identifier: GPL-2.0-only */
 /*
  * Copyright (c) 2016-2021, The Linux Foundation. All rights reserved.
+ * Copyright (c) 2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #ifndef _CAM_REQ_MGR_WORKQ_H_
@@ -45,27 +46,29 @@ enum crm_workq_context {
 };
 
 /** struct crm_workq_task
- * @priority   : caller can assign priority to task based on type.
- * @payload    : depending of user of task this payload type will change
- * @process_cb : registered callback called by workq when task enqueued is
- *               ready for processing in workq thread context
- * @parent     : workq's parent is link which is enqqueing taks to this workq
- * @entry      : list head of this list entry is worker's empty_head
- * @cancel     : if caller has got free task from pool but wants to abort
- *               or put back without using it
- * @priv       : when task is enqueuer caller can attach priv along which
- *               it will get in process callback
- * @ret        : return value in future to use for blocking calls
+ * @priority         : caller can assign priority to task based on type.
+ * @payload          : depending of user of task this payload type will change
+ * @process_cb       : registered callback called by workq when task enqueued is
+ *                     ready for processing in workq thread context
+ * @parent           : workq's parent is link which is enqqueing taks to this workq
+ * @entry            : list head of this list entry is worker's empty_head
+ * @cancel           : if caller has got free task from pool but wants to abort
+ *                     or put back without using it
+ * @priv             : when task is enqueuer caller can attach priv along which
+ *                     it will get in process callback
+ * @ret              : return value in future to use for blocking calls
+ * @task_scheduled_ts: enqueue time of task
  */
 struct crm_workq_task {
 	int32_t                    priority;
+	int32_t                    ret;
 	void                      *payload;
 	int32_t                  (*process_cb)(void *priv, void *data);
 	void                      *parent;
 	struct list_head           entry;
 	uint8_t                    cancel;
 	void                      *priv;
-	int32_t                    ret;
+	ktime_t                    task_scheduled_ts;
 };
 
 /** struct cam_req_mgr_core_workq

drivers/cam_sensor_module/cam_cci/cam_cci_core.c

@@ -1,7 +1,7 @@
 // SPDX-License-Identifier: GPL-2.0-only
 /*
  * Copyright (c) 2017-2021, The Linux Foundation. All rights reserved.
- * Copyright (c) 2022-2023 Qualcomm Innovation Center, Inc. All rights reserved.
+ * Copyright (c) 2022-2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include <linux/module.h>
@@ -1584,7 +1584,7 @@ static void cam_cci_write_async_helper(struct work_struct *work)
 	struct cam_cci_master_info *cci_master_info;
 
 	cam_common_util_thread_switch_delay_detect(
-		"CCI workq schedule",
+		"cam_cci_workq", "schedule", cam_cci_write_async_helper,
 		write_async->workq_scheduled_ts,
 		CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
 	cci_dev = write_async->cci_dev;

drivers/cam_sync/cam_sync_util.c

@@ -1,7 +1,7 @@
 // SPDX-License-Identifier: GPL-2.0-only
 /*
  * Copyright (c) 2017-2018, 2020-2021 The Linux Foundation. All rights reserved.
- * Copyright (c) 2022-2023 Qualcomm Innovation Center, Inc. All rights reserved.
+ * Copyright (c) 2022-2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include "cam_sync_util.h"
@@ -629,9 +629,10 @@ void cam_sync_util_cb_dispatch(struct work_struct *cb_dispatch_work)
 		struct sync_callback_info,
 		cb_dispatch_work);
 	sync_callback sync_data = cb_info->callback_func;
+	void *cb = cb_info->callback_func;
 
 	cam_common_util_thread_switch_delay_detect(
-		"CAM-SYNC workq schedule",
+		"cam_sync_workq", "schedule", cb,
 		cb_info->workq_scheduled_ts,
 		CAM_WORKQ_SCHEDULE_TIME_THRESHOLD);
 	sync_data(cb_info->sync_obj, cb_info->status, cb_info->cb_data);

drivers/cam_utils/cam_common_util.c

@@ -1,7 +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.
+ * Copyright (c) 2022-2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #include <linux/string.h>
@@ -142,8 +142,8 @@ int cam_common_modify_timer(struct timer_list *timer, int32_t timeout_val)
 	return 0;
 }
 
-void cam_common_util_thread_switch_delay_detect(
-	const char *token, ktime_t scheduled_time, uint32_t threshold)
+void cam_common_util_thread_switch_delay_detect(char *wq_name, const char *state,
+	void *cb, ktime_t scheduled_time, uint32_t threshold)
 {
 	uint64_t                         diff;
 	ktime_t                          cur_time;
@@ -157,8 +157,9 @@ 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 sched timestamp:[%lld.%06lld] cur timestamp:[%lld.%06lld] diff %ld: threshold %d",
-			token, scheduled_ts.tv_sec,
+			"%s cb: %ps delay in %s detected %ld:%06ld cur %ld:%06ld\n"
+			"diff %ld: threshold %d",
+			wq_name, cb, state, scheduled_ts.tv_sec,
 			scheduled_ts.tv_nsec/NSEC_PER_USEC,
 			cur_ts.tv_sec, cur_ts.tv_nsec/NSEC_PER_USEC,
 			diff, threshold);

drivers/cam_utils/cam_common_util.h

@@ -1,7 +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.
+ * Copyright (c) 2022-2023, Qualcomm Innovation Center, Inc. All rights reserved.
  */
 
 #ifndef _CAM_COMMON_UTIL_H_
@@ -329,13 +329,15 @@ int cam_common_modify_timer(struct timer_list *timer, int32_t timeout_val);
  *
  * @brief                  Detect if there is any scheduling delay
  *
- * @token:                 String identifier to print workq name or tasklet
+ * @wq_name:               workq name
+ * @state:                 either schedule or execution
+ * @cb:                    callback scheduled or executed
  * @scheduled_time:        Time when workq or tasklet was scheduled
  * @threshold:             Threshold time
  *
  */
-void cam_common_util_thread_switch_delay_detect(const char *token,
-	ktime_t scheduled_time, uint32_t threshold);
+void cam_common_util_thread_switch_delay_detect(char *wq_name, const char *state,
+	void *cb, ktime_t scheduled_time, uint32_t threshold);
 
 /**
  * cam_common_register_mini_dump_cb()