All of lore.kernel.org
 help / color / mirror / Atom feed
* ftrace - graph tracer for Microblaze
@ 2009-11-06 11:03 Michal Simek
  2009-11-06 15:54 ` Steven Rostedt
  0 siblings, 1 reply; 3+ messages in thread
From: Michal Simek @ 2009-11-06 11:03 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Steven Rostedt, linux-kernel, John Williams

Hi Steven,

I found the problem in my mcount function. I was Microblaze dependent 
fault - I had to save all registers which are not saved across function 
calls.

I am getting some problem is irqsoff tracing. Is there any special 
things which needs to be implemented/changed?

I would like to implement ftrace graph support and stack save support.

I believe that for stack_trace I need just to implement save_stack_trace.
If I understand correctly that feature should look at current process
and trace that process back to zero stack size.
It is just for current task right?

Then output shows which functions are called and size of stack. I found 
your post which is at http://lkml.org/lkml/2009/8/21/319 but you don't 
have any zero size stack size. Here is my log which seems to me weird 
because of zero size values. Is it correct or not?

# echo 1 > /proc/sys/kernel/stack_tracer_enabled
# cat /debug/tracing/stack_trace
         Depth    Size   Location    (63 entries)
         -----    ----   --------
   0)     2100       0   stack_trace_call+0x12c/0x1d8
   1)     2100       0   stack_trace_call+0x12c/0x1d8
   2)     2100       0   _spin_unlock+0x2c/0x3c
   3)     2100     180   __rcu_process_callbacks+0x3e0/0x460
   4)     1920     568   end_graph_tracer+0x24/0x2c
   5)     1352       0   end_graph_tracer+0x24/0x2c
   6)     1352       0   microblaze_read+0x14/0x4c
   7)     1352     184   microblaze_read+0x0/0x4c
...
  63)      156     156   ktime_add_ns+0x88/0x124

Here is my function -> it is the same as we use for dump stack.
I look at mips implementation and is the same

void save_stack_trace(struct stack_trace *trace)
{
	unsigned int sp;
	asm("addik %0, r1, 0" : "=r" (sp));

	while (!kstack_end(sp)) {
		addr = *sp++;
		if (__kernel_text_address(addr)) {
			if (trace->skip > 0)
				trace->skip--;
			else
			   trace->entries[trace->nr_entries++] = addr;

			if (trace->nr_entries >= trace->max_entries)
				break;
		}
	}
}



The second more important is graph part

I read it in ftrace design.txt and I don't understand how this really works.


For function trace without grapth support is calling
  foo()
(ret2foo) -> bar()
    (ret2bar) -> mcount() - I have to save full cpu content
                   -> ftrace_trace_function (ret2bar, ret2foo)
			(do some stuff)
                   <-
                   restore_whole_content and jump back to bar
                   after mcount call (mb do jump +8 - mb convention)
              bar ends -> jump back to foo


For graph is flow a little bit different
  foo()
(ret2foo) -> bar()
    (ret2bar) -> mcount() - I have to save full cpu content
                     ->prepare_ftrace_return(ret2bar, ret2foo)

and here I have to change return address -> Is it mean that from 
prepare_ftrace_return I have to return back to bar and then at the end 
of bar jump to return_to_handler which will call 
ftrace_return_to_handler and then jump back to foo. Is it correct?
What is the correct calling?



This is third topic - maybe I should send three separate emails :-(

I found some incompatibility which IMHO could be synchronize.
There is C implementation for ftrace_graph_entry_stub and ftrace_stub
is implemented in asm. The purpose of that two functions should be the 
same that's I think implementation should be too.

Because of my unresolved issue around irqsoff I traced it in code and 
there is too many tracing_reset_online_cpus() functions. I found one 
calling in __irqsoff_tracer_init and then in tracer_init function. Is 
that correct or one calling is enough?

Then I think that there is some things in Kconfig which should be 
cleared. I found link to /sys/kernel/debug/tracing/profile_branch which 
I don't have in tracing folder. Is it correct?

Thanks for your help,
Michal



^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: ftrace - graph tracer for Microblaze
  2009-11-06 11:03 ftrace - graph tracer for Microblaze Michal Simek
@ 2009-11-06 15:54 ` Steven Rostedt
  2009-11-09  8:10   ` Michal Simek
  0 siblings, 1 reply; 3+ messages in thread
From: Steven Rostedt @ 2009-11-06 15:54 UTC (permalink / raw)
  To: monstr; +Cc: linux-kernel, John Williams

On Fri, 2009-11-06 at 12:03 +0100, Michal Simek wrote:
> Hi Steven,
> 
> I found the problem in my mcount function. I was Microblaze dependent 
> fault - I had to save all registers which are not saved across function 
> calls.

Yep, that could be an issue.

> 
> I am getting some problem is irqsoff tracing. Is there any special 
> things which needs to be implemented/changed?

It is dependent on TRACE_IRQFLAGS_SUPPORT, which is kind of nasty. This
is what LOCKDEP uses. If you can successfully implement LOCKDEP you get
irqsoff tracing for free.

The biggest issue with lockdep implementation is that you need to have a
hook at every irq disable and enable location. This includes assembly.
That's what all those TRACE_IRQS_OFF and TRACE_IRQS_ON are in x86's
entry_*.S.


> 
> I would like to implement ftrace graph support and stack save support.
> 
> I believe that for stack_trace I need just to implement save_stack_trace.
> If I understand correctly that feature should look at current process
> and trace that process back to zero stack size.
> It is just for current task right?

Yes, just current task is needed.

> 
> Then output shows which functions are called and size of stack. I found 
> your post which is at http://lkml.org/lkml/2009/8/21/319 but you don't 
> have any zero size stack size. Here is my log which seems to me weird 
> because of zero size values. Is it correct or not?
> 
> # echo 1 > /proc/sys/kernel/stack_tracer_enabled
> # cat /debug/tracing/stack_trace
>          Depth    Size   Location    (63 entries)
>          -----    ----   --------
>    0)     2100       0   stack_trace_call+0x12c/0x1d8
>    1)     2100       0   stack_trace_call+0x12c/0x1d8
>    2)     2100       0   _spin_unlock+0x2c/0x3c
>    3)     2100     180   __rcu_process_callbacks+0x3e0/0x460
>    4)     1920     568   end_graph_tracer+0x24/0x2c
>    5)     1352       0   end_graph_tracer+0x24/0x2c
>    6)     1352       0   microblaze_read+0x14/0x4c
>    7)     1352     184   microblaze_read+0x0/0x4c
> ...
>   63)      156     156   ktime_add_ns+0x88/0x124
> 
> Here is my function -> it is the same as we use for dump stack.
> I look at mips implementation and is the same
> 
> void save_stack_trace(struct stack_trace *trace)
> {
> 	unsigned int sp;
> 	asm("addik %0, r1, 0" : "=r" (sp));
> 
> 	while (!kstack_end(sp)) {
> 		addr = *sp++;
> 		if (__kernel_text_address(addr)) {

Hmm, this does not look too reliable. That is, anytime there's a text
address in the code you report it, although it may not be a real return
address.

Does Microblaze have any kind of frame pointer? Or a way to detect the
next frame? If so, that would be really helpful here.

> 			if (trace->skip > 0)
> 				trace->skip--;
> 			else
> 			   trace->entries[trace->nr_entries++] = addr;
> 
> 			if (trace->nr_entries >= trace->max_entries)
> 				break;
> 		}
> 	}
> }

The stack tracer is very simple. If you look at the check_stack code in
kernel/trace/trace_stack.c it shows the implementation.

Basically what it does is to look at the address local variable in the
function itself (this_size). It masks it with THREAD_SIZE-1 to get the
top of the stack.

It then starts up the stack looking at the contents to match the
contents of the report from save_stack_trace(). If it finds a return
value, it reports the address off of that. If it does not find that
return value, you will see zero. This is strange since it should have
found all those that were reported. But perhaps those values were in the
stack when calling the save_stack_trace function, but not at the level
of check_stack's stack.

> 
> 
> 
> The second more important is graph part
> 
> I read it in ftrace design.txt and I don't understand how this really works.
> 
> 
> For function trace without grapth support is calling
>   foo()
> (ret2foo) -> bar()
>     (ret2bar) -> mcount() - I have to save full cpu content
>                    -> ftrace_trace_function (ret2bar, ret2foo)
> 			(do some stuff)
>                    <-
>                    restore_whole_content and jump back to bar
>                    after mcount call (mb do jump +8 - mb convention)
>               bar ends -> jump back to foo
> 
> 
> For graph is flow a little bit different
>   foo()
> (ret2foo) -> bar()
>     (ret2bar) -> mcount() - I have to save full cpu content
>                      ->prepare_ftrace_return(ret2bar, ret2foo)
> 
> and here I have to change return address -> Is it mean that from 
> prepare_ftrace_return I have to return back to bar and then at the end 
> of bar jump to return_to_handler which will call 
> ftrace_return_to_handler and then jump back to foo. Is it correct?

Yes that is correct.

> What is the correct calling?

What you just stated ;-)

> 
> 
> 
> This is third topic - maybe I should send three separate emails :-(
> 
> I found some incompatibility which IMHO could be synchronize.
> There is C implementation for ftrace_graph_entry_stub and ftrace_stub
> is implemented in asm. The purpose of that two functions should be the 
> same that's I think implementation should be too.

The two take different arguments. Sure the stubs don't care, but it this
topic came up in the design. We found issues (I don't remember exactly
what they were) by having the two the same. That was the original
design.

> 
> Because of my unresolved issue around irqsoff I traced it in code and 
> there is too many tracing_reset_online_cpus() functions. I found one 
> calling in __irqsoff_tracer_init and then in tracer_init function. Is 
> that correct or one calling is enough?

Hmm, It may be enough to call it just in tracer_init, but it does seem
that irqsoff tracer wants it reset it again after it zeros out the
numbers. I'll look into that. But it should not affect anything, since
this is only at startup of the tracer.

> 
> Then I think that there is some things in Kconfig which should be 
> cleared. I found link to /sys/kernel/debug/tracing/profile_branch which 
> I don't have in tracing folder. Is it correct?

You enabled TRACE_BRANCH_PROFILING and you don't have that?

-- Steve


^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: ftrace - graph tracer for Microblaze
  2009-11-06 15:54 ` Steven Rostedt
@ 2009-11-09  8:10   ` Michal Simek
  0 siblings, 0 replies; 3+ messages in thread
From: Michal Simek @ 2009-11-09  8:10 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: linux-kernel, John Williams, wuzhangjin

Steven Rostedt wrote:
> On Fri, 2009-11-06 at 12:03 +0100, Michal Simek wrote:
>> Hi Steven,
>>

>> I am getting some problem is irqsoff tracing. Is there any special 
>> things which needs to be implemented/changed?
> 
> It is dependent on TRACE_IRQFLAGS_SUPPORT, which is kind of nasty. This
> is what LOCKDEP uses. If you can successfully implement LOCKDEP you get
> irqsoff tracing for free.

That's crucial information. Would it be possible to add this dependency 
to trace/Kconfig?

> 
> The biggest issue with lockdep implementation is that you need to have a
> hook at every irq disable and enable location. This includes assembly.
> That's what all those TRACE_IRQS_OFF and TRACE_IRQS_ON are in x86's
> entry_*.S.

I have there some issues - I am debugging it.

> 
> 
>> I would like to implement ftrace graph support and stack save support.
>>
>> I believe that for stack_trace I need just to implement save_stack_trace.
>> If I understand correctly that feature should look at current process
>> and trace that process back to zero stack size.
>> It is just for current task right?
> 
> Yes, just current task is needed.
> 
>> Then output shows which functions are called and size of stack. I found 
>> your post which is at http://lkml.org/lkml/2009/8/21/319 but you don't 
>> have any zero size stack size. Here is my log which seems to me weird 
>> because of zero size values. Is it correct or not?
>>
>> # echo 1 > /proc/sys/kernel/stack_tracer_enabled
>> # cat /debug/tracing/stack_trace
>>          Depth    Size   Location    (63 entries)
>>          -----    ----   --------
>>    0)     2100       0   stack_trace_call+0x12c/0x1d8
>>    1)     2100       0   stack_trace_call+0x12c/0x1d8
>>    2)     2100       0   _spin_unlock+0x2c/0x3c
>>    3)     2100     180   __rcu_process_callbacks+0x3e0/0x460
>>    4)     1920     568   end_graph_tracer+0x24/0x2c
>>    5)     1352       0   end_graph_tracer+0x24/0x2c
>>    6)     1352       0   microblaze_read+0x14/0x4c
>>    7)     1352     184   microblaze_read+0x0/0x4c
>> ...
>>   63)      156     156   ktime_add_ns+0x88/0x124
>>
>> Here is my function -> it is the same as we use for dump stack.
>> I look at mips implementation and is the same
>>
>> void save_stack_trace(struct stack_trace *trace)
>> {
>> 	unsigned int sp;
>> 	asm("addik %0, r1, 0" : "=r" (sp));
>>
>> 	while (!kstack_end(sp)) {
>> 		addr = *sp++;
>> 		if (__kernel_text_address(addr)) {
> 
> Hmm, this does not look too reliable. That is, anytime there's a text
> address in the code you report it, although it may not be a real return
> address.
> 
> Does Microblaze have any kind of frame pointer? Or a way to detect the
> next frame? If so, that would be really helpful here.
> 
>> 			if (trace->skip > 0)
>> 				trace->skip--;
>> 			else
>> 			   trace->entries[trace->nr_entries++] = addr;
>>
>> 			if (trace->nr_entries >= trace->max_entries)
>> 				break;
>> 		}
>> 	}
>> }
> 
> The stack tracer is very simple. If you look at the check_stack code in
> kernel/trace/trace_stack.c it shows the implementation.
> 
> Basically what it does is to look at the address local variable in the
> function itself (this_size). It masks it with THREAD_SIZE-1 to get the
> top of the stack.
> 
> It then starts up the stack looking at the contents to match the
> contents of the report from save_stack_trace(). If it finds a return
> value, it reports the address off of that. If it does not find that
> return value, you will see zero. This is strange since it should have
> found all those that were reported. But perhaps those values were in the
> stack when calling the save_stack_trace function, but not at the level
> of check_stack's stack.
> 

will look.

...


> 
>>
>>
>> This is third topic - maybe I should send three separate emails :-(
>>
>> I found some incompatibility which IMHO could be synchronize.
>> There is C implementation for ftrace_graph_entry_stub and ftrace_stub
>> is implemented in asm. The purpose of that two functions should be the 
>> same that's I think implementation should be too.
> 
> The two take different arguments. Sure the stubs don't care, but it this
> topic came up in the design. We found issues (I don't remember exactly
> what they were) by having the two the same. That was the original
> design.

ok.

> 
>> Because of my unresolved issue around irqsoff I traced it in code and 
>> there is too many tracing_reset_online_cpus() functions. I found one 
>> calling in __irqsoff_tracer_init and then in tracer_init function. Is 
>> that correct or one calling is enough?
> 
> Hmm, It may be enough to call it just in tracer_init, but it does seem
> that irqsoff tracer wants it reset it again after it zeros out the
> numbers. I'll look into that. But it should not affect anything, since
> this is only at startup of the tracer.

ok

> 
>> Then I think that there is some things in Kconfig which should be 
>> cleared. I found link to /sys/kernel/debug/tracing/profile_branch which 
>> I don't have in tracing folder. Is it correct?
> 
> You enabled TRACE_BRANCH_PROFILING and you don't have that?

maybe it is related with registration.

microblaze_timer_set_mode: oneshot
Warning: could not register all branches stats
Warning: could not register annotated branches stats
msgmni has been set to 488
84000000.serial: ttyUL0 at MMIO 0x84000003 (irq = 8) is a uartlite
console [ttyUL0] enabled
...

uclinux login: root
Password:
login[45]: root login on 'ttyUL0'
# cd ; mkdir /debug; mount -t debugfs none /debug; cat 
/debug/tracing/available_tracers
function_graph function sched_switch nop
# ls /debug/tracing/
README             options            trace              tracing_cpumask
available_events   per_cpu            trace_clock        tracing_enabled
available_tracers  printk_formats     trace_marker       tracing_on
buffer_size_kb     saved_cmdlines     trace_options
current_tracer     set_event          trace_pipe
events             set_ftrace_pid     trace_stat
#
#
# gunzip < /proc/config.gz | grep BRANCH
CONFIG_TRACE_BRANCH_PROFILING=y
# CONFIG_BRANCH_PROFILE_NONE is not set
# CONFIG_PROFILE_ANNOTATED_BRANCHES is not set
CONFIG_PROFILE_ALL_BRANCHES=y
# CONFIG_BRANCH_TRACER is not set
#

Thanks,
Michal


> 
> -- Steve
> 


-- 
Michal Simek, Ing. (M.Eng)
w: www.monstr.eu p: +42-0-721842854
Maintainer of Linux kernel 2.6 Microblaze Linux - http://www.monstr.eu/fdt/
Microblaze U-BOOT custodian

^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2009-11-09  8:12 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2009-11-06 11:03 ftrace - graph tracer for Microblaze Michal Simek
2009-11-06 15:54 ` Steven Rostedt
2009-11-09  8:10   ` Michal Simek

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.