[PATCH v2 0/2] clk: Rate Request Tracing

[PATCH v2 0/2] clk: Rate Request Tracing

[maxime]

Hi,

Here's a couple of patches to enable the tracing of clk_rate_requests as they
are submitted to round/determine_rate.

Let me know what you think,
Maxime

To: Michael Turquette <mturquette@baylibre.com>
To: Stephen Boyd <sboyd@kernel.org>
To: Steven Rostedt <rostedt@goodmis.org>
To: Masami Hiramatsu <mhiramat@kernel.org>
Cc: linux-clk@vger.kernel.org
Cc: linux-kernel@vger.kernel.org
Signed-off-by: Maxime Ripard <maxime@cerno.tech>

---
Changes in v2:
- Used a more optimal structure layout for the event
- Added a commit log to the first patch
- Link to v1: https://lore.kernel.org/r/20221018-clk-rate-request-tracing-v1-0-6f3aa0b0b9de@cerno.tech

---
Maxime Ripard (2):
      clk: Store clk_core for clk_rate_request
      clk: Add trace events for rate requests

 drivers/clk/clk.c            | 32 ++++++++++++++++++++++++++++++++
 include/linux/clk-provider.h |  2 ++
 include/trace/events/clk.h   | 43 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 77 insertions(+)
---
base-commit: 69a14e4a9d5a0e1ed73063e0d439c3cb33ce9829
change-id: 20221018-clk-rate-request-tracing-74e80b4534d1

Best regards,
-- 
Maxime Ripard <maxime@cerno.tech>

[PATCH v2 1/2] clk: Store clk_core for clk_rate_request

[maxime]

The struct clk_rate_request is meant to store the context around a rate
request such as the parent, boundaries, and so on.

However, it doesn't store the clock the rate request is submitted to,
which makes debugging difficult.

Let's add a pointer to the relevant clk_core instance in order to
improve the debugging of rate requests in a subsequent patch.

Signed-off-by: Maxime Ripard <maxime@cerno.tech>
---
 drivers/clk/clk.c            | 1 +
 include/linux/clk-provider.h | 2 ++
 2 files changed, 3 insertions(+)

diff --git a/drivers/clk/clk.c b/drivers/clk/clk.c
index 11c41d987ff4..bc6f964cb676 100644
--- a/drivers/clk/clk.c
+++ b/drivers/clk/clk.c
@@ -1468,6 +1468,7 @@ static void clk_core_init_rate_req(struct clk_core * const core,
 	if (!core)
 		return;
 
+	req->core = core;
 	req->rate = rate;
 	clk_core_get_boundaries(core, &req->min_rate, &req->max_rate);
 
diff --git a/include/linux/clk-provider.h b/include/linux/clk-provider.h
index 267cd06b54a0..842e72a5348f 100644
--- a/include/linux/clk-provider.h
+++ b/include/linux/clk-provider.h
@@ -44,6 +44,7 @@ struct dentry;
  *
  * Should be initialized by calling clk_hw_init_rate_request().
  *
+ * @core: 		Pointer to the struct clk_core affected by this request
  * @rate:		Requested clock rate. This field will be adjusted by
  *			clock drivers according to hardware capabilities.
  * @min_rate:		Minimum rate imposed by clk users.
@@ -55,6 +56,7 @@ struct dentry;
  *
  */
 struct clk_rate_request {
+	struct clk_core *core;
 	unsigned long rate;
 	unsigned long min_rate;
 	unsigned long max_rate;

-- 
b4 0.10.1

[PATCH v2 2/2] clk: Add trace events for rate requests

[maxime]

It is currently fairly difficult to follow what clk_rate_request are
issued, and how they have been modified once done.

Indeed, there's multiple paths that can be taken, some functions are
recursive and will just forward the request to its parent, etc.

Adding a lot of debug prints is just not very convenient, so let's add
trace events for the clock requests, one before they are submitted and
one after they are returned.

That way we can simply toggle the tracing on without modifying the
kernel code and without affecting performances or the kernel logs too
much.

Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
Signed-off-by: Maxime Ripard <maxime@cerno.tech>
---
 drivers/clk/clk.c          | 31 +++++++++++++++++++++++++++++++
 include/trace/events/clk.h | 43 +++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 74 insertions(+)

diff --git a/drivers/clk/clk.c b/drivers/clk/clk.c
index bc6f964cb676..343c50e7e214 100644
--- a/drivers/clk/clk.c
+++ b/drivers/clk/clk.c
@@ -603,10 +603,15 @@ int clk_mux_determine_rate_flags(struct clk_hw *hw,
 			}
 
 			clk_core_forward_rate_req(core, req, parent, &parent_req, req->rate);
+
+			trace_clk_rate_request_start(&parent_req);
+
 			ret = clk_core_round_rate_nolock(parent, &parent_req);
 			if (ret)
 				return ret;
 
+			trace_clk_rate_request_done(&parent_req);
+
 			best = parent_req.rate;
 		} else if (parent) {
 			best = clk_core_get_rate_nolock(parent);
@@ -630,10 +635,15 @@ int clk_mux_determine_rate_flags(struct clk_hw *hw,
 			struct clk_rate_request parent_req;
 
 			clk_core_forward_rate_req(core, req, parent, &parent_req, req->rate);
+
+			trace_clk_rate_request_start(&parent_req);
+
 			ret = clk_core_round_rate_nolock(parent, &parent_req);
 			if (ret)
 				continue;
 
+			trace_clk_rate_request_done(&parent_req);
+
 			parent_rate = parent_req.rate;
 		} else {
 			parent_rate = clk_core_get_rate_nolock(parent);
@@ -1551,10 +1561,15 @@ static int clk_core_round_rate_nolock(struct clk_core *core,
 		struct clk_rate_request parent_req;
 
 		clk_core_forward_rate_req(core, req, core->parent, &parent_req, req->rate);
+
+		trace_clk_rate_request_start(&parent_req);
+
 		ret = clk_core_round_rate_nolock(core->parent, &parent_req);
 		if (ret)
 			return ret;
 
+		trace_clk_rate_request_done(&parent_req);
+
 		req->best_parent_rate = parent_req.rate;
 		req->rate = parent_req.rate;
 
@@ -1605,10 +1620,14 @@ unsigned long clk_hw_round_rate(struct clk_hw *hw, unsigned long rate)
 
 	clk_core_init_rate_req(hw->core, &req, rate);
 
+	trace_clk_rate_request_start(&req);
+
 	ret = clk_core_round_rate_nolock(hw->core, &req);
 	if (ret)
 		return 0;
 
+	trace_clk_rate_request_done(&req);
+
 	return req.rate;
 }
 EXPORT_SYMBOL_GPL(clk_hw_round_rate);
@@ -1637,8 +1656,12 @@ long clk_round_rate(struct clk *clk, unsigned long rate)
 
 	clk_core_init_rate_req(clk->core, &req, rate);
 
+	trace_clk_rate_request_start(&req);
+
 	ret = clk_core_round_rate_nolock(clk->core, &req);
 
+	trace_clk_rate_request_done(&req);
+
 	if (clk->exclusive_count)
 		clk_core_rate_protect(clk->core);
 
@@ -2130,10 +2153,14 @@ static struct clk_core *clk_calc_new_rates(struct clk_core *core,
 
 		clk_core_init_rate_req(core, &req, rate);
 
+		trace_clk_rate_request_start(&req);
+
 		ret = clk_core_determine_round_nolock(core, &req);
 		if (ret < 0)
 			return NULL;
 
+		trace_clk_rate_request_done(&req);
+
 		best_parent_rate = req.best_parent_rate;
 		new_rate = req.rate;
 		parent = req.best_parent_hw ? req.best_parent_hw->core : NULL;
@@ -2329,8 +2356,12 @@ static unsigned long clk_core_req_round_rate_nolock(struct clk_core *core,
 
 	clk_core_init_rate_req(core, &req, req_rate);
 
+	trace_clk_rate_request_start(&req);
+
 	ret = clk_core_round_rate_nolock(core, &req);
 
+	trace_clk_rate_request_done(&req);
+
 	/* restore the protection */
 	clk_core_rate_restore_protect(core, cnt);
 
diff --git a/include/trace/events/clk.h b/include/trace/events/clk.h
index e19edc63ee95..daed3c7a48c1 100644
--- a/include/trace/events/clk.h
+++ b/include/trace/events/clk.h
@@ -264,6 +264,49 @@ DEFINE_EVENT(clk_duty_cycle, clk_set_duty_cycle_complete,
 	TP_ARGS(core, duty)
 );
 
+DECLARE_EVENT_CLASS(clk_rate_request,
+
+	TP_PROTO(struct clk_rate_request *req),
+
+	TP_ARGS(req),
+
+	TP_STRUCT__entry(
+		__string(        name, req->core ? req->core->name : "none")
+		__string(       pname, req->best_parent_hw ? clk_hw_get_name(req->best_parent_hw) : "none" )
+		__field(unsigned long,           min                       )
+		__field(unsigned long,           max                       )
+		__field(unsigned long,           prate                     )
+	),
+
+	TP_fast_assign(
+		__assign_str(name, req->core ? req->core->name : "none");
+		__assign_str(pname, req->best_parent_hw ? clk_hw_get_name(req->best_parent_hw) : "none");
+		__entry->min = req->min_rate;
+		__entry->max = req->max_rate;
+		__entry->prate = req->best_parent_rate;
+	),
+
+	TP_printk("%s min %lu max %lu, parent %s (%lu)", __get_str(name),
+		  (unsigned long)__entry->min,
+		  (unsigned long)__entry->max,
+		  __get_str(pname),
+		  (unsigned long)__entry->prate)
+);
+
+DEFINE_EVENT(clk_rate_request, clk_rate_request_start,
+
+	TP_PROTO(struct clk_rate_request *req),
+
+	TP_ARGS(req)
+);
+
+DEFINE_EVENT(clk_rate_request, clk_rate_request_done,
+
+	TP_PROTO(struct clk_rate_request *req),
+
+	TP_ARGS(req)
+);
+
 #endif /* _TRACE_CLK_H */
 
 /* This part must be outside protection */

-- 
b4 0.10.1

Re: [PATCH v2 1/2] clk: Store clk_core for clk_rate_request

[Stephen Boyd]

Quoting maxime@cerno.tech (2022-10-26 06:46:58)
> The struct clk_rate_request is meant to store the context around a rate
> request such as the parent, boundaries, and so on.
> 
> However, it doesn't store the clock the rate request is submitted to,
> which makes debugging difficult.
> 
> Let's add a pointer to the relevant clk_core instance in order to
> improve the debugging of rate requests in a subsequent patch.
> 
> Signed-off-by: Maxime Ripard <maxime@cerno.tech>
> ---

Applied to clk-next

Re: [PATCH v2 2/2] clk: Add trace events for rate requests

[Stephen Boyd]

Quoting maxime@cerno.tech (2022-10-26 06:46:59)
> It is currently fairly difficult to follow what clk_rate_request are
> issued, and how they have been modified once done.
> 
> Indeed, there's multiple paths that can be taken, some functions are
> recursive and will just forward the request to its parent, etc.
> 
> Adding a lot of debug prints is just not very convenient, so let's add
> trace events for the clock requests, one before they are submitted and
> one after they are returned.
> 
> That way we can simply toggle the tracing on without modifying the
> kernel code and without affecting performances or the kernel logs too
> much.
> 
> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> Signed-off-by: Maxime Ripard <maxime@cerno.tech>
> ---

Applied to clk-next