linux-kernel - Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:	Wed, 03 Dec 2008 02:34:30 +0100
From:	Frederic Weisbecker <fweisbec@...il.com>
To:	Ingo Molnar <mingo@...e.hu>
CC:	Steven Rostedt <rostedt@...dmis.org>,
	Tim Bird <tim.bird@...sony.com>,
	Peter Zijlstra <a.p.zijlstra@...llo.nl>,
	Linux Kernel <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH 2/2] tracing/function-graph-tracer: improve duration output

Frederic Weisbecker wrote:
> Impact: better output of duration for long calls
> 
> The old duration output didn't exceeded 9999.999 us to fit the column
> and the nanosecs were always 3 numbers. As Ingo suggested, it's better
> to have the whole microseconds elapsed time and shift the nanosecs precision
> if needed to fit the maximum 7 numbers. And usec need more number, the case
> should be rare and important enough to break a bit the column alignment to
> show it.
> 
> So, depending of the duration value, we now have these patterns:
> 
> u.nnn
> uu.nnn
> uuu.nnn
> uuuu.nnn
> uuuuu.nn
> uuuuuu.n
> uuuuuuuu.....


An example of a trace after these two patches (with funcgraph-proc enabled):

 0)    cat-2796    |               |            put_prev_task_fair() {
 0)    cat-2796    |   0.609 us    |              update_curr();
 0)    cat-2796    |   1.842 us    |            }
 0)    cat-2796    |               |            pick_next_task_fair() {
 0)    cat-2796    |   0.526 us    |              wakeup_preempt_entity();
 0)    cat-2796    |   0.797 us    |              set_next_entity();
 0)    cat-2796    |   0.541 us    |              hrtick_start_fair();
 0)    cat-2796    |   4.195 us    |            }
 0)    cat-2796    |   1.263 us    |            _spin_trylock();
 0)    cat-2796    |   0.624 us    |            _spin_unlock();
 0)    cat-2796    |   0.789 us    |            _spin_trylock();
 0)    cat-2796    |   0.617 us    |            _spin_unlock();
 0)    cat-2796    |   0.579 us    |            native_load_sp0();
 0)    cat-2796    |   0.722 us    |            native_load_tls();

 ------------------------------------------
 | 0)    cat-2796    =>   events/-9   
 ------------------------------------------

 0)   events/-9    |               |    finish_task_switch() {
 0)   events/-9    |   0.789 us    |      _spin_unlock_irq();
 0)   events/-9    |   2.309 us    |    }
 0)   events/-9    | ! 269848.5 us |  }
 0)   events/-9    |   0.601 us    |  finish_wait();
 0)   events/-9    |   0.662 us    |  kthread_should_stop();
 0)   events/-9    |               |  run_workqueue() {
 0)   events/-9    |   1.136 us    |    _spin_lock_irq();
 0)   events/-9    |   0.918 us    |    _spin_unlock_irq();
 0)   events/-9    |               |    console_callback() {
 0)   events/-9    |               |      acquire_console_sem() {
 0)   events/-9    |               |        down() {
 0)   events/-9    |   1.534 us    |          _spin_lock_irqsave();
 0)   events/-9    |   0.812 us    |          _spin_unlock_irqrestore();
 0)   events/-9    |   4.369 us    |        }
 0)   events/-9    |   5.903 us    |      }
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/