[PATCH RFC] powerpc/ftrace: add powerpc timebase as a trace clock source

Naveen N. Rao naveen.n.rao at linux.vnet.ibm.com
Thu Apr 23 15:17:32 AEST 2015


On 2015/04/23 01:14PM, Michael Ellerman wrote:
> On Wed, 2015-04-22 at 10:48 +0530, Naveen N. Rao wrote:
> > On 2015/04/21 09:25AM, Steven Rostedt wrote:
> > > On Tue, 21 Apr 2015 16:33:36 +0530
> > > "Naveen N. Rao" <naveen.n.rao at linux.vnet.ibm.com> wrote:
> > > 
> > > > Add a new powerpc-specific trace clock using the timebase register,
> > > > similar to x86-tsc. This gives us a fast, monotonic, cross-cpu clock
> > > > for trace entries and can be used to correlate events across cpus as
> > > > well as across hypervisor and guest (assuming it is not a migrated guest
> > > > with a non-zero tb_offset).
> > > > 
> > > > Signed-off-by: Naveen N. Rao <naveen.n.rao at linux.vnet.ibm.com>
> > > > ---
> > > > I have followed the approach used by x86-tsc here, but we could get rid of
> > > > trace_clock.c if we directly use get_tb() with perhaps the notrace annotation.
> > > > Would that be preferable?
> > > > 
> > > 
> > > Probably. But all clocks used by tracing should be marked by notrace.
> > > Don't just wrap it with a notrace. But looking at the code, it seems
> > > that get_tb() is a static inline, which wont work as a pointer. Seems
> > > you still need the indirect function call.
> > > 
> > > Note, all "inline" functions are notrace by default, so you do not need
> > > to add any notrace annotation to an inlined function.
> > 
> > Steve,
> > Thanks for the clarification - the current approach is better in that 
> > case.
> > 
> > Paul, Mike,
> > Can you please let me know your thoughts on this?
> 
> What is the value in adding a powerpc specific clock, which requires educating
> people to use it, vs just using the global clock?

Hi Michael,
There are two reasons:
- One, using the timebase register gives us a very fast (just one 
  instruction) hardware clock source for trace entries compared to the 
  global clock.
- Two, using the timebase values allows us to correlate trace events 
  across hypervisor and guest, which is not possible using the other 
  trace clocks. [With migrated guests, there could be a non-zero 
  tb_offset which we may also want to make available to userspace in 
  some manner. Any suggestions?]

This will show up as an additional trace clock and can be selected if 
one wishes to use it. As an example:

[root at rhel7-img ~]# cd /sys/kernel/debug/tracing
[root at rhel7-img tracing]# cat trace_clock
[local] global counter uptime perf mono ppc-tb
[root at rhel7-img tracing]# head -30 trace
# tracer: nop
#
# entries-in-buffer/entries-written: 534/534   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           tuned-1080  [003] ....  1108.294606: sys_select -> 0x0
           tuned-1080  [003] ....  1108.294655: sys_select(n: 0, inp: 0, outp: 0, exp: 0, tvp: 3fff9b7fcdf0)
            bash-2732  [001] ....  1108.336317: sys_write -> 0x6
            bash-2732  [001] ....  1108.336321: sys_dup2(oldfd: a, newfd: 1)
            bash-2732  [001] ....  1108.336323: sys_dup2 -> 0x1
            bash-2732  [001] ....  1108.336327: sys_fcntl(fd: a, cmd: 1, arg: 0)
            bash-2732  [001] ....  1108.336328: sys_fcntl -> 0x1
            bash-2732  [001] ....  1108.336330: sys_close(fd: a)
            bash-2732  [001] ....  1108.336330: sys_close -> 0x0
            bash-2732  [001] ....  1108.336340: sys_rt_sigprocmask(how: 0, nset: 0, oset: 10146e48, sigsetsize: 8)
            bash-2732  [001] ....  1108.336341: sys_rt_sigprocmask -> 0x0
            bash-2732  [001] ....  1108.336342: sys_rt_sigaction(sig: 2, act: 3fffc17d8e20, oact: 3fffc17d8d80, sigsetsize: 8)
            bash-2732  [001] ....  1108.336343: sys_rt_sigaction -> 0x0
            bash-2732  [001] ....  1108.336352: sys_rt_sigprocmask(how: 0, nset: 0, oset: 10146e48, sigsetsize: 8)
            bash-2732  [001] ....  1108.336352: sys_rt_sigprocmask -> 0x0
            bash-2732  [001] ....  1108.336476: sys_write(fd: 1, buf: 3fff7f370000, count: 2d)
            bash-2732  [001] ....  1108.336484: sys_write -> 0x2d
            bash-2732  [001] ....  1108.336512: sys_rt_sigprocmask(how: 0, nset: 3fffc17d7c40, oset: 3fffc17d7cc0, sigsetsize: 8)
            bash-2732  [001] ....  1108.336513: sys_rt_sigprocmask -> 0x0
[root at rhel7-img tracing]# echo ppc-tb > trace_clock
[root at rhel7-img tracing]# cat trace_clock
local global counter uptime perf mono [ppc-tb]
[root at rhel7-img tracing]# echo 0 > trace
[root at rhel7-img tracing]# head -30 trace
# tracer: nop
#
# entries-in-buffer/entries-written: 396/396   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-2732  [002] .... 34405585249004: sys_write -> 0x7
            bash-2732  [002] .... 34405585251162: sys_dup2(oldfd: a, newfd: 1)
            bash-2732  [002] .... 34405585252104: sys_dup2 -> 0x1
            bash-2732  [002] .... 34405585253774: sys_fcntl(fd: a, cmd: 1, arg: 0)
            bash-2732  [002] .... 34405585254385: sys_fcntl -> 0x1
            bash-2732  [002] .... 34405585255051: sys_close(fd: a)
            bash-2732  [002] .... 34405585255589: sys_close -> 0x0
            bash-2732  [002] .... 34405585260898: sys_rt_sigprocmask(how: 0, nset: 0, oset: 10146e48, sigsetsize: 8)
            bash-2732  [002] .... 34405585261482: sys_rt_sigprocmask -> 0x0
            bash-2732  [002] .... 34405585262339: sys_rt_sigaction(sig: 2, act: 3fffc17d8e20, oact: 3fffc17d8d80, sigsetsize: 8)
            bash-2732  [002] .... 34405585262927: sys_rt_sigaction -> 0x0
            bash-2732  [002] .... 34405585267215: sys_rt_sigprocmask(how: 0, nset: 0, oset: 10146e48, sigsetsize: 8)
            bash-2732  [002] .... 34405585267690: sys_rt_sigprocmask -> 0x0
            bash-2732  [002] .... 34405585345924: sys_write(fd: 1, buf: 3fff7f370000, count: 2d)
            bash-2732  [002] .n.. 34405585350359: sys_write -> 0x2d
            bash-2732  [002] .... 34405585428096: sys_rt_sigprocmask(how: 0, nset: 3fffc17d7c40, oset: 3fffc17d7cc0, sigsetsize: 8)
            bash-2732  [002] .... 34405585447011: sys_rt_sigprocmask -> 0x0
            bash-2732  [002] .... 34405585447956: sys_ioctl(fd: ff, cmd: 80047476, arg: 3fffc17d7c08)
            bash-2732  [002] .... 34405585449451: sys_ioctl -> 0x0


- Naveen



More information about the Linuxppc-dev mailing list