// SPDX-License-Identifier: GPL-2.0/* * Copyright (C) 2023 Red Hat Inc, Daniel Bristot de Oliveira <bristot@kernel.org> */ #include <stdlib.h>#include <errno.h>#include "timerlat.h"#include <unistd.h> enum timelat_state { TIMERLAT_INIT = 0, TIMERLAT_WAITING_IRQ, TIMERLAT_WAITING_THREAD,}; /* Used to fill spaces in the output */static const char *spaces = " "; #define MAX_COMM 24 /* * Per-cpu data statistics and data. */struct timerlat_aa_data { /* Current CPU state */ int curr_state; /* timerlat IRQ latency */ unsigned long long tlat_irq_seqnum; unsigned long long tlat_irq_latency; unsigned long long tlat_irq_timstamp; /* timerlat Thread latency */ unsigned long long tlat_thread_seqnum; unsigned long long tlat_thread_latency; unsigned long long tlat_thread_timstamp; /* * Information about the thread running when the IRQ * arrived. * * This can be blocking or interference, depending on the * priority of the thread. Assuming timerlat is the highest * prio, it is blocking. If timerlat has a lower prio, it is * interference. * note: "unsigned long long" because they are fetch using tep_get_field_val(); */ unsigned long long run_thread_pid; char run_thread_comm[MAX_COMM]; unsigned long long thread_blocking_duration; unsigned long long max_exit_idle_latency; /* Information about the timerlat timer irq */ unsigned long long timer_irq_start_time; unsigned long long timer_irq_start_delay; unsigned long long timer_irq_duration; unsigned long long timer_exit_from_idle; /* * Information about the last IRQ before the timerlat irq * arrived. * * If now - timestamp is <= latency, it might have influenced * in the timerlat irq latency. Otherwise, ignore it. */ unsigned long long prev_irq_duration; unsigned long long prev_irq_timstamp; /* * Interference sum. */ unsigned long long thread_nmi_sum; unsigned long long thread_irq_sum; unsigned long long thread_softirq_sum; unsigned long long thread_thread_sum; /* * Interference task information. */ struct trace_seq *prev_irqs_seq; struct trace_seq *nmi_seq; struct trace_seq *irqs_seq; struct trace_seq *softirqs_seq; struct trace_seq *threads_seq; struct trace_seq *stack_seq; /* * Current thread. */ char current_comm[MAX_COMM]; unsigned long long current_pid; /* * Is the system running a kworker? */ unsigned long long kworker; unsigned long long kworker_func;}; /* * The analysis context and system wide view */struct timerlat_aa_context { int dump_tasks; enum stack_format stack_format; /* per CPU data */ struct timerlat_aa_data *taa_data; /* * required to translate function names and register * events. */ struct osnoise_tool *tool;}; /* * The data is stored as a local variable, but accessed via a helper function. * * It could be stored inside the trace context. But every access would * require container_of() + a series of pointers. Do we need it? Not sure. * * For now keep it simple. If needed, store it in the tool, add the *context * as a parameter in timerlat_aa_get_ctx() and do the magic there. */static struct timerlat_aa_context *__timerlat_aa_ctx; static struct timerlat_aa_context *timerlat_aa_get_ctx(void){ return __timerlat_aa_ctx;} /* * timerlat_aa_get_data - Get the per-cpu data from the timerlat context */static struct timerlat_aa_data*timerlat_aa_get_data(struct timerlat_aa_context *taa_ctx, int cpu){ return &taa_ctx->taa_data[cpu];} /* * timerlat_aa_irq_latency - Handles timerlat IRQ event */static int timerlat_aa_irq_latency(struct timerlat_aa_data *taa_data, struct trace_seq *s, struct tep_record *record, struct tep_event *event){ /* * For interference, we start now looking for things that can delay * the thread. */ taa_data->curr_state = TIMERLAT_WAITING_THREAD; taa_data->tlat_irq_timstamp = record->ts; /* * Zero values. */ taa_data->thread_nmi_sum = 0; taa_data->thread_irq_sum = 0; taa_data->thread_softirq_sum = 0; taa_data->thread_thread_sum = 0; taa_data->thread_blocking_duration = 0; taa_data->timer_irq_start_time = 0; taa_data->timer_irq_duration = 0; taa_data->timer_exit_from_idle = 0; /* * Zero interference tasks. */ trace_seq_reset(taa_data->nmi_seq); trace_seq_reset(taa_data->irqs_seq); trace_seq_reset(taa_data->softirqs_seq); trace_seq_reset(taa_data->threads_seq); /* IRQ latency values */ tep_get_field_val(s, event, "timer_latency", record, &taa_data->tlat_irq_latency, 1); tep_get_field_val(s, event, "seqnum", record, &taa_data->tlat_irq_seqnum, 1); /* The thread that can cause blocking */ tep_get_common_field_val(s, event, "common_pid", record, &taa_data->run_thread_pid, 1); /* * Get exit from idle case. * * If it is not idle thread: */ if (taa_data->run_thread_pid) return 0; /* * if the latency is shorter than the known exit from idle: */ if (taa_data->tlat_irq_latency < taa_data->max_exit_idle_latency) return 0; /* * To be safe, ignore the cases in which an IRQ/NMI could have * interfered with the timerlat IRQ. */ if (taa_data->tlat_irq_timstamp - taa_data->tlat_irq_latency < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) return 0; taa_data->max_exit_idle_latency = taa_data->tlat_irq_latency; return 0;} /* * timerlat_aa_thread_latency - Handles timerlat thread event */static int timerlat_aa_thread_latency(struct timerlat_aa_data *taa_data, struct trace_seq *s, struct tep_record *record, struct tep_event *event){ /* * For interference, we start now looking for things that can delay * the IRQ of the next cycle. */ taa_data->curr_state = TIMERLAT_WAITING_IRQ; taa_data->tlat_thread_timstamp = record->ts; /* Thread latency values */ tep_get_field_val(s, event, "timer_latency", record, &taa_data->tlat_thread_latency, 1); tep_get_field_val(s, event, "seqnum", record, &taa_data->tlat_thread_seqnum, 1); return 0;} /* * timerlat_aa_handler - Handle timerlat events * * This function is called to handle timerlat events recording statistics. * * Returns 0 on success, -1 otherwise. */static int timerlat_aa_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context){ struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long thread; if (!taa_data) return -1; tep_get_field_val(s, event, "context", record, &thread, 1); if (!thread) return timerlat_aa_irq_latency(taa_data, s, record, event); else return timerlat_aa_thread_latency(taa_data, s, record, event);} /* * timerlat_aa_nmi_handler - Handles NMI noise * * It is used to collect information about interferences from NMI. It is * hooked to the osnoise:nmi_noise event. */static int timerlat_aa_nmi_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context){ struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long duration; unsigned long long start; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) { taa_data->prev_irq_duration = duration; taa_data->prev_irq_timstamp = start; trace_seq_reset(taa_data->prev_irqs_seq); trace_seq_printf(taa_data->prev_irqs_seq, " %24s %.*s %9.2f us\n", "nmi", 24, spaces, ns_to_usf(duration)); return 0; } taa_data->thread_nmi_sum += duration; trace_seq_printf(taa_data->nmi_seq, " %24s %.*s %9.2f us\n", "nmi", 24, spaces, ns_to_usf(duration)); return 0;} /* * timerlat_aa_irq_handler - Handles IRQ noise * * It is used to collect information about interferences from IRQ. It is * hooked to the osnoise:irq_noise event. * * It is a little bit more complex than the other because it measures: * - The IRQs that can delay the timer IRQ before it happened. * - The Timerlat IRQ handler * - The IRQs that happened between the timerlat IRQ and the timerlat thread * (IRQ interference). */static int timerlat_aa_irq_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context){ struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long expected_start; unsigned long long duration; unsigned long long vector; unsigned long long start; char *desc; int val; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); tep_get_field_val(s, event, "vector", record, &vector, 1); desc = tep_get_field_raw(s, event, "desc", record, &val, 1); /* * Before the timerlat IRQ. */ if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) { taa_data->prev_irq_duration = duration; taa_data->prev_irq_timstamp = start; trace_seq_reset(taa_data->prev_irqs_seq); trace_seq_printf(taa_data->prev_irqs_seq, " %24s:%-3llu %.*s %9.2f us\n", desc, vector, 15, spaces, ns_to_usf(duration)); return 0; } /* * The timerlat IRQ: taa_data->timer_irq_start_time is zeroed at * the timerlat irq handler. */ if (!taa_data->timer_irq_start_time) { expected_start = taa_data->tlat_irq_timstamp - taa_data->tlat_irq_latency; taa_data->timer_irq_start_time = start; taa_data->timer_irq_duration = duration; /* * We are dealing with two different clock sources: the * external clock source that timerlat uses as a reference * and the clock used by the tracer. There are also two * moments: the time reading the clock and the timer in * which the event is placed in the buffer (the trace * event timestamp). If the processor is slow or there * is some hardware noise, the difference between the * timestamp and the external clock read can be longer * than the IRQ handler delay, resulting in a negative * time. If so, set IRQ start delay as 0. In the end, * it is less relevant than the noise. */ if (expected_start < taa_data->timer_irq_start_time) taa_data->timer_irq_start_delay = taa_data->timer_irq_start_time - expected_start; else taa_data->timer_irq_start_delay = 0; /* * not exit from idle. */ if (taa_data->run_thread_pid) return 0; if (expected_start > taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) taa_data->timer_exit_from_idle = taa_data->timer_irq_start_delay; return 0; } /* * IRQ interference. */ taa_data->thread_irq_sum += duration; trace_seq_printf(taa_data->irqs_seq, " %24s:%-3llu %.*s %9.2f us\n", desc, vector, 24, spaces, ns_to_usf(duration)); return 0;} static char *softirq_name[] = { "HI", "TIMER", "NET_TX", "NET_RX", "BLOCK", "IRQ_POLL", "TASKLET", "SCHED", "HRTIMER", "RCU" }; /* * timerlat_aa_softirq_handler - Handles Softirq noise * * It is used to collect information about interferences from Softirq. It is * hooked to the osnoise:softirq_noise event. * * It is only printed in the non-rt kernel, as softirqs become thread on RT. */static int timerlat_aa_softirq_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context){ struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long duration; unsigned long long vector; unsigned long long start; if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) return 0; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); tep_get_field_val(s, event, "vector", record, &vector, 1); taa_data->thread_softirq_sum += duration; trace_seq_printf(taa_data->softirqs_seq, " %24s:%-3llu %.*s %9.2f us\n", vector < ARRAY_SIZE(softirq_name) ? softirq_name[vector] : "UNKNOWN", vector, 24, spaces, ns_to_usf(duration)); return 0;} /* * timerlat_aa_softirq_handler - Handles thread noise * * It is used to collect information about interferences from threads. It is * hooked to the osnoise:thread_noise event. * * Note: if you see thread noise, your timerlat thread was not the highest prio one. */static int timerlat_aa_thread_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context){ struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long duration; unsigned long long start; unsigned long long pid; const char *comm; int val; if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) return 0; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); tep_get_common_field_val(s, event, "common_pid", record, &pid, 1); comm = tep_get_field_raw(s, event, "comm", record, &val, 1); if (pid == taa_data->run_thread_pid && !taa_data->thread_blocking_duration) { taa_data->thread_blocking_duration = duration; if (comm) strncpy(taa_data->run_thread_comm, comm, MAX_COMM); else sprintf(taa_data->run_thread_comm, "<...>"); } else { taa_data->thread_thread_sum += duration; trace_seq_printf(taa_data->threads_seq, " %24s:%-12llu %.*s %9.2f us\n", comm, pid, 15, spaces, ns_to_usf(duration)); } return 0;} /* * timerlat_aa_stack_handler - Handles timerlat IRQ stack trace * * Saves and parse the stack trace generated by the timerlat IRQ. */static int timerlat_aa_stack_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context){ struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); enum stack_format stack_format = taa_ctx->stack_format; unsigned long *caller; const char *function; int val; unsigned long long i; trace_seq_reset(taa_data->stack_seq); trace_seq_printf(taa_data->stack_seq, " Blocking thread stack trace\n"); caller = tep_get_field_raw(s, event, "caller", record, &val, 1); if (caller) { unsigned long long size; unsigned long long max_entries; if (tep_get_field_val(s, event, "size", record, &size, 1) == 0) max_entries = size < 64 ? size : 64;Lines 1–500 of 1075. Load more
// SPDX-License-Identifier: GPL-2.0 /* * Copyright (C) 2023 Red Hat Inc, Daniel Bristot de Oliveira <bristot@kernel.org> */ #include <stdlib.h> #include <errno.h> #include "timerlat.h" #include <unistd.h> enum timelat_state { TIMERLAT_INIT = 0, TIMERLAT_WAITING_IRQ, TIMERLAT_WAITING_THREAD, }; /* Used to fill spaces in the output */ static const char *spaces = " "; #define MAX_COMM 24 /* * Per-cpu data statistics and data. */ struct timerlat_aa_data { /* Current CPU state */ int curr_state; /* timerlat IRQ latency */ unsigned long long tlat_irq_seqnum; unsigned long long tlat_irq_latency; unsigned long long tlat_irq_timstamp; /* timerlat Thread latency */ unsigned long long tlat_thread_seqnum; unsigned long long tlat_thread_latency; unsigned long long tlat_thread_timstamp; /* * Information about the thread running when the IRQ * arrived. * * This can be blocking or interference, depending on the * priority of the thread. Assuming timerlat is the highest * prio, it is blocking. If timerlat has a lower prio, it is * interference. * note: "unsigned long long" because they are fetch using tep_get_field_val(); */ unsigned long long run_thread_pid; char run_thread_comm[MAX_COMM]; unsigned long long thread_blocking_duration; unsigned long long max_exit_idle_latency; /* Information about the timerlat timer irq */ unsigned long long timer_irq_start_time; unsigned long long timer_irq_start_delay; unsigned long long timer_irq_duration; unsigned long long timer_exit_from_idle; /* * Information about the last IRQ before the timerlat irq * arrived. * * If now - timestamp is <= latency, it might have influenced * in the timerlat irq latency. Otherwise, ignore it. */ unsigned long long prev_irq_duration; unsigned long long prev_irq_timstamp; /* * Interference sum. */ unsigned long long thread_nmi_sum; unsigned long long thread_irq_sum; unsigned long long thread_softirq_sum; unsigned long long thread_thread_sum; /* * Interference task information. */ struct trace_seq *prev_irqs_seq; struct trace_seq *nmi_seq; struct trace_seq *irqs_seq; struct trace_seq *softirqs_seq; struct trace_seq *threads_seq; struct trace_seq *stack_seq; /* * Current thread. */ char current_comm[MAX_COMM]; unsigned long long current_pid; /* * Is the system running a kworker? */ unsigned long long kworker; unsigned long long kworker_func; }; /* * The analysis context and system wide view */ struct timerlat_aa_context { int dump_tasks; enum stack_format stack_format; /* per CPU data */ struct timerlat_aa_data *taa_data; /* * required to translate function names and register * events. */ struct osnoise_tool *tool; }; /* * The data is stored as a local variable, but accessed via a helper function. * * It could be stored inside the trace context. But every access would * require container_of() + a series of pointers. Do we need it? Not sure. * * For now keep it simple. If needed, store it in the tool, add the *context * as a parameter in timerlat_aa_get_ctx() and do the magic there. */ static struct timerlat_aa_context *__timerlat_aa_ctx; static struct timerlat_aa_context *timerlat_aa_get_ctx(void) { return __timerlat_aa_ctx; } /* * timerlat_aa_get_data - Get the per-cpu data from the timerlat context */ static struct timerlat_aa_data *timerlat_aa_get_data(struct timerlat_aa_context *taa_ctx, int cpu) { return &taa_ctx->taa_data[cpu]; } /* * timerlat_aa_irq_latency - Handles timerlat IRQ event */ static int timerlat_aa_irq_latency(struct timerlat_aa_data *taa_data, struct trace_seq *s, struct tep_record *record, struct tep_event *event) { /* * For interference, we start now looking for things that can delay * the thread. */ taa_data->curr_state = TIMERLAT_WAITING_THREAD; taa_data->tlat_irq_timstamp = record->ts; /* * Zero values. */ taa_data->thread_nmi_sum = 0; taa_data->thread_irq_sum = 0; taa_data->thread_softirq_sum = 0; taa_data->thread_thread_sum = 0; taa_data->thread_blocking_duration = 0; taa_data->timer_irq_start_time = 0; taa_data->timer_irq_duration = 0; taa_data->timer_exit_from_idle = 0; /* * Zero interference tasks. */ trace_seq_reset(taa_data->nmi_seq); trace_seq_reset(taa_data->irqs_seq); trace_seq_reset(taa_data->softirqs_seq); trace_seq_reset(taa_data->threads_seq); /* IRQ latency values */ tep_get_field_val(s, event, "timer_latency", record, &taa_data->tlat_irq_latency, 1); tep_get_field_val(s, event, "seqnum", record, &taa_data->tlat_irq_seqnum, 1); /* The thread that can cause blocking */ tep_get_common_field_val(s, event, "common_pid", record, &taa_data->run_thread_pid, 1); /* * Get exit from idle case. * * If it is not idle thread: */ if (taa_data->run_thread_pid) return 0; /* * if the latency is shorter than the known exit from idle: */ if (taa_data->tlat_irq_latency < taa_data->max_exit_idle_latency) return 0; /* * To be safe, ignore the cases in which an IRQ/NMI could have * interfered with the timerlat IRQ. */ if (taa_data->tlat_irq_timstamp - taa_data->tlat_irq_latency < taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) return 0; taa_data->max_exit_idle_latency = taa_data->tlat_irq_latency; return 0; } /* * timerlat_aa_thread_latency - Handles timerlat thread event */ static int timerlat_aa_thread_latency(struct timerlat_aa_data *taa_data, struct trace_seq *s, struct tep_record *record, struct tep_event *event) { /* * For interference, we start now looking for things that can delay * the IRQ of the next cycle. */ taa_data->curr_state = TIMERLAT_WAITING_IRQ; taa_data->tlat_thread_timstamp = record->ts; /* Thread latency values */ tep_get_field_val(s, event, "timer_latency", record, &taa_data->tlat_thread_latency, 1); tep_get_field_val(s, event, "seqnum", record, &taa_data->tlat_thread_seqnum, 1); return 0; } /* * timerlat_aa_handler - Handle timerlat events * * This function is called to handle timerlat events recording statistics. * * Returns 0 on success, -1 otherwise. */ static int timerlat_aa_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context) { struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long thread; if (!taa_data) return -1; tep_get_field_val(s, event, "context", record, &thread, 1); if (!thread) return timerlat_aa_irq_latency(taa_data, s, record, event); else return timerlat_aa_thread_latency(taa_data, s, record, event); } /* * timerlat_aa_nmi_handler - Handles NMI noise * * It is used to collect information about interferences from NMI. It is * hooked to the osnoise:nmi_noise event. */ static int timerlat_aa_nmi_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context) { struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long duration; unsigned long long start; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) { taa_data->prev_irq_duration = duration; taa_data->prev_irq_timstamp = start; trace_seq_reset(taa_data->prev_irqs_seq); trace_seq_printf(taa_data->prev_irqs_seq, " %24s %.*s %9.2f us\n", "nmi", 24, spaces, ns_to_usf(duration)); return 0; } taa_data->thread_nmi_sum += duration; trace_seq_printf(taa_data->nmi_seq, " %24s %.*s %9.2f us\n", "nmi", 24, spaces, ns_to_usf(duration)); return 0; } /* * timerlat_aa_irq_handler - Handles IRQ noise * * It is used to collect information about interferences from IRQ. It is * hooked to the osnoise:irq_noise event. * * It is a little bit more complex than the other because it measures: * - The IRQs that can delay the timer IRQ before it happened. * - The Timerlat IRQ handler * - The IRQs that happened between the timerlat IRQ and the timerlat thread * (IRQ interference). */ static int timerlat_aa_irq_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context) { struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long expected_start; unsigned long long duration; unsigned long long vector; unsigned long long start; char *desc; int val; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); tep_get_field_val(s, event, "vector", record, &vector, 1); desc = tep_get_field_raw(s, event, "desc", record, &val, 1); /* * Before the timerlat IRQ. */ if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) { taa_data->prev_irq_duration = duration; taa_data->prev_irq_timstamp = start; trace_seq_reset(taa_data->prev_irqs_seq); trace_seq_printf(taa_data->prev_irqs_seq, " %24s:%-3llu %.*s %9.2f us\n", desc, vector, 15, spaces, ns_to_usf(duration)); return 0; } /* * The timerlat IRQ: taa_data->timer_irq_start_time is zeroed at * the timerlat irq handler. */ if (!taa_data->timer_irq_start_time) { expected_start = taa_data->tlat_irq_timstamp - taa_data->tlat_irq_latency; taa_data->timer_irq_start_time = start; taa_data->timer_irq_duration = duration; /* * We are dealing with two different clock sources: the * external clock source that timerlat uses as a reference * and the clock used by the tracer. There are also two * moments: the time reading the clock and the timer in * which the event is placed in the buffer (the trace * event timestamp). If the processor is slow or there * is some hardware noise, the difference between the * timestamp and the external clock read can be longer * than the IRQ handler delay, resulting in a negative * time. If so, set IRQ start delay as 0. In the end, * it is less relevant than the noise. */ if (expected_start < taa_data->timer_irq_start_time) taa_data->timer_irq_start_delay = taa_data->timer_irq_start_time - expected_start; else taa_data->timer_irq_start_delay = 0; /* * not exit from idle. */ if (taa_data->run_thread_pid) return 0; if (expected_start > taa_data->prev_irq_timstamp + taa_data->prev_irq_duration) taa_data->timer_exit_from_idle = taa_data->timer_irq_start_delay; return 0; } /* * IRQ interference. */ taa_data->thread_irq_sum += duration; trace_seq_printf(taa_data->irqs_seq, " %24s:%-3llu %.*s %9.2f us\n", desc, vector, 24, spaces, ns_to_usf(duration)); return 0; } static char *softirq_name[] = { "HI", "TIMER", "NET_TX", "NET_RX", "BLOCK", "IRQ_POLL", "TASKLET", "SCHED", "HRTIMER", "RCU" }; /* * timerlat_aa_softirq_handler - Handles Softirq noise * * It is used to collect information about interferences from Softirq. It is * hooked to the osnoise:softirq_noise event. * * It is only printed in the non-rt kernel, as softirqs become thread on RT. */ static int timerlat_aa_softirq_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context) { struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long duration; unsigned long long vector; unsigned long long start; if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) return 0; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); tep_get_field_val(s, event, "vector", record, &vector, 1); taa_data->thread_softirq_sum += duration; trace_seq_printf(taa_data->softirqs_seq, " %24s:%-3llu %.*s %9.2f us\n", vector < ARRAY_SIZE(softirq_name) ? softirq_name[vector] : "UNKNOWN", vector, 24, spaces, ns_to_usf(duration)); return 0; } /* * timerlat_aa_softirq_handler - Handles thread noise * * It is used to collect information about interferences from threads. It is * hooked to the osnoise:thread_noise event. * * Note: if you see thread noise, your timerlat thread was not the highest prio one. */ static int timerlat_aa_thread_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context) { struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); unsigned long long duration; unsigned long long start; unsigned long long pid; const char *comm; int val; if (taa_data->curr_state == TIMERLAT_WAITING_IRQ) return 0; tep_get_field_val(s, event, "duration", record, &duration, 1); tep_get_field_val(s, event, "start", record, &start, 1); tep_get_common_field_val(s, event, "common_pid", record, &pid, 1); comm = tep_get_field_raw(s, event, "comm", record, &val, 1); if (pid == taa_data->run_thread_pid && !taa_data->thread_blocking_duration) { taa_data->thread_blocking_duration = duration; if (comm) strncpy(taa_data->run_thread_comm, comm, MAX_COMM); else sprintf(taa_data->run_thread_comm, "<...>"); } else { taa_data->thread_thread_sum += duration; trace_seq_printf(taa_data->threads_seq, " %24s:%-12llu %.*s %9.2f us\n", comm, pid, 15, spaces, ns_to_usf(duration)); } return 0; } /* * timerlat_aa_stack_handler - Handles timerlat IRQ stack trace * * Saves and parse the stack trace generated by the timerlat IRQ. */ static int timerlat_aa_stack_handler(struct trace_seq *s, struct tep_record *record, struct tep_event *event, void *context) { struct timerlat_aa_context *taa_ctx = timerlat_aa_get_ctx(); struct timerlat_aa_data *taa_data = timerlat_aa_get_data(taa_ctx, record->cpu); enum stack_format stack_format = taa_ctx->stack_format; unsigned long *caller; const char *function; int val; unsigned long long i; trace_seq_reset(taa_data->stack_seq); trace_seq_printf(taa_data->stack_seq, " Blocking thread stack trace\n"); caller = tep_get_field_raw(s, event, "caller", record, &val, 1); if (caller) { unsigned long long size; unsigned long long max_entries; if (tep_get_field_val(s, event, "size", record, &size, 1) == 0) max_entries = size < 64 ? size : 64;