Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751445AbaLaHaa (ORCPT ); Wed, 31 Dec 2014 02:30:30 -0500 Received: from LGEMRELSE6Q.lge.com ([156.147.1.121]:57851 "EHLO lgemrelse6q.lge.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750710AbaLaHa3 (ORCPT ); Wed, 31 Dec 2014 02:30:29 -0500 X-Original-SENDERIP: 10.177.220.156 X-Original-MAILFROM: minchan@kernel.org Date: Wed, 31 Dec 2014 16:32:40 +0900 From: Minchan Kim To: Namhyung Kim Cc: Gioh Kim , Laura Abbott , "Stefan I. Strogin" , linux-mm@kvack.org, linux-kernel@vger.kernel.org, Joonsoo Kim , Andrew Morton , Marek Szyprowski , Michal Nazarewicz , aneesh.kumar@linux.vnet.ibm.com, Laurent Pinchart , Dmitry Safonov , Pintu Kumar , Weijie Yang , SeongJae Park , Hui Zhu , Dyasly Sergey , Vyacheslav Tyrtov , rostedt@goodmis.org Subject: Re: [PATCH 0/3] mm: cma: /proc/cmainfo Message-ID: <20141231073240.GE22342@bbox> References: <20141229023639.GC27095@bbox> <54A1B11A.6020307@codeaurora.org> <20141230044726.GA22342@bbox> <54A34A1C.90603@lge.com> <20141231064759.GB1766@sejong> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: <20141231064759.GB1766@sejong> User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Wed, Dec 31, 2014 at 03:47:59PM +0900, Namhyung Kim wrote: > 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. I did and feel it would be useful to check only max latency data. Anyway, off-topic: IMO, it would be very useful to check latency of several functions which has different threshold at the same time without helping other tools. > > 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 > #include > +#include > #include > #include > #include > @@ -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, send a message with 'unsubscribe linux-mm' in > the body to majordomo@kvack.org. For more info on Linux MM, > see: http://www.linux-mm.org/ . > Don't email: email@kvack.org -- Kind regards, Minchan Kim -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/