Simulation Output
*****************

At this point, you should be able to execute any of the built-in programs distributed with ns-3.  Next, we will look at how to generate and tailor the simulation output, before turning to how to modify simulation scripts to do different things.

Tracing Basics
==============

The whole point of simulation is to generate output for further study, and the ns-3 tracing system is a primary mechanism for this. Since ns-3 is a C++ program, standard facilities for generating output from C++ programs apply:

#include <iostream>
...
int main ()
{
  ...
  std::cout << "The value of x is " << x << std::endl;
  ...
}

The goal of the ns-3 tracing system is to provide a structured way to configure the simulator to output results in standard or modifiable formats.

  * For basic tasks, the tracing system should allow the user to generate standard tracing for popular tracing sources, and to customize which objects generate the tracing.

  * Intermediate users will be able to extend the tracing system to modify the output format generated, or to insert new tracing sources, without modifying the core of the simulator.

  * Advanced users can modify the simulator core to add new tracing sources and sinks.

The ns-3 tracing system is fundamentally built on the concept of separating tracing sources from sinks.

 1. Trace sources (e.g., provide access to every packet received)

 2. Trace sinks (e.g., print out the packet)

 3. A mechanism to tie together sources and sinks

The rationale for this division is to allow users to attach new types of sinks to existing tracing sources, without requiring users to edit and recompile the core of the simulator. Thus, in the example above, a user could write a new tracing sink and attach it to an existing tracing source.  What remains to be defined is a way for users to find these hooks (tracing sources) and attach sinks to them.  A new tracing namespace is defined for this purpose.

We will first walk through how some pre-defined sources and sinks are provided and may be customized with little user effort.  We return later in this chapter to advanced tracing configuration including extending the tracing namespace and creating new tracing sources.

ASCII tracing
-------------

For Internet nodes, the ASCII trace wrapper is a wrapper around the ns-3 low-level tracing system that lets you get access to underlying trace events easily. The output of a trace of a simulation run is an ASCII file --- thus the name. In the spirit of keeping things simple, you won't be able to control or configure the output at this stage.

For those familiar with ns-2 output, this type of trace is analogous to the out.tr generated by many scripts.

Let's just jump right in.  As usual, we need to include the definitions related to using ASCII tracing (don't edit any files quite yet):

  #include "ns3/ascii-trace.h"

We then need to add the code to the script to actually enable the ASCII tracing code.  The following code must be inserted before the call to Simulator::Run ();:

  AsciiTrace asciitrace ("tutorial.tr");
  asciitrace.TraceAllQueues ();
  asciitrace.TraceAllNetDeviceRx ();

The first line declares an object of type AsciiTrace named asciitrace and passes a string parameter to its constructor.  This parameter is a file name to which all of the trace information will be written. The second line, asciitrace.TraceAllQueues (); asks the trace object to arrange that all queue operations (enqueue, dequeue, drop) on the queues in all of the nodes of the system be traced.  On the receive side, asciitrace.TraceAlllNetDeviceRx () traces packets received by a NetDevice.  For those familiar with ns-2, these are equivalent to the popular trace points that log "+", "-", "d", and "r" events.

Try running the following program from the command line:
  ./waf --run tutorial-csma-echo-ascii-trace

Just as you have seen previously, you will see some messages from Waf and then the ``Compilation finished successfully'' message.  The next message, UDP Echo Simulation is from the running program.  When it ran, the program will have created a file named tutorial.tr. Because of the way that Waf works, the file is not created in the local directory, it is created at the top-level directory of the repository.  So, change into the top level directory and take a look at the file tutorial.tr in your favorite editor.

Parsing Ascii Traces
....................

This section parses in detail the structure of the ascii tracing output.  If you find this output format self explanatory (it resembles tcpdump output), you may skip to the next section on pcap tracing.

There's a lot of information there in a pretty dense form, but the first thing to notice is that there are a number of distinct lines in this file.  It may be difficult to see this clearly unless you widen your windows considerably. Each line in the file corresponds to a trace event.  A trace event happens whenever specific conditions happen in the simulation.  In this case we are tracing events on the device queue present in every net device on every node in the simulation.  The device queue is a queue through which every packet destined for a channel must pass --- it is the device transmit queue.  Note that each line in the trace file begins with a lone character (has a space after it).  This character will have the following meaning:

  * +: An enqueue operation occurred on the device queue;

  * -: A dequeue operation occurred on the device queue;

  * d: A packet was dropped, typically because the queue was full.

Let's take a more detailed view of the first line.  I'll break it down into sections (indented for clarity) with a two digit reference number on the left side:

  00  +
  01  2
  02  nodeid=0
  03  device=0
  04  queue-enqueue
  05  pkt-uid=9
  06  ETHERNET
  07    length/type=0x806,
  08    source=08:00:2e:00:00:00,
  09    destination=ff:ff:ff:ff:ff:ff
  10      ARP(request
  11        source mac: 08:00:2e:00:00:00
  12        source ipv4: 10.1.1.1
  13        dest ipv4: 10.1.1.2)
  14  ETHERNET fcs=0

The first line of this expanded trace event (reference number 00) is the queue operation.  We have a + character, so this corresponds to an enqueue operation.  The second line (reference 01) is the simulation time expressed in seconds.  You may recall that we asked the UdpEchoClient to start sending packets at two seconds.  Here we see confirmation that this is, indeed, happening.

The next lines of the example listing (references 02 and 03) tell us that this trace event originated in a given node and net device.  Each time a node is created it is given an identifying number that monotonically increases from zero.  Therefore, nodeid=0 means that the node in which the given trace event originated is the first node we created.  In the case of our script, this first node is is the node pointed to by the smart pointer n0.  Not too surprisingly, this is also the node to which we attached the UdpEchoClient.  The device number is local to each node, and so the device given by device=0 is the first net device that we added to the node in question.  In our simulation, this corresponds to the CsmaNetDevice we added to node zero (n0).

The next line (reference 04) is a more readable form of the operation code seen in the first line --- i.e., the character + means queue-enqueue.  Reference number 05 indicates that the unique id of the packet being enqueued is 9.  The fact that the first packet we see has a unique ID of 9 should indicates to you that other things have happened in the protocol stack before we got to this point.  This will become clear momentarily.

Reference items 06 and 14 indicate that this is an Ethernet packet with a zero (not computed) checksum (note the indentation to make parsing this trace event a little easier).  Reference 08 and 09 are the source and destination addresses of this packet.  The packet is from the MAC address we assigned to the node zero net device in the script, and is destined for the broadcast address --- this is a broadcast packet.

Reference items 10 through 13 make clear what is happening.  This is an ARP (Address Resolution Protocol) request for the MAC address of the node on which the UdpEchoServer resides.  The protocol stack can't send a UDP packet to be echoed until it knows (resolves) the MAC address; and this trace event corresponds to an ARP request being queued for transmission to the local network.  The next line in the trace file (partially expanded),

  00  -
  01  2
  02  nodeid=0
  03  device=0
  04  queue-dequeue
  05  pkt-uid=9
  ...

shows the (same) ARP request packet being dequeued from the device queue by the net device and (implicitly) being sent down the channel to the broadcast MAC address.  We are not tracing net device reception events so we don't actually see all of the net devices receiving the broadcast packet.  We do, however see the following in the third line of the trace file:

  00  +
  01  2.00207
  02  nodeid=1
  03  device=0
  04  queue-enqueue
  05  pkt-uid=10
  06  ETHERNET
  07    length/type=0x806,
  08    source=08:00:2e:00:00:01,
  09    destination=08:00:2e:00:00:00,
  10      ARP(reply
  11        source mac: 08:00:2e:00:00:01
  12        source ipv4: 10.1.1.2
  13        dest mac: 08:00:2e:00:00:00
  14        dest ipv4: 10.1.1.1)
  15  ETHERNET fcs=0

Notice that this is a queue-enqueue operation (references 00 and 04) happening on node one (reference 02) at simulation time 2.00207 seconds (reference 01). Looking at the packet payload (references 10-14) we see that this is an ARP reply to the request sent by node one.  Note that the simulation time (reference 01) is now 2.00207 seconds.  This is direct result of the data rate (5 mb/s) and latency (2 ms) parameters that we passed to the CsmaChannel when we created it.  Clearly the ARP request packet was sent over the channel and received approximately 2 ms later by node one.  A corresponding ARP response packet was created and enqueued on node one's net device.  It is this enqueue trace event that has being logged.

Given the current state of affairs, the next thing you may expect to see is this ARP request being received by node zero, but remember we are only looking at trace events on the device transmit queue.  The reception of the ARP response by node zero will not directly trigger any trace event in this case, but it will enable the protocol stack to continue what it was originally doing (trying to send an echo packet).  Thus, the next line we see in the trace file (tutorial.tr) is the first UDP echo packet being sent to the net device.

  00 +
  01 2.00415
  02 nodeid=0
  03 device=0
  04 queue-enqueue
  05 pkt-uid=7
  06 ETHERNET
  07   length/type=0x800,
  08   source=08:00:2e:00:00:00,
  09   destination=08:00:2e:00:00:01
  10   IPV4(
  11     tos 0x0
  12     ttl 64
  13     id 0
  14     offset 0
  15     flags [none]
  16     length: 1052) 10.1.1.1 > 10.1.1.2
  17     UDP(length: 1032)
  18       49153 > 7
  19       DATA (length 1024)
  20 ETHERNET fcs=0

I won't go into too much detail about this packet, but I will point out a few key items in the trace.  First, the packet was enqueued at simulation time of 2.00415 seconds.  This time reflects the fact that the echo client application started at 2. seconds and there were two ARP packets transmitted across the network (two milliseconds + data transmission time each way).  The packet unique identifier (reference 05) is 7.  Notice that this is a lower number than the ARP request packet, which had a unique ID of 9.  This tells us that the UDP packet was actually created before the ARP request packet --- which makes perfect sense since it was the attempt to send packet 7 that triggered sending the ARP request packet 9.  Note that this an Ethernet packet (reference 06) like all other packets in this simulation, however this particular packet carries an IPV4 payload and therefore has an IP version 4 header (indicated by references 10-16).  This Ipv4 in turn contains a UDP header (references 17, 18) and finally 1024 bytes of data (reference 20). Clearly, this is the UDP echo packet emitted by the UdpEchoClient Application.

The next trace event is an ARP request from node one.  We can infer that node one has received the UDP echo packet and the UdpEchoServer Application on that node has turned the packet around.  Just as node zero needed to ARP for the MAC address of node one, now node one must ARP for the MAC address of node zero.  We see the ARP request enqueued on the transmit queue of node one; then we see the ARP request dequeued from the transmit queue of node one (and implicitly transmitted to node zero).  Then we see an ARP response enqueued on the transmit queue of node zero; and finally the ARP response dequeued (and implicitly transmitted back to node one).

This exchange is summarized in the following trace event excerpts,

  + 2.00786 nodeid=1 ... ARP(request ...
  - 2.00786 nodeid=1 ... ARP(request ...
  + 2.00994 nodeid=0 ... ARP(reply ...
  - 2.00994 nodeid=0 ... ARP(reply ...

The final two trace events in the tutorial.tr file correspond to the echoed packet being enqueued for transmission on the net device for node one, and that packet being dequeued (and implicitly transmitted back to node zero).

If you look at the trace file (tutorial.tr) you will also see some entries with an r event, indicating a receive trace event.  Recall that the first packet sent on the network was a broadcast ARP request.  We should then see all four nodes receive a copy of this request.  This is the case, as the first four receive trace events are,

  r 2.00207 nodeid=0 device=0 dev-rx pkt-uid=9 ARP(request ...
  r 2.00207 nodeid=1 device=0 dev-rx pkt-uid=9 ARP(request ...
  r 2.00207 nodeid=2 device=0 dev-rx pkt-uid=9 ARP(request ...
  r 2.00207 nodeid=3 device=0 dev-rx pkt-uid=9 ARP(request ...

You can see that a copy of the broadcast packet with unique ID 9 was received by the net devices on nodes 0, 1, 2 and 3.  We leave it up to you to parse the rest of the trace file and understand the remaining reception events.

PCAP Trace Wrapper
------------------

The ns-3 pcap trace wrapper is used to create trace files in .pcap format.  The acronym pcap (usually written in lower case) stands for packet capture, and is actually an API that includes the definition of a .pcap file format.  The most popular program that can read and display this format is Wireshark (formerly called Ethereal). However, there are many traffic trace analyzers that use this packet format, including X, Y, and Z.  We encourage users to exploit the many tools available for analyzing pcap traces; below, we show how tcpdump and Wireshark can be used..

The code used to enable pcap tracing is similar to that for ASCII tracing. We have provided another file, tutorial-csma-echo-pcap-trace.cc that uses the pcap trace wrapper.  We have added the code to include the pcap trace wrapper definitions:

  #include "ns3/pcap-trace.h"

And then added the following code below the AsciiTrace methods:

  PcapTrace pcaptrace ("tutorial.pcap");
  pcaptrace.TraceAllIp ();

The first line of the code immediately above declares an object of type PcapTrace named pcaptrace and passes a string parameter to its constructor.  This object is used to hide the details of the actual tracing subsystem.  The parameter is a base file name from which the actual trace file names will be built.  The second line of code tells the PcamTrace object to trace all IP activity in all of the nodes present in the simulation.

Trace files are not created until trace activity is detected.  Each file name is composed of the base file name, followed by a '-', a node id followed by a '-', and an IP interface index.  You will soon see a file named tutorial.pcap-0-1, for example.  This will be the trace file generated as events are detected on node zero, interface index one.  N.B. Interface indices are different that net device indices --- interface index zero corresponds to the loopback interface and interface index one corresponds to the first net device you added to a node.

You may run the new program just like all of the others so far:

  ./waf --run tutorial-csma-echo-pcap-trace

If you look at the top level directory of your distribution, you should now see three log files:  tutorial.tr is the ASCII trace file we have previously examined.  tutorial.pcap-0-1 and tutorial.pcap-1-1 are the new pcap files we just generated.  There will not be files corresponding to nodes two and three since we have not sent any IP packets to those nodes.

Reading output with tcpdump
...........................

Reading output with Wireshark
.............................

If you are unfamiliar with Wireshark, there is a web site available from which you can download programs and documentation:  http://www.wireshark.org/.

If you have Wireshark available, you can open each of the trace files and display the contents as if you had captured the packets using a packet sniffer.  Note that only IP packets are traced using this wrapper, so you will not see the ARP exchanges that were logged when using the ASCII trace wrapper.  You are encouraged to take a look at the contents of these pcap files using your favorite pcap software (or Wireshark).

Advanced Tracing
================