Re: [RFD 5/5] tracing: Add trace_irqsoff tracepoints
It is possible to avoid the hackery from patch 4 completely.
If the tracepoint is placed in stop_critical_timing(),
lockdep doesn't complain anymore.
I have changed this patch so that I don't do need to any additional
work to get the latency calculated. Instead just use the values
from check_critical_timing().
That means the tracepoints will only be hit if the tracer
preemptirqsoff & co is enabled. Instead having several
different tracepoints just add the a new field which describes where
the latency is coming from. Furthermore, this approach also avoids
adding additional overhead when the tracers are compiled in but
not used.
# cat /sys/kernel/debug/tracing/events/latency/latency/format
name: latency
ID: 333
format:
field:unsigned short common_type; offset:0; size:2;
signed:0;
field:unsigned char common_flags; offset:2; size:1;
signed:0;
field:unsigned char common_preempt_count; offset:3; size:1;
signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int source; offset:8; size:4; signed:1;
field:cycles_t latency; offset:16; size:8; signed:0;
print fmt: "source=%s latency=%llu", __print_symbolic(REC->source, {1,
"critical section" }, {2, "irq"}, {3, "preempt"}), REC->latency
So in short you could do following to get a histogram:
# echo preemptirqsoff > /sys/kernel/debug/tracing/current_tracer
# echo 1 > /sys/kernel/debug/tracing/tracing_on
# echo 'hist:key=latency.bucket:val=hitcount:sort=latency ' \
'if source == 1' > \
/sys/kernel/debug/tracing/events/latency/latency/trigger
# cat /sys/kernel/debug/tracing/events/latency/latency/hist | head -20
# trigger info: hist:keys=latency.bucket:vals=:sort=latency.bucket:size=2048 if
source == 1 [active]
latency: 1792 hitcount: 7
latency: 2048 hitcount: 23
latency: 2304 hitcount: 37
latency: 2560 hitcount: 57
latency: 2816 hitcount: 33
latency: 3072 hitcount: 40
latency: 3328 hitcount: 16
latency: 3584 hitcount: 40
latency: 3840 hitcount:133
latency: 4096 hitcount:150
latency: 4352 hitcount:196
latency: 4608 hitcount:338
latency: 4864 hitcount:159
latency: 5120 hitcount: 92
latency: 5376 hitcount: 58
latency: 5632 hitcount: 26
latency: 5888 hitcount: 25
latency: 6144 hitcount: 24
I do some more testing to see if I missed something.
cheers,
daniel
>From 449c6881425cc461dd7ea6b6f865d2efe99175b3 Mon Sep 17 00:00:00 2001
From: Daniel Wagner
Date: Wed, 29 Apr 2015 17:09:04 +0200
Subject: [PATCH] tracing: Add trace_irqsoff tracepoints
In order to create latency histograms, we place a tracepoint at the end
of critical section.
Not for inclusion!
Not-Signed-off-by: Daniel Wagner
---
include/trace/events/latency.h | 41 +
kernel/trace/trace_irqsoff.c | 22 ++
2 files changed, 55 insertions(+), 8 deletions(-)
create mode 100644 include/trace/events/latency.h
diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h
new file mode 100644
index 000..1ed8b13
--- /dev/null
+++ b/include/trace/events/latency.h
@@ -0,0 +1,41 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM latency
+
+#if !defined(_TRACE_LATENCY_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_LATENCY_H
+
+#include
+
+#define LATENCY_CS 1
+#define LATENCY_IRQ2
+#define LATENCY_PREEMPT3
+
+#define latency_source_sym \
+ {LATENCY_CS,"critical section" }, \
+ {LATENCY_IRQ, "irq"}, \
+ {LATENCY_PREEMPT, "preempt"}
+
+TRACE_EVENT(latency,
+ TP_PROTO(int source, cycles_t latency),
+
+ TP_ARGS(source, latency),
+
+ TP_STRUCT__entry(
+ __field(int,source)
+ __field(cycles_t, latency)
+ ),
+
+ TP_fast_assign(
+ __entry->source = source;
+ __entry->latency= latency;
+ ),
+
+ TP_printk("source=%s latency=%llu",
+ __print_symbolic(__entry->source, latency_source_sym),
+ __entry->latency)
+);
+
+#endif /* _TRACE_LATENCY_H */
+
+/* This part must be outside protection */
+#include
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 8523ea3..7a1d254 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -14,8 +14,13 @@
#include
#include
+#include
+
#include "trace.h"
+#define CREATE_TRACE_POINTS
+#include
+
static struct trace_array *irqsoff_trace __read_mostly;
static int tra
Re: [RFD 5/5] tracing: Add trace_irqsoff tracepoints
On 05/04/2015 04:05 PM, Daniel Wagner wrote:
> On 05/01/2015 11:23 AM, Daniel Wagner wrote:
>> On 05/01/2015 02:54 AM, Steven Rostedt wrote:
>>> On Thu, 30 Apr 2015 21:14:52 -0500
>>> Tom Zanussi wrote:
>>>
>>>
> 'hist:key=latency.bucket:val=hitcount:sort=latency if cpu==0'
>
> but I haven't got this working. I didn't spend much time figuring out
> why this doesn't work. Even if the above is working you still
I think it doesn't work because the tracepoint doesn't actually have a
'cpu' field to use in the filter...
>>>
>>> Perhaps we should add special fields that don't use the tracepoint
>>> field, but can use generically know fields that are always known when
>>> the tracepoint is triggered. COMM could be one, as well as CPU.
Here my second attempt.
Changes v0:
- Added COMM filter predicate
- Avoid API break in format by introducing a new list for
generic fields
>From 10a58dcc9157ef29514b237aa5d5d8412365a389 Mon Sep 17 00:00:00 2001
From: Daniel Wagner
Date: Mon, 4 May 2015 15:44:24 +0200
Subject: [PATCH] tracing: Allow triggers to filter for CPUs and COMM
By extending the filter rules by more generic fields
we can write triggers filters like
echo 'stacktrace if cpu == 1' > \
/sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
or
echo 'stacktrace if comm == sshd' > \
/sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
We don't want to change the API for the format files. Therefore a new
list (ftrace_generic_fields) is introduced and by this we avoid
getting them listed.
Not for inclusion!
Not-Signed-off-by: Daniel Wagner
---
kernel/trace/trace_events.c| 25 ++
kernel/trace/trace_events_filter.c | 54 --
2 files changed, 77 insertions(+), 2 deletions(-)
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index c4de47f..805cb75 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -30,6 +30,7 @@
DEFINE_MUTEX(event_mutex);
LIST_HEAD(ftrace_events);
+static LIST_HEAD(ftrace_generic_fields);
static LIST_HEAD(ftrace_common_fields);
#define GFP_TRACE (GFP_KERNEL | __GFP_ZERO)
@@ -94,6 +95,10 @@ trace_find_event_field(struct ftrace_event_call *call, char
*name)
struct ftrace_event_field *field;
struct list_head *head;
+ field = __find_event_field(&ftrace_generic_fields, name);
+ if (field)
+ return field;
+
field = __find_event_field(&ftrace_common_fields, name);
if (field)
return field;
@@ -144,6 +149,13 @@ int trace_define_field(struct ftrace_event_call *call,
const char *type,
}
EXPORT_SYMBOL_GPL(trace_define_field);
+#define __generic_field(type, item, filter_type) \
+ ret = __trace_define_field(&ftrace_generic_fields, #type, \
+ #item, 0, 0, is_signed_type(type), \
+ filter_type);\
+ if (ret)\
+ return ret;
+
#define __common_field(type, item) \
ret = __trace_define_field(&ftrace_common_fields, #type,\
"common_" #item, \
@@ -153,6 +165,16 @@ EXPORT_SYMBOL_GPL(trace_define_field);
if (ret)\
return ret;
+static int trace_define_generic_fields(void)
+{
+ int ret;
+
+ __generic_field(int, cpu, FILTER_OTHER);
+ __generic_field(char *, comm, FILTER_PTR_STRING);
+
+ return ret;
+}
+
static int trace_define_common_fields(void)
{
int ret;
@@ -2671,6 +2693,9 @@ static __init int event_trace_init(void)
if (!entry)
pr_warn("Could not create tracefs 'available_events' entry\n");
+ if (trace_define_generic_fields())
+ pr_warn("tracing: Failed to allocated generic fields");
+
if (trace_define_common_fields())
pr_warn("tracing: Failed to allocate common fields");
diff --git a/kernel/trace/trace_events_filter.c
b/kernel/trace/trace_events_filter.c
index ced69da..74feaf4 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -252,6 +252,50 @@ static int filter_pred_strloc(struct filter_pred *pred,
void *event)
return match;
}
+/* Filter predicate for CPUs. */
+static int filter_pred_cpu(struct filter_pred *pred, void *event)
+{
+ int cpu, cmp;
+ int match = 0;
+
+ cpu = raw_smp_processor_id();
+ cmp = pred->val;
+
+ switch (pred->op) {
+ case OP_EQ:
+ match = cpu == cmp;
+ break;
+ case OP_LT:
+ match = cpu < cmp;
+ break;
+ case OP_LE:
+ match = cpu <= cmp;
+ break;
+
Re: [RFD 5/5] tracing: Add trace_irqsoff tracepoints
On 05/01/2015 11:23 AM, Daniel Wagner wrote:
> On 05/01/2015 02:54 AM, Steven Rostedt wrote:
>> On Thu, 30 Apr 2015 21:14:52 -0500
>> Tom Zanussi wrote:
>>
>>
'hist:key=latency.bucket:val=hitcount:sort=latency if cpu==0'
but I haven't got this working. I didn't spend much time figuring out
why this doesn't work. Even if the above is working you still
>>>
>>> I think it doesn't work because the tracepoint doesn't actually have a
>>> 'cpu' field to use in the filter...
>>
>> Perhaps we should add special fields that don't use the tracepoint
>> field, but can use generically know fields that are always known when
>> the tracepoint is triggered. COMM could be one, as well as CPU.
Here a first attempt:
>From fcd910836179dd738b3300dbf93a30f352e90996 Mon Sep 17 00:00:00 2001
From: Daniel Wagner
Date: Mon, 4 May 2015 15:44:24 +0200
Subject: [PATCH] tracing: Allow triggers to filter for CPUs
By extending the filter rules by more 'generically know' fields
we can write triggers filters like
'stacktrace:5 if cpu == 1'
We add a new element to ftrace_common_fields which describes
the new 'generically know' field. This change is visiable to user space.
E.g. the format file changes for kmem:kmalloc changes to
name: kmalloc
ID: 395
format:
field:int cpu; offset:0; size:0; signed:1;
field:unsigned short common_type; offset:0; size:2;
signed:0;
field:unsigned char common_flags; offset:2; size:1;
signed:0;
field:unsigned char common_preempt_count; offset:3; size:1;
signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:unsigned long call_site; offset:8; size:8; signed:0;
field:const void * ptr; offset:16; size:8; signed:0;
field:size_t bytes_req; offset:24; size:8; signed:0;
field:size_t bytes_alloc; offset:32; size:8; signed:0;
field:gfp_t gfp_flags; offset:40; size:4; signed:0;
I think that is not complete correct since the field cpu doesn't
really exists in trace event entry. Propably moving those known fields
their own list is a way to overcome this problem. What do you think?
And yes, I am still marveling on this comment
/* If not of not match is equal to not of not, then it is a match */
from DEFINE_COMPARISON_PRED. This led me to copy it for
filter_pred_cpu() :)
Not for inclusion!
Not-Signed-off-by: Daniel Wagner
---
kernel/trace/trace_events.c| 8
kernel/trace/trace_events_filter.c | 37 -
2 files changed, 44 insertions(+), 1 deletion(-)
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index c4de47f..3f51f2b 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -144,6 +144,13 @@ int trace_define_field(struct ftrace_event_call *call,
const char *type,
}
EXPORT_SYMBOL_GPL(trace_define_field);
+#define __trace_field(type, item) \
+ ret = __trace_define_field(&ftrace_common_fields, #type,\
+ #item, 0, 0, is_signed_type(type), \
+ FILTER_OTHER); \
+ if (ret)\
+ return ret;
+
#define __common_field(type, item) \
ret = __trace_define_field(&ftrace_common_fields, #type,\
"common_" #item, \
@@ -158,6 +165,7 @@ static int trace_define_common_fields(void)
int ret;
struct trace_entry ent;
+ __trace_field(int, cpu);
__common_field(unsigned short, type);
__common_field(unsigned char, flags);
__common_field(unsigned char, preempt_count);
diff --git a/kernel/trace/trace_events_filter.c
b/kernel/trace/trace_events_filter.c
index ced69da..af2a6bb 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -252,6 +252,38 @@ static int filter_pred_strloc(struct filter_pred *pred,
void *event)
return match;
}
+/* Filter predicate for CPUs. */
+static int filter_pred_cpu(struct filter_pred *pred, void *event)
+{
+ int cpu, cmp;
+ int match = 0;
+
+ cpu = raw_smp_processor_id();
+ cmp = pred->val;
+
+ switch (pred->op) {
+ case OP_EQ:
+ match = cpu == cmp;
+ break;
+ case OP_LT:
+ match = cpu < cmp;
+ break;
+ case OP_LE:
+ match = cpu <= cmp;
+ break;
+ case OP_GT:
+ match = cpu > cmp;
+ break;
+ case OP_GE:
+ match = cpu >= cmp;
+ break;
+ default:
+ break;
+ }
+
+ return !!match == !pred->not;
+}
+
static int filter_pred_none(struct filter_pred *pred, void *event)
{
return
Re: [RFD 5/5] tracing: Add trace_irqsoff tracepoints
On 05/01/2015 02:54 AM, Steven Rostedt wrote: On Thu, 30 Apr 2015 21:14:52 -0500 Tom Zanussi wrote: 'hist:key=latency.bucket:val=hitcount:sort=latency if cpu==0' but I haven't got this working. I didn't spend much time figuring out why this doesn't work. Even if the above is working you still I think it doesn't work because the tracepoint doesn't actually have a 'cpu' field to use in the filter... Perhaps we should add special fields that don't use the tracepoint field, but can use generically know fields that are always known when the tracepoint is triggered. COMM could be one, as well as CPU. I'll give it a try if no one objects next week (public holiday today :)) cheers, daniel -- 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/
Re: [RFD 5/5] tracing: Add trace_irqsoff tracepoints
On Thu, 30 Apr 2015 21:14:52 -0500 Tom Zanussi wrote: > > 'hist:key=latency.bucket:val=hitcount:sort=latency if cpu==0' > > > > but I haven't got this working. I didn't spend much time figuring out > > why this doesn't work. Even if the above is working you still > > I think it doesn't work because the tracepoint doesn't actually have a > 'cpu' field to use in the filter... Perhaps we should add special fields that don't use the tracepoint field, but can use generically know fields that are always known when the tracepoint is triggered. COMM could be one, as well as CPU. -- Steve -- 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/
Re: [RFD 5/5] tracing: Add trace_irqsoff tracepoints
On Thu, 2015-04-30 at 12:06 +0200, Daniel Wagner wrote: > Finally we place a few tracepoint at the end of critical section. With > the hist trigger in place we can generate the plots. > > There are a few drawbacks compared to the latency_hist.patch [1] > > The latency plots contain the values from all CPUs. In theory you > can also filter with something like > > 'hist:key=latency.bucket:val=hitcount:sort=latency if cpu==0' > > but I haven't got this working. I didn't spend much time figuring out > why this doesn't work. Even if the above is working you still I think it doesn't work because the tracepoint doesn't actually have a 'cpu' field to use in the filter... Tom -- 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/
