[lttng-dev] [PATCH latency-tracker] Fix: sizeof() bug, state tracking merge issue, PID 0
Julien Desfossez
jdesfossez at efficios.com
Wed Aug 24 13:54:06 UTC 2016
Merged, big thanks !
Julien
On 23-Aug-2016 07:37:01 PM, Mathieu Desnoyers wrote:
> - 3 sizeof() issues (using pointer size rather than object size),
> - state tracking merge issue on switch in: the get following the
> insertion may not get the same node when there are duplicates,
> - also features a refactoring of keys: add a "p" parent field for the
> type.
> - PID 0 needs to be compared with its cpu ID too.
>
> Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com>
> ---
> examples/rt.c | 164 +++++++++++++++++++++++++++++++-----------------------
> latency_tracker.h | 7 +++
> tracker.c | 20 ++++++-
> 3 files changed, 120 insertions(+), 71 deletions(-)
>
> diff --git a/examples/rt.c b/examples/rt.c
> index f9703ca..7b3b2b3 100644
> --- a/examples/rt.c
> +++ b/examples/rt.c
> @@ -139,53 +139,59 @@ enum event_out_types {
> OUT_NO_CB = 4,
> };
>
> +struct generic_key_t {
> + enum rt_key_type type;
> +} __attribute__((__packed__));
> +
> struct do_irq_key_t {
> + struct generic_key_t p;
> unsigned int cpu;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> struct local_timer_key_t {
> + struct generic_key_t p;
> unsigned int cpu;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> struct hrtimer_key_t {
> + struct generic_key_t p;
> unsigned int cpu;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> struct hardirq_key_t {
> + struct generic_key_t p;
> unsigned int cpu;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> struct raise_softirq_key_t {
> + struct generic_key_t p;
> unsigned int cpu;
> unsigned int vector;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> struct softirq_key_t {
> + struct generic_key_t p;
> unsigned int cpu;
> int pid;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> struct waking_key_t {
> + struct generic_key_t p;
> + int cpu;
> int pid;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> struct switch_key_t {
> + struct generic_key_t p;
> + int cpu;
> int pid;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> #define MAX_COOKIE_SIZE 32
> struct work_begin_key_t {
> + struct generic_key_t p;
> char cookie[MAX_COOKIE_SIZE];
> int cookie_size;
> - enum rt_key_type type;
> } __attribute__((__packed__));
>
> /* Keep up-to-date with a list of all key structs. */
> @@ -445,6 +451,7 @@ static
> int entry_do_irq(struct kretprobe_instance *p, struct pt_regs *regs)
> {
> enum latency_tracker_event_in_ret ret;
> + struct latency_tracker_event *s;
> struct do_irq_key_t key;
> u64 now;
>
> @@ -452,26 +459,20 @@ int entry_do_irq(struct kretprobe_instance *p, struct pt_regs *regs)
> return 0;
>
> now = trace_clock_monotonic_wrapper();
> + key.p.type = KEY_DO_IRQ;
> key.cpu = smp_processor_id();
> - key.type = KEY_DO_IRQ;
> - ret = _latency_tracker_event_in(tracker, &key, sizeof(key), 1, now,
> - NULL);
> + ret = _latency_tracker_event_in_get(tracker, &key, sizeof(key), 1, now,
> + NULL, &s);
> if (ret != LATENCY_TRACKER_OK) {
> failed_event_in++;
> return 0;
> }
> + WARN_ON_ONCE(!s);
>
> if (config.text_breakdown) {
> - struct latency_tracker_event *s;
> -
> - s = latency_tracker_get_event(tracker, &key, sizeof(key));
> - if (!s) {
> - BUG_ON(1);
> - return 0;
> - }
> append_delta_ts(s, KEY_DO_IRQ, "do_IRQ", now, 0, NULL, 0);
> - latency_tracker_put_event(s);
> }
> + latency_tracker_put_event(s);
>
> #ifdef DEBUG
> printk("%llu do_IRQ (cpu %u)\n", trace_clock_monotonic_wrapper(),
> @@ -488,8 +489,8 @@ int exit_do_irq(struct kretprobe_instance *p, struct pt_regs *regs)
>
> if (!config.irq_tracing)
> return 0;
> + key.p.type = KEY_DO_IRQ;
> key.cpu = smp_processor_id();
> - key.type = KEY_DO_IRQ;
> latency_tracker_event_out(tracker, &key,
> sizeof(key), OUT_IRQHANDLER_NO_CB, 0);
>
> @@ -618,15 +619,13 @@ struct latency_tracker_event *event_transition(void *key_in, int key_in_len,
> }
> orig_ts = latency_tracker_event_get_start_ts(event_in);
>
> - ret = _latency_tracker_event_in(tracker, key_out,
> - key_out_len, unique, orig_ts, NULL);
> + ret = _latency_tracker_event_in_get(tracker, key_out,
> + key_out_len, unique, orig_ts, NULL, &event_out);
> if (ret != LATENCY_TRACKER_OK) {
> - goto end_del;
> failed_event_in++;
> - }
> - event_out = latency_tracker_get_event(tracker, key_out, key_out_len);
> - if (!event_out)
> goto end_del;
> + }
> + WARN_ON_ONCE(!event_out);
> data_out = (struct event_data *) latency_tracker_event_get_priv_data(event_out);
> if (!data_out) {
> BUG_ON(1);
> @@ -679,6 +678,7 @@ out:
> LT_PROBE_DEFINE(local_timer_entry, int vector)
> {
> enum latency_tracker_event_in_ret ret;
> + struct latency_tracker_event *s;
> struct local_timer_key_t key;
> u64 now;
>
> @@ -686,26 +686,20 @@ LT_PROBE_DEFINE(local_timer_entry, int vector)
> goto end;
>
> now = trace_clock_monotonic_wrapper();
> + key.p.type = KEY_TIMER_INTERRUPT;
> key.cpu = smp_processor_id();
> - key.type = KEY_TIMER_INTERRUPT;
> - ret = _latency_tracker_event_in(tracker, &key, sizeof(key), 1, now,
> - NULL);
> + ret = _latency_tracker_event_in_get(tracker, &key, sizeof(key), 1, now,
> + NULL, &s);
> if (ret != LATENCY_TRACKER_OK) {
> failed_event_in++;
> goto end;
> }
> -
> + WARN_ON_ONCE(!s);
> if (config.text_breakdown) {
> - struct latency_tracker_event *s;
> - s = latency_tracker_get_event(tracker, &key, sizeof(key));
> - if (!s) {
> - BUG_ON(1);
> - goto end;
> - }
> append_delta_ts(s, KEY_TIMER_INTERRUPT, "local_timer_entry", now,
> vector, NULL, 0);
> - latency_tracker_put_event(s);
> }
> + latency_tracker_put_event(s);
>
> #ifdef DEBUG
> printk("%llu local_timer_entry (cpu %u)\n", trace_clock_monotonic_wrapper(),
> @@ -722,8 +716,8 @@ LT_PROBE_DEFINE(local_timer_exit, int vector)
>
> if (!config.timer_tracing)
> goto end;
> + local_timer_key.p.type = KEY_TIMER_INTERRUPT;
> local_timer_key.cpu = smp_processor_id();
> - local_timer_key.type = KEY_TIMER_INTERRUPT;
> latency_tracker_event_out(tracker, &local_timer_key,
> sizeof(local_timer_key), OUT_IRQHANDLER_NO_CB, 0);
> end:
> @@ -743,11 +737,11 @@ LT_PROBE_DEFINE(irq_handler_entry, int irq, struct irqaction *action)
> goto end;
> }
>
> + do_irq_key.p.type = KEY_DO_IRQ;
> do_irq_key.cpu = smp_processor_id();
> - do_irq_key.type = KEY_DO_IRQ;
>
> + hardirq_key.p.type = KEY_HARDIRQ;
> hardirq_key.cpu = smp_processor_id();
> - hardirq_key.type = KEY_HARDIRQ;
>
> s = event_transition(&do_irq_key, sizeof(do_irq_key), &hardirq_key,
> sizeof(hardirq_key), 0, 1, 0);
> @@ -777,8 +771,8 @@ LT_PROBE_DEFINE(irq_handler_exit, int irq, struct irqaction *action,
> goto end;
> }
>
> + hardirq_key.p.type = KEY_HARDIRQ;
> hardirq_key.cpu = smp_processor_id();
> - hardirq_key.type = KEY_HARDIRQ;
>
> if (config.text_breakdown) {
> struct latency_tracker_event *s;
> @@ -809,12 +803,16 @@ LT_PROBE_DEFINE(softirq_raise, unsigned int vec_nr)
> if (config.softirq_filter > 0 && config.softirq_filter != vec_nr)
> goto end;
>
> + switch_key.p.type = KEY_SWITCH;
> switch_key.pid = current->pid;
> - switch_key.type = KEY_SWITCH;
> + if (!current->pid)
> + switch_key.cpu = smp_processor_id();
> + else
> + switch_key.cpu = -1;
>
> + raise_softirq_key.p.type = KEY_RAISE_SOFTIRQ;
> raise_softirq_key.cpu = smp_processor_id();
> raise_softirq_key.vector = vec_nr;
> - raise_softirq_key.type = KEY_RAISE_SOFTIRQ;
>
> s = event_transition(&switch_key, sizeof(switch_key),
> &raise_softirq_key, sizeof(raise_softirq_key), 0, 0, 1);
> @@ -841,12 +839,12 @@ LT_PROBE_DEFINE(softirq_raise, unsigned int vec_nr)
> if (config.softirq_filter > 0 && config.softirq_filter != vec_nr)
> goto end;
>
> + hardirq_key.p.type = KEY_HARDIRQ;
> hardirq_key.cpu = smp_processor_id();
> - hardirq_key.type = KEY_HARDIRQ;
>
> + raise_softirq_key.p.type = KEY_RAISE_SOFTIRQ;
> raise_softirq_key.cpu = smp_processor_id();
> raise_softirq_key.vector = vec_nr;
> - raise_softirq_key.type = KEY_RAISE_SOFTIRQ;
>
> s = event_transition(&hardirq_key, sizeof(hardirq_key),
> &raise_softirq_key, sizeof(raise_softirq_key), 0, 0, 1);
> @@ -874,17 +872,17 @@ LT_PROBE_DEFINE(softirq_entry, unsigned int vec_nr)
> if (config.softirq_filter > 0 && config.softirq_filter != vec_nr)
> goto end;
>
> + raise_softirq_key.p.type = KEY_RAISE_SOFTIRQ;
> raise_softirq_key.cpu = smp_processor_id();
> raise_softirq_key.vector = vec_nr;
> - raise_softirq_key.type = KEY_RAISE_SOFTIRQ;
>
> /*
> * Insert the softirq_entry event.
> * TODO: Use the CPU as key on non-RT kernel and PID on PREEMPT_RT.
> */
> + softirq_key.p.type = KEY_SOFTIRQ;
> softirq_key.cpu = smp_processor_id();
> softirq_key.pid = current->pid;
> - softirq_key.type = KEY_SOFTIRQ;
>
> do {
> s = event_transition(&raise_softirq_key, sizeof(raise_softirq_key),
> @@ -912,15 +910,15 @@ LT_PROBE_DEFINE(hrtimer_expire_entry, struct hrtimer *hrtimer,
>
> if (!config.timer_tracing)
> goto end;
> + local_timer_key.p.type = KEY_TIMER_INTERRUPT;
> local_timer_key.cpu = smp_processor_id();
> - local_timer_key.type = KEY_TIMER_INTERRUPT;
>
> /*
> * Insert the hrtimer_expire_entry event.
> * TODO: Use the CPU as key on non-RT kernel and PID on PREEMPT_RT.
> */
> + hrtimer_key.p.type = KEY_HRTIMER;
> hrtimer_key.cpu = smp_processor_id();
> - hrtimer_key.type = KEY_HRTIMER;
>
> s = event_transition(&local_timer_key, sizeof(local_timer_key),
> &hrtimer_key, sizeof(hrtimer_key), 0, 1, 0);
> @@ -943,15 +941,15 @@ LT_PROBE_DEFINE(hrtimer_expire_exit, struct timer_list *timer)
>
> if (!config.timer_tracing)
> goto end;
> + hrtimer_key.p.type = KEY_HRTIMER;
> hrtimer_key.cpu = smp_processor_id();
> - hrtimer_key.type = KEY_HRTIMER;
>
> /*
> * Insert the hrtimer_expire_entry event.
> * TODO: Use the CPU as key on non-RT kernel and PID on PREEMPT_RT.
> */
> + hrtimer_key.p.type = KEY_HRTIMER;
> hrtimer_key.cpu = smp_processor_id();
> - hrtimer_key.type = KEY_HRTIMER;
>
> latency_tracker_event_out(tracker, &hrtimer_key, sizeof(hrtimer_key),
> OUT_IRQHANDLER_NO_CB, 0);
> @@ -970,9 +968,9 @@ LT_PROBE_DEFINE(softirq_exit, unsigned int vec_nr)
> /*
> * Just cleanup the softirq_entry event
> */
> + softirq_key.p.type = KEY_SOFTIRQ;
> softirq_key.cpu = smp_processor_id();
> softirq_key.pid = current->pid;
> - softirq_key.type = KEY_SOFTIRQ;
> if (config.text_breakdown) {
> struct latency_tracker_event *s;
>
> @@ -996,11 +994,11 @@ void irq_waking(struct waking_key_t *waking_key)
> struct latency_tracker_event *s;
> struct do_irq_key_t do_irq_key;
>
> + do_irq_key.p.type = KEY_DO_IRQ;
> do_irq_key.cpu = smp_processor_id();
> - do_irq_key.type = KEY_DO_IRQ;
>
> s = event_transition(&do_irq_key, sizeof(do_irq_key),
> - waking_key, sizeof(waking_key), 0, 0, 1);
> + waking_key, sizeof(*waking_key), 0, 0, 1);
> if (!s)
> return;
> append_delta_ts(s, KEY_WAKEUP, "to sched_waking", 0, waking_key->pid,
> @@ -1018,12 +1016,12 @@ void softirq_waking(struct waking_key_t *waking_key)
> struct softirq_key_t softirq_key;
> struct latency_tracker_event *s;
>
> + softirq_key.p.type = KEY_SOFTIRQ;
> softirq_key.cpu = smp_processor_id();
> softirq_key.pid = current->pid;
> - softirq_key.type = KEY_SOFTIRQ;
>
> s = event_transition(&softirq_key, sizeof(softirq_key),
> - waking_key, sizeof(waking_key), 0, 0, 1);
> + waking_key, sizeof(*waking_key), 0, 0, 1);
> if (!s)
> return;
> append_delta_ts(s, KEY_WAKEUP, "to sched_waking", 0, waking_key->pid,
> @@ -1045,10 +1043,10 @@ int hrtimer_waking(struct waking_key_t *waking_key)
> struct latency_tracker_event *s;
>
> /* TODO: PREEMPT_RT */
> + hrtimer_key.p.type = KEY_HRTIMER;
> hrtimer_key.cpu = smp_processor_id();
> - hrtimer_key.type = KEY_HRTIMER;
> s = event_transition(&hrtimer_key, sizeof(hrtimer_key),
> - waking_key, sizeof(waking_key), 0, 0, 1);
> + waking_key, sizeof(*waking_key), 0, 0, 1);
> if (!s)
> return 0;
> append_delta_ts(s, KEY_WAKEUP, "to sched_waking", 0, waking_key->pid,
> @@ -1069,11 +1067,15 @@ void thread_waking(struct waking_key_t *waking_key)
> struct latency_tracker_event *s;
> u64 now = trace_clock_monotonic_wrapper();
>
> + switch_key.p.type = KEY_SWITCH;
> switch_key.pid = current->pid;
> - switch_key.type = KEY_SWITCH;
> + if (!current->pid)
> + switch_key.cpu = smp_processor_id();
> + else
> + switch_key.cpu = -1;
>
> s = event_transition(&switch_key, sizeof(switch_key), waking_key,
> - sizeof(waking_key), 0, 0, 1);
> + sizeof(*waking_key), 0, 0, 1);
> if (s) {
> /* switch_in after a waking */
> append_delta_ts(s, KEY_WAKEUP, "to sched_waking", now,
> @@ -1118,8 +1120,12 @@ LT_PROBE_DEFINE(sched_waking, struct task_struct *p, int success)
> * target process.
> */
>
> + waking_key.p.type = KEY_WAKEUP;
> waking_key.pid = p->pid;
> - waking_key.type = KEY_WAKEUP;
> + if (!p->pid)
> + waking_key.cpu = smp_processor_id();
> + else
> + waking_key.cpu = -1;
>
> /* In order of nesting */
> if (in_nmi()) {
> @@ -1158,14 +1164,22 @@ void sched_switch_in(struct task_struct *next)
> int nr_found = 0, ret;
> u64 now = trace_clock_monotonic_wrapper();
>
> + switch_key.p.type = KEY_SWITCH;
> switch_key.pid = next->pid;
> - switch_key.type = KEY_SWITCH;
> + if (!next->pid)
> + switch_key.cpu = smp_processor_id();
> + else
> + switch_key.cpu = -1;
>
> /* We can switch from a wakeup/waking or after being preempted */
>
> /* sched in */
> + waking_key.p.type = KEY_WAKEUP;
> waking_key.pid = next->pid;
> - waking_key.type = KEY_WAKEUP;
> + if (!next->pid)
> + waking_key.cpu = smp_processor_id();
> + else
> + waking_key.cpu = -1;
>
> /* switch after one or multiple waking */
> do {
> @@ -1226,8 +1240,12 @@ void sched_switch_out(struct task_struct *prev, struct task_struct *next)
> u64 now = trace_clock_monotonic_wrapper();
>
> /* switch out */
> + switch_key.p.type = KEY_SWITCH;
> switch_key.pid = prev->pid;
> - switch_key.type = KEY_SWITCH;
> + if (!prev->pid)
> + switch_key.cpu = smp_processor_id();
> + else
> + switch_key.cpu = -1;
> /* Handle duplicates */
> for (;;) {
> if (config.text_breakdown) {
> @@ -1385,8 +1403,12 @@ ssize_t write_work_done(struct file *filp, const char __user *ubuf,
> * The current process should be tracked otherwise we can't
> * link this event to an origin.
> */
> + switch_key.p.type = KEY_SWITCH;
> switch_key.pid = current->pid;
> - switch_key.type = KEY_SWITCH;
> + if (!current->pid)
> + switch_key.cpu = smp_processor_id();
> + else
> + switch_key.cpu = -1;
> s = latency_tracker_get_event(tracker, &switch_key,
> sizeof(switch_key));
> if (!s)
> @@ -1398,8 +1420,8 @@ ssize_t write_work_done(struct file *filp, const char __user *ubuf,
> sizeof(switch_key),
> OUT_WORK_DONE, now);
> } else {
> + work_begin_key.p.type = KEY_WORK_BEGIN;
> work_begin_key.cookie_size = r;
> - work_begin_key.type = KEY_WORK_BEGIN;
>
> s = latency_tracker_get_event(tracker, &work_begin_key,
> sizeof(work_begin_key));
> @@ -1469,11 +1491,15 @@ ssize_t write_work_begin(struct file *filp, const char __user *ubuf,
> * The current process should be tracked otherwise we can't link
> * this event to an origin.
> */
> + switch_key.p.type = KEY_SWITCH;
> switch_key.pid = current->pid;
> - switch_key.type = KEY_SWITCH;
> + if (!current->pid)
> + switch_key.cpu = smp_processor_id();
> + else
> + switch_key.cpu = -1;
>
> + work_begin_key.p.type = KEY_WORK_BEGIN;
> work_begin_key.cookie_size = r;
> - work_begin_key.type = KEY_WORK_BEGIN;
>
> /*
> * From now on, only a work_done event can complete this branch.
> diff --git a/latency_tracker.h b/latency_tracker.h
> index 0bccb8d..c276b1a 100644
> --- a/latency_tracker.h
> +++ b/latency_tracker.h
> @@ -32,6 +32,7 @@
> #define DEFAULT_THRESHOLD 1000000000
>
> struct latency_tracker_event_ctx;
> +struct latency_tracker_event;
>
> struct latency_tracker_key {
> size_t key_len;
> @@ -216,6 +217,12 @@ enum latency_tracker_event_in_ret latency_tracker_event_in(
> void *key, size_t key_len,
> unsigned int unique, void *priv);
>
> +enum latency_tracker_event_in_ret _latency_tracker_event_in_get(
> + struct latency_tracker *tracker,
> + void *key, size_t key_len,
> + unsigned int unique, u64 ts_override,
> + void *priv, struct latency_tracker_event **new_event);
> +
> enum latency_tracker_event_in_ret _latency_tracker_event_in(
> struct latency_tracker *tracker,
> void *key, size_t key_len, unsigned int unique,
> diff --git a/tracker.c b/tracker.c
> index 1c502e1..b3deba6 100644
> --- a/tracker.c
> +++ b/tracker.c
> @@ -550,11 +550,11 @@ void latency_tracker_timeout_cb(struct latency_tracker *tracker,
> tracker->cb(&ctx);
> }
>
> -enum latency_tracker_event_in_ret _latency_tracker_event_in(
> +enum latency_tracker_event_in_ret _latency_tracker_event_in_get(
> struct latency_tracker *tracker,
> void *key, size_t key_len,
> unsigned int unique, u64 ts_override,
> - void *priv)
> + void *priv, struct latency_tracker_event **new_event)
> {
> struct latency_tracker_event *s, *old_s;
> int ret;
> @@ -618,6 +618,10 @@ enum latency_tracker_event_in_ret _latency_tracker_event_in(
> &tracker->timeout_tail, &s->u.timeout_node);
> }
>
> + if (new_event) {
> + kref_get(&s->refcount);
> + *new_event = s;
> + }
> /*
> * If we specify the unique property, get rid of other duplicate keys
> * without calling the callback.
> @@ -653,6 +657,18 @@ end:
> #endif
> return ret;
> }
> +EXPORT_SYMBOL_GPL(_latency_tracker_event_in_get);
> +
> +enum latency_tracker_event_in_ret _latency_tracker_event_in(
> + struct latency_tracker *tracker,
> + void *key, size_t key_len,
> + unsigned int unique, u64 ts_override,
> + void *priv)
> +{
> + return _latency_tracker_event_in_get(tracker,
> + key, key_len, unique, ts_override,
> + priv, NULL);
> +}
> EXPORT_SYMBOL_GPL(_latency_tracker_event_in);
>
> enum latency_tracker_event_in_ret latency_tracker_event_in(
> --
> 2.1.4
>
More information about the lttng-dev
mailing list