sched_monitor.c 25 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910
  1. #define DEBUG 1
  2. #include <linux/proc_fs.h>
  3. #include <linux/sched.h>
  4. #include <linux/kallsyms.h>
  5. #include <linux/utsname.h>
  6. #include <linux/slab.h>
  7. #include <linux/uaccess.h>
  8. #include <linux/module.h>
  9. #include <linux/pid.h>
  10. #include <linux/irq.h>
  11. #include <linux/irqnr.h>
  12. #include <linux/interrupt.h>
  13. #include <linux/stacktrace.h>
  14. #include <mt-plat/aee.h>
  15. #include <linux/stacktrace.h>
  16. #include "mt_sched_mon.h"
  17. #include "internal.h"
  18. static unsigned int WARN_ISR_DUR;
  19. static unsigned int WARN_SOFTIRQ_DUR;
  20. static unsigned int WARN_TASKLET_DUR;
  21. static unsigned int WARN_HRTIMER_DUR;
  22. static unsigned int WARN_STIMER_DUR;
  23. static unsigned int WARN_BURST_IRQ_DETECT;
  24. static unsigned int WARN_PREEMPT_DUR;
  25. enum mt_event_type {
  26. evt_ISR = 1,
  27. evt_SOFTIRQ = 2,
  28. evt_TASKLET,
  29. evt_HRTIMER,
  30. evt_STIMER,
  31. };
  32. DEFINE_PER_CPU(struct sched_block_event, ISR_mon);
  33. DEFINE_PER_CPU(struct sched_block_event, SoftIRQ_mon);
  34. DEFINE_PER_CPU(struct sched_block_event, tasklet_mon);
  35. DEFINE_PER_CPU(struct sched_block_event, hrt_mon);
  36. DEFINE_PER_CPU(struct sched_block_event, sft_mon);
  37. DEFINE_PER_CPU(struct sched_stop_event, IRQ_disable_mon);
  38. DEFINE_PER_CPU(struct sched_stop_event, Preempt_disable_mon);
  39. DEFINE_PER_CPU(struct sched_lock_event, Raw_spin_lock_mon);
  40. DEFINE_PER_CPU(struct sched_lock_event, rq_lock_mon);
  41. DEFINE_PER_CPU(int, mt_timer_irq);
  42. /* TIMER debug */
  43. DEFINE_PER_CPU(int, mtsched_mon_enabled);
  44. DEFINE_PER_CPU(unsigned long long, local_timer_ts);
  45. DEFINE_PER_CPU(unsigned long long, local_timer_te);
  46. #ifdef CONFIG_MT_SCHED_MONITOR
  47. /* Save stack trace */
  48. static DEFINE_PER_CPU(struct stack_trace, MT_stack_trace);
  49. static DEFINE_PER_CPU(unsigned long long, TS_irq_off);
  50. #endif
  51. /* [IRQ-disable] White List
  52. * Flags for special scenario*/
  53. DEFINE_PER_CPU(int, MT_trace_in_sched);
  54. DEFINE_PER_CPU(int, MT_trace_in_resume_console);
  55. #define MAX_STACK_TRACE_DEPTH 32
  56. #define TIME_1MS 1000000
  57. static DEFINE_MUTEX(mt_sched_mon_lock);
  58. /* //////////////////////////////////////////////////////// */
  59. #define SPLIT_NS_H(x) nsec_high(x)
  60. #define SPLIT_NS_L(x) nsec_low(x)
  61. /* */
  62. /* //////////////////////////////////////////////////////// */
  63. /* --------------------------------------------------- */
  64. /* Real work */
  65. #if defined(CONFIG_MT_SCHED_MONITOR) || defined(CONFIG_PREEMPT_MONITOR)
  66. static const char *task_name(void *task)
  67. {
  68. struct task_struct *p = NULL;
  69. p = task;
  70. if (p)
  71. return p->comm;
  72. return NULL;
  73. }
  74. static void sched_monitor_aee(struct sched_block_event *b)
  75. {
  76. #ifdef CONFIG_MT_SCHED_MON_DEFAULT_ENABLE
  77. char aee_str[60];
  78. unsigned long long t_dur;
  79. t_dur = b->last_te - b->last_ts;
  80. switch (b->type) {
  81. case evt_ISR:
  82. snprintf(aee_str, 60, "SCHED MONITOR : ISR DURATION WARN");
  83. aee_kernel_warning_api(__FILE__, __LINE__, DB_OPT_DUMMY_DUMP | DB_OPT_FTRACE,
  84. aee_str, "ISR DURATION WARN: IRQ[%d:%s] dur:%llu ns",
  85. (int)b->last_event, isr_name(b->last_event), t_dur);
  86. break;
  87. case evt_SOFTIRQ:
  88. snprintf(aee_str, 60, "SCHED MONITOR : SOFTIRQ DURATION WARN");
  89. aee_kernel_warning_api(__FILE__, __LINE__, DB_OPT_DUMMY_DUMP | DB_OPT_FTRACE,
  90. aee_str, "SOFTIRQ DURATION WARN: SoftIRQ:%d dur:%llu ns",
  91. (int)b->last_event, t_dur);
  92. break;
  93. }
  94. #else
  95. return;
  96. #endif
  97. }
  98. #endif
  99. #ifdef CONFIG_MT_SCHED_MONITOR
  100. static void event_duration_check(struct sched_block_event *b)
  101. {
  102. unsigned long long t_dur;
  103. t_dur = b->last_te - b->last_ts;
  104. switch (b->type) {
  105. case evt_ISR:
  106. if (t_dur > WARN_ISR_DUR) {
  107. pr_err
  108. ("[ISR DURATION WARN] IRQ[%d:%s], dur:%llu ns > %d ms,(s:%llu,e:%llu)\n",
  109. (int)b->last_event, isr_name(b->last_event), t_dur,
  110. WARN_ISR_DUR / 1000000, b->last_ts, b->last_te);
  111. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x1))
  112. sched_monitor_aee(b);
  113. }
  114. if (b->preempt_count != preempt_count())
  115. pr_err("[ISR WARN]IRQ[%d:%s], Unbalanced Preempt Count:0x%x! Should be 0x%x\n",
  116. (int)b->last_event, isr_name(b->last_event), preempt_count(), b->preempt_count);
  117. break;
  118. case evt_SOFTIRQ:
  119. if (t_dur > WARN_SOFTIRQ_DUR) {
  120. struct sched_block_event *b_isr;
  121. b_isr = &__raw_get_cpu_var(ISR_mon);
  122. pr_err
  123. ("[SOFTIRQ DURATION WARN] SoftIRQ:%d, dur:%llu ns > %d ms,(s:%llu,e:%llu)\n",
  124. (int)b->last_event, t_dur, WARN_SOFTIRQ_DUR / 1000000, b->last_ts,
  125. b->last_te);
  126. if (b_isr->last_ts > b->last_ts) { /* ISR occur during Tasklet */
  127. pr_err
  128. (" IRQ occurrs in this duration, IRQ[%d:%s], dur:%llu ns (s:%llu, e:%llu)\n\n",
  129. (int)b_isr->last_event, isr_name(b_isr->last_event),
  130. b_isr->last_te - b_isr->last_ts, b_isr->last_ts,
  131. b_isr->last_te);
  132. }
  133. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x1)
  134. && (b->last_event != RCU_SOFTIRQ))
  135. sched_monitor_aee(b);
  136. }
  137. if (b->preempt_count != preempt_count())
  138. pr_err("[SOFTIRQ WARN] SoftIRQ:%d, Unbalanced Preempt Count:0x%x! Should be 0x%x\n",
  139. (int)b->last_event, preempt_count(), b->preempt_count);
  140. break;
  141. case evt_TASKLET:
  142. if (t_dur > WARN_TASKLET_DUR) {
  143. struct sched_block_event *b_isr;
  144. b_isr = &__raw_get_cpu_var(ISR_mon);
  145. pr_err
  146. ("[TASKLET DURATION WARN] Tasklet:%pS, dur:%llu ns > %d ms,(s:%llu,e:%llu)\n",
  147. (void *)b->last_event, t_dur, WARN_TASKLET_DUR / 1000000, b->last_ts,
  148. b->last_te);
  149. if (b_isr->last_ts > b->last_ts) { /* ISR occur during Tasklet */
  150. pr_err
  151. (" IRQ occurrs in this duration, IRQ[%d:%s], dur:%llu ns (s:%llu, e:%llu)\n\n",
  152. (int)b_isr->last_event, isr_name(b_isr->last_event),
  153. b_isr->last_te - b_isr->last_ts, b_isr->last_ts,
  154. b_isr->last_te);
  155. }
  156. }
  157. if (b->preempt_count != preempt_count())
  158. pr_err("[TASKLET WARN] TASKLET:%pS, Unbalanced Preempt Count:0x%x! Should be 0x%x\n",
  159. (void *)b->last_event, preempt_count(), b->preempt_count);
  160. break;
  161. case evt_HRTIMER:
  162. if (t_dur > WARN_HRTIMER_DUR) {
  163. struct sched_lock_event *lock_e;
  164. lock_e = &__raw_get_cpu_var(rq_lock_mon);
  165. pr_err
  166. ("[HRTIMER DURATION WARN] HRTIMER:%pS, dur:%llu ns > %d ms,(s:%llu,e:%llu)\n",
  167. (void *)b->last_event, t_dur, WARN_HRTIMER_DUR / 1000000,
  168. b->last_ts, b->last_te);
  169. if (lock_e->lock_owner && lock_e->lock_ts > b->last_ts
  170. && lock_e->lock_dur > TIME_1MS) {
  171. pr_err
  172. ("[HRTIMER WARN]get rq->lock, last owner:%s dur: %llu ns(s:%llu,e:%llu)\n",
  173. task_name((void *)lock_e->lock_owner), lock_e->lock_dur,
  174. usec_high(lock_e->lock_ts), usec_high(lock_e->lock_te));
  175. }
  176. }
  177. if (b->preempt_count != preempt_count())
  178. pr_err("[HRTIMER WARN] HRTIMER:%pS, Unbalanced Preempt Count:0x%x! Should be 0x%x\n",
  179. (void *)b->last_event, preempt_count(), b->preempt_count);
  180. break;
  181. case evt_STIMER:
  182. if (t_dur > WARN_STIMER_DUR) {
  183. struct sched_block_event *b_isr;
  184. b_isr = &__raw_get_cpu_var(ISR_mon);
  185. pr_err
  186. ("[STIMER DURATION WARN] SoftTIMER:%pS, dur:%llu ns > %d ms,(s:%llu,e:%llu)\n",
  187. (void *)b->last_event, t_dur, WARN_STIMER_DUR / 1000000, b->last_ts,
  188. b->last_te);
  189. if (b_isr->last_ts > b->last_ts) { /* ISR occur during Softtimer */
  190. pr_err
  191. (" IRQ occurrs in this duration, IRQ[%d:%s], dur:%llu ns (s:%llu, e:%llu)\n\n",
  192. (int)b_isr->last_event, isr_name(b_isr->last_event),
  193. b_isr->last_te - b_isr->last_ts, b_isr->last_ts,
  194. b_isr->last_te);
  195. }
  196. }
  197. if (b->preempt_count != preempt_count()) {
  198. pr_err("[STTIMER WARN] SoftTIMER:%pS, Unbalanced Preempt Count:0x%x! Should be 0x%x\n",
  199. (void *)b->last_event, preempt_count(), b->preempt_count);
  200. }
  201. break;
  202. }
  203. }
  204. static void reset_event_count(struct sched_block_event *b)
  205. {
  206. b->last_count = b->cur_count;
  207. b->cur_count = 0;
  208. }
  209. /* ISR monitor */
  210. void mt_trace_ISR_start(int irq)
  211. {
  212. struct sched_block_event *b;
  213. b = &__raw_get_cpu_var(ISR_mon);
  214. b->preempt_count = preempt_count();
  215. b->cur_ts = sched_clock();
  216. b->cur_event = (unsigned long)irq;
  217. aee_rr_rec_last_irq_enter(smp_processor_id(), irq, b->cur_ts);
  218. }
  219. void mt_trace_ISR_end(int irq)
  220. {
  221. struct sched_block_event *b;
  222. b = &__raw_get_cpu_var(ISR_mon);
  223. WARN_ON(b->cur_event != irq);
  224. b->last_event = b->cur_event;
  225. b->last_ts = b->cur_ts;
  226. b->last_te = sched_clock();
  227. b->cur_event = 0;
  228. b->cur_ts = 0;
  229. event_duration_check(b);
  230. aee_rr_rec_last_irq_exit(smp_processor_id(), irq, b->last_te);
  231. /* reset HRTimer function counter */
  232. b = &__raw_get_cpu_var(hrt_mon);
  233. reset_event_count(b);
  234. }
  235. /* SoftIRQ monitor */
  236. void mt_trace_SoftIRQ_start(int sq_num)
  237. {
  238. struct sched_block_event *b;
  239. b = &__raw_get_cpu_var(SoftIRQ_mon);
  240. b->preempt_count = preempt_count();
  241. b->cur_ts = sched_clock();
  242. b->cur_event = (unsigned long)sq_num;
  243. }
  244. void mt_trace_SoftIRQ_end(int sq_num)
  245. {
  246. struct sched_block_event *b;
  247. b = &__raw_get_cpu_var(SoftIRQ_mon);
  248. WARN_ON(b->cur_event != sq_num);
  249. b->last_event = b->cur_event;
  250. b->last_ts = b->cur_ts;
  251. b->last_te = sched_clock();
  252. b->cur_event = 0;
  253. b->cur_ts = 0;
  254. event_duration_check(b);
  255. /* reset soft timer function counter */
  256. b = &__raw_get_cpu_var(sft_mon);
  257. reset_event_count(b);
  258. /* reset tasklet function counter */
  259. b = &__raw_get_cpu_var(tasklet_mon);
  260. reset_event_count(b);
  261. }
  262. /* Tasklet monitor */
  263. void mt_trace_tasklet_start(void *func)
  264. {
  265. struct sched_block_event *b;
  266. b = &__raw_get_cpu_var(tasklet_mon);
  267. b->preempt_count = preempt_count();
  268. b->cur_ts = sched_clock();
  269. b->cur_event = (unsigned long)func;
  270. b->cur_count++;
  271. }
  272. void mt_trace_tasklet_end(void *func)
  273. {
  274. struct sched_block_event *b;
  275. b = &__raw_get_cpu_var(tasklet_mon);
  276. WARN_ON(b->cur_event != (unsigned long)func);
  277. b->last_event = b->cur_event;
  278. b->last_ts = b->cur_ts;
  279. b->last_te = sched_clock();
  280. b->cur_event = 0;
  281. b->cur_ts = 0;
  282. event_duration_check(b);
  283. }
  284. /* HRTimer monitor */
  285. void mt_trace_hrt_start(void *func)
  286. {
  287. struct sched_block_event *b;
  288. b = &__raw_get_cpu_var(hrt_mon);
  289. b->preempt_count = preempt_count();
  290. b->cur_ts = sched_clock();
  291. b->cur_event = (unsigned long)func;
  292. b->cur_count++;
  293. }
  294. void mt_trace_hrt_end(void *func)
  295. {
  296. struct sched_block_event *b;
  297. b = &__raw_get_cpu_var(hrt_mon);
  298. WARN_ON(b->cur_event != (unsigned long)func);
  299. b->last_event = b->cur_event;
  300. b->last_ts = b->cur_ts;
  301. b->last_te = sched_clock();
  302. b->cur_event = 0;
  303. b->cur_ts = 0;
  304. event_duration_check(b);
  305. }
  306. void mt_trace_rqlock_start(raw_spinlock_t *lock)
  307. {
  308. struct sched_lock_event *lock_e;
  309. struct task_struct *owner = NULL;
  310. #ifdef CONFIG_DEBUG_SPINLOCK
  311. if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
  312. owner = lock->owner;
  313. #endif
  314. lock_e = &__raw_get_cpu_var(rq_lock_mon);
  315. lock_e->lock_ts = sched_clock();
  316. lock_e->lock_owner = (unsigned long)owner;
  317. }
  318. void mt_trace_rqlock_end(raw_spinlock_t *lock)
  319. {
  320. struct sched_lock_event *lock_e;
  321. struct task_struct *owner = NULL;
  322. #ifdef CONFIG_DEBUG_SPINLOCK
  323. if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
  324. owner = lock->owner;
  325. #endif
  326. lock_e = &__raw_get_cpu_var(rq_lock_mon);
  327. lock_e->lock_te = sched_clock();
  328. lock_e->lock_dur = lock_e->lock_te - lock_e->lock_ts;
  329. }
  330. /* SoftTimer monitor */
  331. void mt_trace_sft_start(void *func)
  332. {
  333. struct sched_block_event *b;
  334. b = &__raw_get_cpu_var(sft_mon);
  335. b->preempt_count = preempt_count();
  336. b->cur_ts = sched_clock();
  337. b->cur_event = (unsigned long)func;
  338. b->cur_count++;
  339. }
  340. void mt_trace_sft_end(void *func)
  341. {
  342. struct sched_block_event *b;
  343. b = &__raw_get_cpu_var(sft_mon);
  344. WARN_ON(b->cur_event != (unsigned long)func);
  345. b->last_event = b->cur_event;
  346. b->last_ts = b->cur_ts;
  347. b->last_te = sched_clock();
  348. b->cur_event = 0;
  349. b->cur_ts = 0;
  350. event_duration_check(b);
  351. }
  352. #endif
  353. #ifdef CONFIG_PREEMPT_MONITOR
  354. /* Preempt off monitor */
  355. void MT_trace_preempt_off(void)
  356. {
  357. struct sched_stop_event *e;
  358. int cpu = smp_processor_id();
  359. struct rq *rq = cpu_rq(cpu);
  360. struct task_struct *curr = rq->curr;
  361. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x1)) {
  362. if (strncmp(curr->comm, "swapper", 7)
  363. && strncmp(curr->comm, "migration", 9)
  364. && !in_interrupt()) {
  365. e = &__raw_get_cpu_var(Preempt_disable_mon);
  366. e->cur_ts = sched_clock();
  367. }
  368. }
  369. }
  370. void MT_trace_preempt_on(void)
  371. {
  372. struct sched_stop_event *e;
  373. unsigned long long t_dur = 0;
  374. int cpu = smp_processor_id();
  375. struct rq *rq = cpu_rq(cpu);
  376. struct task_struct *curr = rq->curr;
  377. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x1)) {
  378. if (strncmp(curr->comm, "swapper", 7)
  379. && strncmp(curr->comm, "migration", 9)
  380. && !in_interrupt()) {
  381. e = &__raw_get_cpu_var(Preempt_disable_mon);
  382. e->last_ts = e->cur_ts;
  383. e->last_te = sched_clock();
  384. t_dur = e->last_te - e->last_ts;
  385. if (t_dur != e->last_te)
  386. curr->preempt_dur = t_dur;
  387. }
  388. }
  389. }
  390. extern void MT_trace_check_preempt_dur(void)
  391. {
  392. struct sched_stop_event *e;
  393. struct sched_block_event *b;
  394. unsigned long long t_dur = 0;
  395. unsigned long long t_dur_tmp = 0;
  396. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x1)) {
  397. b = &__raw_get_cpu_var(ISR_mon);
  398. e = &__raw_get_cpu_var(Preempt_disable_mon);
  399. t_dur = current->preempt_dur;
  400. if (t_dur > WARN_PREEMPT_DUR && e->last_ts > 0 && e->last_te > 0) {
  401. pr_err("[PREEMPT DURATION WARN]dur:%llu ns (s:%llu,e:%llu),lock_dur:%llu owenr:%s lock:%pS\n",
  402. t_dur, usec_high(e->last_ts), usec_high(e->last_te),
  403. e->lock_dur, task_name((void *)e->lock_owner), e->lock);
  404. if (b->last_ts > e->last_ts && b->last_te < e->last_te) {
  405. t_dur_tmp = b->last_te - b->cur_ts;
  406. pr_err("[PREEMPT DURATION WARN] IRQ[%d:%s] dur %llu (s:%llu,e:%llu)\n",
  407. (int)b->last_event, isr_name(b->last_event), t_dur_tmp,
  408. usec_high(b->last_ts), usec_high(b->last_te));
  409. }
  410. #ifdef CONFIG_MT_SCHED_MON_DEFAULT_ENABLE
  411. if (oops_in_progress == 0)
  412. aee_kernel_warning_api(__FILE__, __LINE__, DB_OPT_DUMMY_DUMP | DB_OPT_FTRACE,
  413. "SCHED MONITOR : PREEMPT DURATION WARN",
  414. "PREEMPT DURATION WARN dur:%llu ns", t_dur);
  415. #endif
  416. }
  417. current->preempt_dur = 0;
  418. e->cur_ts = 0;
  419. e->last_te = 0;
  420. e->last_ts = 0;
  421. e->lock_dur = 0;
  422. }
  423. }
  424. #ifdef CONFIG_DEBUG_SPINLOCK
  425. void MT_trace_raw_spin_lock_s(raw_spinlock_t *lock)
  426. {
  427. struct sched_lock_event *lock_e;
  428. struct sched_stop_event *e;
  429. unsigned long long curr = 0;
  430. struct task_struct *owner = NULL;
  431. if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
  432. owner = lock->owner;
  433. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x1)) {
  434. curr = sched_clock();
  435. lock_e = &__raw_get_cpu_var(Raw_spin_lock_mon);
  436. e = &__raw_get_cpu_var(Preempt_disable_mon);
  437. if (e->cur_ts && (curr > e->cur_ts)) {
  438. lock_e->lock_ts = curr;
  439. lock_e->lock_owner = (unsigned long)owner;
  440. }
  441. }
  442. }
  443. void MT_trace_raw_spin_lock_e(raw_spinlock_t *lock)
  444. {
  445. struct sched_lock_event *lock_e;
  446. struct sched_stop_event *e;
  447. struct task_struct *owner = NULL;
  448. if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
  449. owner = lock->owner;
  450. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x1)) {
  451. lock_e = &__raw_get_cpu_var(Raw_spin_lock_mon);
  452. e = &__raw_get_cpu_var(Preempt_disable_mon);
  453. if (e->cur_ts && !e->last_te) {
  454. lock_e->lock_te = sched_clock();
  455. lock_e->lock_dur = lock_e->lock_te - lock_e->lock_ts;
  456. if (lock_e->lock_dur > WARN_PREEMPT_DUR) {
  457. e->lock_dur = lock_e->lock_dur;
  458. e->lock_owner = lock_e->lock_owner;
  459. e->lock = lock;
  460. }
  461. }
  462. }
  463. }
  464. #endif /*CONFIG_DEBUG_SPINLOCK*/
  465. /* IRQ off monitor */
  466. void MT_trace_irq_off(void)
  467. {
  468. struct sched_stop_event *e;
  469. #ifdef CONFIG_MT_SCHED_MONITOR
  470. struct stack_trace *trace;
  471. #endif
  472. e = &__raw_get_cpu_var(IRQ_disable_mon);
  473. e->cur_ts = sched_clock();
  474. #ifdef CONFIG_MT_SCHED_MONITOR
  475. /*save timestap */
  476. __raw_get_cpu_var(TS_irq_off) = sched_clock();
  477. trace = &__raw_get_cpu_var(MT_stack_trace);
  478. /*save backtraces */
  479. trace->nr_entries = 0;
  480. trace->max_entries = MAX_STACK_TRACE_DEPTH; /* 32 */
  481. trace->skip = 0;
  482. save_stack_trace_tsk(current, trace);
  483. #endif
  484. }
  485. void MT_trace_irq_on(void)
  486. {
  487. struct sched_stop_event *e;
  488. e = &__raw_get_cpu_var(IRQ_disable_mon);
  489. e->last_ts = e->cur_ts;
  490. e->cur_ts = 0;
  491. e->last_te = sched_clock();
  492. }
  493. #endif /*CONFIG_PREEMPT_MONITOR*/
  494. #ifdef CONFIG_MT_SCHED_MONITOR
  495. #include <linux/irqnr.h>
  496. #include <linux/kernel_stat.h>
  497. #include <asm/hardirq.h>
  498. DEFINE_PER_CPU(struct mt_irq_count, irq_count_mon);
  499. DEFINE_PER_CPU(struct mt_local_irq_count, ipi_count_mon);
  500. DEFINE_PER_CPU(unsigned long long, save_irq_count_time);
  501. #define TIME_200MS 200000000
  502. DEFINE_SPINLOCK(mt_irq_count_lock);
  503. void mt_save_irq_counts(int action)
  504. {
  505. int irq, cpu, count, irq_num;
  506. unsigned long flags;
  507. unsigned long long t_diff, t_avg;
  508. /* do not refresh data in 200ms */
  509. if (action == SCHED_TICK &&
  510. (sched_clock() - __raw_get_cpu_var(save_irq_count_time) < TIME_200MS))
  511. return;
  512. spin_lock_irqsave(&mt_irq_count_lock, flags);
  513. cpu = smp_processor_id();
  514. t_diff = sched_clock() - __raw_get_cpu_var(save_irq_count_time);
  515. __raw_get_cpu_var(save_irq_count_time) = sched_clock();
  516. for (irq = 0; irq < nr_irqs && irq < MAX_NR_IRQS; irq++) {
  517. irq_num = kstat_irqs_cpu(irq, cpu);
  518. count = irq_num - __raw_get_cpu_var(irq_count_mon).irqs[irq];
  519. if (count != 0) {
  520. t_avg = t_diff;
  521. do_div(t_avg, count);
  522. if (t_avg < WARN_BURST_IRQ_DETECT)
  523. pr_err("[BURST IRQ DURATION WARN] IRQ[%3d:%14s] +%d ( dur %lld us , avg %lld us)\n",
  524. irq, isr_name(irq), count, usec_high(t_diff), usec_high(t_avg));
  525. }
  526. __raw_get_cpu_var(irq_count_mon).irqs[irq] = irq_num;
  527. }
  528. #ifdef CONFIG_SMP
  529. for (irq = 0; irq < NR_IPI; irq++)
  530. __raw_get_cpu_var(ipi_count_mon).ipis[irq] = __get_irq_stat(cpu, ipi_irqs[irq]);
  531. #endif
  532. spin_unlock_irqrestore(&mt_irq_count_lock, flags);
  533. }
  534. #endif
  535. /**/
  536. #define TIME_2MS 2000000
  537. #define TIME_3MS 3000000
  538. #define TIME_5MS 5000000
  539. #define TIME_10MS 10000000
  540. #define TIME_20MS 20000000
  541. #define TIME_1S 1000000000
  542. #define TIME_5S 5000000000
  543. #define TIME_30S 30000000000
  544. static unsigned long long t_threshold = TIME_5S;
  545. static DEFINE_PER_CPU(int, MT_tracing_cpu);
  546. static DEFINE_PER_CPU(unsigned long long, t_irq_on);
  547. static DEFINE_PER_CPU(unsigned long long, t_irq_off);
  548. void MT_trace_softirqs_on(unsigned long ip) {}
  549. void MT_trace_softirqs_off(unsigned long ip) {}
  550. void mt_dump_irq_off_traces(void)
  551. {
  552. #ifdef CONFIG_MT_SCHED_MONITOR
  553. int i;
  554. struct stack_trace *trace;
  555. trace = &__raw_get_cpu_var(MT_stack_trace);
  556. pr_emerg("irq off at:%lld.%lu ms\n",
  557. SPLIT_NS_H(__raw_get_cpu_var(TS_irq_off)), SPLIT_NS_L(__raw_get_cpu_var(TS_irq_off)));
  558. pr_emerg("irq off backtraces:\n");
  559. for (i = 0; i < trace->nr_entries; i++)
  560. pr_emerg("[<%pK>] %pS\n", (void *)trace->entries[i], (void *)trace->entries[i]);
  561. #endif
  562. }
  563. EXPORT_SYMBOL(mt_dump_irq_off_traces);
  564. void MT_trace_hardirqs_on(void)
  565. {
  566. unsigned long long t_diff, t_on, t_off;
  567. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x2)) {
  568. if (0 == current->pid) /* Ignore swap thread */
  569. return;
  570. if (__raw_get_cpu_var(MT_trace_in_sched))
  571. return;
  572. if (__raw_get_cpu_var(MT_trace_in_resume_console))
  573. return;
  574. if (__raw_get_cpu_var(MT_tracing_cpu) == 1) {
  575. MT_trace_irq_on();
  576. t_on = sched_clock();
  577. t_off = __raw_get_cpu_var(t_irq_off);
  578. t_diff = t_on - t_off;
  579. __raw_get_cpu_var(t_irq_on) = t_on;
  580. if (t_diff > t_threshold) {
  581. pr_emerg("\n----------------------------[IRQ disable monitor]-------------------------\n");
  582. pr_emerg("[Sched Latency Warning:IRQ Disable too long(>%lldms)] Duration: %lld.%lu ms (off:%lld.%lums, on:%lld.%lums)\n",
  583. nsec_high(t_threshold),
  584. SPLIT_NS_H(t_diff), SPLIT_NS_L(t_diff), SPLIT_NS_H(t_off),
  585. SPLIT_NS_L(t_off), SPLIT_NS_H(t_on), SPLIT_NS_L(t_on));
  586. mt_dump_irq_off_traces();
  587. pr_emerg("irq on at: %lld.%lu ms\n", SPLIT_NS_H(t_on), SPLIT_NS_L(t_on));
  588. pr_emerg("irq on backtraces:\n");
  589. dump_stack();
  590. pr_emerg
  591. ("--------------------------------------------------------------------------\n\n");
  592. }
  593. __raw_get_cpu_var(t_irq_off) = 0;
  594. }
  595. __raw_get_cpu_var(MT_tracing_cpu) = 0;
  596. }
  597. }
  598. EXPORT_SYMBOL(MT_trace_hardirqs_on);
  599. void MT_trace_hardirqs_off(void)
  600. {
  601. if (unlikely(__raw_get_cpu_var(mtsched_mon_enabled) & 0x2)) {
  602. if (0 == current->pid) /* Ignore swap thread */
  603. return;
  604. if (__raw_get_cpu_var(MT_trace_in_sched))
  605. return;
  606. if (__raw_get_cpu_var(MT_trace_in_resume_console))
  607. return;
  608. if (__raw_get_cpu_var(MT_tracing_cpu) == 0) {
  609. MT_trace_irq_off();
  610. __raw_get_cpu_var(t_irq_off) = sched_clock();
  611. }
  612. __raw_get_cpu_var(MT_tracing_cpu) = 1;
  613. }
  614. }
  615. EXPORT_SYMBOL(MT_trace_hardirqs_off);
  616. /* --------------------------------------------------- */
  617. /* Define Proc entry */
  618. /* --------------------------------------------------- */
  619. MT_DEBUG_ENTRY(sched_monitor);
  620. static int mt_sched_monitor_show(struct seq_file *m, void *v)
  621. {
  622. int cpu;
  623. SEQ_printf(m, "=== mt Scheduler monitoring ===\n");
  624. SEQ_printf(m,
  625. " 0: Disable All\n 1: [Preemption] Monitor\n 2: [IRQ disable] Monitor\n 3: Enable All\n");
  626. for_each_possible_cpu(cpu) {
  627. SEQ_printf(m, " Scheduler Monitor:%d (CPU#%d)\n",
  628. per_cpu(mtsched_mon_enabled, cpu), cpu);
  629. }
  630. return 0;
  631. }
  632. void mt_sched_monitor_switch(int on)
  633. {
  634. int cpu;
  635. preempt_disable_notrace();
  636. mutex_lock(&mt_sched_mon_lock);
  637. for_each_possible_cpu(cpu) {
  638. pr_emerg("[mtprof] sched monitor on CPU#%d switch from %d to %d\n", cpu,
  639. per_cpu(mtsched_mon_enabled, cpu), on);
  640. per_cpu(mtsched_mon_enabled, cpu) = on; /* 0x1 || 0x2, IRQ & Preempt */
  641. }
  642. mutex_unlock(&mt_sched_mon_lock);
  643. preempt_enable_notrace();
  644. }
  645. static ssize_t mt_sched_monitor_write(struct file *filp, const char *ubuf,
  646. size_t cnt, loff_t *data)
  647. {
  648. char buf[64];
  649. unsigned long val;
  650. int ret;
  651. if (cnt >= sizeof(buf))
  652. return -EINVAL;
  653. if (copy_from_user(&buf, ubuf, cnt))
  654. return -EFAULT;
  655. buf[cnt] = 0;
  656. ret = kstrtoul(buf, 10, &val);
  657. if (ret < 0)
  658. return ret;
  659. /* 0: off, 1:on */
  660. /* val = !!val; */
  661. if (val == 8)
  662. mt_dump_sched_traces();
  663. if (val == 18) /* 0x12 */
  664. mt_dump_irq_off_traces();
  665. mt_sched_monitor_switch(val);
  666. pr_err(" to %lu\n", val);
  667. return cnt;
  668. }
  669. void reset_sched_monitor(void)
  670. {
  671. }
  672. void start_sched_monitor(void)
  673. {
  674. }
  675. void stop_sched_monitor(void)
  676. {
  677. }
  678. #define DECLARE_MT_SCHED_MATCH(param, warn_dur) \
  679. static ssize_t mt_sched_monitor_##param##_write( \
  680. struct file *filp, \
  681. const char *ubuf, \
  682. size_t cnt, loff_t *data) \
  683. { \
  684. char buf[64]; \
  685. unsigned long val; \
  686. int ret; \
  687. \
  688. if (cnt >= sizeof(buf)) \
  689. return -EINVAL; \
  690. \
  691. if (copy_from_user(&buf, ubuf, cnt)) \
  692. return -EFAULT; \
  693. \
  694. buf[cnt] = 0; \
  695. ret = kstrtoul(buf, 10, &val); \
  696. if (ret < 0) \
  697. return ret; \
  698. \
  699. warn_dur = val; \
  700. \
  701. return cnt; \
  702. \
  703. } \
  704. \
  705. static int mt_sched_monitor_##param##_show( \
  706. struct seq_file *m, \
  707. void *v) \
  708. { \
  709. SEQ_printf(m, \
  710. "%d ns\n", warn_dur); \
  711. return 0; \
  712. } \
  713. static int mt_sched_monitor_##param##_open(struct inode *inode, struct file *file) \
  714. { \
  715. return single_open(file, mt_sched_monitor_##param##_show, inode->i_private); \
  716. } \
  717. \
  718. static const struct file_operations mt_sched_monitor_##param##_fops = { \
  719. .open = mt_sched_monitor_##param##_open, \
  720. .write = mt_sched_monitor_##param##_write,\
  721. .read = seq_read, \
  722. .llseek = seq_lseek, \
  723. .release = single_release, \
  724. }
  725. DECLARE_MT_SCHED_MATCH(ISR_DUR, WARN_ISR_DUR);
  726. DECLARE_MT_SCHED_MATCH(SOFTIRQ_DUR, WARN_SOFTIRQ_DUR);
  727. DECLARE_MT_SCHED_MATCH(TASKLET_DUR, WARN_TASKLET_DUR);
  728. DECLARE_MT_SCHED_MATCH(HRTIMER_DUR, WARN_HRTIMER_DUR);
  729. DECLARE_MT_SCHED_MATCH(STIMER_DUR, WARN_STIMER_DUR);
  730. DECLARE_MT_SCHED_MATCH(PREEMPT_DUR, WARN_PREEMPT_DUR);
  731. DECLARE_MT_SCHED_MATCH(BURST_IRQ, WARN_BURST_IRQ_DETECT);
  732. static int __init init_mtsched_mon(void)
  733. {
  734. #ifdef CONFIG_MT_SCHED_MONITOR
  735. int cpu;
  736. struct proc_dir_entry *pe;
  737. for_each_possible_cpu(cpu) {
  738. per_cpu(MT_stack_trace, cpu).entries =
  739. kmalloc(MAX_STACK_TRACE_DEPTH * sizeof(unsigned long), GFP_KERNEL);
  740. per_cpu(MT_tracing_cpu, cpu) = 0;
  741. per_cpu(mtsched_mon_enabled, cpu) = 0; /* 0x1 || 0x2, IRQ & Preempt */
  742. per_cpu(ISR_mon, cpu).type = evt_ISR;
  743. per_cpu(SoftIRQ_mon, cpu).type = evt_SOFTIRQ;
  744. per_cpu(tasklet_mon, cpu).type = evt_TASKLET;
  745. per_cpu(hrt_mon, cpu).type = evt_HRTIMER;
  746. per_cpu(sft_mon, cpu).type = evt_STIMER;
  747. }
  748. WARN_ISR_DUR = TIME_3MS;
  749. WARN_SOFTIRQ_DUR = TIME_5MS;
  750. WARN_TASKLET_DUR = TIME_10MS;
  751. WARN_HRTIMER_DUR = TIME_3MS;
  752. WARN_STIMER_DUR = TIME_10MS;
  753. WARN_BURST_IRQ_DETECT = 25000;
  754. WARN_PREEMPT_DUR = TIME_10MS;
  755. if (!proc_mkdir("mtmon", NULL))
  756. return -1;
  757. pe = proc_create("mtmon/sched_mon", 0664, NULL, &mt_sched_monitor_fops);
  758. if (!pe)
  759. return -ENOMEM;
  760. pe = proc_create("mtmon/sched_mon_duration_ISR", 0664, NULL, &mt_sched_monitor_ISR_DUR_fops);
  761. if (!pe)
  762. return -ENOMEM;
  763. pe = proc_create("mtmon/sched_mon_duration_SOFTIRQ", 0664, NULL, &mt_sched_monitor_SOFTIRQ_DUR_fops);
  764. if (!pe)
  765. return -ENOMEM;
  766. pe = proc_create("mtmon/sched_mon_duration_TASKLET", 0664, NULL, &mt_sched_monitor_TASKLET_DUR_fops);
  767. if (!pe)
  768. return -ENOMEM;
  769. pe = proc_create("mtmon/sched_mon_duration_HRTIMER", 0664, NULL, &mt_sched_monitor_HRTIMER_DUR_fops);
  770. if (!pe)
  771. return -ENOMEM;
  772. pe = proc_create("mtmon/sched_mon_duration_STIMER", 0664, NULL, &mt_sched_monitor_STIMER_DUR_fops);
  773. if (!pe)
  774. return -ENOMEM;
  775. pe = proc_create("mtmon/sched_mon_duration_BURST_IRQ", 0664, NULL, &mt_sched_monitor_BURST_IRQ_fops);
  776. if (!pe)
  777. return -ENOMEM;
  778. pe = proc_create("mtmon/sched_mon_duration_PREEMPT", 0664, NULL, &mt_sched_monitor_PREEMPT_DUR_fops);
  779. if (!pe)
  780. return -ENOMEM;
  781. #endif
  782. return 0;
  783. }
  784. device_initcall(init_mtsched_mon);