aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
-rw-r--r--kernel/trace/trace.c149
-rw-r--r--kernel/trace/trace.h7
-rw-r--r--kernel/trace/trace_output.c107
-rw-r--r--kernel/trace/trace_output.h3
4 files changed, 151 insertions, 115 deletions
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 2f8ac1f008f5..5ec49c3c1597 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -227,7 +227,7 @@ static DECLARE_WAIT_QUEUE_HEAD(trace_wait);
227 227
228/* trace_flags holds trace_options default values */ 228/* trace_flags holds trace_options default values */
229unsigned long trace_flags = TRACE_ITER_PRINT_PARENT | TRACE_ITER_PRINTK | 229unsigned long trace_flags = TRACE_ITER_PRINT_PARENT | TRACE_ITER_PRINTK |
230 TRACE_ITER_ANNOTATE; 230 TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO;
231 231
232/** 232/**
233 * trace_wake_up - wake up tasks waiting for trace input 233 * trace_wake_up - wake up tasks waiting for trace input
@@ -285,6 +285,7 @@ static const char *trace_options[] = {
285 "userstacktrace", 285 "userstacktrace",
286 "sym-userobj", 286 "sym-userobj",
287 "printk-msg-only", 287 "printk-msg-only",
288 "context-info",
288 NULL 289 NULL
289}; 290};
290 291
@@ -1171,8 +1172,8 @@ __find_next_entry(struct trace_iterator *iter, int *ent_cpu, u64 *ent_ts)
1171} 1172}
1172 1173
1173/* Find the next real entry, without updating the iterator itself */ 1174/* Find the next real entry, without updating the iterator itself */
1174static struct trace_entry * 1175struct trace_entry *trace_find_next_entry(struct trace_iterator *iter,
1175find_next_entry(struct trace_iterator *iter, int *ent_cpu, u64 *ent_ts) 1176 int *ent_cpu, u64 *ent_ts)
1176{ 1177{
1177 return __find_next_entry(iter, ent_cpu, ent_ts); 1178 return __find_next_entry(iter, ent_cpu, ent_ts);
1178} 1179}
@@ -1351,57 +1352,6 @@ print_trace_header(struct seq_file *m, struct trace_iterator *iter)
1351 seq_puts(m, "\n"); 1352 seq_puts(m, "\n");
1352} 1353}
1353 1354
1354static void
1355lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
1356{
1357 int hardirq, softirq;
1358 char *comm;
1359
1360 comm = trace_find_cmdline(entry->pid);
1361
1362 trace_seq_printf(s, "%8.8s-%-5d ", comm, entry->pid);
1363 trace_seq_printf(s, "%3d", cpu);
1364 trace_seq_printf(s, "%c%c",
1365 (entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
1366 (entry->flags & TRACE_FLAG_IRQS_NOSUPPORT) ? 'X' : '.',
1367 ((entry->flags & TRACE_FLAG_NEED_RESCHED) ? 'N' : '.'));
1368
1369 hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
1370 softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
1371 if (hardirq && softirq) {
1372 trace_seq_putc(s, 'H');
1373 } else {
1374 if (hardirq) {
1375 trace_seq_putc(s, 'h');
1376 } else {
1377 if (softirq)
1378 trace_seq_putc(s, 's');
1379 else
1380 trace_seq_putc(s, '.');
1381 }
1382 }
1383
1384 if (entry->preempt_count)
1385 trace_seq_printf(s, "%x", entry->preempt_count);
1386 else
1387 trace_seq_puts(s, ".");
1388}
1389
1390unsigned long preempt_mark_thresh = 100;
1391
1392static void
1393lat_print_timestamp(struct trace_seq *s, u64 abs_usecs,
1394 unsigned long rel_usecs)
1395{
1396 trace_seq_printf(s, " %4lldus", abs_usecs);
1397 if (rel_usecs > preempt_mark_thresh)
1398 trace_seq_puts(s, "!: ");
1399 else if (rel_usecs > 1)
1400 trace_seq_puts(s, "+: ");
1401 else
1402 trace_seq_puts(s, " : ");
1403}
1404
1405static void test_cpu_buff_start(struct trace_iterator *iter) 1355static void test_cpu_buff_start(struct trace_iterator *iter)
1406{ 1356{
1407 struct trace_seq *s = &iter->seq; 1357 struct trace_seq *s = &iter->seq;
@@ -1419,46 +1369,24 @@ static void test_cpu_buff_start(struct trace_iterator *iter)
1419 trace_seq_printf(s, "##### CPU %u buffer started ####\n", iter->cpu); 1369 trace_seq_printf(s, "##### CPU %u buffer started ####\n", iter->cpu);
1420} 1370}
1421 1371
1422static enum print_line_t 1372static enum print_line_t print_lat_fmt(struct trace_iterator *iter)
1423print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
1424{ 1373{
1425 struct trace_seq *s = &iter->seq; 1374 struct trace_seq *s = &iter->seq;
1426 unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK); 1375 unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
1427 struct trace_entry *next_entry;
1428 struct trace_event *event; 1376 struct trace_event *event;
1429 unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE);
1430 struct trace_entry *entry = iter->ent; 1377 struct trace_entry *entry = iter->ent;
1431 unsigned long abs_usecs;
1432 unsigned long rel_usecs;
1433 u64 next_ts;
1434 char *comm;
1435 int ret; 1378 int ret;
1436 1379
1437 test_cpu_buff_start(iter); 1380 test_cpu_buff_start(iter);
1438 1381
1439 next_entry = find_next_entry(iter, NULL, &next_ts); 1382 event = ftrace_find_event(entry->type);
1440 if (!next_entry) 1383
1441 next_ts = iter->ts; 1384 if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
1442 rel_usecs = ns2usecs(next_ts - iter->ts); 1385 ret = trace_print_lat_context(iter);
1443 abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); 1386 if (ret)
1444 1387 return ret;
1445 if (verbose) {
1446 comm = trace_find_cmdline(entry->pid);
1447 trace_seq_printf(s, "%16s %5d %3d %d %08x %08x [%08lx]"
1448 " %ld.%03ldms (+%ld.%03ldms): ",
1449 comm,
1450 entry->pid, cpu, entry->flags,
1451 entry->preempt_count, trace_idx,
1452 ns2usecs(iter->ts),
1453 abs_usecs/1000,
1454 abs_usecs % 1000, rel_usecs/1000,
1455 rel_usecs % 1000);
1456 } else {
1457 lat_print_generic(s, entry, cpu);
1458 lat_print_timestamp(s, abs_usecs, rel_usecs);
1459 } 1388 }
1460 1389
1461 event = ftrace_find_event(entry->type);
1462 if (event && event->latency_trace) { 1390 if (event && event->latency_trace) {
1463 ret = event->latency_trace(s, entry, sym_flags); 1391 ret = event->latency_trace(s, entry, sym_flags);
1464 if (ret) 1392 if (ret)
@@ -1476,33 +1404,20 @@ static enum print_line_t print_trace_fmt(struct trace_iterator *iter)
1476 unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK); 1404 unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
1477 struct trace_entry *entry; 1405 struct trace_entry *entry;
1478 struct trace_event *event; 1406 struct trace_event *event;
1479 unsigned long usec_rem;
1480 unsigned long long t;
1481 unsigned long secs;
1482 char *comm;
1483 int ret; 1407 int ret;
1484 1408
1485 entry = iter->ent; 1409 entry = iter->ent;
1486 1410
1487 test_cpu_buff_start(iter); 1411 test_cpu_buff_start(iter);
1488 1412
1489 comm = trace_find_cmdline(iter->ent->pid); 1413 event = ftrace_find_event(entry->type);
1490
1491 t = ns2usecs(iter->ts);
1492 usec_rem = do_div(t, 1000000ULL);
1493 secs = (unsigned long)t;
1494 1414
1495 ret = trace_seq_printf(s, "%16s-%-5d ", comm, entry->pid); 1415 if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
1496 if (!ret) 1416 ret = trace_print_context(iter);
1497 return TRACE_TYPE_PARTIAL_LINE; 1417 if (ret)
1498 ret = trace_seq_printf(s, "[%03d] ", iter->cpu); 1418 return ret;
1499 if (!ret) 1419 }
1500 return TRACE_TYPE_PARTIAL_LINE;
1501 ret = trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem);
1502 if (!ret)
1503 return TRACE_TYPE_PARTIAL_LINE;
1504 1420
1505 event = ftrace_find_event(entry->type);
1506 if (event && event->trace) { 1421 if (event && event->trace) {
1507 ret = event->trace(s, entry, sym_flags); 1422 ret = event->trace(s, entry, sym_flags);
1508 if (ret) 1423 if (ret)
@@ -1525,10 +1440,12 @@ static enum print_line_t print_raw_fmt(struct trace_iterator *iter)
1525 1440
1526 entry = iter->ent; 1441 entry = iter->ent;
1527 1442
1528 ret = trace_seq_printf(s, "%d %d %llu ", 1443 if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
1529 entry->pid, iter->cpu, iter->ts); 1444 ret = trace_seq_printf(s, "%d %d %llu ",
1530 if (!ret) 1445 entry->pid, iter->cpu, iter->ts);
1531 return TRACE_TYPE_PARTIAL_LINE; 1446 if (!ret)
1447 return TRACE_TYPE_PARTIAL_LINE;
1448 }
1532 1449
1533 event = ftrace_find_event(entry->type); 1450 event = ftrace_find_event(entry->type);
1534 if (event && event->raw) { 1451 if (event && event->raw) {
@@ -1553,9 +1470,11 @@ static enum print_line_t print_hex_fmt(struct trace_iterator *iter)
1553 1470
1554 entry = iter->ent; 1471 entry = iter->ent;
1555 1472
1556 SEQ_PUT_HEX_FIELD_RET(s, entry->pid); 1473 if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
1557 SEQ_PUT_HEX_FIELD_RET(s, iter->cpu); 1474 SEQ_PUT_HEX_FIELD_RET(s, entry->pid);
1558 SEQ_PUT_HEX_FIELD_RET(s, iter->ts); 1475 SEQ_PUT_HEX_FIELD_RET(s, iter->cpu);
1476 SEQ_PUT_HEX_FIELD_RET(s, iter->ts);
1477 }
1559 1478
1560 event = ftrace_find_event(entry->type); 1479 event = ftrace_find_event(entry->type);
1561 if (event && event->hex) 1480 if (event && event->hex)
@@ -1575,7 +1494,7 @@ static enum print_line_t print_printk_msg_only(struct trace_iterator *iter)
1575 1494
1576 trace_assign_type(field, entry); 1495 trace_assign_type(field, entry);
1577 1496
1578 ret = trace_seq_printf(s, field->buf); 1497 ret = trace_seq_printf(s, "%s", field->buf);
1579 if (!ret) 1498 if (!ret)
1580 return TRACE_TYPE_PARTIAL_LINE; 1499 return TRACE_TYPE_PARTIAL_LINE;
1581 1500
@@ -1590,9 +1509,11 @@ static enum print_line_t print_bin_fmt(struct trace_iterator *iter)
1590 1509
1591 entry = iter->ent; 1510 entry = iter->ent;
1592 1511
1593 SEQ_PUT_FIELD_RET(s, entry->pid); 1512 if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
1594 SEQ_PUT_FIELD_RET(s, entry->cpu); 1513 SEQ_PUT_FIELD_RET(s, entry->pid);
1595 SEQ_PUT_FIELD_RET(s, iter->ts); 1514 SEQ_PUT_FIELD_RET(s, entry->cpu);
1515 SEQ_PUT_FIELD_RET(s, iter->ts);
1516 }
1596 1517
1597 event = ftrace_find_event(entry->type); 1518 event = ftrace_find_event(entry->type);
1598 if (event && event->binary) 1519 if (event && event->binary)
@@ -1643,7 +1564,7 @@ static enum print_line_t print_trace_line(struct trace_iterator *iter)
1643 return print_raw_fmt(iter); 1564 return print_raw_fmt(iter);
1644 1565
1645 if (iter->iter_flags & TRACE_FILE_LAT_FMT) 1566 if (iter->iter_flags & TRACE_FILE_LAT_FMT)
1646 return print_lat_fmt(iter, iter->idx, iter->cpu); 1567 return print_lat_fmt(iter);
1647 1568
1648 return print_trace_fmt(iter); 1569 return print_trace_fmt(iter);
1649} 1570}
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index e603a291134b..f0c7a0f08cac 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -405,6 +405,10 @@ void init_tracer_sysprof_debugfs(struct dentry *d_tracer);
405 405
406struct trace_entry *tracing_get_trace_entry(struct trace_array *tr, 406struct trace_entry *tracing_get_trace_entry(struct trace_array *tr,
407 struct trace_array_cpu *data); 407 struct trace_array_cpu *data);
408
409struct trace_entry *trace_find_next_entry(struct trace_iterator *iter,
410 int *ent_cpu, u64 *ent_ts);
411
408void tracing_generic_entry_update(struct trace_entry *entry, 412void tracing_generic_entry_update(struct trace_entry *entry,
409 unsigned long flags, 413 unsigned long flags,
410 int pc); 414 int pc);
@@ -591,7 +595,8 @@ enum trace_iterator_flags {
591 TRACE_ITER_ANNOTATE = 0x2000, 595 TRACE_ITER_ANNOTATE = 0x2000,
592 TRACE_ITER_USERSTACKTRACE = 0x4000, 596 TRACE_ITER_USERSTACKTRACE = 0x4000,
593 TRACE_ITER_SYM_USEROBJ = 0x8000, 597 TRACE_ITER_SYM_USEROBJ = 0x8000,
594 TRACE_ITER_PRINTK_MSGONLY = 0x10000 598 TRACE_ITER_PRINTK_MSGONLY = 0x10000,
599 TRACE_ITER_CONTEXT_INFO = 0x20000 /* Print pid/cpu/time */
595}; 600};
596 601
597/* 602/*
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 1a4e144a9f8f..a5752d4d3c33 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -286,6 +286,113 @@ seq_print_ip_sym(struct trace_seq *s, unsigned long ip, unsigned long sym_flags)
286 return ret; 286 return ret;
287} 287}
288 288
289static void
290lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
291{
292 int hardirq, softirq;
293 char *comm;
294
295 comm = trace_find_cmdline(entry->pid);
296
297 trace_seq_printf(s, "%8.8s-%-5d ", comm, entry->pid);
298 trace_seq_printf(s, "%3d", cpu);
299 trace_seq_printf(s, "%c%c",
300 (entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
301 (entry->flags & TRACE_FLAG_IRQS_NOSUPPORT) ? 'X' : '.',
302 ((entry->flags & TRACE_FLAG_NEED_RESCHED) ? 'N' : '.'));
303
304 hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
305 softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
306 if (hardirq && softirq) {
307 trace_seq_putc(s, 'H');
308 } else {
309 if (hardirq) {
310 trace_seq_putc(s, 'h');
311 } else {
312 if (softirq)
313 trace_seq_putc(s, 's');
314 else
315 trace_seq_putc(s, '.');
316 }
317 }
318
319 if (entry->preempt_count)
320 trace_seq_printf(s, "%x", entry->preempt_count);
321 else
322 trace_seq_puts(s, ".");
323}
324
325static unsigned long preempt_mark_thresh = 100;
326
327static void
328lat_print_timestamp(struct trace_seq *s, u64 abs_usecs,
329 unsigned long rel_usecs)
330{
331 trace_seq_printf(s, " %4lldus", abs_usecs);
332 if (rel_usecs > preempt_mark_thresh)
333 trace_seq_puts(s, "!: ");
334 else if (rel_usecs > 1)
335 trace_seq_puts(s, "+: ");
336 else
337 trace_seq_puts(s, " : ");
338}
339
340int trace_print_context(struct trace_iterator *iter)
341{
342 struct trace_seq *s = &iter->seq;
343 struct trace_entry *entry = iter->ent;
344 char *comm = trace_find_cmdline(entry->pid);
345 unsigned long long t = ns2usecs(iter->ts);
346 unsigned long usec_rem = do_div(t, USEC_PER_SEC);
347 unsigned long secs = (unsigned long)t;
348
349 if (!trace_seq_printf(s, "%16s-%-5d ", comm, entry->pid))
350 goto partial;
351 if (!trace_seq_printf(s, "[%03d] ", entry->cpu))
352 goto partial;
353 if (!trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem))
354 goto partial;
355
356 return 0;
357
358partial:
359 return TRACE_TYPE_PARTIAL_LINE;
360}
361
362int trace_print_lat_context(struct trace_iterator *iter)
363{
364 u64 next_ts;
365 struct trace_seq *s = &iter->seq;
366 struct trace_entry *entry = iter->ent,
367 *next_entry = trace_find_next_entry(iter, NULL,
368 &next_ts);
369 unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE);
370 unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start);
371 unsigned long rel_usecs;
372
373 if (!next_entry)
374 next_ts = iter->ts;
375 rel_usecs = ns2usecs(next_ts - iter->ts);
376
377 if (verbose) {
378 char *comm = trace_find_cmdline(entry->pid);
379 trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08lx]"
380 " %ld.%03ldms (+%ld.%03ldms): ",
381 comm,
382 entry->pid, entry->cpu, entry->flags,
383 entry->preempt_count, iter->idx,
384 ns2usecs(iter->ts),
385 abs_usecs/1000,
386 abs_usecs % 1000, rel_usecs/1000,
387 rel_usecs % 1000);
388 } else {
389 lat_print_generic(s, entry, entry->cpu);
390 lat_print_timestamp(s, abs_usecs, rel_usecs);
391 }
392
393 return 0;
394}
395
289static const char state_to_char[] = TASK_STATE_TO_CHAR_STR; 396static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
290 397
291static int task_state_char(unsigned long state) 398static int task_state_char(unsigned long state)
diff --git a/kernel/trace/trace_output.h b/kernel/trace/trace_output.h
index 1cbab5e3dc99..ec2ed90f10f0 100644
--- a/kernel/trace/trace_output.h
+++ b/kernel/trace/trace_output.h
@@ -33,6 +33,9 @@ int seq_print_userip_objs(const struct userstack_entry *entry,
33int seq_print_user_ip(struct trace_seq *s, struct mm_struct *mm, 33int seq_print_user_ip(struct trace_seq *s, struct mm_struct *mm,
34 unsigned long ip, unsigned long sym_flags); 34 unsigned long ip, unsigned long sym_flags);
35 35
36int trace_print_context(struct trace_iterator *iter);
37int trace_print_lat_context(struct trace_iterator *iter);
38
36struct trace_event *ftrace_find_event(int type); 39struct trace_event *ftrace_find_event(int type);
37int register_ftrace_event(struct trace_event *event); 40int register_ftrace_event(struct trace_event *event);
38int unregister_ftrace_event(struct trace_event *event); 41int unregister_ftrace_event(struct trace_event *event);