Re: [PATCH] clk: debugfs: Support frequency stats accounting
From: Badhri Jagan Sridharan
Date: Mon Mar 23 2015 - 17:33:25 EST
>
> 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@xxxxxxxxxx>
---
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.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/