[ECOS] simple eCos profiler

[ECOS] simple eCos profiler

[NavEcos]

Hello,

I have received permission from my company to release a hack profiler
that I made.  Currently it only supports x86-pc, but I hope that
others will port it to use to the other platforms.  I would port it
myself if I could get the hardware (yes, if you send me a currently
supported evaluation board, I will port it to that board FREE.)

It requires a FEW minor changes to the kernel in vectors.S but that's
it.  Two low priority tasks (servers) run to send data to the host.
One server simply sends program counters and task ID's at regular
invervals, the other takes requests and turns task ID's into thread
names. 

It's a simple profiler but gets the job done.  Here is some sample
output with just the profiler running and 30 pings/sec (of 9000
bytes) being sent to the board as it's being profiled.  The '#'
are added by me and aren't actually output by the program.
It might help if you have a fixed width font to read this:


# this is just global counts
# Count = how often this function was seen
# Address = actual PC recorded, for debug of the profiler
# Symbol = name demangled C function (or C++ or assembly)

Count   : Address  : Symbol
------- : -------- : --------------
2       : 00109d77 : PacketRxReady
1       : 0010a05d : TxMachine
1       : 0010a2a5 : i82559_can_send
1       : 0010a3c8 : i82559_send
1       : 0010a677 : i82559_deliver
2001    : 0010da18 : hal_idle_thread_action
1       : 0010f6a9 : hal_if_diag_write_char
1846    : 0010f89f : hal_ctrlc_check
62      : 00110c7c : memcpy
1       : 00111278 : cyg_interrupt_acknowledge
1       : 00111408 : cyg_current_time
1       : 00111dd6 : Cyg_Thread::wake(void)
1       : 001129ba : Cyg_Interrupt::call_pending_DSRs_inner(void)
7       : 001129d8 : cyg_interrupt_call_pending_DSRs
8       : 00112c48 : Cyg_Interrupt::mask_interrupt(unsigned int)
3       : 00112cc0 : Cyg_Interrupt::unmask_interrupt(unsigned int)
5       : 00112d10 : Cyg_Interrupt::acknowledge_interrupt(unsigned int)
1       : 00113378 : Cyg_Scheduler::unlock_inner(unsigned int)
1       : 00113c24 : Cyg_Flag::setbits(unsigned int)
2       : 00114260 : Cyg_Mutex::lock(void)
1       : 0011447c : Cyg_Mutex::unlock(void)
1       : 0011ec3a : cyg_netint
3       : 0011ef11 : cyg_splimp
1       : 0011f07e : cyg_splinternal
2       : 0011f0a4 : cyg_splx
1       : 0011f402 : alarm_thread
1       : 0011f678 : cyg_callout_stop
1       : 00123056 : cyg_rtalloc1
2       : 00127610 : cyg_ip_input
1       : 00127afc : ipintr
1       : 00127e34 : ip_reass
2       : 001294ba : cyg_ip_output
2       : 0012ed05 : cyg_sbdrop
1       : 0012fdb4 : cyg_m_freem
4       : 00131e01 : eth_drv_send
1       : 00132148 : eth_drv_recv
1       : 0013284d : eth_drv_dsr
1       : 0013292d : hal_thread_switch_context_load
1       : 001338ad : Cyg_Counter::add_alarm(Cyg_Alarm *)
2       : 00134bcb : memmove
14      : 0013ac64 : cyg_in_cksumdata
1       : 0013af4f : cyg_in_cksum_hdr
2       : 0013b92b : cyg_icmp_input
2       : 0013ce2d : cyg_arpresolve
3       : 0013de70 : cyg_tcp_input
1       : 0013f998 : tcp_xmit_timer

# this lists by task which functions were seen most often
# First the task is printed, and how often it was seen
# then is a list below the task, each with a count

Task list dump
--------------

1       -> (TID:00153120) profiler task
  1       -> Cyg_Mutex::lock(void)

1       -> (TID:00154640) task name server
  1       -> hal_if_diag_write_char

2004    -> (TID:00157240) Idle Thread
  2001    -> hal_idle_thread_action
  1       -> Cyg_Interrupt::call_pending_DSRs_inner(void)
  2       -> cyg_interrupt_call_pending_DSRs

104     -> (TID:0015c200) Network support
  1       -> PacketRxReady
  1       -> TxMachine
  1       -> i82559_can_send
  1       -> i82559_send
  40      -> memcpy
  1       -> cyg_interrupt_acknowledge
  1       -> Cyg_Thread::wake(void)
  2       -> cyg_interrupt_call_pending_DSRs
  7       -> Cyg_Interrupt::mask_interrupt(unsigned int)
  1       -> Cyg_Interrupt::unmask_interrupt(unsigned int)
  5       -> Cyg_Interrupt::acknowledge_interrupt(unsigned int)
  1       -> Cyg_Flag::setbits(unsigned int)
  1       -> cyg_netint
  1       -> cyg_splimp
  1       -> cyg_splx
  1       -> cyg_callout_stop
  1       -> cyg_rtalloc1
  2       -> cyg_ip_input
  1       -> ipintr
  1       -> ip_reass
  2       -> cyg_ip_output
  2       -> cyg_sbdrop
  4       -> eth_drv_send
  2       -> memmove
  14      -> cyg_in_cksumdata
  1       -> cyg_in_cksum_hdr
  2       -> cyg_icmp_input
  2       -> cyg_arpresolve
  3       -> cyg_tcp_input
  1       -> tcp_xmit_timer
 
1890    -> (TID:0019d3a0) Network alarm support
  1       -> PacketRxReady
  1       -> i82559_deliver
  1846    -> hal_ctrlc_check
  22      -> memcpy
  1       -> cyg_current_time
  3       -> cyg_interrupt_call_pending_DSRs
  1       -> Cyg_Interrupt::mask_interrupt(unsigned int)
  2       -> Cyg_Interrupt::unmask_interrupt(unsigned int)
  1       -> Cyg_Scheduler::unlock_inner(unsigned int)
  1       -> Cyg_Mutex::lock(void)
  1       -> Cyg_Mutex::unlock(void)
  2       -> cyg_splimp
  1       -> cyg_splinternal
  1       -> cyg_splx
  1       -> alarm_thread
  1       -> cyg_m_freem
  1       -> eth_drv_recv
  1       -> eth_drv_dsr
  1       -> hal_thread_switch_context_load
  1       -> Cyg_Counter::add_alarm(Cyg_Alarm *)


So it's easy to see which tasks are functions are taking the most
time.  As I said, this is a hack.  I can release the source though.
It's in C++ mostly.  You can feel free to change the numbers to
percentages, but at the time I preferred raw data.

I would like to get at least hooks for this into the main tree.  It
will not slow down eCos, it will be conditionally compilable.  I
can do the CDL if requested.  How do I get it into CVS?

-Rich

P.S.  hal_ctrlc_check gets called a LOT and seems to get called
more, the more pings I send it.  I haven't debugged this to find out
why, but it's perplexing.  Anybody know what is going on with it?

-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[Andrew Lunn]

Hi Rich.

This looks similar to the one i wrote a few years ago for eCos. Its
sitting in the ecos-discuss archive somewhere. That was for the
EBSA285, but could be easily ported to other targets. I find a
profiler useful at times, so it would be good to get something
incorporated.

> I would like to get at least hooks for this into the main tree.  It
> will not slow down eCos, it will be conditionally compilable.  I
> can do the CDL if requested.  How do I get it into CVS?

Post the patch to ecos-patches. We the community can then take a look
at it and decide what needs doing to make it incorperatable, eg cdl,
making it more generic etc. 

> -Rich
> 
> P.S.  hal_ctrlc_check gets called a LOT and seems to get called
> more, the more pings I send it.  I haven't debugged this to find out
> why, but it's perplexing.  Anybody know what is going on with it?

This function acts as the interface between the application network
stack and redboot. Each packet received by the application is passed
down to redboot to let it decide if the packet is actually for the
redboot stack, not the application stack. 

        Andrew

-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[NavEcos]

On Wednesday 31 July 2002 01:05, Andrew Lunn wrote:
> Hi Rich.
>
> This looks similar to the one i wrote a few years ago for eCos. Its
> sitting in the ecos-discuss archive somewhere. That was for the
> EBSA285, but could be easily ported to other targets. I find a
> profiler useful at times, so it would be good to get something
> incorporated.

I just want to get something basic, perhaps later on a more polished
tool can be made.

> > I would like to get at least hooks for this into the main tree.  It
> > will not slow down eCos, it will be conditionally compilable.  I
> > can do the CDL if requested.  How do I get it into CVS?
>
> Post the patch to ecos-patches. We the community can then take a look
> at it and decide what needs doing to make it incorperatable, eg cdl,
> making it more generic etc.

There is a significant amount of code, most of it is not kernel code.
Is it OK if I post a link to a webpage?  I just have to set one up :D

> > -Rich
> >
> > P.S.  hal_ctrlc_check gets called a LOT and seems to get called
> > more, the more pings I send it.  I haven't debugged this to find out
> > why, but it's perplexing.  Anybody know what is going on with it?
>
> This function acts as the interface between the application network
> stack and redboot. Each packet received by the application is passed
> down to redboot to let it decide if the packet is actually for the
> redboot stack, not the application stack.

Oh.  That name seem sort of obsfucated, but I get it.

I will have to look at this more.  I have found that it can take up
significant time (like 33% of the active time) if I send enough
network traffic through it.

I have a question.  When redboot "runs", can the application on
top of redboot interrupt it?  I haven't investigated the relationship
between the two very much.

>         Andrew

Thank you,
-Rich

-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[Andrew Lunn]

> There is a significant amount of code, most of it is not kernel code.
> Is it OK if I post a link to a webpage?  I just have to set one up :D

Yep. Or you could use bugzilla.redhat.com. Create a new enhancement
bug and attach the code using the attachment feature.

> > > P.S.  hal_ctrlc_check gets called a LOT and seems to get called
> > > more, the more pings I send it.  I haven't debugged this to find out
> > > why, but it's perplexing.  Anybody know what is going on with it?
> >
> > This function acts as the interface between the application network
> > stack and redboot. Each packet received by the application is passed
> > down to redboot to let it decide if the packet is actually for the
> > redboot stack, not the application stack.
> 
> Oh.  That name seem sort of obsfucated, but I get it.

Its historic. The redboot network stack is a recent bolt on addition.

> I will have to look at this more.  I have found that it can take up
> significant time (like 33% of the active time) if I send enough
> network traffic through it.

That does seem a lot. It is possible to disable this, but you loose
some of the network debugging facilities. Without this you cannot use
^C to interrupt a running system and tcp connections will die after a
while since the keep alive won't happen.

Actually, its possible your figure is misleading. I think interrupts
are disabled in this function before it jumps into redboot. After
redboot exits the function re-enabled interupts. Im guessing your
profiler is interrupt based? So any profiler interrupts while it is in
redboot will actually be serviced in this function once the interrupts
are re-enabled.

> I have a question.  When redboot "runs", can the application on top
> of redboot interrupt it?  I haven't investigated the relationship
> between the two very much.

Nope. 

      Andrew


-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[NavEcos]

On Wednesday 31 July 2002 02:02, Andrew Lunn wrote:
> > There is a significant amount of code, most of it is not kernel code.
> > Is it OK if I post a link to a webpage?  I just have to set one up :D
>
> Yep. Or you could use bugzilla.redhat.com. Create a new enhancement
> bug and attach the code using the attachment feature.

I'll make a webpage for it.  I'm too lazy ATM to learn yet another thing.
I'll try to get it posted within the next 24 hours.

> > > > P.S.  hal_ctrlc_check gets called a LOT and seems to get called
> > > > more, the more pings I send it.  I haven't debugged this to find out
> > > > why, but it's perplexing.  Anybody know what is going on with it?
> > >
> > > This function acts as the interface between the application network
> > > stack and redboot. Each packet received by the application is passed
> > > down to redboot to let it decide if the packet is actually for the
> > > redboot stack, not the application stack.
> >
> > Oh.  That name seem sort of obsfucated, but I get it.
>
> Its historic. The redboot network stack is a recent bolt on addition.
>
> > I will have to look at this more.  I have found that it can take up
> > significant time (like 33% of the active time) if I send enough
> > network traffic through it.
>
> That does seem a lot. It is possible to disable this, but you loose
> some of the network debugging facilities. Without this you cannot use
> ^C to interrupt a running system and tcp connections will die after a
> while since the keep alive won't happen.
>
> Actually, its possible your figure is misleading. I think interrupts
> are disabled in this function before it jumps into redboot. After
> redboot exits the function re-enabled interupts. Im guessing your
> profiler is interrupt based? So any profiler interrupts while it is in
> redboot will actually be serviced in this function once the interrupts
> are re-enabled.

Yep, you're right:

My profiler is based on the system tick interrupt.  I AM aware of
the inherit problems of doing it this way but this was the most
portable way of doing it.  For a heavily loaded system, doing it
this way shouldn't skew results too much I don't think.

Anyhow, although my figure is misleading, a lot of time is being spent
uncessarily in that function.  Perhaps a quick hack "fix" would be
keep track of the last time the function was called, and if "X" amount
of ticks hasn't elapsed, to skip the check.  This would probably
disable control-C ability for the most part of the stack is active,
but at least the keep alive should work I think?

> > I have a question.  When redboot "runs", can the application on top
> > of redboot interrupt it?  I haven't investigated the relationship
> > between the two very much.
>
> Nope.
>
>       Andrew

thanks,
-Rich

-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[Andrew Lunn]

> Yep, you're right:
> 
> My profiler is based on the system tick interrupt.  I AM aware of
> the inherit problems of doing it this way but this was the most
> portable way of doing it.  For a heavily loaded system, doing it
> this way shouldn't skew results too much I don't think.

When i wrote my profiler i did not like the idea of using the system
tick interrupt, even thought its more portable. Timer actions will be
triggered by the timer tick, which have an important affect on the
flow of execution in an RTOS. Thus your profiler will give squewed
results which tend to show more of the low priority background tasks
which are always running and less of the higher priority tasks which
are general somehow linked to the system clock. 

I used a second timer which i set to run at a different frequency
which is not a multiple of the system clock. This should give more
accurate results. The down side is its less portable since it has to
play around with the hardware to setup this timer.

What would be nice is to split the code into two halfs. One to setup
the interrupts etc, which would be hardware dependent and the second
half to actually do the logging. We could provide a generic version
using the system tick and the option to add hardware specific
implementations using other timers.

     Andrew

-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[Scott Dattalo]

On Wed, 31 Jul 2002, Andrew Lunn wrote:

> > Yep, you're right:
> > 
> > My profiler is based on the system tick interrupt.  I AM aware of
> > the inherit problems of doing it this way but this was the most
> > portable way of doing it.  For a heavily loaded system, doing it
> > this way shouldn't skew results too much I don't think.
> 
> When i wrote my profiler i did not like the idea of using the system
> tick interrupt, even thought its more portable. Timer actions will be
> triggered by the timer tick, which have an important affect on the
> flow of execution in an RTOS. Thus your profiler will give squewed
> results which tend to show more of the low priority background tasks
> which are always running and less of the higher priority tasks which
> are general somehow linked to the system clock. 
> 
> I used a second timer which i set to run at a different frequency
> which is not a multiple of the system clock. This should give more
> accurate results. The down side is its less portable since it has to
> play around with the hardware to setup this timer.
> 
> What would be nice is to split the code into two halfs. One to setup
> the interrupts etc, which would be hardware dependent and the second
> half to actually do the logging. We could provide a generic version
> using the system tick and the option to add hardware specific
> implementations using other timers.


Along these lines, may I suggest yet another way? Would it be difficult to
decouple the profiling process from the timer source in such a way that
you could either dynamically or at compile time select the sampling
stimulus. For example, for an old microcontroller application I used an
interrupt pin to trigger the profiler. The interrupt routine did nothing
more than examine the call stack to extract where the code was executing
and copied this into a circular buffer. It's not exactly a profiler, but
it can gave me a rough idea of where the processor was spending its time.

Perhaps, Andrew, this is what you already mean by splitting the code into 
two halves?

Scott


-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[Gary Thomas]

On Wed, 2002-07-31 at 03:59, NavEcos wrote:
> On Wednesday 31 July 2002 02:02, Andrew Lunn wrote:
> > > There is a significant amount of code, most of it is not kernel code.
> > > Is it OK if I post a link to a webpage?  I just have to set one up :D
> >
> > Yep. Or you could use bugzilla.redhat.com. Create a new enhancement
> > bug and attach the code using the attachment feature.
> 
> I'll make a webpage for it.  I'm too lazy ATM to learn yet another thing.
> I'll try to get it posted within the next 24 hours.
> 
> > > > > P.S.  hal_ctrlc_check gets called a LOT and seems to get called
> > > > > more, the more pings I send it.  I haven't debugged this to find out
> > > > > why, but it's perplexing.  Anybody know what is going on with it?
> > > >
> > > > This function acts as the interface between the application network
> > > > stack and redboot. Each packet received by the application is passed
> > > > down to redboot to let it decide if the packet is actually for the
> > > > redboot stack, not the application stack.
> > >
> > > Oh.  That name seem sort of obsfucated, but I get it.
> >
> > Its historic. The redboot network stack is a recent bolt on addition.
> >
> > > I will have to look at this more.  I have found that it can take up
> > > significant time (like 33% of the active time) if I send enough
> > > network traffic through it.
> >
> > That does seem a lot. It is possible to disable this, but you loose
> > some of the network debugging facilities. Without this you cannot use
> > ^C to interrupt a running system and tcp connections will die after a
> > while since the keep alive won't happen.
> >
> > Actually, its possible your figure is misleading. I think interrupts
> > are disabled in this function before it jumps into redboot. After
> > redboot exits the function re-enabled interupts. Im guessing your
> > profiler is interrupt based? So any profiler interrupts while it is in
> > redboot will actually be serviced in this function once the interrupts
> > are re-enabled.
> 
> Yep, you're right:
> 
> My profiler is based on the system tick interrupt.  I AM aware of
> the inherit problems of doing it this way but this was the most
> portable way of doing it.  For a heavily loaded system, doing it
> this way shouldn't skew results too much I don't think.
> 
> Anyhow, although my figure is misleading, a lot of time is being spent
> uncessarily in that function.  Perhaps a quick hack "fix" would be
> keep track of the last time the function was called, and if "X" amount
> of ticks hasn't elapsed, to skip the check.  This would probably
> disable control-C ability for the most part of the stack is active,
> but at least the keep alive should work I think?
> 

Note that this code only executes if the debug (console) channel is via
a network connection.  Having such implies that you _want_ network 
debugging to be available.  If this is the case, then you simply need to
expect to pay the cost of supporting it.

Your suggestion would probably render the network debugging useless or
nearly so, sorry.  The simplest solution is to use a serial port for
the debug channel (RedBoot can still load your program via the network).
Then this cost will nearly vanish (there will still be a small cost for
checking for ^C on the serial port, but it is a very quick test).

> > > I have a question.  When redboot "runs", can the application on top
> > > of redboot interrupt it?  I haven't investigated the relationship
> > > between the two very much.
> >
> > Nope.
> >
> >       Andrew
> 
> thanks,
> -Rich
> 
> -- 
> Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
> and search the list archive: http://sources.redhat.com/ml/ecos-discuss



-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss

Re: [ECOS] simple eCos profiler

[NavEcos]

Here is a link to the code of the quick and dirty ecos profiler I wrote
for the i-386 target.

http://ecos.dynu.com

You will need ecos 2.0, will have to apply the patch (provided at
the webpage) and compile the kernel to support either openbsd or
netbsd (template = net or new_net).

It should not be too difficult to port this to other platforms.

The webpage should be up for the next week or so, but not forever.
I will move it to a more permanent location at some time in the
future.  You can download it all in one shot here:

http://ecos.dynu.com/all.tgz.

This is a direct link to my computer using the service provided by
http://www.dynu.com. </plug>

-Rich

-- 
Before posting, please read the FAQ: http://sources.redhat.com/fom/ecos
and search the list archive: http://sources.redhat.com/ml/ecos-discuss