37.1.4 Tracing

Each object writes out trace information that can be used to track the progress of the object in its error recovery. Each trace entry is of the form:
\tup{prefix} \tup{tag} \tup{type of entry} \tup{values}
The prefix is as describe in the previous section for statistics. The tag is Q for request objects, P for repair objects, and S for session objects. The following types of trace entries and parameters are written by each object:

  Type of    
Tag Object Other values Comments
Q DETECT    
Q INTERVALS C1 C1_ C2 C2_ dist distance i backoff_  
Q NTIMER at time Time the request timer will fire
Q SENDNACK    
Q NACK IGNORE-BACKOFF time Receive NACK, ignore other NACKs until time
Q REPAIR IGNORES time Receive REPAIR, ignore NACKs until time
Q DATA   Agent receives data instead of repair. Possibly indicates out of order arrival of data.
P NACK from requester Receive NACK, initiate repair
P INTERVALS D1 D1_ D2 D2_ dist distance  
P RTIMER at time Time the repair timer will fire
P SENDREP    
P REPAIR IGNORES time Receive REPAIR, ignore NACKs until time
P DATA   Agent receives data instead of repair. Indicates premature request by an agent.
S SESSION   logs session message sent
The following illustrates a typical trace for a single loss and recovery.
 3.5543 n 1 m <1:1> r 0 Q DETECT
 3.5543 n 1 m <1:1> r 1 Q INTERVALS C1 2.0 C2 0.0 d 0.0105 i 1
 3.5543 n 1 m <1:1> r 1 Q NTIMER at 3.57527
 3.5685 n 2 m <1:1> r 0 Q DETECT
 3.5685 n 2 m <1:1> r 1 Q INTERVALS C1 2.0 C2 0.0 d 0.021 i 1
 3.5685 n 2 m <1:1> r 1 Q NTIMER at 3.61053
 3.5753 n 1 m <1:1> r 1 Q SENDNACK
 3.5753 n 1 m <1:1> r 2 Q INTERVALS C1 2.0 C2 0.0 d 0.0105 i 2
 3.5753 n 1 m <1:1> r 2 Q NTIMER at 3.61727
 3.5753 n 1 m <1:1> r 2 Q NACK IGNORE-BACKOFF 3.59627
 3.5828 n 3 m <1:1> r 0 Q DETECT
 3.5828 n 3 m <1:1> r 1 Q INTERVALS C1 2.0 C2 0.0 d 0.032 i 1
 3.5828 n 3 m <1:1> r 1 Q NTIMER at 3.6468
 3.5854 n 0 m <1:1> r 0 P NACK from 257
 3.5854 n 0 m <1:1> r 1 P INTERVALS D1 1.0 D2 0.0 d 0.0105
 3.5854 n 0 m <1:1> r 1 P RTIMER at 3.59586
 3.5886 n 2 m <1:1> r 2 Q INTERVALS C1 2.0 C2 0.0 d 0.021 i 2
 3.5886 n 2 m <1:1> r 2 Q NTIMER at 3.67262
 3.5886 n 2 m <1:1> r 2 Q NACK IGNORE-BACKOFF 3.63062
 3.5959 n 0 m <1:1> r 1 P SENDREP
 3.5959 n 0 m <1:1> r 1 P REPAIR IGNORES 3.62736
 3.5971 n 4 m <1:1> r 0 Q DETECT
 3.5971 n 4 m <1:1> r 1 Q INTERVALS C1 2.0 C2 0.0 d 0.0425 i 1
 3.5971 n 4 m <1:1> r 1 Q NTIMER at 3.68207
 3.5971 n 5 m <1:1> r 0 Q DETECT
 3.5971 n 5 m <1:1> r 1 Q INTERVALS C1 2.0 C2 0.0 d 0.042 i 1
 3.5971 n 5 m <1:1> r 1 Q NTIMER at 3.68107
 3.6029 n 3 m <1:1> r 2 Q INTERVALS C1 2.0 C2 0.0 d 0.032 i 2
 3.6029 n 3 m <1:1> r 2 Q NTIMER at 3.73089
 3.6029 n 3 m <1:1> r 2 Q NACK IGNORE-BACKOFF 3.66689
 3.6102 n 1 m <1:1> r 2 Q REPAIR IGNORES 3.64171
 3.6172 n 4 m <1:1> r 2 Q INTERVALS C1 2.0 C2 0.0 d 0.0425 i 2
 3.6172 n 4 m <1:1> r 2 Q NTIMER at 3.78715
 3.6172 n 4 m <1:1> r 2 Q NACK IGNORE-BACKOFF 3.70215
 3.6172 n 5 m <1:1> r 2 Q INTERVALS C1 2.0 C2 0.0 d 0.042 i 2
 3.6172 n 5 m <1:1> r 2 Q NTIMER at 3.78515
 3.6172 n 5 m <1:1> r 2 Q NACK IGNORE-BACKOFF 3.70115
 3.6246 n 2 m <1:1> r 2 Q REPAIR IGNORES 3.68756
 3.6389 n 3 m <1:1> r 2 Q REPAIR IGNORES 3.73492
 3.6533 n 4 m <1:1> r 2 Q REPAIR IGNORES 3.78077
 3.6533 n 5 m <1:1> r 2 Q REPAIR IGNORES 3.77927
The logging of request and repair traces is done by []SRM::evTrace../ns-2/srm.tclSRM::evTrace. However, the routine []SRM/Session::evTrace../ns-2/srm.tclSRM/Session::evTrace, overrides the base class definition of []srm::evTrace, and writes out nothing. Individual simulation scripts can override these methods for greater flexibility in logging options. One possible reason to override these methods might to reduce the amount of data generated; the new procedure could then generate compressed and processed output.

Notice that the trace filoe contains sufficient information and details to derive most of the statistics written out in the log file, or is stored in the statistics arrays.

Tom Henderson 2011-11-05