by Daniel Wagner

[permalink] [raw]

Subject: 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 <[email protected]> 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 <[email protected]>
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 <[email protected]>
---
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;
+ case OP_GT:
+ match = cpu > cmp;
+ break;
+ case OP_GE:
+ match = cpu >= cmp;
+ break;
+ default:
+ break;
+ }
+
+ return !!match == !pred->not;
+}
+
+/* Filter predicate for COMM. */
+static int filter_pred_comm(struct filter_pred *pred, void *event)
+{
+ int cmp, match;
+
+ cmp = pred->regex.match(current->comm, &pred->regex,
+ pred->regex.field_len);
+ match = cmp ^ pred->not;
+
+ return match;
+}
+
static int filter_pred_none(struct filter_pred *pred, void *event)
{
return 0;
@@ -1002,7 +1046,10 @@ static int init_pred(struct filter_parse_state *ps,
if (is_string_field(field)) {
filter_build_regex(pred);

- if (field->filter_type == FILTER_STATIC_STRING) {
+ if (!strcmp(field->name, "comm")) {
+ fn = filter_pred_comm;
+ pred->regex.field_len = TASK_COMM_LEN;
+ } else if (field->filter_type == FILTER_STATIC_STRING) {
fn = filter_pred_string;
pred->regex.field_len = field->size;
} else if (field->filter_type == FILTER_DYN_STRING)
@@ -1025,7 +1072,10 @@ static int init_pred(struct filter_parse_state *ps,
}
pred->val = val;

- fn = select_comparison_fn(pred->op, field->size,
+ if (!strcmp(field->name, "cpu"))
+ fn = filter_pred_cpu;
+ else
+ fn = select_comparison_fn(pred->op, field->size,
field->is_signed);
if (!fn) {
parse_error(ps, FILT_ERR_INVALID_OP, 0);
--
2.1.0

2015-05-06 06:31:25

by Daniel Wagner

[permalink] [raw]

Subject: 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 <[email protected]>
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 <[email protected]>
---
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 0000000..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 <linux/tracepoint.h>
+
+#define LATENCY_CS 1
+#define LATENCY_IRQ 2
+#define LATENCY_PREEMPT 3
+
+#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 <trace/define_trace.h>
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 <linux/module.h>
#include <linux/ftrace.h>

+#include <trace/events/sched.h>
+
#include "trace.h"

+#define CREATE_TRACE_POINTS
+#include <trace/events/latency.h>
+
static struct trace_array *irqsoff_trace __read_mostly;
static int tracer_enabled __read_mostly;

@@ -311,7 +316,7 @@ static void
check_critical_timing(struct trace_array *tr,
struct trace_array_cpu *data,
unsigned long parent_ip,
- int cpu)
+ int cpu, int source)
{
cycle_t T0, T1, delta;
unsigned long flags;
@@ -325,6 +330,7 @@ check_critical_timing(struct trace_array *tr,

pc = preempt_count();

+ trace_latency(source, delta);
if (!report_latency(tr, delta))
goto out;

@@ -396,7 +402,7 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
}

static inline void
-stop_critical_timing(unsigned long ip, unsigned long parent_ip)
+stop_critical_timing(unsigned long ip, unsigned long parent_ip, int source)
{
int cpu;
struct trace_array *tr = irqsoff_trace;
@@ -423,7 +429,7 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)

local_save_flags(flags);
__trace_function(tr, ip, parent_ip, flags, preempt_count());
- check_critical_timing(tr, data, parent_ip ? : ip, cpu);
+ check_critical_timing(tr, data, parent_ip ? : ip, cpu, source);
data->critical_start = 0;
atomic_dec(&data->disabled);
}
@@ -439,7 +445,7 @@ EXPORT_SYMBOL_GPL(start_critical_timings);
void stop_critical_timings(void)
{
if (preempt_trace() || irq_trace())
- stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LATENCY_CS);
}
EXPORT_SYMBOL_GPL(stop_critical_timings);

@@ -448,7 +454,7 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
void time_hardirqs_on(unsigned long a0, unsigned long a1)
{
if (!preempt_trace() && irq_trace())
- stop_critical_timing(a0, a1);
+ stop_critical_timing(a0, a1, LATENCY_IRQ);
}

void time_hardirqs_off(unsigned long a0, unsigned long a1)
@@ -481,7 +487,7 @@ inline void print_irqtrace_events(struct task_struct *curr)
void trace_hardirqs_on(void)
{
if (!preempt_trace() && irq_trace())
- stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LATENCY_IRQ);
}
EXPORT_SYMBOL(trace_hardirqs_on);

@@ -495,7 +501,7 @@ EXPORT_SYMBOL(trace_hardirqs_off);
__visible void trace_hardirqs_on_caller(unsigned long caller_addr)
{
if (!preempt_trace() && irq_trace())
- stop_critical_timing(CALLER_ADDR0, caller_addr);
+ stop_critical_timing(CALLER_ADDR0, caller_addr, LATENCY_IRQ);
}
EXPORT_SYMBOL(trace_hardirqs_on_caller);

@@ -513,7 +519,7 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller);
void trace_preempt_on(unsigned long a0, unsigned long a1)
{
if (preempt_trace() && !irq_trace())
- stop_critical_timing(a0, a1);
+ stop_critical_timing(a0, a1, LATENCY_PREEMPT);
}

void trace_preempt_off(unsigned long a0, unsigned long a1)
--
2.1.0