Re: [PATCH v3 3/3] tracing: format non-nanosec times from tsc clockwithout a decimal point.

From: Steven Rostedt
Date: Mon Sep 24 2012 - 23:27:08 EST


On Thu, 2012-09-20 at 15:52 -0700, David Sharp wrote:
> With the addition of the "tsc" clock, formatting timestamps to look like
> fractional seconds is misleading. Mark clocks as either in nanoseconds or
> not, and format non-nanosecond timestamps as decimal integers.

I got this:

/work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3'
/work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3'
/work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3'
/work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3'
/work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3'
/work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__umoddi3'
/work/autotest/nobackup/linux-test.git/kernel/trace/trace_output.c:636: undefined reference to `__udivdi3'

when building for x86_32.

> + int ret;
> + struct trace_seq *s = &iter->seq;
> + unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE;
> + unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS;
> + unsigned long long abs_ts = iter->ts - iter->tr->time_start;
> + unsigned long long rel_ts = next_ts - iter->ts;
> + unsigned long mark_thresh;
> +
> + if (in_ns) {
> + abs_ts = ns2usecs(abs_ts);
> + rel_ts = ns2usecs(rel_ts);
> + mark_thresh = preempt_mark_thresh_us;
> + } else
> + mark_thresh = preempt_mark_thresh_cycles;
> +
> + if (verbose && in_ns) {
> + ret = trace_seq_printf(
> + s, "[%08llx] %lld.%03lldms (+%lld.%03lldms): ",
> + ns2usecs(iter->ts),
> + abs_ts / USEC_PER_MSEC,
> + abs_ts % USEC_PER_MSEC,
> + rel_ts / USEC_PER_MSEC,

You can't divide 64 bit numbers in the kernel. It breaks on 32bit archs.

-- Steve

> + rel_ts % USEC_PER_MSEC);
> + } else if (verbose && !in_ns) {
> + ret = trace_seq_printf(
> + s, "[%016llx] %lld (+%lld): ",
> + iter->ts, abs_ts, rel_ts);
> + } else { /* !verbose */
> + ret = trace_seq_printf(
> + s, " %4lld%s%c: ",
> + abs_ts,
> + in_ns ? "us" : "",
> + rel_ts > mark_thresh ? '!' :
> + rel_ts > 1 ? '+' : ' ');
> + }
> + return ret;
> }
>
> int trace_print_context(struct trace_iterator *iter)
> {
> struct trace_seq *s = &iter->seq;
> struct trace_entry *entry = iter->ent;
> - unsigned long long t = ns2usecs(iter->ts);
> - unsigned long usec_rem = do_div(t, USEC_PER_SEC);
> - unsigned long secs = (unsigned long)t;
> + unsigned long long t;
> + unsigned long secs, usec_rem;
> char comm[TASK_COMM_LEN];
> int ret;
>
> @@ -644,8 +677,13 @@ int trace_print_context(struct trace_iterator *iter)
> return 0;
> }
>
> - return trace_seq_printf(s, " %5lu.%06lu: ",
> - secs, usec_rem);
> + if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) {
> + t = ns2usecs(iter->ts);
> + usec_rem = do_div(t, USEC_PER_SEC);
> + secs = (unsigned long)t;
> + return trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem);
> + } else
> + return trace_seq_printf(s, "%12llu: ", iter->ts);
> }
>
> int trace_print_lat_context(struct trace_iterator *iter)
> @@ -659,36 +697,30 @@ int trace_print_lat_context(struct trace_iterator *iter)
> *next_entry = trace_find_next_entry(iter, NULL,
> &next_ts);
> unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE);
> - unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start);
> - unsigned long rel_usecs;
> +
>
> /* Restore the original ent_size */
> iter->ent_size = ent_size;
>
> if (!next_entry)
> next_ts = iter->ts;
> - rel_usecs = ns2usecs(next_ts - iter->ts);
>
> if (verbose) {
> char comm[TASK_COMM_LEN];
>
> trace_find_cmdline(entry->pid, comm);
>
> - ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]"
> - " %ld.%03ldms (+%ld.%03ldms): ", comm,
> - entry->pid, iter->cpu, entry->flags,
> - entry->preempt_count, iter->idx,
> - ns2usecs(iter->ts),
> - abs_usecs / USEC_PER_MSEC,
> - abs_usecs % USEC_PER_MSEC,
> - rel_usecs / USEC_PER_MSEC,
> - rel_usecs % USEC_PER_MSEC);
> + ret = trace_seq_printf(
> + s, "%16s %5d %3d %d %08x %08lx ",
> + comm, entry->pid, iter->cpu, entry->flags,
> + entry->preempt_count, iter->idx);
> } else {
> ret = lat_print_generic(s, entry, iter->cpu);
> - if (ret)
> - ret = lat_print_timestamp(s, abs_usecs, rel_usecs);
> }
>
> + if (ret)
> + ret = lat_print_timestamp(iter, next_ts);
> +
> return ret;
> }
>


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/