[PATCH] clk: debugfs: Support frequency stats accounting

[PATCH] clk: debugfs: Support frequency stats accounting

[Badhri Jagan Sridharan]

Added frequency statistics accounting to common
clk debug framework. This change tracks the
frequency of the clocks which don't have the
CLK_GET_RATE_NOCACHE flag set. This is done by
monitoring the calls to  clk_set_rate, clk_enable
and then clk_disable. This patch would help
debugging power drain issues.

There is a new node called frequency_stats_table
created under DEBUG_FS/clk/<clk_debug_name>/ to
report the collected statistics. In addition,
the stats also gets printed as a part of the
clk_summary. Frequency gets reported in HZ and
the time_spent gets reported in msec units.

sample output of clk_summary:

   clock                         enable_cnt  prepare_cnt        rate   accuracy   phase
----------------------------------------------------------------------------------------
 clk24mhz                                 2            3    24000000          0 0
 *[        default_freq                                   48188]
 *         400000000					     54

default_freq accounts the time for which the
clk was on without an explicit call to the
clk_set_rate API. The [] braces highlight the
latest frequency set through clk_set_rate API.

Frequency accounting can be started(or)stopped
by writing 1(or)0 to /d/clk/freq_stats_on.
Writing 1 also causes the counters to reset.

Enabling CONFIG_FREQ_STATS_ACCOUNTING includes
the feature.

Enabling CONFIG_BEGIN_ACCOUNTING_FROM_BOOT
starts accounting right from boot.

Signed-off-by: Badhri Jagan Sridharan <Badhri@google.com>
---
 drivers/clk/Kconfig |  18 ++++
 drivers/clk/clk.c   | 299 ++++++++++++++++++++++++++++++++++++++++++++++++++--
 2 files changed, 311 insertions(+), 6 deletions(-)

diff --git a/drivers/clk/Kconfig b/drivers/clk/Kconfig
index 0b474a0..0ea6cc2 100644
--- a/drivers/clk/Kconfig
+++ b/drivers/clk/Kconfig
@@ -143,6 +143,24 @@ config COMMON_CLK_CDCE706
 	---help---
 	  This driver supports TI CDCE706 programmable 3-PLL clock synthesizer.
 
+config COMMON_CLK_FREQ_STATS_ACCOUNTING
+	bool "Enable clock frequency stats accounting"
+	depends on COMMON_CLK
+	depends on DEBUG_FS
+	---help---
+	 Allows accounting of the time spent by various clocks in each
+	 of its operating frequency. The stats get reported as a part
+	 of clk_summary. Would be be useful in finding out which
+	 components are running at what power states to debug
+	 battery consumption issues.
+
+config COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT
+	bool "Start clock frequency stats accounting from boot"
+	depends on COMMON_CLK_FREQ_STATS_ACCOUNTING
+	---help---
+	 Enabling this option starts the frequency accounting right from
+	 the boot.
+
 source "drivers/clk/qcom/Kconfig"
 
 endmenu
diff --git a/drivers/clk/clk.c b/drivers/clk/clk.c
index 237f23f..6d082e9 100644
--- a/drivers/clk/clk.c
+++ b/drivers/clk/clk.c
@@ -11,16 +11,19 @@
 
 #include <linux/clk-provider.h>
 #include <linux/clk/clk-conf.h>
-#include <linux/module.h>
-#include <linux/mutex.h>
-#include <linux/spinlock.h>
+#include <linux/device.h>
 #include <linux/err.h>
+#include <linux/init.h>
+#include <linux/ktime.h>
 #include <linux/list.h>
-#include <linux/slab.h>
+#include <linux/module.h>
+#include <linux/mutex.h>
 #include <linux/of.h>
-#include <linux/device.h>
-#include <linux/init.h>
+#include <linux/rbtree.h>
 #include <linux/sched.h>
+#include <linux/spinlock.h>
+#include <linux/slab.h>
+#include <linux/timekeeping.h>
 
 #include "clk.h"
 
@@ -45,6 +48,13 @@ static bool clk_core_is_enabled(struct clk_core *clk);
 static struct clk_core *clk_core_lookup(const char *name);
 
 /***    private data structures    ***/
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+struct freq_stats {
+	ktime_t time_spent;
+	unsigned long rate;
+	struct rb_node node;
+};
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
 
 struct clk_core {
 	const char		*name;
@@ -73,6 +83,12 @@ struct clk_core {
 	unsigned int		notifier_count;
 #ifdef CONFIG_DEBUG_FS
 	struct dentry		*dentry;
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+	struct rb_root freq_stats_table;
+	struct freq_stats *current_freq_stats;
+	ktime_t default_freq_time;
+	ktime_t start_time;
+#endif /* CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
 #endif
 	struct kref		ref;
 };
@@ -163,6 +179,134 @@ static struct hlist_head *orphan_list[] = {
 	NULL,
 };
 
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+
+#ifdef CONFIG_COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT
+static bool freq_stats_on = true;
+#else
+static bool freq_stats_on;
+#endif /*CONFIG_COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT*/
+
+void free_tree(struct rb_node *node)
+{
+	struct freq_stats *this;
+
+	if (!node)
+		return;
+
+	free_tree(node->rb_left);
+	free_tree(node->rb_right);
+
+	this = rb_entry(node, struct freq_stats, node);
+	kfree(this);
+}
+
+struct freq_stats *freq_stats_insert(struct rb_root *freq_stats_table,
+				unsigned long rate)
+{
+	struct rb_node **new = &(freq_stats_table->rb_node), *parent = NULL;
+	struct freq_stats *this;
+
+	/* Figure out where to put new node */
+	while (*new) {
+		this = rb_entry(*new, struct freq_stats, node);
+		parent = *new;
+
+		if (rate < this->rate)
+			new = &((*new)->rb_left);
+		else if (rate > this->rate)
+			new = &((*new)->rb_right);
+		else
+			return this;
+	}
+
+	this = kzalloc(sizeof(*this), GFP_ATOMIC);
+	this->rate = rate;
+
+	/* Add new node and rebalance tree. */
+	rb_link_node(&this->node, parent, new);
+	rb_insert_color(&this->node, freq_stats_table);
+
+	return this;
+}
+
+static void generic_print_freq_stats_table(struct seq_file *m,
+				struct clk_core *clk,
+				bool indent, int level)
+{
+	struct rb_node *pos;
+	struct freq_stats *cur;
+
+	if (indent)
+		seq_printf(m, "%*s*%s%20s", level * 3 + 1, "",
+			!clk->current_freq_stats ? "[" : "",
+			"default_freq");
+	else
+		seq_printf(m, "%2s%20s", !clk->current_freq_stats ? "[" : "",
+			"default_freq");
+
+	if (!clk->current_freq_stats && !ktime_equal(clk->start_time,
+					ktime_set(0, 0)))
+		seq_printf(m, "%40llu",
+			ktime_to_ms(ktime_add(clk->default_freq_time,
+			ktime_sub(ktime_get(), clk->start_time))));
+	else
+		seq_printf(m, "%40llu", ktime_to_ms(clk->default_freq_time));
+
+	if (!clk->current_freq_stats)
+		seq_puts(m, "]");
+
+	seq_puts(m, "\n");
+
+	for (pos = rb_first(&clk->freq_stats_table); pos; pos = rb_next(pos)) {
+		cur = rb_entry(pos, typeof(*cur), node);
+
+		if (indent)
+			seq_printf(m, "%*s*%s%20lu", level * 3 + 1, "",
+				cur->rate == clk->rate ? "[" : "", cur->rate);
+		else
+			seq_printf(m, "%2s%20lu", cur->rate == clk->rate ?
+				"[" : "", cur->rate);
+
+		if (cur->rate == clk->rate && !ktime_equal(clk->start_time,
+					ktime_set(0, 0)))
+			seq_printf(m, "%40llu",
+				ktime_to_ms(ktime_add(cur->time_spent,
+				ktime_sub(ktime_get(), clk->start_time))));
+		else
+			seq_printf(m, "%40llu", ktime_to_ms(cur->time_spent));
+
+		if (cur->rate == clk->rate)
+			seq_puts(m, "]");
+		seq_puts(m, "\n");
+	}
+}
+
+
+static int clock_print_freq_stats_table(struct seq_file *m, void *unused)
+{
+	struct clk_core *clk = m->private;
+
+	if (!(clk->flags & CLK_GET_RATE_NOCACHE))
+		generic_print_freq_stats_table(m, clk, false, 0);
+
+	return 0;
+}
+
+static int freq_stats_table_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, clock_print_freq_stats_table,
+			inode->i_private);
+}
+
+static const struct file_operations freq_stats_table_fops = {
+	.open           = freq_stats_table_open,
+	.read           = seq_read,
+	.llseek         = seq_lseek,
+	.release        = seq_release,
+};
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
+
 static void clk_summary_show_one(struct seq_file *s, struct clk_core *c,
 				 int level)
 {
@@ -174,8 +318,14 @@ static void clk_summary_show_one(struct seq_file *s, struct clk_core *c,
 		   30 - level * 3, c->name,
 		   c->enable_count, c->prepare_count, clk_core_get_rate(c),
 		   clk_core_get_accuracy(c), clk_core_get_phase(c));
+
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+	if (!(c->flags & CLK_GET_RATE_NOCACHE))
+		generic_print_freq_stats_table(s, c, true, level);
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
 }
 
+
 static void clk_summary_show_subtree(struct seq_file *s, struct clk_core *c,
 				     int level)
 {
@@ -290,6 +440,78 @@ static const struct file_operations clk_dump_fops = {
 	.release	= single_release,
 };
 
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+static int freq_stats_get(void *unused, u64 *val)
+{
+	*val = freq_stats_on;
+	return 0;
+}
+
+static void clk_traverse_subtree(struct clk_core *clk, int freq_stats_on)
+{
+	struct clk_core *child;
+	struct rb_node *node;
+
+	if (!clk)
+		return;
+
+	if (freq_stats_on) {
+		for (node = rb_first(&clk->freq_stats_table);
+			node; node = rb_next(node))
+			rb_entry(node, struct freq_stats, node)->time_spent =
+							ktime_set(0, 0);
+
+		clk->current_freq_stats = freq_stats_insert(
+						&clk->freq_stats_table,
+						clk_core_get_rate(clk));
+
+		if (clk->enable_count > 0)
+			clk->start_time = ktime_get();
+	} else {
+		if (clk->enable_count > 0) {
+			if (!clk->current_freq_stats)
+				clk->default_freq_time =
+				ktime_add(clk->default_freq_time,
+				ktime_sub(ktime_get(), clk->start_time));
+			else
+				clk->current_freq_stats->time_spent =
+				ktime_add(clk->current_freq_stats->time_spent,
+				ktime_sub(ktime_get(), clk->start_time));
+
+			clk->start_time = ktime_set(0, 0);
+		}
+	}
+	hlist_for_each_entry(child, &clk->children, child_node)
+		clk_traverse_subtree(child, freq_stats_on);
+}
+
+static int freq_stats_set(void *data, u64 val)
+{
+	struct clk_core *c;
+	unsigned long flags;
+	struct hlist_head **lists = (struct hlist_head **)data;
+
+	clk_prepare_lock();
+	flags = clk_enable_lock();
+
+	if (val == 0)
+		freq_stats_on = 0;
+	else
+		freq_stats_on = 1;
+
+	for (; *lists; lists++)
+		hlist_for_each_entry(c, *lists, child_node)
+			clk_traverse_subtree(c, freq_stats_on);
+
+	clk_enable_unlock(flags);
+	clk_prepare_unlock();
+
+	return 0;
+}
+DEFINE_SIMPLE_ATTRIBUTE(freq_stats_fops, freq_stats_get,
+			freq_stats_set, "%llu\n");
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
+
 static int clk_debug_create_one(struct clk_core *clk, struct dentry *pdentry)
 {
 	struct dentry *d;
@@ -341,6 +563,14 @@ static int clk_debug_create_one(struct clk_core *clk, struct dentry *pdentry)
 	if (!d)
 		goto err_out;
 
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+	d = debugfs_create_file("frequency_stats_table", S_IRUGO, clk->dentry,
+			clk, &freq_stats_table_fops);
+
+	if (!d)
+		goto err_out;
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
+
 	if (clk->ops->debug_init) {
 		ret = clk->ops->debug_init(clk->hw, clk->dentry);
 		if (ret)
@@ -454,6 +684,13 @@ static int __init clk_debug_init(void)
 	if (!d)
 		return -ENOMEM;
 
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+	d = debugfs_create_file("freq_stats_on", S_IRUGO|S_IWUSR,
+				rootdir, &all_lists, &freq_stats_fops);
+	if (!d)
+		return -ENOMEM;
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
+
 	mutex_lock(&clk_debug_lock);
 	hlist_for_each_entry(clk, &clk_debug_list, debug_node)
 		clk_debug_create_one(clk, rootdir);
@@ -998,6 +1235,22 @@ static void clk_core_disable(struct clk_core *clk)
 	if (clk->ops->disable)
 		clk->ops->disable(clk->hw);
 
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+
+	if (freq_stats_on) {
+		if (!clk->current_freq_stats)
+			clk->default_freq_time =
+			ktime_add(clk->default_freq_time,
+			ktime_sub(ktime_get(), clk->start_time));
+		else
+			clk->current_freq_stats->time_spent =
+			ktime_add(clk->current_freq_stats->time_spent,
+			ktime_sub(ktime_get(), clk->start_time));
+
+		clk->start_time = ktime_set(0, 0);
+	}
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
+
 	clk_core_disable(clk->parent);
 }
 
@@ -1057,6 +1310,11 @@ static int clk_core_enable(struct clk_core *clk)
 				return ret;
 			}
 		}
+
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+	if (freq_stats_on)
+		clk->start_time = ktime_get();
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
 	}
 
 	clk->enable_count++;
@@ -1724,6 +1982,31 @@ static void clk_change_rate(struct clk_core *clk)
 
 	clk->rate = clk_recalc(clk, best_parent_rate);
 
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+	if (freq_stats_on) {
+		if (!ktime_equal(clk->start_time, ktime_set(0, 0))) {
+			if (!clk->current_freq_stats)
+				clk->default_freq_time =
+					ktime_add(clk->default_freq_time,
+					ktime_sub(ktime_get(),
+					clk->start_time));
+			else
+				clk->current_freq_stats->time_spent =
+					ktime_add(
+					clk->current_freq_stats->time_spent,
+					ktime_sub(ktime_get(),
+					clk->start_time));
+		}
+
+		clk->current_freq_stats = freq_stats_insert(
+						&clk->freq_stats_table,
+						clk->rate);
+
+		if (clk->enable_count > 0)
+			clk->start_time = ktime_get();
+	}
+#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
+
 	if (clk->notifier_count && old_rate != clk->rate)
 		__clk_notify(clk, POST_RATE_CHANGE, old_rate, clk->rate);
 
@@ -2519,6 +2802,10 @@ static void __clk_release(struct kref *ref)
 
 	kfree(clk->parent_names);
 	kfree_const(clk->name);
+
+#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
+	free_tree(clk->freq_stats_table.rb_node);
+#endif/*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
 	kfree(clk);
 }
 
-- 
2.2.0.rc0.207.ga3a616c

Re: [PATCH] clk: debugfs: Support frequency stats accounting

[Stephen Boyd]

On 03/20, Badhri Jagan Sridharan wrote:
> Added frequency statistics accounting to common
> clk debug framework. This change tracks the
> frequency of the clocks which don't have the
> CLK_GET_RATE_NOCACHE flag set. This is done by
> monitoring the calls to  clk_set_rate, clk_enable
> and then clk_disable. This patch would help
> debugging power drain issues.
> 
> There is a new node called frequency_stats_table
> created under DEBUG_FS/clk/<clk_debug_name>/ to
> report the collected statistics. In addition,
> the stats also gets printed as a part of the
> clk_summary. Frequency gets reported in HZ and
> the time_spent gets reported in msec units.
> 
> sample output of clk_summary:
> 
>    clock                         enable_cnt  prepare_cnt        rate   accuracy   phase
> ----------------------------------------------------------------------------------------
>  clk24mhz                                 2            3    24000000          0 0
>  *[        default_freq                                   48188]
>  *         400000000					     54
> 
> default_freq accounts the time for which the
> clk was on without an explicit call to the
> clk_set_rate API. The [] braces highlight the
> latest frequency set through clk_set_rate API.
> 
> Frequency accounting can be started(or)stopped
> by writing 1(or)0 to /d/clk/freq_stats_on.
> Writing 1 also causes the counters to reset.
> 
> Enabling CONFIG_FREQ_STATS_ACCOUNTING includes
> the feature.
> 
> Enabling CONFIG_BEGIN_ACCOUNTING_FROM_BOOT
> starts accounting right from boot.
> 
> Signed-off-by: Badhri Jagan Sridharan <Badhri@google.com>
> ---

Some initial questions:

 1. Have you seen the pending tracepoint patches to add
 tracepoints to the framework[1]?

 2. Have you considered using tracepoints and the ability to
 register callbacks on tracepoints and/or register_stat_tracer()
 to implement the functionality in this patch?

 3. If we had tracepoints would it be possible to do
 everything that's done here entirely in userspace with some
 userspace tool that monitors clock trace events?

[1] https://git.kernel.org/cgit/linux/kernel/git/clk/linux.git/commit/?h=clk-next&id=dfc202ead3123988793ac1160849676000b77ee4

>  drivers/clk/Kconfig |  18 ++++
>  drivers/clk/clk.c   | 299 ++++++++++++++++++++++++++++++++++++++++++++++++++--
>  2 files changed, 311 insertions(+), 6 deletions(-)
> 
> diff --git a/drivers/clk/Kconfig b/drivers/clk/Kconfig
> index 0b474a0..0ea6cc2 100644
> --- a/drivers/clk/Kconfig
> +++ b/drivers/clk/Kconfig
> @@ -143,6 +143,24 @@ config COMMON_CLK_CDCE706
>  	---help---
>  	  This driver supports TI CDCE706 programmable 3-PLL clock synthesizer.
>  
> +config COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	bool "Enable clock frequency stats accounting"
> +	depends on COMMON_CLK
> +	depends on DEBUG_FS
> +	---help---
> +	 Allows accounting of the time spent by various clocks in each
> +	 of its operating frequency. The stats get reported as a part
> +	 of clk_summary. Would be be useful in finding out which
> +	 components are running at what power states to debug
> +	 battery consumption issues.

No mention of stats per 'clock_foo' debugfs directory?

> +
> +config COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT
> +	bool "Start clock frequency stats accounting from boot"
> +	depends on COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	---help---
> +	 Enabling this option starts the frequency accounting right from
> +	 the boot.
> +
>  source "drivers/clk/qcom/Kconfig"
>  
>  endmenu
> diff --git a/drivers/clk/clk.c b/drivers/clk/clk.c
> index 237f23f..6d082e9 100644
> --- a/drivers/clk/clk.c
> +++ b/drivers/clk/clk.c
> @@ -11,16 +11,19 @@
>  
>  #include <linux/clk-provider.h>
>  #include <linux/clk/clk-conf.h>
> -#include <linux/module.h>
> -#include <linux/mutex.h>
> -#include <linux/spinlock.h>
> +#include <linux/device.h>
>  #include <linux/err.h>
> +#include <linux/init.h>
> +#include <linux/ktime.h>
>  #include <linux/list.h>
> -#include <linux/slab.h>
> +#include <linux/module.h>
> +#include <linux/mutex.h>
>  #include <linux/of.h>
> -#include <linux/device.h>
> -#include <linux/init.h>
> +#include <linux/rbtree.h>
>  #include <linux/sched.h>
> +#include <linux/spinlock.h>
> +#include <linux/slab.h>
> +#include <linux/timekeeping.h>

Please don't move things around here. Just add what you need. Or
if you do need to move things around please explain why that's
done in the commit text. Alphabetizing can be done later, if at
all.

>  
>  #include "clk.h"
>  
> @@ -45,6 +48,13 @@ static bool clk_core_is_enabled(struct clk_core *clk);
>  static struct clk_core *clk_core_lookup(const char *name);
>  
>  /***    private data structures    ***/
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +struct freq_stats {
> +	ktime_t time_spent;
> +	unsigned long rate;
> +	struct rb_node node;
> +};
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/

Useless and possibly harmful ifdef, please remove.

>  
>  struct clk_core {
>  	const char		*name;
> @@ -73,6 +83,12 @@ struct clk_core {
>  	unsigned int		notifier_count;
>  #ifdef CONFIG_DEBUG_FS
>  	struct dentry		*dentry;
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	struct rb_root freq_stats_table;
> +	struct freq_stats *current_freq_stats;
> +	ktime_t default_freq_time;
> +	ktime_t start_time;
> +#endif /* CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>  #endif
>  	struct kref		ref;
>  };
> @@ -163,6 +179,134 @@ static struct hlist_head *orphan_list[] = {
>  	NULL,
>  };
>  
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +
> +#ifdef CONFIG_COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT
> +static bool freq_stats_on = true;
> +#else
> +static bool freq_stats_on;
> +#endif /*CONFIG_COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT*/

Why do we want a config for this? Why not default false and then
have a module parameter that can be changed from the kernel
commandline?  It certainly makes it easier than having to
recompile the kernel just to set a bool to true.

> +
> +void free_tree(struct rb_node *node)
> +{
> +	struct freq_stats *this;
> +
> +	if (!node)
> +		return;
> +
> +	free_tree(node->rb_left);
> +	free_tree(node->rb_right);
> +
> +	this = rb_entry(node, struct freq_stats, node);
> +	kfree(this);
> +}
> +
> +struct freq_stats *freq_stats_insert(struct rb_root *freq_stats_table,
> +				unsigned long rate)
> +{
> +	struct rb_node **new = &(freq_stats_table->rb_node), *parent = NULL;
> +	struct freq_stats *this;
> +
> +	/* Figure out where to put new node */
> +	while (*new) {
> +		this = rb_entry(*new, struct freq_stats, node);
> +		parent = *new;
> +
> +		if (rate < this->rate)
> +			new = &((*new)->rb_left);
> +		else if (rate > this->rate)
> +			new = &((*new)->rb_right);
> +		else
> +			return this;
> +	}
> +
> +	this = kzalloc(sizeof(*this), GFP_ATOMIC);
> +	this->rate = rate;
> +
> +	/* Add new node and rebalance tree. */
> +	rb_link_node(&this->node, parent, new);
> +	rb_insert_color(&this->node, freq_stats_table);
> +
> +	return this;
> +}
> +
> +static void generic_print_freq_stats_table(struct seq_file *m,
> +				struct clk_core *clk,
> +				bool indent, int level)
> +{
> +	struct rb_node *pos;
> +	struct freq_stats *cur;
> +
> +	if (indent)
> +		seq_printf(m, "%*s*%s%20s", level * 3 + 1, "",
> +			!clk->current_freq_stats ? "[" : "",
> +			"default_freq");
> +	else
> +		seq_printf(m, "%2s%20s", !clk->current_freq_stats ? "[" : "",
> +			"default_freq");
> +
> +	if (!clk->current_freq_stats && !ktime_equal(clk->start_time,
> +					ktime_set(0, 0)))
> +		seq_printf(m, "%40llu",
> +			ktime_to_ms(ktime_add(clk->default_freq_time,
> +			ktime_sub(ktime_get(), clk->start_time))));
> +	else
> +		seq_printf(m, "%40llu", ktime_to_ms(clk->default_freq_time));
> +
> +	if (!clk->current_freq_stats)
> +		seq_puts(m, "]");
> +
> +	seq_puts(m, "\n");
> +
> +	for (pos = rb_first(&clk->freq_stats_table); pos; pos = rb_next(pos)) {
> +		cur = rb_entry(pos, typeof(*cur), node);
> +
> +		if (indent)
> +			seq_printf(m, "%*s*%s%20lu", level * 3 + 1, "",
> +				cur->rate == clk->rate ? "[" : "", cur->rate);
> +		else
> +			seq_printf(m, "%2s%20lu", cur->rate == clk->rate ?
> +				"[" : "", cur->rate);
> +
> +		if (cur->rate == clk->rate && !ktime_equal(clk->start_time,
> +					ktime_set(0, 0)))
> +			seq_printf(m, "%40llu",
> +				ktime_to_ms(ktime_add(cur->time_spent,
> +				ktime_sub(ktime_get(), clk->start_time))));
> +		else
> +			seq_printf(m, "%40llu", ktime_to_ms(cur->time_spent));
> +
> +		if (cur->rate == clk->rate)
> +			seq_puts(m, "]");
> +		seq_puts(m, "\n");
> +	}
> +}
> +
> +
> +static int clock_print_freq_stats_table(struct seq_file *m, void *unused)
> +{
> +	struct clk_core *clk = m->private;
> +
> +	if (!(clk->flags & CLK_GET_RATE_NOCACHE))

Maybe we shouldn't even make the file if there isn't a
possibility of having any contents in the file?

> +		generic_print_freq_stats_table(m, clk, false, 0);
> +
> +	return 0;
> +}
> +
> +static int freq_stats_table_open(struct inode *inode, struct file *file)
> +{
> +	return single_open(file, clock_print_freq_stats_table,
> +			inode->i_private);
> +}
> +
> +static const struct file_operations freq_stats_table_fops = {
> +	.open           = freq_stats_table_open,
> +	.read           = seq_read,
> +	.llseek         = seq_lseek,
> +	.release        = seq_release,
> +};
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
> +
>  static void clk_summary_show_one(struct seq_file *s, struct clk_core *c,
>  				 int level)
>  {
> @@ -174,8 +318,14 @@ static void clk_summary_show_one(struct seq_file *s, struct clk_core *c,
>  		   30 - level * 3, c->name,
>  		   c->enable_count, c->prepare_count, clk_core_get_rate(c),
>  		   clk_core_get_accuracy(c), clk_core_get_phase(c));
> +
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	if (!(c->flags & CLK_GET_RATE_NOCACHE))
> +		generic_print_freq_stats_table(s, c, true, level);
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>  }
>  
> +

Noise?

>  static void clk_summary_show_subtree(struct seq_file *s, struct clk_core *c,
>  				     int level)
>  {
> @@ -290,6 +440,78 @@ static const struct file_operations clk_dump_fops = {
>  	.release	= single_release,
>  };
>  
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +static int freq_stats_get(void *unused, u64 *val)
> +{
> +	*val = freq_stats_on;
> +	return 0;
> +}
> +
> +static void clk_traverse_subtree(struct clk_core *clk, int freq_stats_on)
> +{
> +	struct clk_core *child;
> +	struct rb_node *node;
> +
> +	if (!clk)
> +		return;
> +
> +	if (freq_stats_on) {
> +		for (node = rb_first(&clk->freq_stats_table);
> +			node; node = rb_next(node))
> +			rb_entry(node, struct freq_stats, node)->time_spent =
> +							ktime_set(0, 0);
> +
> +		clk->current_freq_stats = freq_stats_insert(
> +						&clk->freq_stats_table,
> +						clk_core_get_rate(clk));
> +
> +		if (clk->enable_count > 0)
> +			clk->start_time = ktime_get();
> +	} else {
> +		if (clk->enable_count > 0) {
> +			if (!clk->current_freq_stats)
> +				clk->default_freq_time =
> +				ktime_add(clk->default_freq_time,
> +				ktime_sub(ktime_get(), clk->start_time));
> +			else
> +				clk->current_freq_stats->time_spent =
> +				ktime_add(clk->current_freq_stats->time_spent,
> +				ktime_sub(ktime_get(), clk->start_time));
> +
> +			clk->start_time = ktime_set(0, 0);
> +		}
> +	}
> +	hlist_for_each_entry(child, &clk->children, child_node)
> +		clk_traverse_subtree(child, freq_stats_on);
> +}
> +
> +static int freq_stats_set(void *data, u64 val)
> +{
> +	struct clk_core *c;
> +	unsigned long flags;
> +	struct hlist_head **lists = (struct hlist_head **)data;
> +
> +	clk_prepare_lock();
> +	flags = clk_enable_lock();
> +
> +	if (val == 0)
> +		freq_stats_on = 0;
> +	else
> +		freq_stats_on = 1;
> +
> +	for (; *lists; lists++)
> +		hlist_for_each_entry(c, *lists, child_node)
> +			clk_traverse_subtree(c, freq_stats_on);
> +
> +	clk_enable_unlock(flags);
> +	clk_prepare_unlock();
> +
> +	return 0;
> +}
> +DEFINE_SIMPLE_ATTRIBUTE(freq_stats_fops, freq_stats_get,
> +			freq_stats_set, "%llu\n");
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
> +
>  static int clk_debug_create_one(struct clk_core *clk, struct dentry *pdentry)
>  {
>  	struct dentry *d;
> @@ -341,6 +563,14 @@ static int clk_debug_create_one(struct clk_core *clk, struct dentry *pdentry)
>  	if (!d)
>  		goto err_out;
>  
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	d = debugfs_create_file("frequency_stats_table", S_IRUGO, clk->dentry,
> +			clk, &freq_stats_table_fops);
> +
> +	if (!d)
> +		goto err_out;
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
> +
>  	if (clk->ops->debug_init) {
>  		ret = clk->ops->debug_init(clk->hw, clk->dentry);
>  		if (ret)
> @@ -454,6 +684,13 @@ static int __init clk_debug_init(void)
>  	if (!d)
>  		return -ENOMEM;
>  
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	d = debugfs_create_file("freq_stats_on", S_IRUGO|S_IWUSR,

							^
						Space around '|' here please

> +				rootdir, &all_lists, &freq_stats_fops);
> +	if (!d)
> +		return -ENOMEM;
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
> +
>  	mutex_lock(&clk_debug_lock);
>  	hlist_for_each_entry(clk, &clk_debug_list, debug_node)
>  		clk_debug_create_one(clk, rootdir);
> @@ -998,6 +1235,22 @@ static void clk_core_disable(struct clk_core *clk)
>  	if (clk->ops->disable)
>  		clk->ops->disable(clk->hw);
>  
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING

Please remove these ifdefs and make static inline functions or
use IS_ENABLED stuff so that we get better build coverage of this
code.

> +
> +	if (freq_stats_on) {
> +		if (!clk->current_freq_stats)
> +			clk->default_freq_time =
> +			ktime_add(clk->default_freq_time,
> +			ktime_sub(ktime_get(), clk->start_time));
> +		else
> +			clk->current_freq_stats->time_spent =
> +			ktime_add(clk->current_freq_stats->time_spent,
> +			ktime_sub(ktime_get(), clk->start_time));
> +
> +		clk->start_time = ktime_set(0, 0);
> +	}
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
> +
>  	clk_core_disable(clk->parent);
>  }
>  
> @@ -1057,6 +1310,11 @@ static int clk_core_enable(struct clk_core *clk)
>  				return ret;
>  			}
>  		}
> +
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	if (freq_stats_on)
> +		clk->start_time = ktime_get();
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>  	}
>  
>  	clk->enable_count++;
> @@ -1724,6 +1982,31 @@ static void clk_change_rate(struct clk_core *clk)
>  
>  	clk->rate = clk_recalc(clk, best_parent_rate);
>  
> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
> +	if (freq_stats_on) {
> +		if (!ktime_equal(clk->start_time, ktime_set(0, 0))) {
> +			if (!clk->current_freq_stats)
> +				clk->default_freq_time =
> +					ktime_add(clk->default_freq_time,
> +					ktime_sub(ktime_get(),
> +					clk->start_time));
> +			else
> +				clk->current_freq_stats->time_spent =
> +					ktime_add(
> +					clk->current_freq_stats->time_spent,
> +					ktime_sub(ktime_get(),
> +					clk->start_time));
> +		}
> +
> +		clk->current_freq_stats = freq_stats_insert(
> +						&clk->freq_stats_table,
> +						clk->rate);
> +
> +		if (clk->enable_count > 0)
> +			clk->start_time = ktime_get();
> +	}
> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/

In situations like this it's better to make a new function like
clk_core_rate_stat() that hides all these details from readers
who want to understand the flow and not get bogged down in a big
chunk of debug code.

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH] clk: debugfs: Support frequency stats accounting

[Badhri Jagan Sridharan]

 >
 > Some initial questions:
 >
 >   1. Have you seen the pending tracepoint patches to add
 >   tracepoints to the framework[1]?
 >
 >   2. Have you considered using tracepoints and the ability to
 >   register callbacks on tracepoints and/or register_stat_tracer()
 >   to implement the functionality in this patch?
 >
 >   3. If we had tracepoints would it be possible to do
 >   everything that's done here entirely in userspace with some
 >   userspace tool that monitors clock trace events?

Thanks Stephen... Following is one major factor that blocks
me from using trace points... Trace points are unaware of the history of
events that already happened before the start of monitoring of events.
Consider that I start monitoring for clock_events at time instant X, we 
might not get to know the state of the clocks that were enabled and left 
running  before the time instant X.

clk_summary table already has a very intuitive/impressive layout of 
conveying the the states and relationship between different clocks in 
the system. That's why I thought adding the frequency_stats info here 
might make it more comprehensive.
Are there any potential risks of doing so ?

I will wait for your thoughts to address other comments
that you had in my patch.

On 03/21/2015 12:26 AM, Stephen Boyd wrote:
> On 03/20, Badhri Jagan Sridharan wrote:
>> Added frequency statistics accounting to common
>> clk debug framework. This change tracks the
>> frequency of the clocks which don't have the
>> CLK_GET_RATE_NOCACHE flag set. This is done by
>> monitoring the calls to  clk_set_rate, clk_enable
>> and then clk_disable. This patch would help
>> debugging power drain issues.
>>
>> There is a new node called frequency_stats_table
>> created under DEBUG_FS/clk/<clk_debug_name>/ to
>> report the collected statistics. In addition,
>> the stats also gets printed as a part of the
>> clk_summary. Frequency gets reported in HZ and
>> the time_spent gets reported in msec units.
>>
>> sample output of clk_summary:
>>
>>     clock                         enable_cnt  prepare_cnt        rate   accuracy   phase
>> ----------------------------------------------------------------------------------------
>>   clk24mhz                                 2            3    24000000          0 0
>>   *[        default_freq                                   48188]
>>   *         400000000					     54
>>
>> default_freq accounts the time for which the
>> clk was on without an explicit call to the
>> clk_set_rate API. The [] braces highlight the
>> latest frequency set through clk_set_rate API.
>>
>> Frequency accounting can be started(or)stopped
>> by writing 1(or)0 to /d/clk/freq_stats_on.
>> Writing 1 also causes the counters to reset.
>>
>> Enabling CONFIG_FREQ_STATS_ACCOUNTING includes
>> the feature.
>>
>> Enabling CONFIG_BEGIN_ACCOUNTING_FROM_BOOT
>> starts accounting right from boot.
>>
>> Signed-off-by: Badhri Jagan Sridharan <Badhri@google.com>
>> ---
>
> Some initial questions:
>
>   1. Have you seen the pending tracepoint patches to add
>   tracepoints to the framework[1]?
>
>   2. Have you considered using tracepoints and the ability to
>   register callbacks on tracepoints and/or register_stat_tracer()
>   to implement the functionality in this patch?
>
>   3. If we had tracepoints would it be possible to do
>   everything that's done here entirely in userspace with some
>   userspace tool that monitors clock trace events?
>
> [1] https://git.kernel.org/cgit/linux/kernel/git/clk/linux.git/commit/?h=clk-next&id=dfc202ead3123988793ac1160849676000b77ee4
>
>>   drivers/clk/Kconfig |  18 ++++
>>   drivers/clk/clk.c   | 299 ++++++++++++++++++++++++++++++++++++++++++++++++++--
>>   2 files changed, 311 insertions(+), 6 deletions(-)
>>
>> diff --git a/drivers/clk/Kconfig b/drivers/clk/Kconfig
>> index 0b474a0..0ea6cc2 100644
>> --- a/drivers/clk/Kconfig
>> +++ b/drivers/clk/Kconfig
>> @@ -143,6 +143,24 @@ config COMMON_CLK_CDCE706
>>   	---help---
>>   	  This driver supports TI CDCE706 programmable 3-PLL clock synthesizer.
>>
>> +config COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	bool "Enable clock frequency stats accounting"
>> +	depends on COMMON_CLK
>> +	depends on DEBUG_FS
>> +	---help---
>> +	 Allows accounting of the time spent by various clocks in each
>> +	 of its operating frequency. The stats get reported as a part
>> +	 of clk_summary. Would be be useful in finding out which
>> +	 components are running at what power states to debug
>> +	 battery consumption issues.
>
> No mention of stats per 'clock_foo' debugfs directory?
>
>> +
>> +config COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT
>> +	bool "Start clock frequency stats accounting from boot"
>> +	depends on COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	---help---
>> +	 Enabling this option starts the frequency accounting right from
>> +	 the boot.
>> +
>>   source "drivers/clk/qcom/Kconfig"
>>
>>   endmenu
>> diff --git a/drivers/clk/clk.c b/drivers/clk/clk.c
>> index 237f23f..6d082e9 100644
>> --- a/drivers/clk/clk.c
>> +++ b/drivers/clk/clk.c
>> @@ -11,16 +11,19 @@
>>
>>   #include <linux/clk-provider.h>
>>   #include <linux/clk/clk-conf.h>
>> -#include <linux/module.h>
>> -#include <linux/mutex.h>
>> -#include <linux/spinlock.h>
>> +#include <linux/device.h>
>>   #include <linux/err.h>
>> +#include <linux/init.h>
>> +#include <linux/ktime.h>
>>   #include <linux/list.h>
>> -#include <linux/slab.h>
>> +#include <linux/module.h>
>> +#include <linux/mutex.h>
>>   #include <linux/of.h>
>> -#include <linux/device.h>
>> -#include <linux/init.h>
>> +#include <linux/rbtree.h>
>>   #include <linux/sched.h>
>> +#include <linux/spinlock.h>
>> +#include <linux/slab.h>
>> +#include <linux/timekeeping.h>
>
> Please don't move things around here. Just add what you need. Or
> if you do need to move things around please explain why that's
> done in the commit text. Alphabetizing can be done later, if at
> all.
>
>>
>>   #include "clk.h"
>>
>> @@ -45,6 +48,13 @@ static bool clk_core_is_enabled(struct clk_core *clk);
>>   static struct clk_core *clk_core_lookup(const char *name);
>>
>>   /***    private data structures    ***/
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +struct freq_stats {
>> +	ktime_t time_spent;
>> +	unsigned long rate;
>> +	struct rb_node node;
>> +};
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>
> Useless and possibly harmful ifdef, please remove.
>
>>
>>   struct clk_core {
>>   	const char		*name;
>> @@ -73,6 +83,12 @@ struct clk_core {
>>   	unsigned int		notifier_count;
>>   #ifdef CONFIG_DEBUG_FS
>>   	struct dentry		*dentry;
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	struct rb_root freq_stats_table;
>> +	struct freq_stats *current_freq_stats;
>> +	ktime_t default_freq_time;
>> +	ktime_t start_time;
>> +#endif /* CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>>   #endif
>>   	struct kref		ref;
>>   };
>> @@ -163,6 +179,134 @@ static struct hlist_head *orphan_list[] = {
>>   	NULL,
>>   };
>>
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +
>> +#ifdef CONFIG_COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT
>> +static bool freq_stats_on = true;
>> +#else
>> +static bool freq_stats_on;
>> +#endif /*CONFIG_COMMON_CLK_BEGIN_ACCOUNTING_FROM_BOOT*/
>
> Why do we want a config for this? Why not default false and then
> have a module parameter that can be changed from the kernel
> commandline?  It certainly makes it easier than having to
> recompile the kernel just to set a bool to true.
>
>> +
>> +void free_tree(struct rb_node *node)
>> +{
>> +	struct freq_stats *this;
>> +
>> +	if (!node)
>> +		return;
>> +
>> +	free_tree(node->rb_left);
>> +	free_tree(node->rb_right);
>> +
>> +	this = rb_entry(node, struct freq_stats, node);
>> +	kfree(this);
>> +}
>> +
>> +struct freq_stats *freq_stats_insert(struct rb_root *freq_stats_table,
>> +				unsigned long rate)
>> +{
>> +	struct rb_node **new = &(freq_stats_table->rb_node), *parent = NULL;
>> +	struct freq_stats *this;
>> +
>> +	/* Figure out where to put new node */
>> +	while (*new) {
>> +		this = rb_entry(*new, struct freq_stats, node);
>> +		parent = *new;
>> +
>> +		if (rate < this->rate)
>> +			new = &((*new)->rb_left);
>> +		else if (rate > this->rate)
>> +			new = &((*new)->rb_right);
>> +		else
>> +			return this;
>> +	}
>> +
>> +	this = kzalloc(sizeof(*this), GFP_ATOMIC);
>> +	this->rate = rate;
>> +
>> +	/* Add new node and rebalance tree. */
>> +	rb_link_node(&this->node, parent, new);
>> +	rb_insert_color(&this->node, freq_stats_table);
>> +
>> +	return this;
>> +}
>> +
>> +static void generic_print_freq_stats_table(struct seq_file *m,
>> +				struct clk_core *clk,
>> +				bool indent, int level)
>> +{
>> +	struct rb_node *pos;
>> +	struct freq_stats *cur;
>> +
>> +	if (indent)
>> +		seq_printf(m, "%*s*%s%20s", level * 3 + 1, "",
>> +			!clk->current_freq_stats ? "[" : "",
>> +			"default_freq");
>> +	else
>> +		seq_printf(m, "%2s%20s", !clk->current_freq_stats ? "[" : "",
>> +			"default_freq");
>> +
>> +	if (!clk->current_freq_stats && !ktime_equal(clk->start_time,
>> +					ktime_set(0, 0)))
>> +		seq_printf(m, "%40llu",
>> +			ktime_to_ms(ktime_add(clk->default_freq_time,
>> +			ktime_sub(ktime_get(), clk->start_time))));
>> +	else
>> +		seq_printf(m, "%40llu", ktime_to_ms(clk->default_freq_time));
>> +
>> +	if (!clk->current_freq_stats)
>> +		seq_puts(m, "]");
>> +
>> +	seq_puts(m, "\n");
>> +
>> +	for (pos = rb_first(&clk->freq_stats_table); pos; pos = rb_next(pos)) {
>> +		cur = rb_entry(pos, typeof(*cur), node);
>> +
>> +		if (indent)
>> +			seq_printf(m, "%*s*%s%20lu", level * 3 + 1, "",
>> +				cur->rate == clk->rate ? "[" : "", cur->rate);
>> +		else
>> +			seq_printf(m, "%2s%20lu", cur->rate == clk->rate ?
>> +				"[" : "", cur->rate);
>> +
>> +		if (cur->rate == clk->rate && !ktime_equal(clk->start_time,
>> +					ktime_set(0, 0)))
>> +			seq_printf(m, "%40llu",
>> +				ktime_to_ms(ktime_add(cur->time_spent,
>> +				ktime_sub(ktime_get(), clk->start_time))));
>> +		else
>> +			seq_printf(m, "%40llu", ktime_to_ms(cur->time_spent));
>> +
>> +		if (cur->rate == clk->rate)
>> +			seq_puts(m, "]");
>> +		seq_puts(m, "\n");
>> +	}
>> +}
>> +
>> +
>> +static int clock_print_freq_stats_table(struct seq_file *m, void *unused)
>> +{
>> +	struct clk_core *clk = m->private;
>> +
>> +	if (!(clk->flags & CLK_GET_RATE_NOCACHE))
>
> Maybe we shouldn't even make the file if there isn't a
> possibility of having any contents in the file?
>
>> +		generic_print_freq_stats_table(m, clk, false, 0);
>> +
>> +	return 0;
>> +}
>> +
>> +static int freq_stats_table_open(struct inode *inode, struct file *file)
>> +{
>> +	return single_open(file, clock_print_freq_stats_table,
>> +			inode->i_private);
>> +}
>> +
>> +static const struct file_operations freq_stats_table_fops = {
>> +	.open           = freq_stats_table_open,
>> +	.read           = seq_read,
>> +	.llseek         = seq_lseek,
>> +	.release        = seq_release,
>> +};
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>> +
>>   static void clk_summary_show_one(struct seq_file *s, struct clk_core *c,
>>   				 int level)
>>   {
>> @@ -174,8 +318,14 @@ static void clk_summary_show_one(struct seq_file *s, struct clk_core *c,
>>   		   30 - level * 3, c->name,
>>   		   c->enable_count, c->prepare_count, clk_core_get_rate(c),
>>   		   clk_core_get_accuracy(c), clk_core_get_phase(c));
>> +
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	if (!(c->flags & CLK_GET_RATE_NOCACHE))
>> +		generic_print_freq_stats_table(s, c, true, level);
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>>   }
>>
>> +
>
> Noise?
>
>>   static void clk_summary_show_subtree(struct seq_file *s, struct clk_core *c,
>>   				     int level)
>>   {
>> @@ -290,6 +440,78 @@ static const struct file_operations clk_dump_fops = {
>>   	.release	= single_release,
>>   };
>>
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +static int freq_stats_get(void *unused, u64 *val)
>> +{
>> +	*val = freq_stats_on;
>> +	return 0;
>> +}
>> +
>> +static void clk_traverse_subtree(struct clk_core *clk, int freq_stats_on)
>> +{
>> +	struct clk_core *child;
>> +	struct rb_node *node;
>> +
>> +	if (!clk)
>> +		return;
>> +
>> +	if (freq_stats_on) {
>> +		for (node = rb_first(&clk->freq_stats_table);
>> +			node; node = rb_next(node))
>> +			rb_entry(node, struct freq_stats, node)->time_spent =
>> +							ktime_set(0, 0);
>> +
>> +		clk->current_freq_stats = freq_stats_insert(
>> +						&clk->freq_stats_table,
>> +						clk_core_get_rate(clk));
>> +
>> +		if (clk->enable_count > 0)
>> +			clk->start_time = ktime_get();
>> +	} else {
>> +		if (clk->enable_count > 0) {
>> +			if (!clk->current_freq_stats)
>> +				clk->default_freq_time =
>> +				ktime_add(clk->default_freq_time,
>> +				ktime_sub(ktime_get(), clk->start_time));
>> +			else
>> +				clk->current_freq_stats->time_spent =
>> +				ktime_add(clk->current_freq_stats->time_spent,
>> +				ktime_sub(ktime_get(), clk->start_time));
>> +
>> +			clk->start_time = ktime_set(0, 0);
>> +		}
>> +	}
>> +	hlist_for_each_entry(child, &clk->children, child_node)
>> +		clk_traverse_subtree(child, freq_stats_on);
>> +}
>> +
>> +static int freq_stats_set(void *data, u64 val)
>> +{
>> +	struct clk_core *c;
>> +	unsigned long flags;
>> +	struct hlist_head **lists = (struct hlist_head **)data;
>> +
>> +	clk_prepare_lock();
>> +	flags = clk_enable_lock();
>> +
>> +	if (val == 0)
>> +		freq_stats_on = 0;
>> +	else
>> +		freq_stats_on = 1;
>> +
>> +	for (; *lists; lists++)
>> +		hlist_for_each_entry(c, *lists, child_node)
>> +			clk_traverse_subtree(c, freq_stats_on);
>> +
>> +	clk_enable_unlock(flags);
>> +	clk_prepare_unlock();
>> +
>> +	return 0;
>> +}
>> +DEFINE_SIMPLE_ATTRIBUTE(freq_stats_fops, freq_stats_get,
>> +			freq_stats_set, "%llu\n");
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>> +
>>   static int clk_debug_create_one(struct clk_core *clk, struct dentry *pdentry)
>>   {
>>   	struct dentry *d;
>> @@ -341,6 +563,14 @@ static int clk_debug_create_one(struct clk_core *clk, struct dentry *pdentry)
>>   	if (!d)
>>   		goto err_out;
>>
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	d = debugfs_create_file("frequency_stats_table", S_IRUGO, clk->dentry,
>> +			clk, &freq_stats_table_fops);
>> +
>> +	if (!d)
>> +		goto err_out;
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>> +
>>   	if (clk->ops->debug_init) {
>>   		ret = clk->ops->debug_init(clk->hw, clk->dentry);
>>   		if (ret)
>> @@ -454,6 +684,13 @@ static int __init clk_debug_init(void)
>>   	if (!d)
>>   		return -ENOMEM;
>>
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	d = debugfs_create_file("freq_stats_on", S_IRUGO|S_IWUSR,
>
> 							^
> 						Space around '|' here please
>
>> +				rootdir, &all_lists, &freq_stats_fops);
>> +	if (!d)
>> +		return -ENOMEM;
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>> +
>>   	mutex_lock(&clk_debug_lock);
>>   	hlist_for_each_entry(clk, &clk_debug_list, debug_node)
>>   		clk_debug_create_one(clk, rootdir);
>> @@ -998,6 +1235,22 @@ static void clk_core_disable(struct clk_core *clk)
>>   	if (clk->ops->disable)
>>   		clk->ops->disable(clk->hw);
>>
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>
> Please remove these ifdefs and make static inline functions or
> use IS_ENABLED stuff so that we get better build coverage of this
> code.
>
>> +
>> +	if (freq_stats_on) {
>> +		if (!clk->current_freq_stats)
>> +			clk->default_freq_time =
>> +			ktime_add(clk->default_freq_time,
>> +			ktime_sub(ktime_get(), clk->start_time));
>> +		else
>> +			clk->current_freq_stats->time_spent =
>> +			ktime_add(clk->current_freq_stats->time_spent,
>> +			ktime_sub(ktime_get(), clk->start_time));
>> +
>> +		clk->start_time = ktime_set(0, 0);
>> +	}
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>> +
>>   	clk_core_disable(clk->parent);
>>   }
>>
>> @@ -1057,6 +1310,11 @@ static int clk_core_enable(struct clk_core *clk)
>>   				return ret;
>>   			}
>>   		}
>> +
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	if (freq_stats_on)
>> +		clk->start_time = ktime_get();
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>>   	}
>>
>>   	clk->enable_count++;
>> @@ -1724,6 +1982,31 @@ static void clk_change_rate(struct clk_core *clk)
>>
>>   	clk->rate = clk_recalc(clk, best_parent_rate);
>>
>> +#ifdef CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING
>> +	if (freq_stats_on) {
>> +		if (!ktime_equal(clk->start_time, ktime_set(0, 0))) {
>> +			if (!clk->current_freq_stats)
>> +				clk->default_freq_time =
>> +					ktime_add(clk->default_freq_time,
>> +					ktime_sub(ktime_get(),
>> +					clk->start_time));
>> +			else
>> +				clk->current_freq_stats->time_spent =
>> +					ktime_add(
>> +					clk->current_freq_stats->time_spent,
>> +					ktime_sub(ktime_get(),
>> +					clk->start_time));
>> +		}
>> +
>> +		clk->current_freq_stats = freq_stats_insert(
>> +						&clk->freq_stats_table,
>> +						clk->rate);
>> +
>> +		if (clk->enable_count > 0)
>> +			clk->start_time = ktime_get();
>> +	}
>> +#endif /*CONFIG_COMMON_CLK_FREQ_STATS_ACCOUNTING*/
>
> In situations like this it's better to make a new function like
> clk_core_rate_stat() that hides all these details from readers
> who want to understand the flow and not get bogged down in a big
> chunk of debug code.
>

Re: [PATCH] clk: debugfs: Support frequency stats accounting

[Stephen Boyd]

On 03/23, Badhri Jagan Sridharan wrote:
> >Some initial  questions:
> >
> > 1. Have you seen the pending tracepoint patches to add
> > tracepoints to the framework[1]?
> >
> > 2. Have you considered using tracepoints and the ability to
> > register callbacks on tracepoints and/or register_stat_tracer()
> > to implement the functionality in this patch?
> >
> > 3. If we had tracepoints would it be possible to do
> > everything that's done here entirely in userspace with some
> > userspace tool that monitors clock trace events?
> 
> Thanks Stephen... Following is one major factor that blocks
> me from using trace points... Trace points are unaware of the history of
> events that already happened before the start of monitoring of events.
> Consider that I start monitoring for clock_events at time instant X,
> we might
> not get to know the state of the clocks that were enabled and left running
> before the time instant X.

It seems easy enough to enable the tracepoints that matter from
the kernel command line so that we have all the history. If we
have a stat tracer we could do something similar by enabling the
tracer on boot and not require any userspace post processing on
the trace output.

> 
> clk_summary table already has a very intuitive/impressive layout of
> conveying the
> the states and relationship between different clocks in the system.
> That's why
> I thought adding the frequency_stats info here might make it more
> comprehensive.
> Are there any potential risks of doing so ?
> 

The only risk I see is bloating the kernel and putting debug
hooks in places where we already have tracepoints. Less code is
easier to maintain.

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project