path: root/testsuites/samples/capture/capture.doc

#  COPYRIGHT (c) 1989-1999.
#  On-Line Applications Research Corporation (OAR).
#
#  The license and distribution terms for this file may be
#  found in the file LICENSE in this distribution or at
#  http://www.rtems.org/license/LICENSE.
#

Capture Engine Tutorial

The Capture Engine is a software trace tool built into the RTEMS operating
system. Being software it does use CPU and memory resources. If do not use it
does not effect RTEMS or your application. The Capture Engine is designed to
placed the lowest load possible on the system when operating and when disabled
does not effect RTEMS. It binds to RTEMS at runtime and does not require RTEMS
or your application to be rebuilt inorder to use it.

This tutorial will guide you through the building of RTEMS and the sample
programs for the pc586 BSP on Windows using the MinGW tools. The RTEMS Capture
Engine sample programmes are found in CVS and will be available in the next
release of RTEMS. The turoial will show how to create filters and triggers and
how to obtain a trace of the tasks running. The Capture Engine Command Line
Interface (CLI) will be used as this currently is the only available interface
to the Capture Engine.

The tutorial uses the PC586 BSP running under QEMU. This provides a stable
environment that be easly duplicated on readly available hardware. If you are
new to RTEMS, simulators helps you get RTEMS running quickly. The RTEMS Wiki
provides the information needed to download and install these tools.

In this tutorial I have placed the RTEMS source code into the Windows
directory:

  c:\rtems\src\rtems-4.7.0

RTEMS is configured using the shell MSYS with this command:

 $ /c/rtems/src
 $ mkdir pc586
 $ cd pc586
 $ /c/rtems/src/rtems-4.7.0/configure --target=i386-rtems4.8 \
           --enable-network --enable-posix --enable-cxx\ 
           --enable-tests=samples --enable-maintainer-mode \
           --enable-rtemsbsp=pc586
 $ make all

If you wish to use the Windows Command prompt open an RTEMS Command prompt
window by running the c:\rtems\i386\rtems-cmd.bat batch file from Explorer. The
shell commands become:

 RTEMS(i386) C:\rtems\i386> cd ..\src 
 RTEMS(i386) C:\rtems\src> mkdir pc586
 RTEMS(i386) C:\rtems\src> cd pc586 
 RTEMS(i386) C:\rtems\src\pc586> sh /c/rtems/src/rtems-4.7.0/configure
 --target=i386-rtems4.7 --enable-network --enable-posix
 --enable-tests=samples --enable-maintainer-mode --enable-cxx
 --enable-rtems-bsp=pc586
 RTEMS(i386) C:\rtems\src\pc586> make all

Install the Windows version of QEMU and run with the following command:

 RTEMS(i386) C:\rtems\src\pc586> type c:\rtems\i386\bin\qemu.bat
 rem @echo off
 set QEMU=C:\rtems\i386\qemu-0.8.2-windows
 %QEMU%\qemu -L %QEMU% -m 128 -boot a -fda c:\rtems\i386\rtems-boot.img
 -hda fat:%1 %2 %3

You will need to download the GRUB boot loader image from the RTEMS
website. This image will boot the QEMU PC and attempt to read a GRUB
configuration file from the hda root directory. You pass the qemu.bat file the
path on your disk to the hda root directory. The capture engine examples are in
the standard testsuite examples directory. For our Windows host once built they
are in:

 rtems\src\pc586\i386-rtems4.8\c\pc586\testsuites\samples

In this directory create a GRUB configuration file with an entry similar to
this one:

 RTEMS(i386) C:\rtems\src\pc586> type i386-rtems4.8\c\pc586\testsuites\sam
 ples\rtems-grub.cfg
 # RTEMS Grub configuration for the Samples
 set default=0

 menuentry "RTEMS - Capture" {
  set root=(hd0,0)
  multiboot (hd0,0)/capture/capture.exe
 }

It has a single entry the Capture Engine test. Change to the samples directory
and run QEMU using the QEMU batch file we created above:

 RTEMS(i386) C:\rtems\src\pc586> cd i386-rtems4.7\c\pc586\testsuites\samples
 RTEMS(i386) C:\rtems\src\pc586\i386-rtems4.7\c\pc586\testsuites\samples> qemu .

A QEMU console will open and you will see the GNU GRUB menu. The "RTEM -
Capture" menu item will be highlighted. Press Enter and GRUB will load and
execute the RTEMS Capture Engine example.

RTEMS will only take a moment to initialise and you will be presented with the
RTEMS monitor login prompt:

 Initialized console on port CONSOLE


 *** CAPTURE ENGING TEST ***

 Monitor ready, press enter to login.

 rtems $ 

The standard configuration is the Capture Engine not initialised and not
running. It needs to be initialised. You enter a trace buffer size in bytes
with the open command:

 rtems $ copen 5000
 capture engine open
 rtems $ 

If you look in the Capture Engine example source code 'test1.c' a CLI command
'test1' is added to the RTEMS monitor. When you enter the 'test1' command the
'RMON' task will call 'capture_test_1()'. This function creates a task called
'CT1a' and starts it, then task 'CT1b' is created and started and finally
'CT1c' is created and started. All tasks are passed the object id of a
semaphore as a task argument. The RMON command thread then loops sleeping for 1
second, waking to check if all of the tasks that have been created have been
deleted themselves. Once all tasks have been deleted the command returns
presenting the prompt to the user.

The first task started is 'CT1a'. It obtains the mutex, waits 2.5 seconds,
releases it then deletes itself. The second task 'CT1b' loops until task 'CT1c'
has been deleted. The last task 'CT1c' also obtains the semaphore, waits 0.5
seconds, releases the semaphore then deletes itself.

The priority of RMON is 1 and is the highest priority task. The task 'CT1a' has
the lowest priority of 102, task 'CT1b' has a priority of 101, and 'CT1c' is the
highest priority of the three created tasks with 100.

The test generates priority inheritance where task 'CT1a' inherits the priority
of task 'CT1c' and the Capture Engine captures this for you to observe. Task
'CT1a' obtains the semaphore with a priority of 102 then sleeps. Task 'CT1b'
consumes all of the CPU time with a priority of 101. Normally task 'CT1a' would
never run again. Task 'CT1c' runs and blocks waiting for the semaphore. When
task 'CT1a' wakes after 2.5 seconds it inherits the priority of task 'CT1c'
which is 100, higher than task 'CT1b'. Task 'CT1a' can now run and releases the
semaphore which task 'CT1c' obtains. After it wakes from a 0.5 second sleep it
releases the semaphore and deletes itself which causes task 'CT1b' to delete
itself.

We could just open the capture engine, enable it and start tracing how-ever
there could be a large number of context switches before we get to our test and
the tasks events we are interested in. This would create a large amount of
trace noise and add extra load onto the system capturing this noise. A software
capture tool like this one is effective if we can filter the events recorded
into the trace buffer and if we can control when we trigger to start
recording.

The simplest type of filter is the ceiling and floor priority filter. Here we
narrow the range of priorities captured. This is useful for applications which
typically have a middle range of priorites removing device type tasks such as
networking tasks or file system tasks as well as low priority back ground
tasks. Our test tasks have a priority range of 100 to 102. The filter is set
with the following commands:

 rtems $ cwceil 100
 watch ceiling 100.
 rtems $ cwfloor 102
 watch floor is 102.
 rtems $ 

We also need to enable the global watch. This causes all tasks in the priority
range to be captured:

 rtems $ cwglob on
 global watch enabled.
 rtems $ 

You can set or clear a trigger. To start with we will use the simplest trigger
we can have. This is just a task name. As the RMON task handles the RTEMS
monitor keyboard and executes the commands we shall trigger when this task
effects a task in our priority range. To set the trigger use this command:

 rtems $ ctset RMON
 trigger set.
 rtems $ cwlist
 watch priority ceiling is 100
 watch priority floor is 102
 global watch is enabled
 total 1
  00000000 RMON g-  T:S------ F:-----
 rtems $ 

The 'cwlist' command lists the watch and trigger configuration. You will see
the RMON trigger line has a number, a label and flags. Later you will be given
more detail on these values. The number is an RTEMS object id. It is 0 which
means use the label when looking for the trigger. We could have entered the
task id for RMON in the trigger rather than the label.

The capture engine is disabled after being opened and needs to be enabled. The
ability to enable and disable the capture engine with a single command allows
you to remove any effect the capture may have on the application while you are
tracing a problem. To enable enter:

 rtems $ cenable
 capture engine enabled.
 rtems $ 

To dump a recorded the trace you enter:

 rtems $ ctrace
 rtems $ 

The trace buffer is empty. Notice how the capture engine is not triggering on
the RMON task or the execution of any other tasks that may be in the
system. Every monitor key press causes the RMON task to be switched in to
run. It is now time to run the test so enter the 'test1' command:

 rtems $ test1 
 rtems $ 

After a few seconds the RTEMS monitor prompt will return and we can dump the
trace.

 rtems $ ctrace
        91.980000 0a010002 RMON   1   1 CREATED_BY
        91.980000 0a010003 CT1a 102 102 CREATED
        91.980000 0a010002 RMON   1   1 STARTED_BY
        91.980000 0a010003 CT1a 102 102 STARTED
        91.980000 0a010003 CT1a 102 102 SWITCHED_IN
        91.980000 0a010003 CT1a 102 102 BEGIN
        91.980000 0a010003 CT1a 102 102 SWITCHED_OUT
        92.980000 0a010002 RMON   1   1 CREATED_BY
        92.980000 0a010004 CT1b 101 101 CREATED
        92.980000 0a010002 RMON   1   1 STARTED_BY
        92.980000 0a010004 CT1b 101 101 STARTED
        92.980000 0a010004 CT1b 101 101 SWITCHED_IN
        92.980000 0a010004 CT1b 101 101 BEGIN
        93.980000 0a010004 CT1b 101 101 SWITCHED_OUT
        93.980000 0a010002 RMON   1   1 CREATED_BY
        93.980000 0a010004 CT1c 100 100 CREATED
        93.980000 0a010002 RMON   1   1 STARTED_BY
        93.980000 0a010005 CT1c 100 100 STARTED
        93.980000 0a010005 CT1c 100 100 SWITCHED_IN
        93.980000 0a010005 CT1c 100 100 BEGIN
        93.980000 0a010005 CT1c 100 100 SWITCHED_OUT
        93.980000 0a010004 CT1b 101 101 SWITCHED_IN
 rtems $ 

The trace dump command by default displays 24 trace records. We have more so
enter the trace command until all have been displayed. The details of the trace
data will be discussed once we have all the trace data.

 rtems $ ctrace
        94.480000 0a010004 CT1b 101 101 SWITCHED_OUT
        94.480000 0a010003 CT1a 102 100 SWITCHED_IN
        94.480000 0a010003 CT1a 102 102 SWITCHED_OUT
        94.480000 0a010005 CT1c 100 100 SWITCHED_IN
        94.480000 0a010005 CT1c 100 100 SWITCHED_OUT
        94.480000 0a010004 CT1b 101 101 SWITCHED_IN
        94.980000 0a010004 CT1b 101 101 SWITCHED_OUT
        94.980000 0a010005 CT1c 100 100 SWITCHED_IN
        94.980000 0a010005 CT1c 100 100 DETELED_BY
        94.980000 0a010005 CT1c 100 100 DETELED
        94.980000 0a010004 CT1b 101 101 SWITCHED_IN
        94.980000 0a010004 CT1b 101 101 DELETED_BY
        94.980000 0a010004 CT1b 101 101 DELETED
        94.980000 0a010003 CT1a 102 100 SWITCHED_IN
        94.980000 0a010003 CT1a 102 100 DELETED_BY
        94.980000 0a010003 CT1a 102 100 DELETED
 rtems $

The first column of the trace data is the time stamp. The test command started
when the time stamp was 91.98 seconds and took 3 seconds to run. Your trace
will have a different starting value but the total time should be 3
seconds. The actual start value is the time it takes you to enter the various
capture commands. It would seem I am rather slow.

The second column is the object id. In this case they are task ids. The third
column is the object name.

The fourth is the real task priority and fifth column is the executing task
priority. The executing priority follows any priority inheritance. The last
column is the event the capture engine has captured.

The first couple of records:

        91.980000 0a010002 RMON   1   1 CREATED_BY
        91.980000 0a010003 CT1a 102 102 CREATED

show at 91.98 seconds task id '0a010002' named 'RMON' with a priority of 1 and
executing at a priority of 1 created task id '0a010003' named 'CT1a' with a
priority of 102 and an executing priority of 102. Next 'RMON' started 'CT1a'
and it was switch into context, began running, then was switched out.

        91.980000 0a010002 RMON   1   1 STARTED_BY
        91.980000 0a010003 CT1a 102 102 STARTED
        91.980000 0a010003 CT1a 102 102 SWITCHED_IN
        91.980000 0a010003 CT1a 102 102 BEGIN
        91.980000 0a010003 CT1a 102 102 SWITCHED_OUT

The task 'CT1a' was switched out because it blocked on the semaphore.

If you look at the 'test1' command's code you will see the command sleeps for 1
second after starting the task. This is why the lower priority task 'CT1a' is
switched in and able to run. The sleep can be seen in the next event where
'RMON' creates 'CT1b'. The timestamp is 1 second later.

        92.980000 0a010002 RMON   1   1 CREATED_BY
        92.980000 0a010004 CT1b 101 101 CREATED
        92.980000 0a010002 RMON   1   1 STARTED_BY
        92.980000 0a010004 CT1b 101 101 STARTED
        92.980000 0a010004 CT1b 101 101 SWITCHED_IN
        92.980000 0a010004 CT1b 101 101 BEGIN
        93.980000 0a010004 CT1b 101 101 SWITCHED_OUT

There are no 'RMON' switched in or switched out events. These are being
filtered by the priority range filter. We see the 'RMON' CREATED_BY events as
these are actually occuring on test tasks which are in the priority range.

The create and start process is repeated for the remaining two tasks. The
following section of the trace show 'CT1c' being switch out and 'CT1b' being
switch in. Task 'CT1b' loops consuming all of the CPU time until 'CT1a'
wakes. This is 500 milli-seconds.

        93.980000 0a010005 CT1c 100 100 BEGIN
        93.980000 0a010005 CT1c 100 100 SWITCHED_OUT
        93.980000 0a010004 CT1b 101 101 SWITCHED_IN
        94.480000 0a010004 CT1b 101 101 SWITCHED_OUT
        94.480000 0a010003 CT1a 102 100 SWITCHED_IN

When 'CT1a' wakes it is executing at the priority of 'CT1c' of 100 and so
higher than 'CT1b'. Task 'CT1a' then releases the semaphore dropping it
priority back to 102 allowing 'CT1c' to run.

        94.480000 0a010003 CT1a 102 102 SWITCHED_OUT
        94.480000 0a010005 CT1c 100 100 SWITCHED_IN
        94.480000 0a010005 CT1c 100 100 SWITCHED_OUT
        94.480000 0a010004 CT1b 101 101 SWITCHED_IN
        94.980000 0a010004 CT1b 101 101 SWITCHED_OUT
        94.980000 0a010005 CT1c 100 100 SWITCHED_IN

Task 'CT1c' release the semaphore and deletes itself. Task 'CT1b' is switched
in and it is looping waiting for 'CT1c' to delete. This has happen so 'CT1b'
deletes itself. Finally 'CT1a' deletes itself.

        94.980000 0a010005 CT1c 100 100 DETELED_BY
        94.980000 0a010005 CT1c 100 100 DETELED
        94.980000 0a010004 CT1b 101 101 SWITCHED_IN
        94.980000 0a010004 CT1b 101 101 DELETED_BY
        94.980000 0a010004 CT1b 101 101 DELETED
        94.980000 0a010003 CT1a 102 100 SWITCHED_IN
        94.980000 0a010003 CT1a 102 100 DELETED_BY
        94.980000 0a010003 CT1a 102 100 DELETED

The delete event shows the task deleting itself as the DELETED_BY event is the
same as the DELETED event.

We will now explore some more complex filters and triggers. First close the
QEMU window and start QEMU again and open and enable the capture engine:

 rtems $ copen 5000
 capture engine open
 rtems $ cenable
 capture engine enabled.
 rtems $ 

In this example we only want to monitor task 'CT1c' and wish to trigger on a
context switch from 'CT1c' to 'CT1a'. This happens when 'CT1a' releases the
semaphore and CT1c claims it. The set up is:

 rtems $ cwadd CT1c
 watch added.
 rtems $ cwctl CT1c on
 watch enabled.
 rtems $ ctset switch CT1c from CT1a
 trigger set.
 rtems $ cwlist
 watch priority ceiling is 0
 watch priority floor is 0
 global watch is disabled
 total 1
  00000000 CT1c -w  T:------- F:-----
    0:CT1a/00000000:S----
 rtems $ 

We run the test and capture the output:

 rtems $ test1
 rtems $ ctrace
        61.150000 0a010005 CT1c 100 100 SWITCHED_IN
        61.150000 0a010005 CT1c 100 100 SWITCHED_OUT
        61.650000 0a010005 CT1c 100 100 SWITCHED_IN
        61.650000 0a010005 CT1c 100 100 DELETED_BY
        61.650000 0a010005 CT1c 100 100 DELETED
 rtems $ 

The trace shows CT1c being switched in once it has the semaphore then switching
out while it waits 500 milli-seconds, waking and being switched in to delete
itself. The filtering means we can focus on the specific events which we are
interested in and the trigger means we only trace once the specific event we
are interested in occurs.

The filter and trigger do not need to relate. Lets run a variation of the last
configuation where we watch 'CT1b' and trigger on 'CT1c' being switched to from
'CT1a'. Close the QEMU window and start QEMU again and open and enable the
capture engine:

 rtems $ copen 5000
 capture engine open
 rtems $ cenable
 capture engine enabled.
 rtems $ cwadd CT1b
 watch added.
 rtems $ cwctl CT1b on
 watch enabled.
 rtems $ ctset switch CT1c from CT1a
 trigger set.
 rtems $ cwlist
 watch priority ceiling is 0
 watch priority floor is 0
 global watch is disabled
 total 2
  00000000 CT1c --  T:------- F:-----
    0:CT1a/00000000:S----
  00000000 CT1b -w  T:------- F:-----
 rtems $ 

You can see 2 watch controls exist, one for the trigger and one for the filter.
Before we run the test we will take a look at the task list using the 'ctlist'.

 rtems $ ctlist
 total 2
  09010001 IDLE 255 255 255 READY a---   0%   0% (10682)
  0a010002 RMON   1   1   1 READY a---   0%   0% (826)
 rtems $

You can see the 2 tasks that are active. These tasks existed before the capture
engine started. The capture engine learns about tasks that exist in a system if
they do something. If a task exists and does nothing the capture engine will
not know about it. Lets run the test then list the tasks again:

 rtems $ test1
 rtems $ ctlist
 total 3
  0a010004 CT1b 101   0   0 READY dtw- 100%   0% (200)
  09010001 IDLE 255 255 255 READY a---   0%   0% (10682)
  0a010002 RMON   1   1   1 READY a---   0%   0% (826)
 rtems $
 
This time the task lists the test task we are watching 'CT1b'. If how-ever has
been deleted and the task list shows this with the 'd' in the flags. The active
tasks have an 'a'. The capture engine has to retain information on tasks that
have been deleted so the trace data can be generated. The trace buffer holds a
reference to the task's details not the specific details. Once the trace data
has been viewed the task data is no longer needed and released.

 rtems $ ctrace
       551.630000 0a010004 CT1b 101 101 SWITCHED_IN
       552.130000 0a010004 CT1b 101 101 SWITCHED_OUT
       552.130000 0a010004 CT1b 101 101 SWITCHED_IN
       552.130000 0a010004 CT1b 101 101 DELETED_BY
       552.130000 0a010004 CT1b 101 101 DELETED
 rtems $ ctlist
 total 2
  09010001 IDLE 255 255 255 READY a---   0%   0% (10682)
  0a010002 RMON   1   1   1 READY a---   0%   0% (826)
 rtems $

Listing the tasks shows 'CT1b' has gone. The trace buffer does not reference
it any more.

We have now seen the following capture commands:

 copen
 cenable
 ctlist
 cwceil
 cwfloor
 cwglob
 cwadd
 cwctl
 ctset
 ctrace

The ctset is worth a closer look. The general form of the command is:

 ctset [-?] type [to name/id] [from] [from name/id]

The 'type' is the type of trigger. The following possible types of triggers
exist:

 switch  - a context switch from one task to another task
 create  - the executing task creates a task
 start   - the executing task starts a task
 restart - the executing task restarts a task
 delete  - the executing task deletes a task
 begin   - a task is beginning
 exitted - a task is exitting

With the ctset command you set a trigger for a task. If you do not supply a
from task the type of event can be from any task. You can be more specific by
stating the event for a task must be by a specific task. Looking at the examples
from before we set a trigger on a context switch from CT1a to CT1c with:

 ctset switch CT1c from CT1a