diff options
| -rw-r--r-- | arch/x86/include/asm/trace_clock.h | 2 | ||||
| -rw-r--r-- | include/linux/ftrace_event.h | 6 | ||||
| -rw-r--r-- | kernel/trace/trace.c | 15 | ||||
| -rw-r--r-- | kernel/trace/trace.h | 4 | ||||
| -rw-r--r-- | kernel/trace/trace_output.c | 78 |
5 files changed, 72 insertions, 33 deletions
diff --git a/arch/x86/include/asm/trace_clock.h b/arch/x86/include/asm/trace_clock.h index 5c1652728b6d..beab86cc282d 100644 --- a/arch/x86/include/asm/trace_clock.h +++ b/arch/x86/include/asm/trace_clock.h | |||
| @@ -9,7 +9,7 @@ | |||
| 9 | extern u64 notrace trace_clock_x86_tsc(void); | 9 | extern u64 notrace trace_clock_x86_tsc(void); |
| 10 | 10 | ||
| 11 | # define ARCH_TRACE_CLOCKS \ | 11 | # define ARCH_TRACE_CLOCKS \ |
| 12 | { trace_clock_x86_tsc, "x86-tsc" }, | 12 | { trace_clock_x86_tsc, "x86-tsc", .in_ns = 0 }, |
| 13 | 13 | ||
| 14 | #else /* !CONFIG_X86_TSC */ | 14 | #else /* !CONFIG_X86_TSC */ |
| 15 | 15 | ||
diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h index b80c8ddfbbdc..a3d489531d83 100644 --- a/include/linux/ftrace_event.h +++ b/include/linux/ftrace_event.h | |||
| @@ -86,6 +86,12 @@ struct trace_iterator { | |||
| 86 | cpumask_var_t started; | 86 | cpumask_var_t started; |
| 87 | }; | 87 | }; |
| 88 | 88 | ||
| 89 | enum trace_iter_flags { | ||
| 90 | TRACE_FILE_LAT_FMT = 1, | ||
| 91 | TRACE_FILE_ANNOTATE = 2, | ||
| 92 | TRACE_FILE_TIME_IN_NS = 4, | ||
| 93 | }; | ||
| 94 | |||
| 89 | 95 | ||
| 90 | struct trace_event; | 96 | struct trace_event; |
| 91 | 97 | ||
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 0d20620c0d27..d943e69569cd 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c | |||
| @@ -484,10 +484,11 @@ static const char *trace_options[] = { | |||
| 484 | static struct { | 484 | static struct { |
| 485 | u64 (*func)(void); | 485 | u64 (*func)(void); |
| 486 | const char *name; | 486 | const char *name; |
| 487 | int in_ns; /* is this clock in nanoseconds? */ | ||
| 487 | } trace_clocks[] = { | 488 | } trace_clocks[] = { |
| 488 | { trace_clock_local, "local" }, | 489 | { trace_clock_local, "local", 1 }, |
| 489 | { trace_clock_global, "global" }, | 490 | { trace_clock_global, "global", 1 }, |
| 490 | { trace_clock_counter, "counter" }, | 491 | { trace_clock_counter, "counter", 0 }, |
| 491 | ARCH_TRACE_CLOCKS | 492 | ARCH_TRACE_CLOCKS |
| 492 | }; | 493 | }; |
| 493 | 494 | ||
| @@ -2478,6 +2479,10 @@ __tracing_open(struct inode *inode, struct file *file) | |||
| 2478 | if (ring_buffer_overruns(iter->tr->buffer)) | 2479 | if (ring_buffer_overruns(iter->tr->buffer)) |
| 2479 | iter->iter_flags |= TRACE_FILE_ANNOTATE; | 2480 | iter->iter_flags |= TRACE_FILE_ANNOTATE; |
| 2480 | 2481 | ||
| 2482 | /* Output in nanoseconds only if we are using a clock in nanoseconds. */ | ||
| 2483 | if (trace_clocks[trace_clock_id].in_ns) | ||
| 2484 | iter->iter_flags |= TRACE_FILE_TIME_IN_NS; | ||
| 2485 | |||
| 2481 | /* stop the trace while dumping */ | 2486 | /* stop the trace while dumping */ |
| 2482 | tracing_stop(); | 2487 | tracing_stop(); |
| 2483 | 2488 | ||
| @@ -3339,6 +3344,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) | |||
| 3339 | if (trace_flags & TRACE_ITER_LATENCY_FMT) | 3344 | if (trace_flags & TRACE_ITER_LATENCY_FMT) |
| 3340 | iter->iter_flags |= TRACE_FILE_LAT_FMT; | 3345 | iter->iter_flags |= TRACE_FILE_LAT_FMT; |
| 3341 | 3346 | ||
| 3347 | /* Output in nanoseconds only if we are using a clock in nanoseconds. */ | ||
| 3348 | if (trace_clocks[trace_clock_id].in_ns) | ||
| 3349 | iter->iter_flags |= TRACE_FILE_TIME_IN_NS; | ||
| 3350 | |||
| 3342 | iter->cpu_file = cpu_file; | 3351 | iter->cpu_file = cpu_file; |
| 3343 | iter->tr = &global_trace; | 3352 | iter->tr = &global_trace; |
| 3344 | mutex_init(&iter->mutex); | 3353 | mutex_init(&iter->mutex); |
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 55010ed175f0..c75d7988902c 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h | |||
| @@ -406,10 +406,6 @@ void tracing_stop_sched_switch_record(void); | |||
| 406 | void tracing_start_sched_switch_record(void); | 406 | void tracing_start_sched_switch_record(void); |
| 407 | int register_tracer(struct tracer *type); | 407 | int register_tracer(struct tracer *type); |
| 408 | int is_tracing_stopped(void); | 408 | int is_tracing_stopped(void); |
| 409 | enum trace_file_type { | ||
| 410 | TRACE_FILE_LAT_FMT = 1, | ||
| 411 | TRACE_FILE_ANNOTATE = 2, | ||
| 412 | }; | ||
| 413 | 409 | ||
| 414 | extern cpumask_var_t __read_mostly tracing_buffer_mask; | 410 | extern cpumask_var_t __read_mostly tracing_buffer_mask; |
| 415 | 411 | ||
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 123b189c732c..194d79602dc7 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c | |||
| @@ -610,24 +610,54 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) | |||
| 610 | return trace_print_lat_fmt(s, entry); | 610 | return trace_print_lat_fmt(s, entry); |
| 611 | } | 611 | } |
| 612 | 612 | ||
| 613 | static unsigned long preempt_mark_thresh = 100; | 613 | static unsigned long preempt_mark_thresh_us = 100; |
| 614 | 614 | ||
| 615 | static int | 615 | static int |
| 616 | lat_print_timestamp(struct trace_seq *s, u64 abs_usecs, | 616 | lat_print_timestamp(struct trace_iterator *iter, u64 next_ts) |
| 617 | unsigned long rel_usecs) | ||
| 618 | { | 617 | { |
| 619 | return trace_seq_printf(s, " %4lldus%c: ", abs_usecs, | 618 | unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE; |
| 620 | rel_usecs > preempt_mark_thresh ? '!' : | 619 | unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS; |
| 621 | rel_usecs > 1 ? '+' : ' '); | 620 | unsigned long long abs_ts = iter->ts - iter->tr->time_start; |
| 621 | unsigned long long rel_ts = next_ts - iter->ts; | ||
| 622 | struct trace_seq *s = &iter->seq; | ||
| 623 | |||
| 624 | if (in_ns) { | ||
| 625 | abs_ts = ns2usecs(abs_ts); | ||
| 626 | rel_ts = ns2usecs(rel_ts); | ||
| 627 | } | ||
| 628 | |||
| 629 | if (verbose && in_ns) { | ||
| 630 | unsigned long abs_usec = do_div(abs_ts, USEC_PER_MSEC); | ||
| 631 | unsigned long abs_msec = (unsigned long)abs_ts; | ||
| 632 | unsigned long rel_usec = do_div(rel_ts, USEC_PER_MSEC); | ||
| 633 | unsigned long rel_msec = (unsigned long)rel_ts; | ||
| 634 | |||
| 635 | return trace_seq_printf( | ||
| 636 | s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ", | ||
| 637 | ns2usecs(iter->ts), | ||
| 638 | abs_msec, abs_usec, | ||
| 639 | rel_msec, rel_usec); | ||
| 640 | } else if (verbose && !in_ns) { | ||
| 641 | return trace_seq_printf( | ||
| 642 | s, "[%016llx] %lld (+%lld): ", | ||
| 643 | iter->ts, abs_ts, rel_ts); | ||
| 644 | } else if (!verbose && in_ns) { | ||
| 645 | return trace_seq_printf( | ||
| 646 | s, " %4lldus%c: ", | ||
| 647 | abs_ts, | ||
| 648 | rel_ts > preempt_mark_thresh_us ? '!' : | ||
| 649 | rel_ts > 1 ? '+' : ' '); | ||
| 650 | } else { /* !verbose && !in_ns */ | ||
| 651 | return trace_seq_printf(s, " %4lld: ", abs_ts); | ||
| 652 | } | ||
| 622 | } | 653 | } |
| 623 | 654 | ||
| 624 | int trace_print_context(struct trace_iterator *iter) | 655 | int trace_print_context(struct trace_iterator *iter) |
| 625 | { | 656 | { |
| 626 | struct trace_seq *s = &iter->seq; | 657 | struct trace_seq *s = &iter->seq; |
| 627 | struct trace_entry *entry = iter->ent; | 658 | struct trace_entry *entry = iter->ent; |
| 628 | unsigned long long t = ns2usecs(iter->ts); | 659 | unsigned long long t; |
| 629 | unsigned long usec_rem = do_div(t, USEC_PER_SEC); | 660 | unsigned long secs, usec_rem; |
| 630 | unsigned long secs = (unsigned long)t; | ||
| 631 | char comm[TASK_COMM_LEN]; | 661 | char comm[TASK_COMM_LEN]; |
| 632 | int ret; | 662 | int ret; |
| 633 | 663 | ||
| @@ -644,8 +674,13 @@ int trace_print_context(struct trace_iterator *iter) | |||
| 644 | return 0; | 674 | return 0; |
| 645 | } | 675 | } |
| 646 | 676 | ||
| 647 | return trace_seq_printf(s, " %5lu.%06lu: ", | 677 | if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) { |
| 648 | secs, usec_rem); | 678 | t = ns2usecs(iter->ts); |
| 679 | usec_rem = do_div(t, USEC_PER_SEC); | ||
| 680 | secs = (unsigned long)t; | ||
| 681 | return trace_seq_printf(s, " %5lu.%06lu: ", secs, usec_rem); | ||
| 682 | } else | ||
| 683 | return trace_seq_printf(s, " %12llu: ", iter->ts); | ||
| 649 | } | 684 | } |
| 650 | 685 | ||
| 651 | int trace_print_lat_context(struct trace_iterator *iter) | 686 | int trace_print_lat_context(struct trace_iterator *iter) |
| @@ -659,36 +694,29 @@ int trace_print_lat_context(struct trace_iterator *iter) | |||
| 659 | *next_entry = trace_find_next_entry(iter, NULL, | 694 | *next_entry = trace_find_next_entry(iter, NULL, |
| 660 | &next_ts); | 695 | &next_ts); |
| 661 | unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); | 696 | unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE); |
| 662 | unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start); | ||
| 663 | unsigned long rel_usecs; | ||
| 664 | 697 | ||
| 665 | /* Restore the original ent_size */ | 698 | /* Restore the original ent_size */ |
| 666 | iter->ent_size = ent_size; | 699 | iter->ent_size = ent_size; |
| 667 | 700 | ||
| 668 | if (!next_entry) | 701 | if (!next_entry) |
| 669 | next_ts = iter->ts; | 702 | next_ts = iter->ts; |
| 670 | rel_usecs = ns2usecs(next_ts - iter->ts); | ||
| 671 | 703 | ||
| 672 | if (verbose) { | 704 | if (verbose) { |
| 673 | char comm[TASK_COMM_LEN]; | 705 | char comm[TASK_COMM_LEN]; |
| 674 | 706 | ||
| 675 | trace_find_cmdline(entry->pid, comm); | 707 | trace_find_cmdline(entry->pid, comm); |
| 676 | 708 | ||
| 677 | ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]" | 709 | ret = trace_seq_printf( |
| 678 | " %ld.%03ldms (+%ld.%03ldms): ", comm, | 710 | s, "%16s %5d %3d %d %08x %08lx ", |
| 679 | entry->pid, iter->cpu, entry->flags, | 711 | comm, entry->pid, iter->cpu, entry->flags, |
| 680 | entry->preempt_count, iter->idx, | 712 | entry->preempt_count, iter->idx); |
| 681 | ns2usecs(iter->ts), | ||
| 682 | abs_usecs / USEC_PER_MSEC, | ||
| 683 | abs_usecs % USEC_PER_MSEC, | ||
| 684 | rel_usecs / USEC_PER_MSEC, | ||
| 685 | rel_usecs % USEC_PER_MSEC); | ||
| 686 | } else { | 713 | } else { |
| 687 | ret = lat_print_generic(s, entry, iter->cpu); | 714 | ret = lat_print_generic(s, entry, iter->cpu); |
| 688 | if (ret) | ||
| 689 | ret = lat_print_timestamp(s, abs_usecs, rel_usecs); | ||
| 690 | } | 715 | } |
| 691 | 716 | ||
| 717 | if (ret) | ||
| 718 | ret = lat_print_timestamp(iter, next_ts); | ||
| 719 | |||
| 692 | return ret; | 720 | return ret; |
| 693 | } | 721 | } |
| 694 | 722 | ||
