.. include:: replace.txt

.. highlight:: cpp

.. role:: raw-role(raw)

   :format: html latex

.. Mimic doxygen formatting for parameter names

.. raw:: html

    <style>.param {font-weight:bold; color:#602020;}</style>

.. role:: param

Tracing

-------

Background

**********

As mentioned in :ref:`UsingTracingSystem`, the whole point

of running an |ns3| simulation is to generate output for study.  You

have two basic strategies to obtain output from |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 may require writing scripts to

parse and filter for data of interest.  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.  ``NS_LOG`` output is not considered part of the |ns3|

API, and can change without warning between releases.  In addition,

``NS_LOG`` output is only available in debug builds, so relying on it

imposes a performance penalty.  Of course, if the information of

interest 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``, ``awk``, ``perl`` or ``python``

scripts.  If you desire, your output can be formatted directly into a

form acceptable by gnuplot, for example (see also

:ref:`GnuplotHelper`).  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 print the information directly 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

(see :ref:`UsingLogging`).  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.  Here is the original::

  /** 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 log the no ACK case, you can add a new ``NS_LOG_LOGIC`` in the

``if`` statement body::

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

``NS_LOG`` statements 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, which is typically an entire

source code file.

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 

which you depend on 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.

Finally, ``NS_LOG`` output is only available in debug builds, you

can't get log output from optimized builds, which run about twice as

fast.  Relying on ``NS_LOG`` imposes a performance penalty.

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|, but not suitable for serious work.

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 user code 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 :ref:`Attribute <Attribute>` and :ref:`Config

<Config>` subsystems allowing for relatively simple use scenarios.

Overview

********

The |ns3| 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.  Every time

the congestion window changes connected trace sinks are notified with

the old and new value.

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

data 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.  Inserting

trace sources introduces a very small execution overhead.

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

hooked to 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.

Simple 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 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;

(But read the `C++-FAQ Section 33

<http://www.parashift.com/c++-faq/pointers-to-members.html>`_ before

writing code like this!)  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 need 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 works.

Basically, a trace sink *is* a callback.  When a trace sink expresses

interest in receiving trace events, it adds itself as 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 arguments.  The

``operator(...)`` eventually wanders down into the system and does

something remarkably like the indirect call you just saw, providing

zero or more parameters, just as 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 multiple

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

|ns3| Manual.

Walkthrough: ``fourth.cc``

~~~~~~~~~~~~~~~~~~~~~~~~~~

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 to get everything at once, but we do

the includes explicitly here to illustrate 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 itself around,

rather than passing the address of the object.  What this all really

means is that you will be able to trace all changes made to a

TracedValue in a really simple way.

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 ())

        .SetGroupName ("MyGroup")

        .AddConstructor<MyObject> ()

        .AddTraceSource ("MyInteger",

                         "An integer value to trace.",

                         MakeTraceSourceAccessor (&MyObject::m_myInt),

                         "ns3::TracedValueCallback::Int32")

        ;

      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

first argument is a name for this trace source, which makes it

visible in the Config system. The second argument is a help string.

Now look at the third argument, in fact focus on the *argument* of

the third argument: ``&MyObject::m_myInt``. This is the TracedValue

which is being added to the class; it is always a class data member.

(The final argument is the name of a ``typedef`` for the TracedValue

type, as a string.  This is used to generate documentation for the

correct Callback function signature, which is useful especially

for more general types of Callbacks.)

The ``TracedValue<>`` declaration provides the infrastructure that

drives the callback process.  Any time the underlying value is changed

the TracedValue mechanism will provide both the old and the new value

of that variable, in this case an ``int32_t`` value.  The trace

sink function ``traceSink`` for this TracedValue will need the signature

::

  void (* traceSink)(int32_t oldValue, int32_t newValue);

All trace sinks hooking this trace source must have this signature.

We'll discuss below how you can determine the required callback

signature in other cases.

Sure enough, continuing through ``fourth.cc`` we see::

  void

  IntTrace (int32_t oldValue, int32_t newValue)

  {

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

  }

This is the definition of a matching trace sink.  It corresponds

directly to the callback function signature.  Once it is connected,

this function will be called whenever the ``TracedValue`` changes.

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

code to connect the source to the sink, which happens in ``main``::

  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 MyObject instance in which the trace source

lives.

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

connection between the trace source and the trace sink.  The first

argument is just the trace source name "MyInteger" we saw above.

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 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 assignment

operators 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 assigning a value to ``m_myInt``::

   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.

Since ``m_myInt`` is a ``TracedValue``, this operator is defined 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 who

registering interest in the source being called with the parameters

provided by the source.

If you now build and run this example,

.. sourcecode:: bash

  $ ./waf --run fourth

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

as the trace source is hit:

.. sourcecode:: bash

  Traced 0 to 1234

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