{Previous tutorial}[link:files/doc/tutorials/03-PlannedPath_rdoc.html]
{Next tutorial}[link:files/doc/tutorials/05-ErrorHandling_rdoc.html]
= Understanding event propagation

This tutorial will show you how to trace plan execution, and understand how the
plans you build are actually executed by the system. It will not go in great
details, but it should help you understand more advanced uses of Roby. For that,
we will base ourselves on the execution trace of the controller we built in the
previous tutorial.

Roby plan execution is based on a fixed-duration execution cycle which includes
three steps:

link:../../images/roby_cycle_overview.png

This tutorial focusses on the first process. It will show how to use the log and
display tools that are shipped with Roby, and how event propagation works. The
last section will also give you a glimpse of the purpose of the garbage
collection algorithm.


== Getting a log file

We will first get a log file of the plan execution of the PathPlan robot
(previous tutorial). Plan execution logs are expensive from a CPU point of
view, so they are disabled by default. Enable them back by editing
<tt>config/app.yml</tt> and uncomment <tt>events: true</tt> around line 23. 

Now, run again the controller

  # scripts/run PathPlan

and in the shell, do

  >> move_to! :x => 10, :y => 10
  => MoveTo{goal => Vector3D(x=10.000000,y=10.000000,z=0.000000)}:0x4840c8d8[]
  >>
  !task MoveTo{goal => Vector3D(x=10.000000,y=10.000000,z=0.000000)}:0x4840c8d8[] finished successfully

Now, let's save the log files for further analysis (otherwise, one could
destroy them by restarting the controller).

  # scripts/result tut04
  moving /home/doudou/dev/roby-tutorials/log to /home/doudou/dev/roby-tutorials/results/20080502-tut04

<tt>scripts/result</tt> copies all files in <tt>log/</tt> into a subdirectory
of the result dir (by default APP_DIR/results, but can be changed in
<tt>config/app.yml</tt>). The target directory name is generated following a pattern of
<tt><current date>-<name provided on command line></tt>.

== Displaying the log file
Now, let's go in the directory where the results are (see <tt>scripts/results</tt> output). If you look into it,
two PathPlan files are present: <tt>PathPlan-events.log</tt> and
<tt>PathPlan-index.log</tt>.  The first one includes a trace of everything that
happens in the Roby controller which has been traced. The second one can
actually be generated from data in the first one. It is simply used to speed up
operations.

The data in the event log can be used to display the plan operations in a GUI.
For that, you need to have installed {Ruby/Qt4}[http://korundum.rubyforge.org], as
the GUI is written using Qt and Ruby.

To start it, simply do the following in the directory of the log files:

  # roby-log replay PathPlan

The following window should appear:

link:../../images/roby_replay_startup.png

This window is separated in three:
* the toplevel part is the list of data sources defined for this project. It is
  for instance possible to have a synchronized display of the logs of two
  different Roby controllers -- for multi-robot setup.
* the second part is the set of displays defined. More about that later.
* the third part is the replay controls: play, fast forward, position, ...

Note that you can either print the display, or export it as a SVG file for
further editing. See the +View+ menu.

Right now, we will be looking at the plan structure and execution trace. The
+Relations+ display is designed for that. Let's add one by clicking on the
+Add+ button just next to the display type combo. The configuration options
appear (including the data source associated with the display), and a new
window:

link:../../images/roby_replay_relations.png

This display will show two things: the task structure (i.e. how tasks are
related to each other) and the event propagation (i.e. how events call and/or
emit each other). The set of task relations to display has to be selected on
the configuration part of the relation display, including the colors for each
displayed relation. For our purposes, we only need the +Hierarchy+ (it is the
actual name of the +realized_by+ relation) and the +PlannedBy+ relations.

<b>Very important note</b> your own display may not look exactly like the ones
displayed here. Some of the features showed here (like threaded planning) are
asynchronous and as such the exact displays depend on the execution timing. Note
that, even though it is the case, the robot _behaviour_ remains unchanged.

== Startup of the <tt>move_to!</tt> action

Let's get to the first task-related events. Click on the 'Step' button until
something appears on the display. It should look like the next image:

link:../../images/roby_replay_first_state.png

The displays shows two plans (black boxes). The left one is the plan as it is
being executed. The right one is called a _transaction_ and allows to build a
new plan without interfering with the execution. Transactions are presented in
the sixth tutorial. The task description includes the task model and the task
owners (which is only useful in multi-robot setup). The <tt>Task labels</tt>
menu allows to customize that.

The left part is a representation of the plan built when the <tt>move_to!</tt>
command is entered in the shell. It consists of a generic task (Roby::Task)
which is +planned_by+ a Roby::PlanningTask. This is how Roby handles action
requests from the shell: (i) it searches a planner defined for that robot with
the specific action and (ii) generates the plan representing the planning
process.

Once that initial plan has been built, the Roby::PlanningTask task has been
started.  The various cases of event propagation are represented in different
ways, based on wether or not the event is controlable or contingent, or if it is
called and/or emitted.

link:../../images/roby_replay_event_representation.png

A note about propagation representation: it would be useless to represent all
the event propagation from the beginning of the execution to the current point.
The display therefore represents only the propagations that have taken place
<i>since the last display point</i>. It means that, if you go forward 10
seconds, it will display 10 seconds worth of propagation. In our case, we
displayed only the first execution cycle and we see that, in this cycle, the
planning task +start+ event has been called and emitted.

== The MoveTo plan

Advance again using 'Step' until the display looks like this:

link:../../images/roby_replay_02.png

The MoveTo action has been planned and the executed plan is modified to reflect
that. The MoveTo action itself is then started, and that is propagated to the
ComputePath 'start' event through the signalling relation our plan method has
defined betweem both.

Next execution step gives us the following:

link:../../images/roby_replay_03.png

PlannedPath emitted its +success+ event. We see here that the emission of the
+success+ event of that task does not mean 'the plan modification has just took
place' but instead that 'it has taken place some time earlier'.

The ComputePath task has also finished generating the path. That has two
consequences: the internal data of MoveTo is changed (hence the 'internal_data'
emission) and TrackPath is started. Here, the dotted lines between the events
represent a forwarding relation between the two events, while the plain lines
represent signal relations.

If we go back to the code, we see that nowhere a forwarding relation has been
set up between the +success+ event of ComputePath and the +internal_data+ of
MoveTo. +internal_data+ is actually automatically emitted by Roby::Task#data=,
which is called in ComputePath's event handler of +success+ we installed.

    on :success do |ev|
      parents.find { true }.data = result
    end

The interpretation of Roby in that the causality chain is so that the emission
of +success+ is the cause of the emission of +success+, and as such counts for
a forward. The same would have happened if the event handler would have called
an event command.

Finally, light grey here represents tasks that have finished with the +success+
event. Tasks whose +failed+ event has been emitted are represented in red.

== To finish: the garbage collection process

Now, uncheck the box <tt>View/Hide finalized</tt> in the menu. If you go a few
cycles further, you should then get the following:

link:../../images/roby_replay_04.png

Here, TrackPath has finished its execution with success and MoveTo is therefore
finished as well -- per the forwarding relation between those two events. Note
that the tasks are now in a dark grey instead than a light one. 

The mission of the robot, MoveTo, is therefore finished. From the plan
management point of view, it makes keeping a reference to it useless. In the
same way, the tasks that were in the plan for the purpose of fullfilling that
mission are rendered useless as well and can also be removed. The process which
removes those tasks is called the <i>garbage collection process</i> and runs at
the end of the execution cycle (Roby::Plan#garbage_collect).

The general idea is to kill and remove from the plan the tasks that are not
useful for the achievement of the robot's missions. The "important" tasks for
the robot are defined by two sets:
1. a set of missions (Roby::Plan#missions)
2. a set of "permanent" tasks that should not be considered by Roby's GC
   mechanism (Roby::Plan#keepalive).

Then, the task relations are used to determine what are the tasks, in the plan,
which are actually useful for those "important" tasks
(Roby::Plan#useful_tasks). This is based on the convention that if a
<tt>a=>b</tt> relation exists, then +b+ is useful for +a+.

The remaining tasks, i.e. the tasks that are not useful, are killed (if needed)
and removed from the plan. When it is done, the task is said to be finalized
(hence the need to not hide this kind of task in the View menu).

== Some insight in the internal event propagation process

The whole propagation process tries to make life as easy as possible in cases
where multiple events are propagated towards the same source. To make that happen, 
event propagation is done in a bunch of gathering/propagation pairs:
* the most suitable propagation step (forward and/or signal) is selected
* This step is performed. The associated user code is called (i.e. event
  command in case of a signal and event handler in case of a forward). Any call
  to command and/or emission which is performed in this user code is delayed in
  the set of pending propagation steps, to be considered for propagation in the
  global propagation loop.

See my PhD thesis for more details (links are available in README.txt).

= Next tutorial

Now that we have seen what happens in the nominal case, the {next
tutorial}[link:files/doc/tutorials/05-ErrorHandling_rdoc.html] will introduce
the second part of the execution cycle: the error representation and handling,
which is -- admittedly -- the most important part of this kind of plan-based
system.
---
vim: tw=80 et