.. include:: replace.txt

Tracing

-------

Background

**********

As mentioned in the Using the Tracing System section, the whole point of running

an |ns3| simulation is to generate output for study.  You have two basic 

strategies to work with in |ns3|: 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 mechanisms has the advantage of not requiring any

changes to |ns3|, 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 information to the pre-defined bulk mechanisms,

this can certainly be done; and if you use one of the |ns3| mechanisms, 

you may get your code added as a contribution.

|ns3| 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 (for large simulations, dumping everything

to disk for post-processing can create I/O bottlenecks).  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 |ns3| tracing system is the best way to get information 

out of a simulation and is also therefore one of the most important mechanisms

to understand in |ns3|.

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,

::

  #include <iostream>

  ...

  void

  SomeFunction (void)

  {

    uint32_t x = SOME_INTERESTING_VALUE;

    ...

    std::cout << "The value of x is " << x << std::endl;

    ...

  } 

Nobody is going to prevent you from going deep into the core of |ns3| and

adding print statements.  This is insanely easy to do and, after all, you have 

complete control of your own |ns3| 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 ``NS_LOG``

mechanism.  In order to avoid that, one of the first things you might consider

is using ``NS_LOG`` itself.

We mentioned above that one way to get information out of |ns3| 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 |ns3| and simply add your interesting information

to the output stream.  Now, this is certainly better than adding your own

print statements since it follows |ns3| 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 

|ns3| TCP socket (``tcp-socket-base.cc``) you could just add a new 

message down in the implementation.  Notice that in TcpSocketBase::ReceivedAck()

there is no log message for the no ACK case.  You could simply add one, 

changing the code from:

::

  /** Process the newly received ACK */

  void

  TcpSocketBase::ReceivedAck (Ptr<Packet> packet, const TcpHeader& tcpHeader)

  {

    NS_LOG_FUNCTION (this << tcpHeader);

    // Received ACK. Compare the ACK number against highest unacked seqno

    if (0 == (tcpHeader.GetFlags () & TcpHeader::ACK))

      { // Ignore if no ACK flag

      }

    ...

to add a new ``NS_LOG_LOGIC`` in the appropriate statement:

::

  /** Process the newly received ACK */

  void

  TcpSocketBase::ReceivedAck (Ptr<Packet> packet, const TcpHeader& tcpHeader)

  {

    NS_LOG_FUNCTION (this << tcpHeader);

    // Received ACK. Compare the ACK number against highest unacked seqno

    if (0 == (tcpHeader.GetFlags () & TcpHeader::ACK))

      { // Ignore if no ACK flag

        NS_LOG_LOGIC ("TcpSocketBase " << this << " no ACK flag");

      }

    ...

This may seem fairly simple and satisfying at first glance, but something to

consider is that you will be writing code to add the ``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 |ns3| about the stability of ``NS_LOG``

output, 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 ``std::cout`` and NS_LOG messages 

to be quick and dirty ways to get more information out of |ns3|.

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 poke around in the system looking for things.

The |ns3| tracing system is designed to work along those lines and is 

well-integrated with the Attribute and Config subsystems allowing for relatively

simple use scenarios.

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 interesting 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 |ns3| core.  

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.

Callbacks

~~~~~~~~~

The goal of the Callback system in |ns3| 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,

::

  int (*pfi)(int arg) = 0;

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,

::

  int MyFunction (int arg) {}

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

function:

::

  pfi = MyFunction;

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

the call,

::

  int result = (*pfi) (1234);

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,

::

  int result = pfi (1234);

This looks like you are calling a function named "pfi," but the compiler is

smart enough to know to call through the variable ``pfi`` indirectly to

the function ``MyFunction``.

Conceptually, this is almost exactly how the tracing system will work.

Basically, a trace source *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 ``operator()`` providing zero or more parameters.

The ``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

``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 number of Callbacks.  When a trace

sink expresses interest in notifications from a trace source, it basically just

arranges to add its own function to the callback list.

If you are interested in more details about how this is actually arranged in 

|ns3|, feel free to peruse the Callback section of the manual.

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 ``fourth.cc``.  Let's walk through it.

::

  /* -*- 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;

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, ``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 |ns3| ``Object`` for the trace source

to live in.  The next code snippet declares and defines a simple Object we can

work with.

::

  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;

  };

The two important lines of code, above, with respect to tracing are the 

``.AddTraceSource`` and the ``TracedValue`` declaration of ``m_myInt``.

The ``.AddTraceSource`` provides the "hooks" used for connecting the trace

source to the outside world through the config system.  The ``TracedValue`` 

declaration provides the infrastructure that overloads the operators mentioned 

above and drives the callback process.

::

  void

  IntTrace (int32_t oldValue, int32_t newValue)

  {

    std::cout << "Traced " << oldValue << " to " << newValue << std::endl;

  }

This is the definition of the trace sink.  It corresponds directly to a callback

function.  Once it is connected, this function will be called whenever one of the

overloaded operators of the ``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.

::

  int

  main (int argc, char *argv[])

  {

    Ptr<MyObject> myObject = CreateObject<MyObject> ();

    myObject->TraceConnectWithoutContext ("MyInteger", MakeCallback(&IntTrace));

    myObject->m_myInt = 1234;

  }

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

The next step, the ``TraceConnectWithoutContext``, forms the connection

between the trace source and the trace sink.  Notice the ``MakeCallback``

template function.  This function does the magic required to create the

underlying |ns3| Callback object and associate it with the function

``IntTrace``.  TraceConnect makes the association between your provided

function and the overloaded ``operator()`` in the traced variable referred 

to by the "MyInteger" Attribute.  After this association is made, the trace

source will "fire" your provided callback function.

The code to make all of this happen is, of course, non-trivial, but the essence

is that you are arranging for something that looks just like the ``pfi()``

example above to be called by the trace source.  The declaration of the 

``TracedValue<int32_t> m_myInt;`` in the Object itself performs the magic 

needed to provide the overloaded operators (++, ---, etc.) that will use the

``operator()`` to actually invoke the Callback with the desired parameters.

The ``.AddTraceSource`` performs the magic to connect the Callback to the 

Config system, and ``TraceConnectWithoutContext`` performs the magic to

connect your function to the trace source, which is specified by Attribute

name.

Let's ignore the bit about context for now.

Finally, the line,

::

   myObject->m_myInt = 1234;

should be interpreted as an invocation of ``operator=`` on the member 

variable ``m_myInt`` with the integer ``1234`` passed as a parameter.

It turns out that this operator is defined (by ``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 --- ``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,

::

  ./waf --run fourth

you will see the output from the ``IntTrace`` function execute as soon as the

trace source is hit:

::

  Traced 0 to 1234

When we executed the code, ``myObject->m_myInt = 1234;``, the trace source 

fired and automatically provided the before and after values to the trace sink.

The function ``IntTrace`` then printed this to the standard output.  No 

problem.

Using the Config Subsystem to Connect to Trace Sources

++++++++++++++++++++++++++++++++++++++++++++++++++++++

The ``TraceConnectWithoutContext`` call shown above in the simple example is

actually very rarely used in the system.  More typically, the ``Config``

subsystem is used to allow selecting a trace source in the system using what is

called a *config path*.  We saw an example of this in the previous section

where we hooked the "CourseChange" event when we were playing with 

``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.

::

  void

  CourseChange (std::string context, Ptr<const MobilityModel> model)

  {

    Vector position = model->GetPosition ();

    NS_LOG_UNCOND (context << 

      " x = " << position.x << ", y = " << position.y);

  }

When we connected the "CourseChange" trace source to the above trace sink,

we used what is called a "Config Path" to specify the source when we

arranged a connection between the pre-defined trace source and the new trace 

sink:

::

  std::ostringstream oss;

  oss <<

    "/NodeList/" << wifiStaNodes.Get (nWifi - 1)->GetId () <<

    "/$ns3::MobilityModel/CourseChange";

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

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 ``GetId()`` is "7".  In this case, the path

above turns out to be,

::

  "/NodeList/7/$ns3::MobilityModel/CourseChange"

The last segment of a config path must be an ``Attribute`` of an 

``Object``.  In fact, if you had a pointer to the ``Object`` that has the

"CourseChange" ``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 ``third.cc`` example, the Nodes of

interest are stored in the ``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:

::

  Ptr<Object> theObject = wifiStaNodes.Get (nWifi - 1);

  theObject->TraceConnectWithoutContext ("CourseChange", MakeCallback (&CourseChange));

In the ``third.cc`` example, we actually want an additional "context" to 

be delivered along with the Callback parameters (which will be explained below) so we 

could actually use the following equivalent code,

::

  Ptr<Object> theObject = wifiStaNodes.Get (nWifi - 1);

  theObject->TraceConnect ("CourseChange", MakeCallback (&CourseChange));

It turns out that the internal code for ``Config::ConnectWithoutContext`` and

``Config::Connect`` actually do find a Ptr<Object> and call the appropriate

TraceConnect method at the lowest level.

The ``Config`` functions take a path that represents a chain of ``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 ``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 ``Attribute`` on the last Object it found while walking the path.  The  

``Config`` functions then call the appropriate ``TraceConnect`` or 

``TraceConnectWithoutContext`` method on the final Object.  Let's see what 

happens in a bit more detail when the above path is walked.