Re: [PATCH] clk: debugfs: Support frequency stats accounting
From: Stephen Boyd
Date: Sat Mar 21 2015 - 03:26:18 EST
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.
--
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project
--
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/