This commit refactors logging of dbg_snapshot_irq as following.
1. Remove dbg_snapshot_irq_exit logging (actually it is merged to
dbg_snapshot_irq like measuring latency)
2. Adding logging actually called function in smp_call_function
to dbg_snapshot_irq. its flag is DSS_FLAG_SMP_CALL_FN.
3. Replace logging from irqaction structure to irq_desc structure.
irq_desc includes irqaction and it has more informations.
And we are too hard to see it in ramdump.
Change-Id: I351593a454fd39eb87a965093349d69b6182e7ce
Signed-off-by: Hosung Kim <hosung0.kim@samsung.com>
#include <linux/sched/mm.h>
#include <linux/sched/hotplug.h>
#include <linux/sched/task_stack.h>
+#include <linux/sched/clock.h>
#include <linux/interrupt.h>
#include <linux/cache.h>
#include <linux/profile.h>
{
unsigned int cpu = smp_processor_id();
struct pt_regs *old_regs = set_irq_regs(regs);
+ unsigned long long start_time;
if ((unsigned)ipinr < NR_IPI) {
trace_ipi_entry_rcuidle(ipi_types[ipinr]);
__inc_irq_stat(cpu, ipi_irqs[ipinr]);
}
+ dbg_snapshot_irq_var(start_time);
+ dbg_snapshot_irq(ipinr, handle_IPI, NULL, 0, DSS_FLAG_IN);
+
switch (ipinr) {
case IPI_RESCHEDULE:
- dbg_snapshot_irq(ipinr, scheduler_ipi, NULL, DSS_FLAG_IN);
scheduler_ipi();
break;
case IPI_CPU_STOP:
irq_enter();
- dbg_snapshot_irq(ipinr, ipi_cpu_stop, NULL, DSS_FLAG_IN);
ipi_cpu_stop(cpu, regs);
irq_exit();
break;
case IPI_CPU_CRASH_STOP:
- dbg_snapshot_irq(ipinr, ipi_cpu_crash_stop, NULL, DSS_FLAG_IN);
if (IS_ENABLED(CONFIG_KEXEC_CORE)) {
irq_enter();
ipi_cpu_crash_stop(cpu, regs);
#ifdef CONFIG_GENERIC_CLOCKEVENTS_BROADCAST
case IPI_TIMER:
irq_enter();
- dbg_snapshot_irq(ipinr, tick_receive_broadcast, NULL, DSS_FLAG_IN);
tick_receive_broadcast();
irq_exit();
break;
#ifdef CONFIG_IRQ_WORK
case IPI_IRQ_WORK:
irq_enter();
- dbg_snapshot_irq(ipinr, irq_work_run, NULL, DSS_FLAG_IN);
irq_work_run();
irq_exit();
break;
#ifdef CONFIG_ARM64_ACPI_PARKING_PROTOCOL
case IPI_WAKEUP:
- dbg_snapshot_irq(ipinr, handle_IPI, NULL, DSS_FLAG_IN);
WARN_ONCE(!acpi_parking_protocol_valid(cpu),
"CPU%u: Wake-up IPI outside the ACPI parking protocol\n",
cpu);
#endif
default:
- dbg_snapshot_irq(ipinr, handle_IPI, NULL, DSS_FLAG_IN);
pr_crit("CPU%u: Unknown IPI message 0x%x\n", cpu, ipinr);
break;
}
if ((unsigned)ipinr < NR_IPI)
trace_ipi_exit_rcuidle(ipi_types[ipinr]);
- dbg_snapshot_irq(ipinr, handle_IPI, NULL, DSS_FLAG_OUT);
+ dbg_snapshot_irq(ipinr, handle_IPI, NULL, start_time, DSS_FLAG_OUT);
set_irq_regs(old_regs);
}
extern void dbg_snapshot_work(void *worker, void *v_task, void *fn, int en);
extern void dbg_snapshot_cpuidle(char *modes, unsigned state, int diff, int en);
extern void dbg_snapshot_suspend(char *log, void *fn, void *dev, int state, int en);
-extern void dbg_snapshot_irq(int irq, void *fn, void *val, int en);
+extern void dbg_snapshot_irq(int irq, void *fn, void *val, unsigned long long time, int en);
extern void dbg_snapshot_print_notifier_call(void **nl, unsigned long func, int en);
extern int dbg_snapshot_try_enable(const char *name, unsigned long long duration);
extern int dbg_snapshot_set_enable(const char *name, int en);
extern void dbg_snapshot_dump_sfr(void);
extern int dbg_snapshot_hook_pmsg(char *buffer, size_t count);
extern void dbg_snapshot_save_log(int cpu, unsigned long where);
-
+#define dbg_snapshot_irq_var(v) do { v = cpu_clock(raw_smp_processor_id()); \
+ } while(0)
/* option */
#ifdef CONFIG_DEBUG_SNAPSHOT_ACPM
extern void dbg_snapshot_acpm(unsigned long long timestamp, const char *log, unsigned int data);
#define dbg_snapshot_dm(a,b,c,d,e) do { } while(0)
#endif
-#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT
-extern void dbg_snapshot_irq_exit(unsigned int irq, unsigned long long start_time);
-#define dbg_snapshot_irq_exit_var(v) do { v = cpu_clock(raw_smp_processor_id()); \
- } while(0)
-#else
-#define dbg_snapshot_irq_exit(a,b) do { } while(0)
-#define dbg_snapshot_irq_exit_var(v) do { v = 0; } while(0)
-#endif
-
#ifdef CONFIG_DEBUG_SNAPSHOT_CRASH_KEY
void dbg_snapshot_check_crash_key(unsigned int code, int value);
#else
#define dbg_snapshot_suspend(a,b,c,d,e) do { } while(0)
#define dbg_snapshot_regulator(a,b,c,d,e,f) do { } while(0)
#define dbg_snapshot_thermal(a,b,c,d) do { } while(0)
-#define dbg_snapshot_irq(a,b,c,d) do { } while(0)
-#define dbg_snapshot_irq_exit(a,b) do { } while(0)
+#define dbg_snapshot_irq(a,b,c,d,e) do { } while(0)
#define dbg_snapshot_irqs_disabled(a) do { } while(0)
#define dbg_snapshot_spinlock(a,b) do { } while(0)
#define dbg_snapshot_clk(a,b,c,d) do { } while(0)
#define dbg_snapshot_pmu(a,b,c) do { } while(0)
#define dbg_snapshot_freq(a,b,c,d) do { } while(0)
-#define dbg_snapshot_irq_exit_var(v) do { v = 0; } while(0)
+#define dbg_snapshot_irq_var(v) do { v = 0; } while(0)
#define dbg_snapshot_reg(a,b,c,d) do { } while(0)
#define dbg_snapshot_hrtimer(a,b,c,d) do { } while(0)
#define dbg_snapshot_i2c(a,b,c,d) do { } while(0)
DSS_FLAG_SOFTIRQ = 10000,
DSS_FLAG_SOFTIRQ_HI_TASKLET = 10100,
DSS_FLAG_SOFTIRQ_TASKLET = 10200,
- DSS_FLAG_CALL_TIMER_FN = 20000
+ DSS_FLAG_CALL_TIMER_FN = 20000,
+ DSS_FLAG_SMP_CALL_FN = 30000,
};
enum dsslog_freq_flag {
irqreturn_t res;
trace_irq_handler_entry(irq, action);
- dbg_snapshot_irq(irq, (void *)action->handler, action, DSS_FLAG_IN);
res = action->handler(irq, action->dev_id);
- dbg_snapshot_irq(irq, (void *)action->handler, action, DSS_FLAG_OUT);
trace_irq_handler_exit(irq, action, res);
if (WARN_ONCE(!irqs_disabled(),"irq %u handler %pF enabled interrupts\n",
int generic_handle_irq(unsigned int irq)
{
struct irq_desc *desc = irq_to_desc(irq);
+ struct irqaction *action;
+ unsigned long long start_time;
if (!desc)
return -EINVAL;
+
+ action = desc->action;
+ dbg_snapshot_irq_var(start_time);
+ dbg_snapshot_irq(irq, (void *)action->handler, (void *)desc,
+ 0, DSS_FLAG_IN);
+
generic_handle_irq_desc(desc);
+
+ dbg_snapshot_irq(irq, (void *)action->handler, (void *)desc,
+ start_time, DSS_FLAG_OUT);
+
return 0;
}
EXPORT_SYMBOL_GPL(generic_handle_irq);
bool lookup, struct pt_regs *regs)
{
struct pt_regs *old_regs = set_irq_regs(regs);
- unsigned long long start_time;
unsigned int irq = hwirq;
int ret = 0;
- dbg_snapshot_irq_exit_var(start_time);
irq_enter();
#ifdef CONFIG_IRQ_DOMAIN
}
irq_exit();
- dbg_snapshot_irq_exit(irq, start_time);
set_irq_regs(old_regs);
return ret;
}
void *info = csd->info;
/* This should be called by handle_IPI in smp.c */
- if (warn_cpu_offline)
- dbg_snapshot_irq(1, func, NULL, DSS_FLAG_IN);
+ dbg_snapshot_irq(DSS_FLAG_SMP_CALL_FN, func, NULL, 0, DSS_FLAG_IN);
/* Do we wait until *after* callback? */
if (csd->flags & CSD_FLAG_SYNCHRONOUS) {
csd_unlock(csd);
func(info);
}
+
+ dbg_snapshot_irq(DSS_FLAG_SMP_CALL_FN, func, NULL, 0, DSS_FLAG_OUT);
}
/*
#include <linux/tick.h>
#include <linux/irq.h>
#include <linux/debug-snapshot.h>
+#include <linux/sched/clock.h>
#define CREATE_TRACE_POINTS
#include <trace/events/irq.h>
{
unsigned long end = jiffies + MAX_SOFTIRQ_TIME;
unsigned long old_flags = current->flags;
+ unsigned long long start_time;
int max_restart = MAX_SOFTIRQ_RESTART;
struct softirq_action *h;
bool in_hardirq;
kstat_incr_softirqs_this_cpu(vec_nr);
trace_softirq_entry(vec_nr);
- dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, NULL, DSS_FLAG_IN);
+ dbg_snapshot_irq_var(start_time);
+ dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, NULL, 0, DSS_FLAG_IN);
h->action(h);
- dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, NULL, DSS_FLAG_OUT);
+ dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, NULL, start_time, DSS_FLAG_OUT);
trace_softirq_exit(vec_nr);
if (unlikely(prev_count != preempt_count())) {
pr_err("huh, entered softirq %u %s %p with preempt_count %08x, exited with %08x?\n",
static __latent_entropy void tasklet_action(struct softirq_action *a)
{
struct tasklet_struct *list;
+ unsigned long long start_time;
local_irq_disable();
list = __this_cpu_read(tasklet_vec.head);
if (!test_and_clear_bit(TASKLET_STATE_SCHED,
&t->state))
BUG();
+ dbg_snapshot_irq_var(start_time);
dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_TASKLET,
- t->func, NULL, DSS_FLAG_IN);
+ t->func, NULL, 0, DSS_FLAG_IN);
t->func(t->data);
dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_TASKLET,
- t->func, NULL, DSS_FLAG_OUT);
+ t->func, NULL, start_time, DSS_FLAG_OUT);
tasklet_unlock(t);
continue;
}
static __latent_entropy void tasklet_hi_action(struct softirq_action *a)
{
struct tasklet_struct *list;
+ unsigned long long start_time;
local_irq_disable();
list = __this_cpu_read(tasklet_hi_vec.head);
if (!test_and_clear_bit(TASKLET_STATE_SCHED,
&t->state))
BUG();
+ dbg_snapshot_irq_var(start_time);
dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_HI_TASKLET,
- t->func, NULL, DSS_FLAG_IN);
+ t->func, NULL, 0, DSS_FLAG_IN);
t->func(t->data);
dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_HI_TASKLET,
- t->func, NULL, DSS_FLAG_OUT);
+ t->func, NULL, start_time, DSS_FLAG_OUT);
tasklet_unlock(t);
continue;
}
#include <linux/sched/sysctl.h>
#include <linux/sched/nohz.h>
#include <linux/sched/debug.h>
+#include <linux/sched/clock.h>
#include <linux/slab.h>
#include <linux/compat.h>
#include <linux/debug-snapshot.h>
unsigned long data)
{
int count = preempt_count();
+ unsigned long long start_time;
#ifdef CONFIG_LOCKDEP
/*
*/
lock_map_acquire(&lockdep_map);
+ dbg_snapshot_irq_var(start_time);
trace_timer_expire_entry(timer);
- dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, NULL, DSS_FLAG_IN);
+ dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, NULL, 0, DSS_FLAG_IN);
fn(data);
- dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, NULL, DSS_FLAG_OUT);
+ dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, NULL, start_time, DSS_FLAG_OUT);
trace_timer_expire_exit(timer);
lock_map_release(&lockdep_map);
range 1 4
default 4
-config DEBUG_SNAPSHOT_IRQ_EXIT
- bool "Enable debugging of interrupt exit event by kevent"
- depends on DEBUG_SNAPSHOT && !DEBUG_SNAPSHOT_MINIMIZED_MODE
- default y
-
-config DEBUG_SNAPSHOT_IRQ_EXIT_THRESHOLD
- int "threshold of detection(microsecond)"
- depends on DEBUG_SNAPSHOT_IRQ_EXIT && !DEBUG_SNAPSHOT_MINIMIZED_MODE
- range 0 1000000
- default 0
-
config DEBUG_SNAPSHOT_IRQ_DISABLED
bool "Enable debugging of interrupt disable event by kevent(EXPERIMENTAL)"
depends on DEBUG_SNAPSHOT && !DEBUG_SNAPSHOT_MINIMIZED_MODE
#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_DISABLED
atomic_t irqs_disabled_log_idx[DSS_NR_CPUS];
#endif
-#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT
- atomic_t irq_exit_log_idx[DSS_NR_CPUS];
-#endif
#ifdef CONFIG_DEBUG_SNAPSHOT_REG
atomic_t reg_log_idx[DSS_NR_CPUS];
#endif
-1,
};
-#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT
-int dss_irqexit_exlist[DSS_EX_MAX_NUM] = {
-/* interrupt number ex) 152, 153, 154, */
- -1,
-};
-
-unsigned int dss_irqexit_threshold =
- CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT_THRESHOLD;
-#endif
-
#ifdef CONFIG_DEBUG_SNAPSHOT_REG
struct dss_reg_list {
size_t addr;
#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_DISABLED
atomic_set(&(dss_idx.irqs_disabled_log_idx[i]), -1);
#endif
-#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT
- atomic_set(&(dss_idx.irq_exit_log_idx[i]), -1);
-#endif
#ifdef CONFIG_DEBUG_SNAPSHOT_REG
atomic_set(&(dss_idx.reg_log_idx[i]), -1);
#endif
irq, irq_fn, en == DSS_FLAG_IN ? "IN" : "OUT");
break;
}
-#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT
- case DSS_FLAG_IRQ_EXIT:
- {
- unsigned long end_time, latency;
- int irq;
-
- array_size = ARRAY_SIZE(dss_log->irq_exit[0]) - 1;
- if (!dumper->active) {
- idx = (atomic_read(&dss_idx.irq_exit_log_idx[0]) + 1) & array_size;
- dumper->init_idx = idx;
- dumper->active = true;
- }
- ts = dss_log->irq_exit[cpu][idx].time;
- rem_nsec = do_div(ts, NSEC_PER_SEC);
-
- end_time = dss_log->irq_exit[cpu][idx].end_time;
- latency = dss_log->irq_exit[cpu][idx].latency;
- irq = dss_log->irq_exit[cpu][idx].irq;
-
- *len = snprintf(line, size, "[%8lu.%09lu][%04d:CPU%u] irq:%6d, "
- "latency:%16zu, end_time:%16zu\n",
- (unsigned long)ts, rem_nsec / NSEC_PER_USEC, idx, cpu,
- irq, latency, end_time);
- break;
- }
-#endif
#ifdef CONFIG_DEBUG_SNAPSHOT_SPINLOCK
case DSS_FLAG_SPINLOCK:
{
}
#endif
-void dbg_snapshot_irq(int irq, void *fn, void *val, int en)
+void dbg_snapshot_irq(int irq, void *fn, void *val, unsigned long long start_time, int en)
{
struct dbg_snapshot_item *item = &dss_items[dss_desc.kevents_num];
unsigned long flags;
flags = pure_arch_local_irq_save();
{
int cpu = raw_smp_processor_id();
+ unsigned long long time, latency;
unsigned long i;
- for (i = 0; i < ARRAY_SIZE(dss_irqlog_exlist); i++) {
- if (irq == dss_irqlog_exlist[i]) {
- pure_arch_local_irq_restore(flags);
- return;
- }
- }
+ time = cpu_clock(cpu);
+
+ if (start_time == 0)
+ start_time = time;
+
+ latency = time - start_time;
i = atomic_inc_return(&dss_idx.irq_log_idx[cpu]) &
(ARRAY_SIZE(dss_log->irq[0]) - 1);
- dss_log->irq[cpu][i].time = cpu_clock(cpu);
+ dss_log->irq[cpu][i].time = time;
dss_log->irq[cpu][i].sp = (unsigned long) current_stack_pointer;
dss_log->irq[cpu][i].irq = irq;
dss_log->irq[cpu][i].fn = (void *)fn;
- dss_log->irq[cpu][i].action = (struct irqaction *)val;
+ dss_log->irq[cpu][i].desc = (struct irq_desc *)val;
+ dss_log->irq[cpu][i].latency = latency;
dss_log->irq[cpu][i].en = en;
}
pure_arch_local_irq_restore(flags);
}
-#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT
-void dbg_snapshot_irq_exit(unsigned int irq, unsigned long long start_time)
-{
- struct dbg_snapshot_item *item = &dss_items[dss_desc.kevents_num];
- unsigned long i;
-
- if (unlikely(!dss_base.enabled || !item->entry.enabled))
- return;
-
- for (i = 0; i < ARRAY_SIZE(dss_irqexit_exlist); i++)
- if (irq == dss_irqexit_exlist[i])
- return;
- {
- int cpu = raw_smp_processor_id();
- unsigned long long time, latency;
-
- i = atomic_inc_return(&dss_idx.irq_exit_log_idx[cpu]) &
- (ARRAY_SIZE(dss_log->irq_exit[0]) - 1);
-
- time = cpu_clock(cpu);
- latency = time - start_time;
-
- if (unlikely(latency >
- (dss_irqexit_threshold * 1000))) {
- dss_log->irq_exit[cpu][i].latency = latency;
- dss_log->irq_exit[cpu][i].sp = (unsigned long) current_stack_pointer;
- dss_log->irq_exit[cpu][i].end_time = time;
- dss_log->irq_exit[cpu][i].time = start_time;
- dss_log->irq_exit[cpu][i].irq = irq;
- } else
- atomic_dec(&dss_idx.irq_exit_log_idx[cpu]);
- }
-}
-#endif
-
#ifdef CONFIG_DEBUG_SNAPSHOT_SPINLOCK
void dbg_snapshot_spinlock(void *v_lock, int en)
{
int irq;
void *fn;
#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD
- struct irqaction *action;
+ struct irq_desc *desc;
#else
- void *action;
+ void *desc;
#endif
+ unsigned long long latency;
int en;
} irq[DSS_NR_CPUS][DSS_LOG_MAX_NUM * 2];
-
-#ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT
- struct __irq_exit_log {
- unsigned long long time;
- unsigned long sp;
- unsigned long long end_time;
- unsigned long long latency;
- int irq;
- } irq_exit[DSS_NR_CPUS][DSS_LOG_MAX_NUM];
-#endif
#ifdef CONFIG_DEBUG_SNAPSHOT_SPINLOCK
struct __spinlock_log {
unsigned long long time;