Hello,
On Wed, Dec 31, 2014 at 09:58:04AM +0900, Gioh Kim wrote:
> 2014-12-30 오후 1:47에 Minchan Kim 이(가) 쓴 글:
> >On Mon, Dec 29, 2014 at 11:52:58AM -0800, Laura Abbott wrote:
> >>I've been meaning to write something like this for a while so I'm
> >>happy to see an attempt made to fix this. I can't speak for the
> >>author's reasons for wanting this information but there are
> >>several reasons why I was thinking of something similar.
> >>
> >>The most common bug reports seen internally on CMA are 1) CMA is
> >>too slow and 2) CMA failed to allocate memory. For #1, not all
> >>allocations may be slow so it's useful to be able to keep track
> >>of which allocations are taking too long. For #2, migration
> >
> >Then, I don't think we could keep all of allocations. What we need
> >is only slow allocations. I hope we can do that with ftrace.
> >
> >ex)
> >
> ># cd /sys/kernel/debug/tracing
> ># echo 1 > options/stacktrace
> ># echo cam_alloc > set_ftrace_filter
> ># echo your_threshold > tracing_thresh
> >
> >I know it doesn't work now but I think it's more flexible
> >and general way to handle such issues(ie, latency of some functions).
> >So, I hope we could enhance ftrace rather than new wheel.
> >Ccing ftrace people.
>
> For CMA performance test or code flow check, ftrace is better.
>
> ex)
> echo cma_alloc > /sys/kernel/debug/tracing/set_graph_function
> echo function_graph > /sys/kernel/debug/tracing/current_tracer
> echo funcgraph-proc > /sys/kernel/debug/tracing/trace_options
> echo nosleep-time > /sys/kernel/debug/tracing/trace_options
> echo funcgraph-tail > /sys/kernel/debug/tracing/trace_options
> echo 1 > /sys/kernel/debug/tracing/tracing_on
>
> This can trace every cam_alloc and allocation time.
> I think ftrace is better to debug latency.
> If a buffer had allocated and had peak latency and freed,
> we can check it.
It'd be great if we can reuse the max latency tracing feature for the
function graph tracer in order to track a latency problem of an
arbitrary function more easily. I've written a PoC code that can be
used like below..
# cd /sys/kernel/debug/tracing
# echo 0 > tracing_on
# echo function_graph > current_tracer
# echo funcgraph-latency > trace_options
# echo cma_alloc > graph_latency_func
# echo 1 > tracing_on
Now the tracing_max_latency file has a max latency of the cma_alloc()
in usec and the snapshot file contains a snapshot of all the codepath
to the function at the time.
Would anybody like to play with it? :)
Thanks,
Namhyung
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 0eddfeb05fee..4a3d5ed2802c 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -723,6 +723,7 @@ extern char trace_find_mark(unsigned long long duration);
#define TRACE_GRAPH_PRINT_ABS_TIME 0x20
#define TRACE_GRAPH_PRINT_IRQS 0x40
#define TRACE_GRAPH_PRINT_TAIL 0x80
+#define TRACE_GRAPH_MAX_LATENCY 0x100
#define TRACE_GRAPH_PRINT_FILL_SHIFT 28
#define TRACE_GRAPH_PRINT_FILL_MASK (0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
diff --git a/kernel/trace/trace_functions_graph.c
b/kernel/trace/trace_functions_graph.c
index ba476009e5de..7fc3e21d1354 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -8,6 +8,7 @@
*/
#include <linux/debugfs.h>
#include <linux/uaccess.h>
+#include <linux/module.h>
#include <linux/ftrace.h>
#include <linux/slab.h>
#include <linux/fs.h>
@@ -44,6 +45,10 @@ void ftrace_graph_stop(void)
/* When set, irq functions will be ignored */
static int ftrace_graph_skip_irqs;
+/* When set, record max latency of a given function */
+static int ftrace_graph_max_latency;
+
+static unsigned long ftrace_graph_latency_func;
struct fgraph_cpu_data {
pid_t last_pid;
@@ -84,6 +89,8 @@ static struct tracer_opt trace_opts[] = {
{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
/* Display function name after trailing } */
{ TRACER_OPT(funcgraph-tail, TRACE_GRAPH_PRINT_TAIL) },
+ /* Record max latency of a given function } */
+ { TRACER_OPT(funcgraph-latency, TRACE_GRAPH_MAX_LATENCY) },
{ } /* Empty entry */
};
@@ -389,6 +396,22 @@ trace_graph_function(struct trace_array *tr,
__trace_graph_function(tr, ip, flags, pc);
}
+#ifdef CONFIG_TRACER_MAX_TRACE
+static bool report_latency(struct trace_array *tr,
+ struct ftrace_graph_ret *trace)
+{
+ unsigned long long delta = trace->rettime - trace->calltime;
+
+ if (!ftrace_graph_max_latency)
+ return false;
+
+ if (ftrace_graph_latency_func != trace->func)
+ return false;
+
+ return tr->max_latency < delta;
+}
+#endif
+
void __trace_graph_return(struct trace_array *tr,
struct ftrace_graph_ret *trace,
unsigned long flags,
@@ -428,6 +451,22 @@ void trace_graph_return(struct ftrace_graph_ret *trace)
if (likely(disabled == 1)) {
pc = preempt_count();
__trace_graph_return(tr, trace, flags, pc);
+
+#ifdef CONFIG_TRACER_MAX_TRACE
+ if (report_latency(tr, trace)) {
+ static DEFINE_RAW_SPINLOCK(max_trace_lock);
+ unsigned long long delta;
+
+ delta = trace->rettime - trace->calltime;
+
+ raw_spin_lock(&max_trace_lock);
+ if (delta > tr->max_latency) {
+ tr->max_latency = delta;
+ update_max_tr(tr, current, cpu);
+ }
+ raw_spin_unlock(&max_trace_lock);
+ }
+#endif
}
atomic_dec(&data->disabled);
local_irq_restore(flags);
@@ -456,6 +495,11 @@ static int graph_trace_init(struct trace_array *tr)
int ret;
set_graph_array(tr);
+
+#ifdef CONFIG_TRACE_MAX_LATENCY
+ graph_array->max_latency = 0;
+#endif
+
if (tracing_thresh)
ret = register_ftrace_graph(&trace_graph_thresh_return,
&trace_graph_thresh_entry);
@@ -1358,7 +1402,15 @@ func_graph_set_flag(struct trace_array *tr, u32
old_flags, u32 bit, int set)
{
if (bit == TRACE_GRAPH_PRINT_IRQS)
ftrace_graph_skip_irqs = !set;
+ else if (bit == TRACE_GRAPH_MAX_LATENCY) {
+ ftrace_graph_max_latency = set;
+ if (set && !tr->allocated_snapshot) {
+ int ret = tracing_alloc_snapshot();
+ if (ret < 0)
+ return ret;
+ }
+ }
return 0;
}
@@ -1425,6 +1477,43 @@ graph_depth_read(struct file *filp, char __user *ubuf,
size_t cnt,
return simple_read_from_buffer(ubuf, cnt, ppos, buf, n);
}
+static ssize_t
+graph_latency_write(struct file *filp, const char __user *ubuf, size_t cnt,
+ loff_t *ppos)
+{
+ char buf[KSYM_SYMBOL_LEN];
+ long ret;
+
+ ret = strncpy_from_user(buf, ubuf, cnt);
+ if (ret <= 0)
+ return ret;
+
+ if (buf[ret - 1] == '\n')
+ buf[ret - 1] = '\0';
+
+ ftrace_graph_latency_func = kallsyms_lookup_name(buf);
+ if (!ftrace_graph_latency_func)
+ return -EINVAL;
+
+ *ppos += cnt;
+
+ return cnt;
+}
+
+static ssize_t
+graph_latency_read(struct file *filp, char __user *ubuf, size_t cnt,
+ loff_t *ppos)
+{
+ char buf[KSYM_SYMBOL_LEN];
+
+ if (!ftrace_graph_latency_func)
+ return 0;
+
+ kallsyms_lookup(ftrace_graph_latency_func, NULL, NULL, NULL, buf);
+
+ return simple_read_from_buffer(ubuf, cnt, ppos, buf, strlen(buf));
+}
+
static const struct file_operations graph_depth_fops = {
.open = tracing_open_generic,
.write = graph_depth_write,
@@ -1432,6 +1521,13 @@ static const struct file_operations graph_depth_fops = {
.llseek = generic_file_llseek,
};
+static const struct file_operations graph_latency_fops = {
+ .open = tracing_open_generic,
+ .write = graph_latency_write,
+ .read = graph_latency_read,
+ .llseek = generic_file_llseek,
+};
+
static __init int init_graph_debugfs(void)
{
struct dentry *d_tracer;
@@ -1442,6 +1538,10 @@ static __init int init_graph_debugfs(void)
trace_create_file("max_graph_depth", 0644, d_tracer,
NULL, &graph_depth_fops);
+#ifdef CONFIG_TRACER_MAX_TRACE
+ trace_create_file("graph_latency_func", 0644, d_tracer,
+ NULL, &graph_latency_fops);
+#endif
return 0;
}
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
