unison/doc/tutorial/tracing.texi

@c ============================================================================
@c Begin document body here
@c ============================================================================

@c ============================================================================
@c PART:  The Tracing System
@c ============================================================================
@c The below chapters are under the major heading "The Tracing System"
@c This is similar to the Latex \part command
@c
@c ============================================================================
@c The Tracing System
@c ============================================================================
@node The Tracing System
@chapter The Tracing System

@menu
* Background::
@end menu

@c ============================================================================
@c Background
@c ============================================================================
@node Background
@section Background

As mentioned in the Using the Tracing System section, the whole point of running
an @code{ns-3} simulation is to generate output for study.  You have two basic 
strategies to work with in @code{ns-3}: using generic pre-defined bulk output 
mechanisms and parsing their content to extract interesting information; or 
somehow developing an output mechanism that conveys exactly (and perhaps only) 
the information wanted.

Using pre-defined bulk output mechansims has the advantage of not requiring any
changes to @code{ns-3}, but it does require programming.  Often, pcap or NS_LOG
output messages are gathered during simulation runs and separately run through 
scripts that use grep, sed or awk to parse the messages and reduce and transform
the data to a manageable form.  Programs must be written to do the 
transformation, so this does not come for free.  Of course, if the information
of interest in does not exist in any of the pre-defined output mechanisms,
this approach fails.

If you need to add some tidbit of inforamtion to the pre-defined bulk mechanisms,
this can certainly be done; and if you use one of the @code{ns-3} mechanisms, 
you may get your code added as a contribution.

@code{ns-3} provides another mechanism, called Tracing, that avoids some of the 
problems inherent in the bulk output mechanisms.  It has several important 
advantages.  First, you can reduce the amount of data you have to manage by only
tracing the events of interest to you.  Second, if you use this method, you can 
control the format of the output directly so you avoid the postprocessing step 
with sed or awk script.  If you desire, your output can be formatted directly into
a form acceptable by gnuplot, for example.  You can add hooks in the core which 
can then be accessed by other users, but which will produce no information unless
explicitly asked to do so.  For these reasons, we believe that the @code{ns-3>
Tracing system is the best way to get information out of a simulation and is also
therefore one of the most important mechansisms to understand in @command{ns-3}.

@subsection Blunt Instruments
There are many ways to get information out of a program.  The most 
straightforward way is to just directly print the information to the standard 
output, as in,

@verbatim
  #include <iostream>
  ...
  void
  SomeFunction (void)
  {
   uint32_t x = SOME_INTERESTING_VALUE;
    ...
    std::cout << "The value of x is " << x << std::endl;
    ...
  } 
@end verbatim

Nobody is going to prevent you from going deep into the core of @code{ns-3} and
adding print statements.  This is insanely easy to do and, after all, you have 
complete control of your own @node{ns-3} branch.  This will probably not turn 
out to be very satisfactory in the long term, though.

As the number of print statements increases in your programs, the task of 
dealing with the large number of outputs will become more and more complicated.  
Eventually, you may feel the need to control what information is being printed 
in some way; perhaps by turning on and off certain categories of prints, or 
increasing or decreasing the amount of information you want.  If you continue 
down this path you may discover that you have re-implemented the @code{NS_LOG}
mechanism.  In order to avoid that, one of the first things you might consider
is using @code{NS_LOG} itself.

We mentioned above that one way to get information out of @code{ns-3} is to 
parse existing NS_LOG output for interesting information.  If you discover that 
some tidbit of information you need is not present in existing log output, you 
could edit the core of @code{ns-3} and simply add your interesting information
to the output stream.  Now, this is certainly better than adding your own
print statements since it follows @code{ns-3} coding conventions and could 
potentially be useful to other people as a patch to the existing core.

Let's pick a random example.  If you wanted to add more logging to the 
@code{ns-3} TCP socket (@code{tcp-socket-impl.cc}) you could just add a new 
message down in the implementation.  Notice that in TcpSocketImpl::ProcessAction()
there is no log message for the @code{ACK_TX} case.  You could simply add one, 
changing the code from:

@verbatim
  bool TcpSocketImpl::ProcessAction (Actions_t a)
  { // These actions do not require a packet or any TCP Headers
    NS_LOG_FUNCTION (this << a);
    switch (a)
    {
      case NO_ACT:
        NS_LOG_LOGIC ("TcpSocketImpl " << this <<" Action: NO_ACT");
        break;
      case ACK_TX:
        SendEmptyPacket (TcpHeader::ACK);
        break;
      ...
@end verbatim

to add a new @code{NS_LOG_LOGIC} in the appropriate @code{case} statement:

@verbatim
  bool TcpSocketImpl::ProcessAction (Actions_t a)
  { // These actions do not require a packet or any TCP Headers
    NS_LOG_FUNCTION (this << a);
    switch (a)
    {
      case NO_ACT:
        NS_LOG_LOGIC ("TcpSocketImpl " << this << " Action: NO_ACT");
        break;
      case ACK_TX:
        NS_LOG_LOGIC ("TcpSocketImpl " << this << " Action: ACK_TX");
        SendEmptyPacket (TcpHeader::ACK);
        break;
      ...
@end verbatim

This may seem fairly simple and satisfying at first glance, but somthing to
consider is that you will be writing code to add the @code{NS_LOG} statement 
and you will also have to write code (as in grep, sed or awk scripts) to parse
the log output in order to isolate your information.  This is because even 
though you have some control over what is output by the logging system, you 
only have control down to the log component level.  

If you are adding code to an existing module, you will also have to live with the
output that every other developer has found interesting.  You may find that in 
order to get the small amount of information you need, you may have to wade 
through huge amounts of extraneous messages that are of no interest to you.  You
may be forced to save huge log files to disk and process them down to a few lines
whenever you want to do anything.

Since there are no guarantees in @code{ns-3} about the stability of @code{NS_LOG}
messages, you may also discover that pieces of log output on which you depend 
disappear or change between releases.  If you depend on the structure of the 
output, you may find other messages being added or deleted which may affect your
parsing code.

For these reasons, we consider prints to @code{std::cout} and NS_LOG messages 
simple ways to get more information out of @code{ns-3}, but they are really 
unstable and quite blunt instruments.

It is desirable to have a stable facility using stable APIs that allow one to 
reach into the core system and only get the information required.  It is
desirable to be able to do this without having to change and recompile the
core system.  Even better would be a system that notified the user when an item
of interest changed or an interesting event happened so the user doesn't have 
to actively go poke around in the system looking for things.

The @command{ns-3} tracing system is designed to work along those lines and is 
well-integrated with the Attribute and Config substems allowing for relatively
simple use scenarios.

@node Overview
@section Overview

The ns-3 tracing system is built on the concepts of independent tracing sources
and tracing sinks; along with a uniform mechanism for connecting sources to sinks.

Trace sources are entities that can signal events that happen in a simulation and 
provide access to interesting underlying data.  For example, a trace source could
indicate when a packet is received by a net device and provide access to the 
packet contents for interested trace sinks.  A trace source might also indicate 
when an iteresting state change happens in a model.  For example, the congestion
window of a TCP model is a prime candidate for a trace source.

Trace sources are not useful by themselves; they must be connected to other pieces
of code that actually do something useful with the information provided by the source.
The entities that consume trace information are called trace sinks.  Trace sources 
are generators of events and trace sinks are consumers.  This explicit division 
allows for large numbers of trace sources to be scattered around the system in 
places which model authors believe might be useful.  

There can be zero or more consumers of trace events generated by a trace source.  
One can think of a trace source as a kind of point-to-multipoint information link.  
Your code looking for trace events from a particular piece of core code could 
happily coexist with other code doing something entirely different from the same
information.

Unless a user connects a trace sink to one of these sources, nothing is output.  By
using the tracing system, both you and other people at the same trace source are 
getting exactly what they want and only what they want out of the system.  Neither
of you are impacting any other user by changing what information is output by the 
system.  If you happen to add a trace source, your work as a good open-source 
citizen may allow other users to provide new utilities that are perhaps very useful
overall, without making any changes to the @code{ns-3} core.  

@node A Simple Low-Level Example
@subsection A Simple Low-Level Example

Let's take a few minutes and walk through a simple tracing example.  We are going
to need a little background on Callbacks to understand what is happening in the
example, so we have to take a small detour right away.

@node Callbacks
@subsubsection Callbacks

The goal of the Callback system in @code{ns-3} is to allow one piece of code to 
call a function (or method in C++) without any specific inter-module dependency.
This ultimately means you need some kind of indirection -- you treat the address
of the called function as a variable.  This variable is called a pointer-to-function
variable.  The relationship between function and pointer-to-function pointer is 
really no different that that of object and pointer-to-object.

In C the canonical example of a pointer-to-function is a 
pointer-to-function-returning-integer (PFI).  For a PFI taking one int parameter,
this could be declared like,

@verbatim
  int (*pfi)(int arg) = 0;
@end verbatim

What you get from this is a variable named simply ``pfi'' that is initialized
to the value 0.  If you want to initialize this pointer to something meaningful,
you have to have a function with a matching signature.  In this case, you could
provide a function that looks like,

@verbatim
  int MyFunction (int arg) {}
@end verbatim

If you have this target, you can initialize the variable to point to your
function:

@verbatim
  pfi = MyFunction;
@end verbatim

You can then call MyFunction indirectly using the more suggestive form of
the call,

@verbatim
  int result = (*pfi) (1234);
@end verbatim

This is suggestive since it looks like you are dereferencing the function
pointer just like you would dereference any pointer.  Typically, however,
people take advantage of the fact that the compiler knows what is going on
and will just use a shorter form,

@verbatim
  int result = pfi (1234);
@end verbatim

This looks like you are calling a function named ``pfi,'' but the compiler is
smart enough to know to call through the variable @code{pfi} indirectly to
the function @code{MyFunction}.

Conceptually, this is almost exactly how the tracing system will work.
Basically, a trace source @emph{is} a callback.  When a trace sink expresses
interest in receiving trace events, it adds a Callback to a list of Callbacks
internally held by the trace source.  When an interesting event happens, the 
trace source invokes its @code{operator()} providing zero or more parameters.
The @code{operator()} eventually wanders down into the system and does something
remarkably like the indirect call you just saw.  It provides zero or more 
parameters (the call to ``pfi'' above passed one parameter to the target function
@code{MyFunction}.

The important difference that the tracing system adds is that for each trace
source there is an internal list of Callbacks.  Instead of just making one 
indirect call, a trace source may invoke any numbr of Callbacks.  When a trace
sink expresses interest in notifications from a trace source, it basically just
arranges to add its own fuction to the callback list.

If you are interested in more details about how this is actually arranged in 
@code{ns-3}, feel free to peruse the Callback section of the manual.

@node Example Code
@subsubsection Example Code

We have provided some code to implement what is really the simplest example
of tracing that can be assembled.  You can find this code in the tutorial
directory as @code{fourth.cc}.  Let's walk through it.

@verbatim
  /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
  /*
   * This program is free software; you can redistribute it and/or modify
   * it under the terms of the GNU General Public License version 2 as
   * published by the Free Software Foundation;
   *
   * This program is distributed in the hope that it will be useful,
   * but WITHOUT ANY WARRANTY; without even the implied warranty of
   * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
   * GNU General Public License for more details.
   *
   * You should have received a copy of the GNU General Public License
   * along with this program; if not, write to the Free Software
   * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
   */
  
  #include "ns3/object.h"
  #include "ns3/uinteger.h"
  #include "ns3/traced-value.h"
  #include "ns3/trace-source-accessor.h"
  
  #include <iostream>
  
  using namespace ns3;
@end verbatim

Most of this code should be quite familiar to you.  As mentioned above, the
trace system makes heavy use of the Object and Attribute systems, so you will 
need to include them.  The first two includes above bring in the declarations
for those systems explicitly.  You could use the core module header, but this
illustrates how simple this all really is.  

The file, @code{traced-value.h} brings in the required declarations for tracing
of data that obeys value semantics.  In general, value semantics just means that
you can pass the object around, not an address.  In order to use value semantics
at all you have to have an object with an associated copy constructor and 
assignment operator available.  We extend the requirements to talk about the set
of operators that are pre-defined for plain-old-data (POD) types.  Operator=, 
operator++, operator--, operator+, operator==, etc.

What this all really means is that you will be able to trace changes to a C++
object made using those operators.

Since the tracing system is integrated with Attributes, and Attributes work
with Objects, there must be an @command{ns-3} @code{Object} for the trace source
to live in.  The next code snipped declares and defines a simple Object we can
work with.

@verbatim
  class MyObject : public Object
  {
  public:
    static TypeId GetTypeId (void)
    {
      static TypeId tid = TypeId ("MyObject")
        .SetParent (Object::GetTypeId ())
        .AddConstructor<MyObject> ()
        .AddTraceSource ("MyInteger",
                         "An integer value to trace.",
                         MakeTraceSourceAccessor (&MyObject::m_myInt))
        ;
      return tid;
    }
    
    MyObject () {}
    TracedValue<int32_t> m_myInt;
  };
@end verbatim

The two important lines of code, above, with respect to tracing are the 
@code{.AddTraceSource} and the @code{TracedValue} declaration of @code{m_myInt}.

The @code{.AddTraceSource} provides the ``hooks'' used for connecting the trace
source to the outside world through the config system.  The @code{TracedValue} 
declaration provides the infrastructure that overloads the operators mentioned 
above and drives the callback process.

@verbatim
  void
  IntTrace (int32_t oldValue, int32_t newValue)
  {
    std::cout << "Traced " << oldValue << " to " << newValue << std::endl;
  }
@end verbatim

This is the definition of the trace sink.  It corresponds directly to a callback
function.  This function will be called whenever one of the operators of the
@code{TracedValue} is executed.

We have now seen the trace source and the trace sink.  What remains is code to
connect the source to the sink.

@verbatim
  int
  main (int argc, char *argv[])
  {
    Ptr<MyObject> myObject = CreateObject<MyObject> ();
    myObject->TraceConnectWithoutContext ("MyInteger", MakeCallback(&IntTrace));
  
    myObject->m_myInt = 1234;
  }
@end verbatim

Here we first create the Object in which the trace source lives.

The next step, the @code{TraceConnectWithoutContext}, forms the connection
between the trace source and the trace sink.  Notice the @code{MakeCallback}
template function.  This function does the magic required to create the
underlying callback function.  It will make sure that an overloaded 
@code{operator()} is there which can be used to ``fire'' the callback.  This
is essentially arranging for something that looks just like the @code{pfi()}
example above.  The declaration of the @code{TracedValue<int32_t> m_myInt;}
in the Object itself performs the magic needed to provide the overloaded
operators (++, --, etc.) will use this @code{operator()} to actually invoke
the callback.

The @code{TraceConnectWithoutContext}, takes a string parameter that provides 
the name of the Attribute assigned to the trace source.  Let's ignore the bit
about context for now since it is not important yet.

Finally, the line,

@verbatim
   myObject->m_myInt = 1234;
@end verbatim

should be interpreted as an invocation of @code{operator=} on the member 
variable @code{m_myInt} with the integer @code{1234} passed as a parameter.
It turns out that this operator is defined (by @code{TracedValue}) to execute
a callback that returns void and takes two integer values as parameters -- 
an old value and a new value for the integer in question.  That is exactly 
the function signature for the callback function we provided -- @code{IntTrace}.

To summarize, a trace source is, in essence, a variable that holds a list of
callbacks.  A trace sink is a function used as the target of a callback.  The
Attribute and object type information systems are used to provide a way to 
connect trace sources to trace sinks.  The act of ``hitting'' a trace source
is executing an operator on the trace source which fires callbacks.  This 
results in the trace sink callbacks registering interest in the source being 
called with the parameters provided by the source.

If you now build and run this example,

@verbatim
  ./waf --run fourth
@end verbatim

you will see the output from the @code{IntTrace} function execute as soon as the
trace source is hit:

@verbatim
  Traced 0 to 1234
@end verbatim

When we executed the code, @code{myObject->m_myInt = 1234;}, the trace source 
fired and automatically provided the before and after values to the trace sink.
The function @code{IntTrace} then printed this to the standard output.  No 
problem.

@subsection Using the Config Subsystem to Connect to Trace Sources

The @code{TraceConnectWithoutContext} call shown above in the simple example is
actually very rarely used in the system.  More typically, the @code{Config}
subsystem is used to allow selecting a trace source in the system using what is
called a @emph{config path}.  We saw an example of this in the previous section
where we hooked the ``CourseChange'' event when we were playing with 
@code{third.cc}.

Recall that we defined a trace sink to print course change information from the
mobility models of our simulation.  It should now be a lot more clear to you 
what this function is doing.

@verbatim
  void
  CourseChange (std::string context, Ptr<const MobilityModel> model)
  {
    Vector position = model->GetPosition ();
    NS_LOG_UNCOND (context << 
      " x = " << position.x << ", y = " << position.y);
  }
@end verbatim

When we connected the ``CourseChange'' trace source to the above trace sink,
we used what is clled a ``Config Path'' to specify the source when we
aranged a connection between the pre-defined trace source and the new trace 
sink:

@verbatim
  std::ostringstream oss;
  oss <<
    "/NodeList/" << wifiStaNodes.Get (nWifi - 1)->GetId () <<
    "/$ns3::MobilityModel/CourseChange";

  Config::Connect (oss.str (), MakeCallback (&CourseChange));
@end verbatim

Let's try and make some sense of what is sometimes considered relatively
mysterious code.  For the purposes of discussion, assume that the node 
number returned by the @code{GetId()} is ``7''.  In this case, the path
above turns out to be,

@verbatim
  "/NodeList/7/$ns3::MobilityModel/CourseChange"
@end verbatim

The last segment of a config path must be an @code{Attribute} of an 
@code{Object}.  In fact, if you had a pointer to the @code{Object} that has the
``CourseChange'' @code{Attribute} handy, you could write this just like we did 
in the previous example.  You know by now that we typically store pointers to 
our nodes in a NodeContainer.  In the @code{third.cc} example, the Nodes of
interest are stored in the @code{wifiStaNodes} NodeContainer.  In fact, while
putting the path together, we used this container to get a Ptr<Node> which we
used to call GetId() on.  We could have used this Ptr<Node> directly to call
a connect method directly:

@verbatim
  Ptr<Object> theObject = wifiStaNodes.Get (nWifi - 1);
  theObject->TraceConnectWithoutContext ("CourseChange", MakeCallback (&CourseChange));
@end verbatim

In the @code{third.cc} example, we actually want an additional ``context'' to 
be delivered along with the Callback paramters (which will be explained below) so we 
could actually use the following equivalent code,

@verbatim
  Ptr<Object> theObject = wifiStaNodes.Get (nWifi - 1);
  theObject->TraceConnect ("CourseChange", MakeCallback (&CourseChange));
@end verbatim

It turns out that the internal code for @code{Config::ConnectWithoutContext} and
@code{Config::Connect} actually do find a Ptr<Object> and call the appropriate
TraceConnect method at the lowest level.

The @code{Config} functions take a path that represents a chain of @code{Object} 
pointers.  Each segment of a path corresponds to an Object Attribute.  The last 
segment is the Attribute of interest, and prior segments must be typed to contain
or find Objects.  The @code{Config} code parses and ``walks'' this path until it 
gets to the final segment of the path.  It then interprets the last segment as
an @code{Attribute} on the last Object it found while walking the path.  The  
@code{Config} functions then call the appropriate @code{TraceConnect} or 
@code{TraceConnectWithoutContext} method on the final Object.  Let's see what 
happens in a bit more detail when the above path is walked.

The leading ``/'' character in the path refers to a so-called namespace.  One 
of the predefined namespaces in the config system is ``NodeList'' which is a 
list of all of the nodes in the simulation.  Items in the list are referred to
by indices into the list, so ``/NodeList/7'' refers to the eighth node in the
list of nodes created during the simulation.  This reference is actually a 
@code{Ptr<Node>} and so is a subclass of an @code{ns3::Object}.  

As described in the Object Model section of the @code{ns-3} manual, we support
Object Aggregation.  This allows us to form an association between different 
Objects without any programming.  Each Object in an Aggregation can be reached 
from the other Objects.  

The next path segment being walked begins with the ``$'' character.  This 
indicates to the config system that a @code{GetObject} call should be made 
looking for the type that follows.  It turns out that the MobilityHelper used in 
@code{third.cc} arranges to Aggregate, or associate, a mobility model to each of 
the wireless Nodes.  When you add the ``$'' you are asking for another Object that
has presumably been previously aggregated.  You can think of this as switching
pointers from the original Ptr<Node> as specified by ``/NodeList/7'' to its 
associated mobility model --- which is of type ``$ns3::MobilityModel''.  If you
are familiar with @code{GetObject}, we have asked the system to do the following:

@verbatim
  Ptr<MobilityModel> mobilityModel = node->GetObject<MobilityModel> ()
@end verbatim

We are now at the last Object in the path, so we turn our attention to the 
Attributes of that Object.  The @code{MobilityModel} class defines an Attribute 
called ``CourseChange.''  You can see this by looking at the source code in
@code{src/mobility/mobility-model.cc} and searching for ``CourseChange'' in your
favorite editor.  You should find,

@verbatim
  .AddTraceSource (``CourseChange'',
                   ``The value of the position and/or velocity vector changed'',
                   MakeTraceSourceAccessor (&MobilityModel::m_courseChangeTrace))
@end verbatim

which should look very familiar at this point.  

If you look for the corresponding declaration of the underlying traced variable 
in @code{mobility-model.h} you will find

@verbatim
  TracedCallback<Ptr<const MobilityModel> > m_courseChangeTrace;
@end verbatim

The type declaration @code{TracedCallback} identifies @code{m_courseChangeTrace}
as a special list of Callbacks that can be hooked using the Config functions 
described above.

The @code{MobilityModel} class is designed to be a base class providing a common
interface for all of the specific subclasses.  If you search down to the end of 
the file, you will see a method defined called @code{NotifyCourseChange()}:

@verbatim
  void
  MobilityModel::NotifyCourseChange (void) const
  {
    m_courseChangeTrace(this);
  }
@end verbatim

Derived classes will call into this method whenever they do a course change to
support tracing.  This method invokes @code{operator()} on the underlying 
@code{m_courseChangeTrace}, which will, in turn, invoke all of the registered
Callbacks, calling all of the trace sinks that have registered interest in the
trace source by calling a Config function.

So, in the @code{third.cc} example we looked at, whenever a course change is 
made in one of the @code{RandomWalk2dMobilityModel} instances installed, there
will be a @code{NotifyCourseChange()} call which calls up into the 
@code{MobilityModel} base class.  As seen above, this invokes @code{operator()}
on @code{m_courseChangeTrace}, which in turn, calls any registered trace sinks.
In the example, the only code registering an interest was the code that provided
the config path.  Therefore, the @code{CourseChange} function that was hooked 
from Node number seven will be the only Callback called.

The final piece of the puzzle is the ``context.''  Recall that we saw an output 
looking something like the following from @code{third.cc}:

@verbatim
  /NodeList/7/$ns3::MobilityModel/CourseChange x = 7.27897, y = 2.22677
@end verbatim

The first part of the output is the context.  It is simply the path through
which the config code located the trace source.  In the case we have been looking at
there can be any number of trace sources in the system corresponding to any number
of nodes with mobility models.  There needs to be some way to identify which trace
source is actually the one that fired the Callback.  An easy way is to request a 
trace context when you @code{Config::Connect}.