From ddad4f4d470cf8eda9f1e492ba4252ed4f933e4a Mon Sep 17 00:00:00 2001 From: Hosung Kim Date: Tue, 29 May 2018 15:34:14 +0900 Subject: [PATCH] [COMMON] lib: dss: modify kernel event logging of DSS. Change-Id: Iaf8fb022315fdd419f49310fe7b11a37b07851c3 Signed-off-by: Hosung Kim --- arch/arm64/kernel/smp.c | 16 +++++-- include/linux/debug-snapshot.h | 18 ++++---- kernel/irq/handle.c | 4 +- kernel/smp.c | 4 ++ kernel/softirq.c | 12 ++--- kernel/time/timer.c | 4 +- lib/Kconfig.debug | 5 ++ lib/debug-snapshot-local.h | 83 +++++++++++++++++++++++++++++++--- lib/debug-snapshot-log.c | 17 +++---- 9 files changed, 124 insertions(+), 39 deletions(-) diff --git a/arch/arm64/kernel/smp.c b/arch/arm64/kernel/smp.c index 735474cf082e..012ec9fd8e63 100644 --- a/arch/arm64/kernel/smp.c +++ b/arch/arm64/kernel/smp.c @@ -895,26 +895,32 @@ void handle_IPI(int ipinr, struct pt_regs *regs) __inc_irq_stat(cpu, ipi_irqs[ipinr]); } - dbg_snapshot_irq(ipinr, handle_IPI, irqs_disabled(), DSS_FLAG_IN); - switch (ipinr) { case IPI_RESCHEDULE: + dbg_snapshot_irq(ipinr, scheduler_ipi, NULL, DSS_FLAG_IN); scheduler_ipi(); break; case IPI_CALL_FUNC: irq_enter(); + /* + * dbg_snapshot_irq function is into + * generic_smp_call_function_interrupt() + * + */ generic_smp_call_function_interrupt(); irq_exit(); 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); @@ -926,6 +932,7 @@ void handle_IPI(int ipinr, struct pt_regs *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; @@ -934,6 +941,7 @@ void handle_IPI(int ipinr, struct pt_regs *regs) #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; @@ -941,6 +949,7 @@ void handle_IPI(int ipinr, struct pt_regs *regs) #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); @@ -948,6 +957,7 @@ void handle_IPI(int ipinr, struct pt_regs *regs) #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; } @@ -955,7 +965,7 @@ void handle_IPI(int ipinr, struct pt_regs *regs) if ((unsigned)ipinr < NR_IPI) trace_ipi_exit_rcuidle(ipi_types[ipinr]); - dbg_snapshot_irq(ipinr, handle_IPI, irqs_disabled(), DSS_FLAG_OUT); + dbg_snapshot_irq(ipinr, handle_IPI, NULL, DSS_FLAG_OUT); set_irq_regs(old_regs); } diff --git a/include/linux/debug-snapshot.h b/include/linux/debug-snapshot.h index 7faa1bbe18af..111327481bff 100644 --- a/include/linux/debug-snapshot.h +++ b/include/linux/debug-snapshot.h @@ -23,7 +23,7 @@ extern void dbg_snapshot_task(int cpu, void *v_task); 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(void *fn, void *dev, int en); -extern void dbg_snapshot_irq(int irq, void *fn, unsigned int val, int en); +extern void dbg_snapshot_irq(int irq, void *fn, void *val, 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 int dbg_snapshot_get_enable(const char *name); @@ -242,6 +242,7 @@ static inline void dbg_snapshot_spin_func(void) {do {wfi();} while(1);} /** * dsslog_flag - added log information supported. + * @DSS_FLAG_REQ: Generally, marking starting request something * @DSS_FLAG_IN: Generally, marking into the function * @DSS_FLAG_ON: Generally, marking the status not in, not out * @DSS_FLAG_OUT: Generally, marking come out the function @@ -250,13 +251,14 @@ static inline void dbg_snapshot_spin_func(void) {do {wfi();} while(1);} * @DSS_FLAG_SOFTIRQ_TASKLET: Marking to pass the tasklet function */ enum dsslog_flag { - DSS_FLAG_IN = 1, - DSS_FLAG_ON = 2, - DSS_FLAG_OUT = 3, - DSS_FLAG_SOFTIRQ = 10000, - DSS_FLAG_SOFTIRQ_HI_TASKLET = 10100, - DSS_FLAG_SOFTIRQ_TASKLET = 10200, - DSS_FLAG_CALL_TIMER_FN = 20000 + DSS_FLAG_REQ = 0, + DSS_FLAG_IN = 1, + DSS_FLAG_ON = 2, + DSS_FLAG_OUT = 3, + DSS_FLAG_SOFTIRQ = 10000, + DSS_FLAG_SOFTIRQ_HI_TASKLET = 10100, + DSS_FLAG_SOFTIRQ_TASKLET = 10200, + DSS_FLAG_CALL_TIMER_FN = 20000 }; enum dsslog_freq_flag { diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c index ab75b68f6dd7..0846667ac8f1 100644 --- a/kernel/irq/handle.c +++ b/kernel/irq/handle.c @@ -145,9 +145,9 @@ irqreturn_t __handle_irq_event_percpu(struct irq_desc *desc, unsigned int *flags irqreturn_t res; trace_irq_handler_entry(irq, action); - dbg_snapshot_irq(irq, (void *)action->handler, (int)irqs_disabled(), DSS_FLAG_IN); + 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, (int)irqs_disabled(), DSS_FLAG_OUT); + 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", diff --git a/kernel/smp.c b/kernel/smp.c index 0f2aff5dc1a6..55b39c191bf6 100644 --- a/kernel/smp.c +++ b/kernel/smp.c @@ -238,6 +238,10 @@ static void flush_smp_call_function_queue(bool warn_cpu_offline) smp_call_func_t func = csd->func; 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); + /* Do we wait until *after* callback? */ if (csd->flags & CSD_FLAG_SYNCHRONOUS) { func(info); diff --git a/kernel/softirq.c b/kernel/softirq.c index 6930f35260dd..a496851f35d6 100644 --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -282,9 +282,9 @@ restart: kstat_incr_softirqs_this_cpu(vec_nr); trace_softirq_entry(vec_nr); - dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, irqs_disabled(), DSS_FLAG_IN); + dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, NULL, DSS_FLAG_IN); h->action(h); - dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, irqs_disabled(), DSS_FLAG_OUT); + dbg_snapshot_irq(DSS_FLAG_SOFTIRQ, h->action, NULL, 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", @@ -510,10 +510,10 @@ static __latent_entropy void tasklet_action(struct softirq_action *a) &t->state)) BUG(); dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_TASKLET, - t->func, irqs_disabled(), DSS_FLAG_IN); + t->func, NULL, DSS_FLAG_IN); t->func(t->data); dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_TASKLET, - t->func, irqs_disabled(), DSS_FLAG_OUT); + t->func, NULL, DSS_FLAG_OUT); tasklet_unlock(t); continue; } @@ -550,10 +550,10 @@ static __latent_entropy void tasklet_hi_action(struct softirq_action *a) &t->state)) BUG(); dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_HI_TASKLET, - t->func, irqs_disabled(), DSS_FLAG_IN); + t->func, NULL, DSS_FLAG_IN); t->func(t->data); dbg_snapshot_irq(DSS_FLAG_SOFTIRQ_HI_TASKLET, - t->func, irqs_disabled(), DSS_FLAG_OUT); + t->func, NULL, DSS_FLAG_OUT); tasklet_unlock(t); continue; } diff --git a/kernel/time/timer.c b/kernel/time/timer.c index a16d8e940858..ae4b5352929b 100644 --- a/kernel/time/timer.c +++ b/kernel/time/timer.c @@ -1277,9 +1277,9 @@ static void call_timer_fn(struct timer_list *timer, void (*fn)(unsigned long), lock_map_acquire(&lockdep_map); trace_timer_expire_entry(timer); - dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, irqs_disabled(), DSS_FLAG_IN); + dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, NULL, DSS_FLAG_IN); fn(data); - dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, irqs_disabled(), DSS_FLAG_OUT); + dbg_snapshot_irq(DSS_FLAG_CALL_TIMER_FN, fn, NULL, DSS_FLAG_OUT); trace_timer_expire_exit(timer); lock_map_release(&lockdep_map); diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug index d225116bbe88..9b514c131bed 100644 --- a/lib/Kconfig.debug +++ b/lib/Kconfig.debug @@ -2000,6 +2000,11 @@ menuconfig DEBUG_SNAPSHOT bool "Debug SnapShot Support" default n +config DEBUG_SNAPSHOT_LINUX_BUILD + bool + depends on DEBUG_SNAPSHOT + default y + config DEBUG_SNAPSHOT_CALLSTACK int "shown callstack level" depends on DEBUG_SNAPSHOT diff --git a/lib/debug-snapshot-local.h b/lib/debug-snapshot-local.h index d1a5580b5f60..7a645c2ba825 100644 --- a/lib/debug-snapshot-local.h +++ b/lib/debug-snapshot-local.h @@ -15,10 +15,15 @@ #ifndef DEBUG_SNAPSHOT_LOCAL_H #define DEBUG_SNAPSHOT_LOCAL_H -#include #include #include +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD +#include +#endif + +extern void (*arm_pm_restart)(char str, const char *cmd); + extern void dbg_snapshot_log_idx_init(void); extern void dbg_snapshot_utils_init(void); extern void dbg_snapshot_helper_init(void); @@ -142,16 +147,25 @@ struct dbg_snapshot_log { struct __task_log { unsigned long long time; unsigned long sp; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct task_struct *task; +#else + void *task; +#endif char task_comm[TASK_COMM_LEN]; } task[DSS_NR_CPUS][DSS_LOG_MAX_NUM]; struct __work_log { unsigned long long time; unsigned long sp; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct worker *worker; - char task_comm[TASK_COMM_LEN]; work_func_t fn; +#else + void *worker; + void *fn; +#endif + char task_comm[TASK_COMM_LEN]; int en; } work[DSS_NR_CPUS][DSS_LOG_MAX_NUM]; @@ -160,7 +174,11 @@ struct dbg_snapshot_log { unsigned long sp; char *modes; unsigned state; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD u32 num_online_cpus; +#else + unsigned int num_online_cpus; +#endif int delta; int en; } cpuidle[DSS_NR_CPUS][DSS_LOG_MAX_NUM]; @@ -169,7 +187,11 @@ struct dbg_snapshot_log { unsigned long long time; unsigned long sp; void *fn; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct device *dev; +#else + void *dev; +#endif int en; int core; } suspend[DSS_LOG_MAX_NUM * 4]; @@ -179,8 +201,11 @@ struct dbg_snapshot_log { unsigned long sp; int irq; void *fn; - unsigned int preempt; - unsigned int val; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD + struct irqaction *action; +#else + void *action; +#endif int en; } irq[DSS_NR_CPUS][DSS_LOG_MAX_NUM * 2]; @@ -198,10 +223,18 @@ struct dbg_snapshot_log { unsigned long long time; unsigned long sp; unsigned long long jiffies; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD raw_spinlock_t *lock; #ifdef CONFIG_DEBUG_SPINLOCK u16 next; u16 owner; +#endif +#else + void *lock; +#ifdef CONFIG_DEBUG_SPINLOCK + unsigned short next; + unsigned short owner; +#endif #endif int en; void *caller[DSS_CALLSTACK_MAX_NUM]; @@ -211,7 +244,11 @@ struct dbg_snapshot_log { struct __irqs_disabled_log { unsigned long long time; unsigned long index; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct task_struct *task; +#else + void *task; +#endif char *task_comm; void *caller[DSS_CALLSTACK_MAX_NUM]; } irqs_disabled[DSS_NR_CPUS][SZ_32]; @@ -219,7 +256,11 @@ struct dbg_snapshot_log { #ifdef CONFIG_DEBUG_SNAPSHOT_CLK struct __clk_log { unsigned long long time; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct clk_hw *clk; +#else + void *clk; +#endif const char* f_name; int mode; unsigned long arg; @@ -229,7 +270,7 @@ struct dbg_snapshot_log { struct __pmu_log { unsigned long long time; unsigned int id; - const char* f_name; + const char *f_name; int mode; } pmu[DSS_LOG_MAX_NUM]; #endif @@ -237,7 +278,7 @@ struct dbg_snapshot_log { struct __freq_log { unsigned long long time; int cpu; - char* freq_name; + char *freq_name; unsigned long old_freq; unsigned long target_freq; int en; @@ -250,8 +291,13 @@ struct dbg_snapshot_log { int dm_num; unsigned long min_freq; unsigned long max_freq; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD s32 wait_dmt; s32 do_dmt; +#else + int wait_dmt; + int do_dmt; +#endif } dm[DSS_LOG_MAX_NUM]; #endif #ifdef CONFIG_DEBUG_SNAPSHOT_REG @@ -268,7 +314,11 @@ struct dbg_snapshot_log { struct __hrtimer_log { unsigned long long time; unsigned long long now; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct hrtimer *timer; +#else + void *timer; +#endif void *fn; int en; } hrtimers[DSS_NR_CPUS][DSS_LOG_MAX_NUM]; @@ -289,9 +339,13 @@ struct dbg_snapshot_log { struct __thermal_log { unsigned long long time; int cpu; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct exynos_tmu_platform_data *data; +#else + void *data; +#endif unsigned int temp; - char* cooling_device; + char *cooling_device; unsigned int cooling_state; } thermal[DSS_LOG_MAX_NUM]; #endif @@ -307,8 +361,13 @@ struct dbg_snapshot_log { struct __i2c_log { unsigned long long time; int cpu; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct i2c_adapter *adap; struct i2c_msg *msgs; +#else + void *adp; + void *msgs; +#endif int num; int en; } i2c[DSS_LOG_MAX_NUM]; @@ -317,8 +376,13 @@ struct dbg_snapshot_log { struct __spi_log { unsigned long long time; int cpu; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD struct spi_controller *ctlr; struct spi_message *cur_msg; +#else + void *ctlr; + void *cur_msg; +#endif int en; } spi[DSS_LOG_MAX_NUM]; #endif @@ -327,8 +391,13 @@ struct dbg_snapshot_log { struct __clockevent_log { unsigned long long time; unsigned long long mct_cycle; +#ifdef CONFIG_DEBUG_SNAPSHOT_LINUX_BUILD int64_t delta_ns; ktime_t next_event; +#else + long long delta_ns; + long long next_event; +#endif void *caller[DSS_CALLSTACK_MAX_NUM]; } clockevent[DSS_NR_CPUS][DSS_LOG_MAX_NUM]; diff --git a/lib/debug-snapshot-log.c b/lib/debug-snapshot-log.c index b8645ffe0431..b50d61545038 100644 --- a/lib/debug-snapshot-log.c +++ b/lib/debug-snapshot-log.c @@ -368,7 +368,7 @@ bool dbg_snapshot_dumper_one(void *v_dumper, char *line, size_t size, size_t *le case DSS_FLAG_IRQ: { char irq_fn[KSYM_NAME_LEN]; - int en, irq, preempt, val; + int en, irq; array_size = ARRAY_SIZE(dss_log->irq[0]) - 1; if (!dumper->active) { @@ -381,15 +381,11 @@ bool dbg_snapshot_dumper_one(void *v_dumper, char *line, size_t size, size_t *le lookup_symbol_name((unsigned long)dss_log->irq[cpu][idx].fn, irq_fn); irq = dss_log->irq[cpu][idx].irq; - preempt = dss_log->irq[cpu][idx].preempt; - val = dss_log->irq[cpu][idx].val; en = dss_log->irq[cpu][idx].en; - *len = snprintf(line, size, "[%8lu.%09lu][%04d:CPU%u] irq:%6d, irq_fn:%32s, " - "preempt:%6d, val:%6d, %3s\n", + *len = snprintf(line, size, "[%8lu.%09lu][%04d:CPU%u] irq:%6d, irq_fn:%32s, %3s\n", (unsigned long)ts, rem_nsec / NSEC_PER_USEC, idx, cpu, - irq, irq_fn, preempt, val, - en == DSS_FLAG_IN ? "IN" : "OUT"); + irq, irq_fn, en == DSS_FLAG_IN ? "IN" : "OUT"); break; } #ifdef CONFIG_DEBUG_SNAPSHOT_IRQ_EXIT @@ -641,7 +637,7 @@ void dbg_snapshot_task(int cpu, void *v_task) (ARRAY_SIZE(dss_log->task[0]) - 1); dss_log->task[cpu][i].time = cpu_clock(cpu); - dss_log->task[cpu][i].sp = (unsigned long) current_stack_pointer; + dss_log->task[cpu][i].sp = (unsigned long)current_stack_pointer; dss_log->task[cpu][i].task = (struct task_struct *)v_task; strncpy(dss_log->task[cpu][i].task_comm, dss_log->task[cpu][i].task->comm, @@ -870,7 +866,7 @@ void dbg_snapshot_thermal(void *data, unsigned int temp, char *name, unsigned in } #endif -void dbg_snapshot_irq(int irq, void *fn, unsigned int val, int en) +void dbg_snapshot_irq(int irq, void *fn, void *val, int en) { struct dbg_snapshot_item *item = &dss_items[dss_desc.kevents_num]; unsigned long flags; @@ -896,8 +892,7 @@ void dbg_snapshot_irq(int irq, void *fn, unsigned int val, int en) 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].preempt = preempt_count(); - dss_log->irq[cpu][i].val = val; + dss_log->irq[cpu][i].action = (struct irqaction *)val; dss_log->irq[cpu][i].en = en; } pure_arch_local_irq_restore(flags); -- 2.20.1