Re: [PATCH v4 17/24] PM / devfreq: tegra30: Use tracepoints for debugging

[Chanwoo Choi <cw00.choi@samsung.com>]

On 19. 7. 19. 오전 9:49, Dmitry Osipenko wrote:
> В Thu, 18 Jul 2019 18:47:09 +0900
> Chanwoo Choi <cw00.choi@samsung.com> пишет:
> 
>> On 19. 7. 8. 오전 7:32, Dmitry Osipenko wrote:
>>> Debug messages create too much CPU and memory activity by
>>> themselves, so it's difficult to debug lower rates and catch
>>> unwanted interrupts that happen rarely. Tracepoints are ideal in
>>> that regards because they do not contribute to the sampled date at
>>> all. This allowed me to catch few problems which are fixed by the
>>> followup patches, without tracepoints it would be much harder to do.
>>>
>>> Signed-off-by: Dmitry Osipenko <digetx@gmail.com>
>>> ---
>>>  drivers/devfreq/tegra30-devfreq.c      |  43 +++-------
>>>  include/trace/events/tegra30_devfreq.h | 105
>>> +++++++++++++++++++++++++ 2 files changed, 117 insertions(+), 31
>>> deletions(-) create mode 100644
>>> include/trace/events/tegra30_devfreq.h  
>>
>> As I knew, 'include/trace/events' don't include the header file
>> for only one device driver. Usually, the trace event is provided
>> by framework instead of each devic driver.
> 
> There are at least trace headers there for the tegra-apbdma,
> tegra-host1x, intel-sst and intel-ish devices. I don't think that there
> is a strict rule for the trace headers placement.

OK.

But, As I already replied on patch4, if you want to show the register dump,
you better to add the debugfs feature to devfreq framework for showing
the register dump instead of printing the register dump with debug level
and this trace event. 

As I said, just register dump is not useful for all developers.
Almost developer cannot understand the meaning of debug log for register dump.

Also, it is not proper way that front patch adds the some code
and then later patch removes the additional code in the same series.
Before sending the patches, you can renew them.

> 
>>>
>>> diff --git a/drivers/devfreq/tegra30-devfreq.c
>>> b/drivers/devfreq/tegra30-devfreq.c index
>>> 6ebf0f505767..43c9c5fbfe91 100644 ---
>>> a/drivers/devfreq/tegra30-devfreq.c +++
>>> b/drivers/devfreq/tegra30-devfreq.c @@ -19,6 +19,9 @@
>>>  #include <linux/reset.h>
>>>  #include <linux/workqueue.h>
>>>  
>>> +#define CREATE_TRACE_POINTS
>>> +#include <trace/events/tegra30_devfreq.h>
>>> +
>>>  #include "governor.h"
>>>  
>>>  #define ACTMON_GLB_STATUS
>>> 0x0 @@ -283,9 +286,6 @@ static void
>>> tegra_actmon_get_lower_upper(struct tegra_devfreq *tegra, unsigned
>>> long *lower, unsigned long *upper)
>>>  {
>>> -	struct device *ddev = tegra->devfreq->dev.parent;
>>> -	u32 offset = dev->config->offset;
>>> -
>>>  	/*
>>>  	 * Memory frequencies are guaranteed to have 1MHz
>>> granularity
>>>  	 * and thus we need this rounding down to get a proper
>>> watermarks @@ -298,8 +298,8 @@ static void
>>> tegra_actmon_get_lower_upper(struct tegra_devfreq *tegra, *lower =
>>> tegra_actmon_lower_freq(tegra, target_freq); *upper =
>>> tegra_actmon_upper_freq(tegra, target_freq); 
>>> -	dev_dbg(ddev, "%03x: target_freq %lu lower freq %lu upper
>>> freq %lu\n",
>>> -		offset, target_freq, *lower, *upper);
>>> +	trace_device_lower_upper(dev->config->offset, target_freq,
>>> +				 *lower, *upper);
>>>  
>>>  	/*
>>>  	 * The upper watermark should take into account CPU's
>>> frequency @@ -377,30 +377,13 @@ static void
>>> tegra_devfreq_update_wmark(struct tegra_devfreq *tegra,
>>> device_writel(dev, lower + delta, ACTMON_DEV_LOWER_WMARK); }
>>>  
>>> -static void actmon_device_debug(struct tegra_devfreq *tegra,
>>> -				struct tegra_devfreq_device *dev,
>>> -				const char *prefix)
>>> -{
>>> -	dev_dbg(tegra->devfreq->dev.parent,
>>> -		"%03x: %s: 0x%08x 0x%08x a %u %u %u c %u %u %u b
>>> %lu cpu %u\n",
>>> -		dev->config->offset, prefix,
>>> -		device_readl(dev, ACTMON_DEV_INTR_STATUS),
>>> -		device_readl(dev, ACTMON_DEV_CTRL),
>>> -		device_readl(dev, ACTMON_DEV_AVG_COUNT),
>>> -		device_readl(dev, ACTMON_DEV_AVG_LOWER_WMARK),
>>> -		device_readl(dev, ACTMON_DEV_AVG_UPPER_WMARK),
>>> -		device_readl(dev, ACTMON_DEV_COUNT),
>>> -		device_readl(dev, ACTMON_DEV_LOWER_WMARK),
>>> -		device_readl(dev, ACTMON_DEV_UPPER_WMARK),
>>> -		dev->boost_freq, cpufreq_get(0));
>>> -}
>>> -
>>>  static void actmon_isr_device(struct tegra_devfreq *tegra,
>>>  			      struct tegra_devfreq_device *dev)
>>>  {
>>>  	u32 intr_status, dev_ctrl, avg_intr_mask, avg_count;
>>>  
>>> -	actmon_device_debug(tegra, dev, "isr+");
>>> +	trace_device_isr_enter(tegra->regs, dev->config->offset,
>>> +			       dev->boost_freq, cpufreq_get(0));
>>>  
>>>  	intr_status = device_readl(dev, ACTMON_DEV_INTR_STATUS);
>>>  	avg_count = device_readl(dev, ACTMON_DEV_AVG_COUNT);
>>> @@ -455,7 +438,8 @@ static void actmon_isr_device(struct
>>> tegra_devfreq *tegra, device_writel(dev, dev_ctrl, ACTMON_DEV_CTRL);
>>>  	device_writel(dev, ACTMON_INTR_STATUS_CLEAR,
>>> ACTMON_DEV_INTR_STATUS); 
>>> -	actmon_device_debug(tegra, dev, "isr-");
>>> +	trace_device_isr_exit(tegra->regs, dev->config->offset,
>>> +			      dev->boost_freq, cpufreq_get(0));
>>>  }
>>>  
>>>  static unsigned long actmon_update_target(struct tegra_devfreq
>>> *tegra, @@ -749,7 +733,6 @@ static struct devfreq_dev_profile
>>> tegra_devfreq_profile = { static int
>>> tegra_governor_get_target(struct devfreq *devfreq, unsigned long
>>> *freq) {
>>> -	struct device *ddev = devfreq->dev.parent;
>>>  	struct devfreq_dev_status *stat;
>>>  	struct tegra_devfreq *tegra;
>>>  	struct tegra_devfreq_device *dev;
>>> @@ -770,13 +753,11 @@ static int tegra_governor_get_target(struct
>>> devfreq *devfreq, dev = &tegra->devices[i];
>>>  
>>>  		dev_target_freq = actmon_update_target(tegra, dev);
>>> -
>>>  		target_freq = max(target_freq, dev_target_freq);
>>>  
>>> -		dev_dbg(ddev, "%03x: upd: dev_target_freq %lu\n",
>>> -			dev->config->offset, dev_target_freq);
>>> -
>>> -		actmon_device_debug(tegra, dev, "upd");
>>> +		trace_device_target_freq(dev->config->offset,
>>> dev_target_freq);
>>> +		trace_device_target_update(tegra->regs,
>>> dev->config->offset,
>>> +					   dev->boost_freq,
>>> cpufreq_get(0)); }
>>>  
>>>  	*freq = target_freq;
>>> diff --git a/include/trace/events/tegra30_devfreq.h
>>> b/include/trace/events/tegra30_devfreq.h new file mode 100644
>>> index 000000000000..8f264a489daf
>>> --- /dev/null
>>> +++ b/include/trace/events/tegra30_devfreq.h
>>> @@ -0,0 +1,105 @@
>>> +/* SPDX-License-Identifier: GPL-2.0 */
>>> +#undef TRACE_SYSTEM
>>> +#define TRACE_SYSTEM tegra30_devfreq
>>> +
>>> +#if !defined(_TRACE_TEGRA30_DEVFREQ_H) ||
>>> defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_TEGRA30_DEVFREQ_H
>>> +
>>> +#include <linux/io.h>
>>> +#include <linux/tracepoint.h>
>>> +#include <linux/types.h>
>>> +
>>> +DECLARE_EVENT_CLASS(device_state,
>>> +	TP_PROTO(void __iomem *base, u32 offset, u32 boost, u32
>>> cpufreq),
>>> +	TP_ARGS(base, offset, boost, cpufreq),
>>> +	TP_STRUCT__entry(
>>> +		__field(u32, offset)
>>> +		__field(u32, intr_status)
>>> +		__field(u32, ctrl)
>>> +		__field(u32, avg_count)
>>> +		__field(u32, avg_lower)
>>> +		__field(u32, avg_upper)
>>> +		__field(u32, count)
>>> +		__field(u32, lower)
>>> +		__field(u32, upper)
>>> +		__field(u32, boost_freq)
>>> +		__field(u32, cpu_freq)
>>> +	),
>>> +	TP_fast_assign(
>>> +		__entry->offset		= offset;
>>> +		__entry->intr_status	= readl_relaxed(base +
>>> offset + 0x24);
>>> +		__entry->ctrl		= readl_relaxed(base
>>> + offset + 0x0);
>>> +		__entry->avg_count	= readl_relaxed(base +
>>> offset + 0x20);
>>> +		__entry->avg_lower	= readl_relaxed(base +
>>> offset + 0x14);
>>> +		__entry->avg_upper	= readl_relaxed(base +
>>> offset + 0x10);
>>> +		__entry->count		= readl_relaxed(base
>>> + offset + 0x1c);
>>> +		__entry->lower		= readl_relaxed(base
>>> + offset + 0x8);
>>> +		__entry->upper		= readl_relaxed(base
>>> + offset + 0x4);
>>> +		__entry->boost_freq	= boost;
>>> +		__entry->cpu_freq	= cpufreq;
>>> +	),
>>> +	TP_printk("%03x: intr 0x%08x ctrl 0x%08x avg %010u %010u
>>> %010u cnt %010u %010u %010u boost %010u cpu %u",
>>> +		__entry->offset,
>>> +		__entry->intr_status,
>>> +		__entry->ctrl,
>>> +		__entry->avg_count,
>>> +		__entry->avg_lower,
>>> +		__entry->avg_upper,
>>> +		__entry->count,
>>> +		__entry->lower,
>>> +		__entry->upper,
>>> +		__entry->boost_freq,
>>> +		__entry->cpu_freq)
>>> +);
>>> +
>>> +DEFINE_EVENT(device_state, device_isr_enter,
>>> +	TP_PROTO(void __iomem *base, u32 offset, u32 boost, u32
>>> cpufreq),
>>> +	TP_ARGS(base, offset, boost, cpufreq));
>>> +
>>> +DEFINE_EVENT(device_state, device_isr_exit,
>>> +	TP_PROTO(void __iomem *base, u32 offset, u32 boost, u32
>>> cpufreq),
>>> +	TP_ARGS(base, offset, boost, cpufreq));
>>> +
>>> +DEFINE_EVENT(device_state, device_target_update,
>>> +	TP_PROTO(void __iomem *base, u32 offset, u32 boost, u32
>>> cpufreq),
>>> +	TP_ARGS(base, offset, boost, cpufreq));
>>> +
>>> +TRACE_EVENT(device_lower_upper,
>>> +	TP_PROTO(u32 offset, u32 target, u32 lower, u32 upper),
>>> +	TP_ARGS(offset, target, lower, upper),
>>> +	TP_STRUCT__entry(
>>> +		__field(u32, offset)
>>> +		__field(u32, target)
>>> +		__field(u32, lower)
>>> +		__field(u32, upper)
>>> +	),
>>> +	TP_fast_assign(
>>> +		__entry->offset = offset;
>>> +		__entry->target = target;
>>> +		__entry->lower = lower;
>>> +		__entry->upper = upper;
>>> +	),
>>> +	TP_printk("%03x: freq %010u lower freq %010u upper freq
>>> %010u",
>>> +		__entry->offset,
>>> +		__entry->target,
>>> +		__entry->lower,
>>> +		__entry->upper)
>>> +);
>>> +
>>> +TRACE_EVENT(device_target_freq,
>>> +	TP_PROTO(u32 offset, u32 target),
>>> +	TP_ARGS(offset, target),
>>> +	TP_STRUCT__entry(
>>> +		__field(u32, offset)
>>> +		__field(u32, target)
>>> +	),
>>> +	TP_fast_assign(
>>> +		__entry->offset = offset;
>>> +		__entry->target = target;
>>> +	),
>>> +	TP_printk("%03x: freq %010u", __entry->offset,
>>> __entry->target) +);
>>> +#endif /* _TRACE_TEGRA30_DEVFREQ_H */
>>> +
>>> +/* This part must be outside protection */
>>> +#include <trace/define_trace.h>
>>>   
>>
>>
> 
> 
> 


-- 
Best Regards,
Chanwoo Choi
Samsung Electronics