This is the mail archive of the ecos-discuss@sources.redhat.com mailing list for the eCos project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

simple eCos profiler


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


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]