| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
We have already taken a brief look at the ns-3 logging module while
going over the first.cc script. We will now take a closer look and
see what kind of use-cases the logging subsystem was designed to cover.
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
Many large systems support some kind of message logging facility, and
ns-3 is not an exception. In some cases, only error messages are
logged to the "operator console" (which is typically stderr in Unix-
based systems). In other systems, warning messages may be output as well as
more detailed informational messages. In some cases, logging facilities are
used to output debug messages which can quickly turn the output into a blur.
Ns-3 takes the view that all of these verbosity levels are useful
and we provide a selectable, multi-level approach to message logging. Logging
can be disabled completely, enabled on a component-by-component basis, or
enabled globally; and it provides selectable verbosity levels. The
ns-3 log module provides a straightforward, relatively easy to use
way to get useful information out of your simulation.
You should understand that we do provide a general purpose mechanism -- tracing -- to get data out of your models which should be preferred for simulation output (see the tutorial section Using the Tracing System for more details on our tracing system). Logging should be preferred for debugging information, warnings, error messages, or any time you want to easily get a quick message out of your scripts or models.
There are currently seven levels of log messages of increasing verbosity defined in the system.
We also provide an unconditional logging level that is always displayed, irrespective of logging levels or component selection.
Each level can be requested singly or cumulatively; and logging can be set up using a shell environment variable (NS_LOG) or by logging system function call. As was seen earlier in the tutorial, the logging system has Doxygen documentation and now would be a good time to peruse the Logging Module documentation if you have not done so.
Now that you have read the documentation in great detail, let's use some of
that knowledge to get some interesting information out of the first.cc
example script you have already built.
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
Let's use the NS_LOG environment variable to turn on some more logging, but to get our bearings, go ahead and run the script just as you did previously,
~/repos/ns-3-dev > ./waf --run scratch/first Entering directory `/home/craigdo/repos/ns-3-dev/build' Compilation finished successfully Sent 1024 bytes to 10.1.1.2 Received 1024 bytes from 10.1.1.1 Received 1024 bytes from 10.1.1.2 ~/repos/ns-3-dev >
It turns out that the "Sent" and "Received" messages are actually logging
messages from the UdpEchoClientApplication and
UdpEchoServerApplication. We can ask the client application, for
example, to print more information by setting its logging level via the
NS_LOG environment variable.
I am going to assume from here on that are using an sh-like shell that uses the"VARIABLE=value" syntax. If you are using a csh-like shell, then you will have to convert my examples to the "setenv VARIABLE value" syntax required by those shells.
Right now, the UDP echo client application is responding to the following line
of code in first.cc,
LogComponentEnable("UdpEchoClientApplication", LOG_LEVEL_INFO);
This line of code enables the LOG_LEVEL_INFO level of logging. When
we pass a logging level flag, we are actually enabling the given level and
all lower levels. In this case, we have enabled NS_LOG_INFO,
NS_LOG_DEBUG, NS_LOG_WARN and NS_LOG_ERROR. We can
increase the logging level and get more information without changing the
script and recompiling by setting the NS_LOG environment variable like this:
~/repos/ns-3-dev > export NS_LOG=UdpEchoClientApplication=level_all
This sets the shell environment variable NS_LOG to the string,
UdpEchoClientApplication=level_all
The left hand side of the assignment is the name of the logging component we
want to set, and the right hand side is the flag we want to use. In this case,
we are going to turn on all of the debugging levels for the application. If
you run the script with NS_LOG set this way, the ns-3 logging
system will pick up the change and you should see the following output:
~/repos/ns-3-dev > ./waf --run scratch/first Entering directory `/home/craigdo/repos/ns-3-dev/build' Compilation finished successfully UdpEchoClientApplication:UdpEchoClient() UdpEchoClientApplication:StartApplication() UdpEchoClientApplication:ScheduleTransmit() UdpEchoClientApplication:Send() Sent 1024 bytes to 10.1.1.2 Received 1024 bytes from 10.1.1.1 UdpEchoClientApplication:HandleRead(0x62c640, 0x62cd70) Received 1024 bytes from 10.1.1.2 UdpEchoClientApplication:StopApplication() UdpEchoClientApplication:DoDispose() UdpEchoClientApplication:~UdpEchoClient() ~/repos/ns-3-dev >
The additional debug information provided by the application is from
the NS_LOG_FUNCTION level. This shows every time a function in the application
is called during script execution. Note that there are no requirements in the
ns-3 system that models must support any particular logging
functionality. The decision regarding how much information is logged
is left to the individual model developer. In the case of the echo
applications, a good deal of log output is available.
You can now see a log of the function calls that were made to the application.
If you look closely you will notice a single colon between the string
UdpEchoClientApplication and the method name where you might have
expected a C++ scope operator (::). This is intentional.
The name is not actually a class name, it is a logging component name. When there is a one-to-one correspondence between a source file and a class, this will generally be the class name but you should understand that it is not actually a class name, and there is a single colon there instead of a double colon to remind you in a relatively subtle way to conceptually separate the logging component name from the class name.
It turns out that in come cases, it can be hard to determine which method
actually generates a log message. If you look in the text above, you may
wonder where the string "Received 1024 bytes from 10.1.1.2" comes
from. You can resolve this by ORing the prefix_func level into the
NS_LOG environment variable. Try doing the following,
export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func'
Note that the quotes are required since the vertical bar we use to indicate an OR operation is also a Unix pipe connector.
Now, if you run the script you will see that the logging system makes sure that every message from the given log component is prefixed with the component name.
~/repos/ns-3-dev > ./waf --run scratch/first Entering directory `/home/craigdo/repos/ns-3-dev/build' Compilation finished successfully UdpEchoClientApplication:UdpEchoClient() UdpEchoClientApplication:StartApplication() UdpEchoClientApplication:ScheduleTransmit() UdpEchoClientApplication:Send() UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2 Received 1024 bytes from 10.1.1.1 UdpEchoClientApplication:HandleRead(0x62c710, 0x62ce40) UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2 UdpEchoClientApplication:StopApplication() UdpEchoClientApplication:DoDispose() UdpEchoClientApplication:~UdpEchoClient() ~/repos/ns-3-dev >
You can now see all of the messages coming from the UDP echo client application are identified as such. The message "Received 1024 bytes from 10.1.1.2" is now clearly identified as coming from the echo client application. The remaining message must be coming from the UDP echo server application. We can enable that component by entering a colon separated list of components in the NS_LOG environment variable.
export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func:
UdpEchoServerApplication=level_all|prefix_func'
Note that you will need to remove the newline after the : in the
example text above.
Now, if you run the script you will see all of the log messages from both the echo client and server applications. You may see that this can be very useful in debugging problems.
~/repos/ns-3-dev > ./waf --run scratch/first Entering directory `/home/craigdo/repos/ns-3-dev/build' Compilation finished successfully UdpEchoServerApplication:UdpEchoServer() UdpEchoClientApplication:UdpEchoClient() UdpEchoServerApplication:StartApplication() UdpEchoClientApplication:StartApplication() UdpEchoClientApplication:ScheduleTransmit() UdpEchoClientApplication:Send() UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2 UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1 UdpEchoServerApplication:HandleRead(): Echoing packet UdpEchoClientApplication:HandleRead(0x62c760, 0x62ce90) UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2 UdpEchoServerApplication:StopApplication() UdpEchoClientApplication:StopApplication() UdpEchoClientApplication:DoDispose() UdpEchoServerApplication:DoDispose() UdpEchoClientApplication:~UdpEchoClient() UdpEchoServerApplication:~UdpEchoServer() ~/repos/ns-3-dev >
It is also sometimes useful to be able to see the simulation time at which a log message is generated. You can do this by ORing in the prefix_time bit.
export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func|prefix_time:
UdpEchoServerApplication=level_all|prefix_func|prefix_time'
If you run the script now, you should see the following output:
~/repos/ns-3-dev > ./waf --run scratch/first
Entering directory `/home/craigdo/repos/ns-3-dev/build'
Compilation finished successfully
0ns UdpEchoServerApplication:UdpEchoServer()
0ns UdpEchoClientApplication:UdpEchoClient()
1000000000ns UdpEchoServerApplication:StartApplication()
2000000000ns UdpEchoClientApplication:StartApplication()
2000000000ns UdpEchoClientApplication:ScheduleTransmit()
2000000000ns UdpEchoClientApplication:Send()
2000000000ns UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2
2003686400ns UdpEchoServerApplication:HandleRead(): Received 1024 bytes
from 10.1.1.1
2003686400ns UdpEchoServerApplication:HandleRead(): Echoing packet
2007372800ns UdpEchoClientApplication:HandleRead(0x62c8c0, 0x62d020)
2007372800ns UdpEchoClientApplication:HandleRead(): Received 1024 bytes
from 10.1.1.2
10000000000ns UdpEchoServerApplication:StopApplication()
10000000000ns UdpEchoClientApplication:StopApplication()
UdpEchoClientApplication:DoDispose()
UdpEchoServerApplication:DoDispose()
UdpEchoClientApplication:~UdpEchoClient()
UdpEchoServerApplication:~UdpEchoServer()
~/repos/ns-3-dev >
You can see that the constructor for the UdpEchoServer was called at a simulation time of 0 nanoseconds. This is actually happening before the simulation starts. The same for the UdpEchoClient constructor.
Recall that the first.cc script started the echo server application at
one second into the simulation. You can now see that the
StartApplication method of the server is, in fact, called at one second
(or one billion nanoseconds). You can also see that the echo client
application is started at a simulation time of two seconds as we requested in
the script.
You can now follow the progress of the simulation from the
ScheduleTransmit call in the client that calls Send to the
HandleRead callback in the echo server application. Note that the
elapsed time as the packet is sent across the point-to-point link is 3.6864
milliseconds. You see the echo server logging a message telling you that it
has echoed the packet and then, after a delay, you see the echo client receive
the echoed packet in its HandleRead method.
There is a lot that is happening under the covers in this simulation that you
are not seeing as well. You can very easily follow the entire process by
turning on all of the logging components in the system. Try setting the
NS_LOG variable to the following,
export 'NS_LOG=*=level_all|prefix_func|prefix_time'
The asterisk above is the logging component wildcard. This will turn on all of the logging in all of the components used in the simulation. I won't reproduce the output here (as of this writing it produces 772 lines of output for the single packet echo) but you can redirect this information into a file and look through it with your favorite editor if you like,
~/repos/ns-3-dev > ./waf --run scratch/first >& log.out
I personally use this quite a bit when I am presented with a problem and I have no idea where things are going wrong. I can follow the progress of the code quite easily without having to set breakpoints and step through code in a debugger. When I have a general idea about what is going wrong, I transition into a debugger for fine-grained examination of the problem. This kind of output can be especially useful when your script does something completely unexpected. If you are stepping using a debugger you may miss an unexpected excursion completely. Logging the excursion makes it quickly visible.
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
You can add new logging to your simulations by making calls to the log
component via several macros. Let's do so in the first.cc script we
have in the scratch directory.
Recall that we have defined a logging component in that script:
NS_LOG_COMPONENT_DEFINE ("FirstScriptExample");
You now know that you can enable all of the logging for this component by
setting the NS_LOG environment variable to the various levels. Let's
go ahead add some logging to the script. The macro used to add an
informational level log message is NS_LOG_INFO. Go ahead and add one
just before we start creating the nodes that tells you that the script is
"Creating Topology." This is done as in this code snippet,
NS_LOG_INFO ("Creating Topology");
Now build the script using waf and clear the NS_LOG variable to turn
off the torrent of logging we previously enabled:
~/repos/ns-3-dev > export NS_LOG=
Now, if you run the script, you will not see your new message since its
associated logging component (FirstScriptExample) has not been enabled.
In order to see your message you will have to enable the
FirstScriptExample logging component with a level greater than or equal
to NS_LOG_INFO. If you just want to see this particular level of
logging, you can enable it by,
~/repos/ns-3-dev > export NS_LOG=FirstScriptExample=info
If you now run the script you will see your new "Creating Topology" log message,
~/repos/ns-3-dev > ./waf --run scratch/first Entering directory `/home/craigdo/repos/ns-3-dev/build' Compilation finished successfully Creating Topology Sent 1024 bytes to 10.1.1.2 Received 1024 bytes from 10.1.1.1 Received 1024 bytes from 10.1.1.2 ~/repos/ns-3-dev >
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] |
This document was generated on July, 20 2008 using texi2html 1.76.