drivers/misc/mediatek/mtprof/monitor_debug_out.c

   1 #include <linux/proc_fs.h>
   2 #include <linux/sched.h>
   3 #include <linux/seq_file.h>
   4 #include <linux/kallsyms.h>
   5 #include <linux/utsname.h>
   6 #include <asm/uaccess.h>
   7 #include "prof_ctl.h"
   8 #include <linux/module.h>
   9 #include <linux/pid.h>
  10
  11 #include <linux/irq.h>
  12 #include <linux/irqnr.h>
  13 #include <linux/interrupt.h>
  14
  15 #include <linux/mt_sched_mon.h>
  16
  17 #include <linux/aee.h>
  18 #include <linux/stacktrace.h>
  19
  20 #ifdef CONFIG_MT_SCHED_MONITOR
  21 static long long usec_high(unsigned long long usec)
  22 {
  23         if ((long long)usec < 0) {
  24                 usec = -usec;
  25                 do_div(usec, 1000);
  26                 return -usec;
  27         }
  28         do_div(usec, 1000);
  29
  30         return usec;
  31 }
  32
  33 static const char *isr_name(int irq)
  34 {
  35         struct irqaction *action;
  36         struct irq_desc *desc;
  37
  38         desc = irq_to_desc(irq);
  39         if (!desc)
  40                 return NULL;
  41         else {
  42                 action = desc->action;
  43                 if (!action)
  44                         return NULL;
  45                 else
  46                         return action->name;
  47         }
  48 }
  49
  50 void mt_show_last_irq_counts(void);
  51 void mt_show_current_irq_counts(void);
  52 void mt_show_timer_info(void);
  53 static void mt_aee_show_current_irq_counts(void);
  54 static void mt_aee_show_timer_info(void);
  55 void mt_save_irq_counts(void);
  56 extern void aee_wdt_printf(const char *fmt, ...);
  57 void mt_dump_sched_traces(void)
  58 {
  59         struct sched_block_event *b_isr, *b_sq, *b_tk, *b_hrt, *b_sft;
  60         struct sched_stop_event *e_irq, *e_pmpt;
  61         int cpu;
  62         for_each_possible_cpu(cpu) {
  63
  64                 b_isr = &per_cpu(ISR_mon, cpu);
  65                 b_sq = &per_cpu(SoftIRQ_mon, cpu);
  66                 b_tk = &per_cpu(tasklet_mon, cpu);
  67                 b_hrt = &per_cpu(hrt_mon, cpu);
  68                 b_sft = &per_cpu(sft_mon, cpu);
  69
  70                 e_pmpt = &per_cpu(Preempt_disable_mon, cpu);
  71                 e_irq = &per_cpu(IRQ_disable_mon, cpu);
  72                 pr_err("==CPU[%d]==\n", cpu);
  73                 b_isr->cur_event == 0 ?
  74                     pr_err("[ISR]last_irq:%d, dur:%llu ns (s:%llu, e:%llu)\n\n",
  75                            (int)b_isr->last_event, b_isr->last_te - b_isr->last_ts, b_isr->last_ts,
  76                            b_isr->
  77                            last_te) :
  78                     pr_err
  79                     ("[In ISR]Current irq:%d, Start:%llu (elapsed: %llu ns), last irq#:%d, last_start:%llu, last_end:%llu\n\n",
  80                      (int)b_isr->cur_event, b_isr->cur_ts, sched_clock() - b_isr->cur_ts,
  81                      (int)b_isr->last_event, b_isr->last_ts, b_isr->last_te);
  82
  83                 b_sq->cur_event == 0 ?
  84                     pr_err("[Softirq]last#:%d, dur:%llu ns (s:%llu, e:%llu)\n\n",
  85                            (int)b_sq->last_event, b_sq->last_te - b_sq->last_ts, b_sq->last_ts,
  86                            b_sq->
  87                            last_te) :
  88                     pr_err
  89                     ("[In Softirq]Current softirq#:%d, Start:%llu(elapsed: %llu ns), last softirq#:%d(dur:%llu ns), last_start:%llu, last_end:%llu\n\n",
  90                      (int)b_sq->cur_event, b_sq->cur_ts, sched_clock() - b_sq->cur_ts,
  91                      (int)b_sq->last_event, b_sq->last_te - b_sq->last_ts, b_sq->last_ts,
  92                      b_sq->last_te);
  93
  94
  95                 b_tk->cur_event == 0 ?
  96                     pr_err
  97                     ("[Tasklet]\n Occurs %d times in last SoftIRQ duration\n last fn:%pS, dur:%llu ns (s:%llu, e:%llu)\n\n",
  98                      (int)b_tk->last_count, (void *)b_tk->last_event, b_tk->last_te - b_tk->last_ts,
  99                      b_tk->last_ts,
 100                      b_tk->
 101                      last_te) :
 102                     pr_err
 103                     ("[In Tasklet]\n Occurs: cur:%d, last:%d\n Current:%pS, Start:%llu(elapsed: %llu ns), last#:%pS(dur:%llu ns), last_start:%llu, last_end:%llu\n\n",
 104                      (int)b_tk->cur_count, (int)b_tk->last_count, (void *)b_tk->cur_event,
 105                      b_tk->cur_ts, sched_clock() - b_tk->cur_ts, (void *)b_tk->last_event,
 106                      b_tk->last_te - b_tk->last_ts, b_tk->last_ts, b_tk->last_te);
 107
 108                 b_hrt->cur_event == 0 ?
 109                     pr_err
 110                     ("[HRTimer]\n Occurs %d times in last ISR duration\n last fn:%pS, dur:%llu ns (s:%llu, e:%llu)\n\n",
 111                      (int)b_hrt->last_count, (void *)b_hrt->last_event,
 112                      b_hrt->last_te - b_hrt->last_ts, b_hrt->last_ts,
 113                      b_hrt->
 114                      last_te) :
 115                     pr_err
 116                     ("[In HRTimer]\n Occurs: cur:%d, last:%d\n Current:%pS, Start:%llu(elapsed: %llu ns), last#:%pS(dur:%llu ns), last_start:%llu, last_end:%llu\n\n",
 117                      (int)b_tk->cur_count, (int)b_tk->last_count, (void *)b_hrt->cur_event,
 118                      b_hrt->cur_ts, sched_clock() - b_hrt->cur_ts, (void *)b_hrt->last_event,
 119                      b_hrt->last_te - b_hrt->last_ts, b_hrt->last_ts, b_hrt->last_te);
 120
 121                 b_sft->cur_event == 0 ?
 122                     pr_err
 123                     ("[SoftTimer]\n Occurs %d times in last SoftIRQ duration\n last fn:%pS, dur:%llu ns (s:%llu, e:%llu)\n\n",
 124                      (int)b_sft->last_count, (void *)b_sft->last_event,
 125                      b_sft->last_te - b_sft->last_ts, b_sft->last_ts,
 126                      b_sft->
 127                      last_te) :
 128                     pr_err
 129                     ("[In SoftTimer]\n Occurs: cur:%d, last:%d\n Current:%pS, Start:%llu(elapsed: %llu ns), last#:%pS(dur:%llu ns), last_start:%llu, last_end:%llu\n\n",
 130                      (int)b_sft->cur_count, (int)b_sft->last_count, (void *)b_sft->cur_event,
 131                      b_sft->cur_ts, sched_clock() - b_sft->cur_ts, (void *)b_sft->last_event,
 132                      b_sft->last_te - b_sft->last_ts, b_sft->last_ts, b_sft->last_te);
 133
 134 /****  Dump Stop Events ****/
 135                 e_irq->cur_ts == 0 ?
 136                     pr_err("[IRQ disable] last duration:%llu ns (s: %llu, e: %llu)\n\n",
 137                            e_irq->last_te - e_irq->last_ts, e_irq->last_ts, e_irq->last_te) :
 138                     pr_err
 139                     ("[IRQ disable] cur_ts:%llu(elapsed:%llu ns), last duration:%llu ns(s: %llu, e: %llu)\n\n",
 140                      e_irq->cur_ts, sched_clock() - e_irq->cur_ts, e_irq->last_te - e_irq->last_ts,
 141                      e_irq->last_ts, e_irq->last_te);
 142
 143
 144                 e_pmpt->cur_ts == 0 ?
 145                     pr_err("[Preempt disable] last duration:%llu ns(s: %llu, e: %llu)\n\n",
 146                            e_pmpt->last_te - e_pmpt->last_ts, e_pmpt->last_ts, e_pmpt->last_te) :
 147                     pr_err
 148                     ("[Preempt disable] cur_ts:%llu(elapsed:%llu ns), last duration:%llu ns(s: %llu, e: %llu)\n\n",
 149                      e_pmpt->cur_ts, sched_clock() - e_pmpt->cur_ts,
 150                      e_pmpt->last_te - e_pmpt->last_ts, e_pmpt->last_ts, e_pmpt->last_te);
 151         }
 152         mt_show_current_irq_counts();
 153         mt_show_timer_info();
 154 }
 155
 156 void mt_aee_dump_sched_traces(void)
 157 {
 158         struct sched_block_event *b_isr, *b_sq, *b_tk, *b_hrt, *b_sft;
 159         struct sched_stop_event *e_irq, *e_pmpt;
 160         int cpu;
 161         for_each_possible_cpu(cpu) {
 162
 163                 b_isr = &per_cpu(ISR_mon, cpu);
 164                 b_sq = &per_cpu(SoftIRQ_mon, cpu);
 165                 b_tk = &per_cpu(tasklet_mon, cpu);
 166                 b_hrt = &per_cpu(hrt_mon, cpu);
 167                 b_sft = &per_cpu(sft_mon, cpu);
 168
 169                 e_pmpt = &per_cpu(Preempt_disable_mon, cpu);
 170                 e_irq = &per_cpu(IRQ_disable_mon, cpu);
 171                 aee_wdt_printf("CPU%d\n", cpu);
 172                 b_isr->cur_event == 0 ?
 173                     aee_wdt_printf("[ISR]last#%d,dur:%lld s:%lld\n\n",
 174                                    (int)b_isr->last_event,
 175                                    usec_high(b_isr->last_te - b_isr->last_ts),
 176                                    usec_high(b_isr->
 177                                              last_ts)) :
 178                     aee_wdt_printf
 179                     ("[In ISR]Current irq#:%d, Start:%lld (elapsed: %lld), last irq#:%d, s:%lld, e:%lld\n\n",
 180                      (int)b_isr->cur_event, usec_high(b_isr->cur_ts),
 181                      usec_high(sched_clock() - b_isr->cur_ts), (int)b_isr->last_event,
 182                      usec_high(b_isr->last_ts), usec_high(b_isr->last_te));
 183
 184                 b_sq->cur_event == 0 ?
 185                     aee_wdt_printf("[Softirq]last#%d,dur:%lld s:%lld\n\n",
 186                                    (int)b_sq->last_event, usec_high(b_sq->last_te - b_sq->last_ts),
 187                                    usec_high(b_sq->
 188                                              last_ts)) :
 189                     aee_wdt_printf
 190                     ("[In Softirq]Current softirq#:%d, Start:%lld(elapsed: %lld), last softirq#:%d(dur:%lld), s:%lld, e:%lld\n\n",
 191                      (int)b_sq->cur_event, usec_high(b_sq->cur_ts),
 192                      usec_high(sched_clock() - b_sq->cur_ts), (int)b_sq->last_event,
 193                      usec_high(b_sq->last_te - b_sq->last_ts), usec_high(b_sq->last_ts),
 194                      usec_high(b_sq->last_te));
 195
 196
 197                 b_tk->cur_event == 0 ?
 198                     aee_wdt_printf("[Tasklet]%d/SoftIRQ\n %pS dur:%lld s:%lld\n\n",
 199                                    (int)b_tk->last_count, (void *)b_tk->last_event,
 200                                    usec_high(b_tk->last_te - b_tk->last_ts),
 201                                    usec_high(b_tk->
 202                                              last_ts)) :
 203                     aee_wdt_printf
 204                     ("[In Tasklet]\n Occurs: cur:%d, last:%d\n Current:%pS, Start:%lld(elapsed: %lld), last#:%pS(dur:%lld), last_start:%lld, last_end:%lld\n\n",
 205                      (int)b_tk->cur_count, (int)b_tk->last_count, (void *)b_tk->cur_event,
 206                      usec_high(b_tk->cur_ts), usec_high(sched_clock() - b_tk->cur_ts),
 207                      (void *)b_tk->last_event, usec_high(b_tk->last_te - b_tk->last_ts),
 208                      usec_high(b_tk->last_ts), usec_high(b_tk->last_te));
 209
 210                 b_hrt->cur_event == 0 ?
 211                     aee_wdt_printf("[HRTimer]%d/ISR\n %pS dur:%lld s:%lld\n\n",
 212                                    (int)b_hrt->last_count, (void *)b_hrt->last_event,
 213                                    usec_high(b_hrt->last_te - b_hrt->last_ts),
 214                                    usec_high(b_hrt->
 215                                              last_ts)) :
 216                     aee_wdt_printf
 217                     ("[In HRTimer]\n Occurs: cur:%d, last:%d\n Current:%pS, Start:%lld(elapsed: %lld), last#:%pS(dur:%lld), last_start:%lld, last_end:%lld\n\n",
 218                      (int)b_tk->cur_count, (int)b_tk->last_count, (void *)b_hrt->cur_event,
 219                      usec_high(b_hrt->cur_ts), usec_high(sched_clock() - b_hrt->cur_ts),
 220                      (void *)b_hrt->last_event, usec_high(b_hrt->last_te - b_hrt->last_ts),
 221                      usec_high(b_hrt->last_ts), usec_high(b_hrt->last_te));
 222
 223                 b_sft->cur_event == 0 ?
 224                     aee_wdt_printf("[SoftTimer]%d/SoftIRQ\n %pS dur:%lld s:%lld\n\n",
 225                                    (int)b_sft->last_count, (void *)b_sft->last_event,
 226                                    usec_high(b_sft->last_te - b_sft->last_ts),
 227                                    usec_high(b_sft->
 228                                              last_ts)) :
 229                     aee_wdt_printf
 230                     ("[In SoftTimer]\n Occurs: cur:%d, last:%d\n Current:%pS, Start:%lld(elapsed: %lld), last#:%pS(dur:%lld), last_start:%lld, last_end:%lld\n\n",
 231                      (int)b_sft->cur_count, (int)b_sft->last_count, (void *)b_sft->cur_event,
 232                      usec_high(b_sft->cur_ts), usec_high(sched_clock() - b_sft->cur_ts),
 233                      (void *)b_sft->last_event, usec_high(b_sft->last_te - b_sft->last_ts),
 234                      usec_high(b_sft->last_ts), usec_high(b_sft->last_te));
 235
 236 /****  Dump Stop Events ****/
 237                 /*
 238                    e_irq->cur_ts == 0?
 239                    aee_wdt_printf("[IRQ disable] last duration:%llu ns (s: %llu, e: %llu)\n\n",
 240                    e_irq->last_te - e_irq->last_ts, e_irq->last_ts, e_irq->last_te):
 241                    aee_wdt_printf("[IRQ disable] cur_ts:%llu(elapsed:%llu ns), last duration:%llu ns(s: %llu, e: %llu)\n\n",
 242                    e_irq->cur_ts, sched_clock() - e_irq->cur_ts, e_irq->last_te - e_irq->last_ts, e_irq->last_ts, e_irq->last_te);
 243
 244                    e_pmpt->cur_ts == 0?
 245                    aee_wdt_printf("[Preempt disable] last duration:%llu ns(s: %llu, e: %llu)\n\n",
 246                    e_pmpt->last_te - e_pmpt->last_ts, e_pmpt->last_ts, e_pmpt->last_te):
 247                    aee_wdt_printf("[Preempt disable] cur_ts:%llu(elapsed:%llu ns), last duration:%llu ns(s: %llu, e: %llu)\n\n",
 248                    e_pmpt->cur_ts, sched_clock() - e_pmpt->cur_ts, e_pmpt->last_te - e_pmpt->last_ts, e_pmpt->last_ts, e_pmpt->last_te);
 249                  */
 250         }
 251         mt_aee_show_current_irq_counts();
 252         mt_aee_show_timer_info();
 253 }
 254
 255 #include <linux/irqnr.h>
 256 #include <linux/kernel_stat.h>
 257 #include <asm/hardirq.h>
 258
 259 extern int mt_irq_count[NR_CPUS][MAX_NR_IRQS];
 260 #ifdef CONFIG_SMP
 261 extern int mt_local_irq_count[NR_CPUS][NR_IPI];
 262 #endif
 263 extern unsigned long long mt_save_irq_count_time;
 264 extern spinlock_t mt_irq_count_lock;
 265
 266 void mt_show_last_irq_counts(void)
 267 {
 268         int irq, cpu;
 269         unsigned long flags;
 270         spin_lock_irqsave(&mt_irq_count_lock, flags);
 271         pr_err("Last irq counts record at [%llu] ns\n", mt_save_irq_count_time);
 272         for (cpu = 0; cpu < num_possible_cpus(); cpu++) {
 273                 pr_err("CPU#%d:\n", cpu);
 274                 for (irq = 0; irq < nr_irqs && irq < MAX_NR_IRQS; irq++) {
 275                         if (mt_irq_count[cpu][irq] != 0)
 276                                 pr_err("[%3d] = %8d\n", irq, mt_irq_count[cpu][irq]);
 277                 }
 278         }
 279
 280 #ifdef CONFIG_SMP
 281         for (cpu = 0; cpu < num_possible_cpus(); cpu++) {
 282                 for (irq = 0; irq < NR_IPI; irq++) {
 283                         if (mt_local_irq_count[cpu][irq] != 0)
 284                                 pr_err("(CPU#%d)IPI[%3d] = %8d\n", cpu, irq,
 285                                        mt_local_irq_count[cpu][irq]);
 286                 }
 287         }
 288 #endif
 289         spin_unlock_irqrestore(&mt_irq_count_lock, flags);
 290 }
 291
 292 void mt_show_current_irq_counts(void)
 293 {
 294         int irq, cpu, count;
 295         unsigned long flags;
 296         unsigned long long t_cur, t_diff;
 297         t_cur = sched_clock();
 298         spin_lock_irqsave(&mt_irq_count_lock, flags);
 299
 300         t_diff = t_cur - mt_save_irq_count_time;
 301         pr_err("=========================================\nIRQ Status:\n");
 302         pr_err("Current irq counts record at [%llu] ns.(last at %llu, diff:+%llu ns)\n", t_cur,
 303                mt_save_irq_count_time, t_diff);
 304         for (cpu = 0; cpu < num_possible_cpus(); cpu++) {
 305                 pr_err(" --CPU%d--\n", cpu);
 306                 for (irq = 0; irq < nr_irqs && irq < MAX_NR_IRQS; irq++) {
 307                         count = kstat_irqs_cpu(irq, cpu);
 308                         if (count != 0)
 309                                 pr_err(" IRQ[%3d:%14s] = %8d, (+%d times in %lld us)\n", irq,
 310                                        isr_name(irq), count, count - mt_irq_count[cpu][irq],
 311                                        usec_high(t_diff));
 312                 }
 313         }
 314 #ifdef CONFIG_SMP
 315         for (cpu = 0; cpu < num_possible_cpus(); cpu++) {
 316                 pr_err("Local IRQ on CPU#%d:\n", cpu);
 317                 for (irq = 0; irq < NR_IPI; irq++) {
 318                         count = __get_irq_stat(cpu, ipi_irqs[irq]);
 319                         if (count != 0)
 320                                 pr_err(" IRQ[%2d:  IPI] = %8d,(+%d times in %lld us)\n", irq, count,
 321                                        count - mt_local_irq_count[cpu][irq], usec_high(t_diff));
 322                 }
 323         }
 324 #endif
 325         spin_unlock_irqrestore(&mt_irq_count_lock, flags);
 326 }
 327
 328 void mt_show_timer_info(void)
 329 {
 330         int cpu;
 331         for_each_possible_cpu(cpu) {
 332                 pr_err("[TimerISR#%d] last timer ISR start:%llu ns, end:%llu ns\n", cpu,
 333                        per_cpu(local_timer_ts, cpu), per_cpu(local_timer_te, cpu));
 334         }
 335 }
 336
 337 /* for MTK fiq debug log mechanism*/
 338 static void mt_aee_show_current_irq_counts(void)
 339 {
 340
 341         int irq, cpu, count;
 342         unsigned long long t_cur, t_diff;
 343         t_cur = sched_clock();
 344         /* spin_lock_irqsave(&mt_irq_count_lock, flags); */
 345
 346         t_diff = t_cur - mt_save_irq_count_time;
 347         aee_wdt_printf("\nIRQ Status\n");
 348         aee_wdt_printf("Dur:%lld us,(now:%lld,last:%lld)\n", usec_high(t_diff), usec_high(t_cur),
 349                        mt_save_irq_count_time);
 350         for (cpu = 0; cpu < num_possible_cpus(); cpu++) {
 351                 aee_wdt_printf(" CPU%d\n", cpu);
 352                 for (irq = 0; irq < nr_irqs && irq < MAX_NR_IRQS; irq++) {
 353                         count = kstat_irqs_cpu(irq, cpu);
 354                         if (count != 0)
 355                                 aee_wdt_printf(" %d:%s +%d(%d)\n", irq, isr_name(irq),
 356                                                count - mt_irq_count[cpu][irq], count);
 357                 }
 358         }
 359 #ifdef CONFIG_SMP
 360         for (cpu = 0; cpu < num_possible_cpus(); cpu++) {
 361                 aee_wdt_printf("CPU#%d:\n", cpu);
 362                 for (irq = 0; irq < NR_IPI; irq++) {
 363                         count = __get_irq_stat(cpu, ipi_irqs[irq]);
 364                         if (count != 0)
 365                                 aee_wdt_printf(" %d:IPI +%d(%d)\n", irq,
 366                                                count - mt_local_irq_count[cpu][irq], count);
 367                 }
 368         }
 369 #endif
 370         /* spin_unlock_irqrestore(&mt_irq_count_lock, flags); */
 371 }
 372
 373 static void mt_aee_show_timer_info(void)
 374 {
 375         int cpu;
 376         for_each_possible_cpu(cpu) {
 377                 aee_wdt_printf("[TimerISR#%d]last s:%llu e:%llu ns\n", cpu,
 378                                per_cpu(local_timer_ts, cpu), per_cpu(local_timer_te, cpu));
 379         }
 380 }
 381 #else
 382
 383 void mt_dump_sched_traces(void)
 384 {
 385 }
 386
 387 void mt_aee_dump_sched_traces(void)
 388 {
 389 }
 390
 391 void mt_show_last_irq_counts(void)
 392 {
 393 }
 394
 395 void mt_show_current_irq_counts(void)
 396 {
 397 }
 398
 399 void mt_show_timer_info(void)
 400 {
 401 }
 402 #endif