tracing/function-return-tracer: add the overrun field

Impact: help to find the better depth of trace

We decided to arbitrary define the depth of function return trace as "20". Perhaps this is not enough. To help finding an optimal depth, we measure now the overrun: the number of functions that have been missed for the current thread. By default this is not displayed, we have to do set a particular flag on the return tracer: echo overrun

Quoted 1 line

/debug/tracing/trace_options And the overrun will be printed on

the right.

As the trace shows below, the current 20 depth is not enough.

update_wall_time+0x37f/0x8c0 -> update_xtime_cache (345 ns) (Overruns: 2838)
update_wall_time+0x384/0x8c0 -> clocksource_get_next (1141 ns) (Overruns: 2838)
do_timer+0x23/0x100 -> update_wall_time (3882 ns) (Overruns: 2838)

Quoted 7 lines · Frederic Weisbecker

Impact: help to find the better depth of trace

We decided to arbitrary define the depth of function return trace as "20". Perhaps this is not enough. To help finding an optimal depth, we measure now the overrun: the number of functions that have been missed for the current thread. By default this is not displayed, we have to do set a particular flag on the return tracer: echo overrun

Quoted 8 lines

Quoted 1 line

/debug/tracing/trace_options And the overrun will be printed on

the right.

As the trace shows below, the current 20 depth is not enough.

update_wall_time+0x37f/0x8c0 -> update_xtime_cache (345 ns) (Overruns: 2838)
update_wall_time+0x384/0x8c0 -> clocksource_get_next (1141 ns) (Overruns: 2838)
do_timer+0x23/0x100 -> update_wall_time (3882 ns) (Overruns: 2838)

hm, interesting. Have you tried to figure out what a practical depth limit would be?

With lockdep we made the experience that function call stacks can be very deep - if we count IRQ contexts too it can be up to 100 in the extreme cases. (but at that stage kernel stack limits start hitting us)

I'd say 50 would be needed.

Ingo

Quoted 28 lines · Ingo Molnar

Quoted 7 lines · Frederic Weisbecker

Impact: help to find the better depth of trace

We decided to arbitrary define the depth of function return trace as "20". Perhaps this is not enough. To help finding an optimal depth, we measure now the overrun: the number of functions that have been missed for the current thread. By default this is not displayed, we have to do set a particular flag on the return tracer: echo overrun

Quoted 8 lines

Quoted 1 line

/debug/tracing/trace_options And the overrun will be printed on

the right.

As the trace shows below, the current 20 depth is not enough.

update_wall_time+0x37f/0x8c0 -> update_xtime_cache (345 ns) (Overruns: 2838)
update_wall_time+0x384/0x8c0 -> clocksource_get_next (1141 ns) (Overruns: 2838)
do_timer+0x23/0x100 -> update_wall_time (3882 ns) (Overruns: 2838)

hm, interesting. Have you tried to figure out what a practical depth limit would be?

With lockdep we made the experience that function call stacks can be very deep - if we count IRQ contexts too it can be up to 100 in the extreme cases. (but at that stage kernel stack limits start hitting us)

I'd say 50 would be needed.

Quoted 1 line

Ingo

Ok I will try with 50. If there are still a lot and often missing traces with this depth, perhaps should we consider a hybrid solution between ret stack and trampolines? We could use the normal ret stack on struct info for most common cases and the trampoline when we are exceeding the depth....

Quoted 6 lines

Ok I will try with 50. If there are still a lot and often missing traces with this depth, perhaps should we consider a hybrid solution between ret stack and trampolines? We could use the normal ret stack on struct info for most common cases and the trampoline when we are exceeding the depth....

dunno, trampolines make me feel uneasy.

Could you set it to some really large value (200) and add a "max depth seen" variable perhaps, and see the maximum depth?

Quoted 7 lines · Ingo Molnar

Quoted 6 lines

Ok I will try with 50. If there are still a lot and often missing traces with this depth, perhaps should we consider a hybrid solution between ret stack and trampolines? We could use the normal ret stack on struct info for most common cases and the trampoline when we are exceeding the depth....

Quoted 4 lines

dunno, trampolines make me feel uneasy.

Could you set it to some really large value (200) and add a "max depth seen" variable perhaps, and see the maximum depth?

Don't run that on a box you care about ;-) But hopefully the stacks will not collide. This should also depend on IRQSTACKS.

Quoted 14 lines · Steven Rostedt

Quoted 11 lines · Ingo Molnar

Quoted 6 lines

Ok I will try with 50. If there are still a lot and often missing traces with this depth, perhaps should we consider a hybrid solution between ret stack and trampolines? We could use the normal ret stack on struct info for most common cases and the trampoline when we are exceeding the depth....

dunno, trampolines make me feel uneasy.

Could you set it to some really large value (200) and add a "max depth seen" variable perhaps, and see the maximum depth?

Quoted 2 lines

Don't run that on a box you care about ;-) But hopefully the stacks will not collide. This should also depend on IRQSTACKS.

that reminds me: ti->ret_stack[] should be moved to task->ret_stack[]. That way we decouple its size from any kernel stack size limits. (thread-info resides at one end of the kernel stack, on x86)

Quoted 20 lines · Ingo Molnar

Quoted 16 lines · Steven Rostedt

Quoted 11 lines · Ingo Molnar

Quoted 6 lines

Ok I will try with 50. If there are still a lot and often missing traces with this depth, perhaps should we consider a hybrid solution between ret stack and trampolines? We could use the normal ret stack on struct info for most common cases and the trampoline when we are exceeding the depth....

dunno, trampolines make me feel uneasy.

Could you set it to some really large value (200) and add a "max depth seen" variable perhaps, and see the maximum depth?

Don't run that on a box you care about ;-) But hopefully the stacks will not collide. This should also depend on IRQSTACKS.

Quoted 3 lines

that reminds me: ti->ret_stack[] should be moved to task->ret_stack[]. That way we decouple its size from any kernel stack size limits. (thread-info resides at one end of the kernel stack, on x86)

Yeah, I recommended that to Frederic to save space. But that can be dangerous. Using task instead would be safer with the downside of making the task struct even bigger.

Quoted 8 lines

Quoted 4 lines

that reminds me: ti->ret_stack[] should be moved to task->ret_stack[]. That way we decouple its size from any kernel stack size limits. (thread-info resides at one end of the kernel stack, on x86)

Yeah, I recommended that to Frederic to save space. But that can be dangerous. Using task instead would be safer with the downside of making the task struct even bigger.

We almost never put new stuff into thread_info - we have the lockdep lock stack in the task structure too, for similar reasons.

Quoted 9 lines · Ingo Molnar

Quoted 8 lines

Quoted 4 lines

that reminds me: ti->ret_stack[] should be moved to task->ret_stack[]. That way we decouple its size from any kernel stack size limits. (thread-info resides at one end of the kernel stack, on x86)

Yeah, I recommended that to Frederic to save space. But that can be dangerous. Using task instead would be safer with the downside of making the task struct even bigger.

Quoted 2 lines

We almost never put new stuff into thread_info - we have the lockdep lock stack in the task structure too, for similar reasons.

Yeah, it was just a recommendation, and perhaps not a good one ;-)

Frederic, it is better if you move the array from the thread info to the task struct. It will take up more memory but it is a hell of a lot safer. The pro here definitely outways the con.

Quoted 12 lines · Ingo Molnar

Quoted 9 lines

Quoted 8 lines

Quoted 4 lines

that reminds me: ti->ret_stack[] should be moved to task->ret_stack[]. That way we decouple its size from any kernel stack size limits. (thread-info resides at one end of the kernel stack, on x86)

Yeah, I recommended that to Frederic to save space. But that can be dangerous. Using task instead would be safer with the downside of making the task struct even bigger.

Quoted 8 lines

Quoted 2 lines

We almost never put new stuff into thread_info - we have the lockdep lock stack in the task structure too, for similar reasons.

Yeah, it was just a recommendation, and perhaps not a good one ;-)

Frederic, it is better if you move the array from the thread info to the task struct. It will take up more memory but it is a hell of a lot safer. The pro here definitely outways the con.

if the memory footprint starts mattering we could turn this into a single pointer to an array - and add/remove these arrays (from all tasks currently running) as the tracer is turned on/off.

Ingo

2008/11/18 Ingo Molnar <[email protected]>:

Quoted 27 lines · Steven Rostedt

Quoted 12 lines · Ingo Molnar

Quoted 9 lines

Quoted 8 lines

Quoted 4 lines

that reminds me: ti->ret_stack[] should be moved to task->ret_stack[]. That way we decouple its size from any kernel stack size limits. (thread-info resides at one end of the kernel stack, on x86)

Yeah, I recommended that to Frederic to save space. But that can be dangerous. Using task instead would be safer with the downside of making the task struct even bigger.

Quoted 8 lines

Quoted 2 lines

We almost never put new stuff into thread_info - we have the lockdep lock stack in the task structure too, for similar reasons.

Yeah, it was just a recommendation, and perhaps not a good one ;-)

Frederic, it is better if you move the array from the thread info to the task struct. It will take up more memory but it is a hell of a lot safer. The pro here definitely outways the con.

if the memory footprint starts mattering we could turn this into a single pointer to an array - and add/remove these arrays (from all tasks currently running) as the tracer is turned on/off.

Quoted 2 lines

Ingo

Ok. So what do you suggest once? Do I begin to move the array from thread info to struct task but by keeping the static array or should I directly use a dynamic allocation and add/remove dynamically?

Would be nice to have the dynamic allocation straight away

I would recommend using a static array

2008/11/18 Ingo Molnar <[email protected]>:

Quoted 1 line

Would be nice to have the dynamic allocation straight away

2008/11/18 Steven Rostedt <[email protected]>:

Quoted 1 line

I would recommend using a static array

:-)

How about a compromise, start off the patch series getting it working with task struct static array, and then finish the series with the dynamic array.

This is my development model, because it lets me know where the bugs are better. If we find some strange bug, this can help pin point via a bisect if the bug is with the general code, or with the use of a dynamic array.

Just my preference ;-)

2008/11/18 Steven Rostedt <[email protected]>:

Quoted 9 lines

How about a compromise, start off the patch series getting it working with task struct static array, and then finish the series with the dynamic array.

This is my development model, because it lets me know where the bugs are better. If we find some strange bug, this can help pin point via a bisect if the bug is with the general code, or with the use of a dynamic array.

Just my preference ;-)

Ooh. I first agreed with Ingo's arguments about the fact that distros can enable it whithout worrying.
But as I read your message, I guess that would be better to start with static arrays to better find the bugs,
state by state...

Ingo, what do you think?

2008/11/18 Frédéric Weisbecker <[email protected]>:

Quoted 18 lines

2008/11/18 Steven Rostedt <[email protected]>:

Quoted 9 lines

How about a compromise, start off the patch series getting it working with task struct static array, and then finish the series with the dynamic array.

This is my development model, because it lets me know where the bugs are better. If we find some strange bug, this can help pin point via a bisect if the bug is with the general code, or with the use of a dynamic array.

Just my preference ;-)

Ooh. I first agreed with Ingo's arguments about the fact that distros can enable it whithout worrying.
But as I read your message, I guess that would be better to start with static arrays to better find the bugs,
state by state...

Quoted 2 lines

Ingo, what do you think?

And then a last state with dynamic arrays...

2008/11/18 Ingo Molnar <[email protected]>:

Quoted 1 line

Would be nice to have the dynamic allocation straight away

2008/11/18 Steven Rostedt <[email protected]>:

Quoted 1 line

I would recommend using a static array

:-)

it's your call really, either way is fine as long as the end result works! :-)

Generally it's indeed much easier to do as small steps as possible, and to validate every step in practice.

Ingo

hey, look at the bright side of it: whichever variant you pick, if it goes wrong, you'll always have someone else to blame for that unbelievably stupid suggestion ;-)

Ingo

hey, look at the bright side of it: whichever variant you pick, if it goes wrong, you'll always have someone else to blame for that unbelievably stupid suggestion ;-)

When the tracer will be launched, I will hold the tasklist_lock to allocate/insert the dynamic arrays. So in this atomic context, I will not be able to call kmalloc with GFP_KERNEL. And I fear that using GFP_ATOMIC for possible hundreds of tasks would be clearly unacceptable.

What do you think of this way:

_tracer activates
_a function enters the tracer entry-hooker. If the array is allocated for the current task, that's well. If not I launch a kernel thread that will later allocate an array for the current task (I will pass the pid as a parameter). So the current task will be soon be traced. _ when a process forks, I can allocate a dynamic array for the new task without problem (I hope).

So some tasks will not be traced at the early beggining of tracing but they will soon all be traced.... There is perhaps a problem with tasks that are sleeping for long times... There will be some losses once they will be awaken...

Quoted 17 lines

When the tracer will be launched, I will hold the tasklist_lock to allocate/insert the dynamic arrays. So in this atomic context, I will not be able to call kmalloc with GFP_KERNEL. And I fear that using GFP_ATOMIC for possible hundreds of tasks would be clearly unacceptable.

What do you think of this way:

_tracer activates
_a function enters the tracer entry-hooker. If the array is allocated for the current task, that's well. If not I launch a kernel thread that will later allocate an array for the current task (I will pass the pid as a parameter). So the current task will be soon be traced. _ when a process forks, I can allocate a dynamic array for the new task without problem (I hope).

Quoted 4 lines

So some tasks will not be traced at the early beggining of tracing but they will soon all be traced.... There is perhaps a problem with tasks that are sleeping for long times... There will be some losses once they will be awaken...

i'd suggest a different approach that is simpler:

- step0: set flag that "all newly created tasks need the array allocated from now on".

- step1: allocate N arrays outside tasklist_lock

- step2: take tasklist_lock, loop over all tasks that exist and pass in the N arrays to all tasks that still need it.

If tasks were 'refilled', drop tasklist_lock and go back to step 1.

- step3: free N (superfluously allocated) arrays

Make N something like 32 to not get into a bad quadratic nr_tasks double loop in practice. (Possibly allocate arrays[32] dynamically as well at step0 and not have it on the kernel stack - so 32 can be changed to 128 or so.)

Ingo

2008/11/21 Ingo Molnar <[email protected]>:

Quoted 43 lines · Frédéric Weisbecker

Quoted 17 lines

When the tracer will be launched, I will hold the tasklist_lock to allocate/insert the dynamic arrays. So in this atomic context, I will not be able to call kmalloc with GFP_KERNEL. And I fear that using GFP_ATOMIC for possible hundreds of tasks would be clearly unacceptable.

What do you think of this way:

_tracer activates
_a function enters the tracer entry-hooker. If the array is allocated for the current task, that's well. If not I launch a kernel thread that will later allocate an array for the current task (I will pass the pid as a parameter). So the current task will be soon be traced. _ when a process forks, I can allocate a dynamic array for the new task without problem (I hope).

Quoted 4 lines

So some tasks will not be traced at the early beggining of tracing but they will soon all be traced.... There is perhaps a problem with tasks that are sleeping for long times... There will be some losses once they will be awaken...

i'd suggest a different approach that is simpler:

- step0: set flag that "all newly created tasks need the array allocated from now on".

- step1: allocate N arrays outside tasklist_lock

- step2: take tasklist_lock, loop over all tasks that exist and pass in the N arrays to all tasks that still need it.

If tasks were 'refilled', drop tasklist_lock and go back to step 1.

- step3: free N (superfluously allocated) arrays

Make N something like 32 to not get into a bad quadratic nr_tasks double loop in practice. (Possibly allocate arrays[32] dynamically as well at step0 and not have it on the kernel stack - so 32 can be changed to 128 or so.)

Quoted 2 lines

Ingo

Ok. I thought about this method but wondered about the fact that kmalloc can schedule and then I could run in an infinite loop (or a too long one).

I will try this. Thanks.

Quoted 11 lines

Quoted 6 lines

Yeah, it was just a recommendation, and perhaps not a good one ;-)

Frederic, it is better if you move the array from the thread info to the task struct. It will take up more memory but it is a hell of a lot safer. The pro here definitely outways the con.

if the memory footprint starts mattering we could turn this into a single pointer to an array - and add/remove these arrays (from all tasks currently running) as the tracer is turned on/off.

Quoted 2 lines

Ingo

Ok. So what do you suggest once? Do I begin to move the array from thread info to struct task but by keeping the static
array or should I directly use a dynamic allocation and add/remove dynamically?

Quoted 7 lines · Frederic Weisbecker

Impact: help to find the better depth of trace

We decided to arbitrary define the depth of function return trace as "20". Perhaps this is not enough. To help finding an optimal depth, we measure now the overrun: the number of functions that have been missed for the current thread. By default this is not displayed, we have to do set a particular flag on the return tracer: echo overrun

Quoted 8 lines

Quoted 1 line

/debug/tracing/trace_options And the overrun will be printed on

the right.

As the trace shows below, the current 20 depth is not enough.

update_wall_time+0x37f/0x8c0 -> update_xtime_cache (345 ns) (Overruns: 2838)
update_wall_time+0x384/0x8c0 -> clocksource_get_next (1141 ns) (Overruns: 2838)
do_timer+0x23/0x100 -> update_wall_time (3882 ns) (Overruns: 2838)

hm, interesting. Have you tried to figure out what a practical depth limit would be?

With lockdep we made the experience that function call stacks can be very deep - if we count IRQ contexts too it can be up to 100 in the extreme cases. (but at that stage kernel stack limits start hitting us)

I'd say 50 would be needed.

Quoted 27 lines · Ingo Molnar

Quoted 7 lines · Frederic Weisbecker

Impact: help to find the better depth of trace

We decided to arbitrary define the depth of function return trace as "20". Perhaps this is not enough. To help finding an optimal depth, we measure now the overrun: the number of functions that have been missed for the current thread. By default this is not displayed, we have to do set a particular flag on the return tracer: echo overrun

Quoted 8 lines

Quoted 1 line

/debug/tracing/trace_options And the overrun will be printed on

the right.

As the trace shows below, the current 20 depth is not enough.

update_wall_time+0x37f/0x8c0 -> update_xtime_cache (345 ns) (Overruns: 2838)
update_wall_time+0x384/0x8c0 -> clocksource_get_next (1141 ns) (Overruns: 2838)
do_timer+0x23/0x100 -> update_wall_time (3882 ns) (Overruns: 2838)

hm, interesting. Have you tried to figure out what a practical depth limit would be?

With lockdep we made the experience that function call stacks can be very deep - if we count IRQ contexts too it can be up to 100 in the extreme cases. (but at that stage kernel stack limits start hitting us)

Quoted 1 line

I'd say 50 would be needed.

I was just looking at the stack tracer, and it pretty much gives us the answer ;-) I'm hitting on max traces around 55, but some of those are asm calls. We could do 50 or 60? We probably want to make sure that the two do not come close to hitting. That is, the bottom of the stack to overwrite the saved return addresses.

Quoted 6 lines · Steven Rostedt

I was just looking at the stack tracer, and it pretty much gives us the answer ;-) I'm hitting on max traces around 55, but some of those are asm calls. We could do 50 or 60? We probably want to make sure that the two do not come close to hitting. That is, the bottom of the stack to overwrite the saved return addresses.

does the stack tracer properly nest across IRQ entry boundaries already on x86? We used to have problems in that area.

Quoted 10 lines · Ingo Molnar

Quoted 6 lines · Steven Rostedt

I was just looking at the stack tracer, and it pretty much gives us the answer ;-) I'm hitting on max traces around 55, but some of those are asm calls. We could do 50 or 60? We probably want to make sure that the two do not come close to hitting. That is, the bottom of the stack to overwrite the saved return addresses.

does the stack tracer properly nest across IRQ entry boundaries already on x86? We used to have problems in that area.

Actually, because the stack tracer is in generic code, we punt on IRQ stacks:

	/* we do not handle interrupt stacks yet */
	if (!object_is_on_stack(&this_size))
		return;

I check if the local variable "this_size" is on the current->stack and if it is not then this means that we are using some other stack, and we do not record it.

What would be needed is to make a per-arch stack call. Perhaps have a:

   arch_check_stack(&this_size, &max_stack_trace, &max_stack_size);

Where a weak function can be defined to return nothing. But the arch can check which stack the "this_size" variable is on and run the stack tracer against that stack.

Maybe we should have two stack traces, a stack_trace file and a stack_trace_irq ?

Because, some archs, like x86_64 have different size stacks. The thread stack is 8K where as the IRQ stack is 4K. We may want to see which IRQ stack call is the worst, and not compare it to the thread stack call.

Quoted 13 lines

What would be needed is to make a per-arch stack call. Perhaps have a:

   arch_check_stack(&this_size, &max_stack_trace, &max_stack_size);

Where a weak function can be defined to return nothing. But the arch can check which stack the "this_size" variable is on and run the stack tracer against that stack.

Maybe we should have two stack traces, a stack_trace file and a stack_trace_irq ?

Quoted 4 lines

Because, some archs, like x86_64 have different size stacks. The thread stack is 8K where as the IRQ stack is 4K. We may want to see which IRQ stack call is the worst, and not compare it to the thread stack call.

... and on 64-bit x86 the IRQ stacks are 16K, and some of the IST exception stacks have different sizes as well.