Sprinkled calls to TBDebugTimeStamp all over, so that we can get a

better picture of where time is spent during experiment setup.

tbsetup/assign_wrapper.in

@@ -90,6 +90,8 @@ sub printdb {
     }
 };
 
+TBDebugTimeStamp("assign_wrapper started");
+
 ######################################################################
 # Step 1 - Setup virtual topology
 #
@@ -164,6 +166,8 @@ $delayid = 0;
 
 printdb "Generating TOP file.\n";
 
+TBDebugTimeStamp("top started");
+
 # Let's figure out what kind of links we have.
 printdb "Finding interface speeds:";
 my $result = DBQueryFatal("SELECT type,max_speed from interface_types");
@@ -545,6 +549,8 @@ DBQueryFatal("UPDATE experiments set maximum_nodes=$maximum_nodes, " .
 print "Minumum nodes = $minimum_nodes\n";
 print "Maximum nodes = $maximum_nodes\n";
 
+TBDebugTimeStamp("top finished");
+
 ######################################################################
 # Step 2 - Assign Loop
 # 
@@ -561,6 +567,7 @@ print "Maximum nodes = $maximum_nodes\n";
 #  the second.
 #######################################################################
 
+TBDebugTimeStamp("assign_loop started");
 $currentrun = 1;
 while (1) {
     print "Assign Run $currentrun\n";
@@ -576,8 +583,10 @@ while (1) {
     undef %p2vmap;
     undef %plinks;
 
+    TBDebugTimeStamp("ptopgen started");
     # Snapshot
     system("ptopgen > $ptopfile");
+    TBDebugTimeStamp("ptopgen finished");
 
     # Get number of nodes
     my $numnodes_result = 
@@ -593,6 +602,7 @@ while (1) {
 	exit(2);
     }
 
+    TBDebugTimeStamp("assign started");
     # Run assign
     $fail = 0;
     print "assign -b -t $ptopfile $topfile\n";
@@ -693,7 +703,9 @@ while (1) {
     }
     while (<ASSIGNFP>) { } # Read anything left in the pipe before closing
     close(ASSIGNFP);
+    TBDebugTimeStamp("assign finished");
 
+    TBDebugTimeStamp("reserving started");
     # Reserve resources
     if (!$fail) {
 	print "Reserving resources.\n";
@@ -711,6 +723,7 @@ while (1) {
 	    last;
 	}
     }
+    TBDebugTimeStamp("reserving finished");
 
     # Check for exit
     if ($currentrun >= $maxrun) {
@@ -733,6 +746,8 @@ while (1) {
     $currentrun++;
 }
 
+TBDebugTimeStamp("assign_loop finished");
+
 #
 # VIRTNODES HACK: physical nodes (from the nodes table) might really
 # be a virtual node :-) Must get the underlying phys_nodeid.
@@ -753,6 +768,7 @@ foreach my $pnode (keys(%p2vmap)) {
     $p2pmap{$pnode} = $phys_nodeid;
 }
 
+
 ######################################################################
 # Step 3 - Convert to vlans, delays, and portmap
 # 
@@ -788,6 +804,7 @@ foreach $pnode (keys(%p2vmap)) {
 }
 
 printdb "Interpreting results.\n";
+TBDebugTimeStamp("interpreting started");
 foreach $plink (keys(%plinks)) {
     ($nodeportA,$nodeportB) = @{$plinks{$plink}};
     ($nodeA,$portA) = split(":",$nodeportA);
@@ -911,6 +928,7 @@ foreach $plink (keys(%plinks)) {
     }
     # Else delaysrc case, will be handled by one of the other cases.
 }
+TBDebugTimeStamp("interpreting finished");
 
 ######################################################################
 # Step 4 - Upload to DB
@@ -918,6 +936,7 @@ foreach $plink (keys(%plinks)) {
 # Nothing fancy.
 ######################################################################
 printdb "Uploading to DB\n";
+TBDebugTimeStamp("uploading started");
 foreach $vlan (keys(%vlans)) {
     ($lan,$members) = @{$vlans{$vlan}};
     DBQueryFatal("insert into vlans (id,pid,eid,virtual,members) values" .
@@ -1291,6 +1310,9 @@ if ($query_result->numrows) {
 		     " vnode='$target_vnode' and vname='$target_vname'");
     }
 }
+TBDebugTimeStamp("uploading finished");
+
+TBDebugTimeStamp("assign_wrapper finished");
 
 ######################################################################
 # Subroutines

tbsetup/os_setup.in

@@ -115,6 +115,8 @@ if ($UID && !TBAdmin($UID)) {
     }
 }
 
+TBDebugTimeStamp("os_setup started");
+
 #
 # Get the set of nodes, as well as the nodes table information for them.
 #
@@ -361,6 +363,7 @@ while (my %row = $db_result->fetchhash()) {
 #
 # We need to issue the reboots and the reloads in parallel.
 #
+TBDebugTimeStamp("rebooting/reloading started");
 if (!$TESTMODE) {
     my %pids  = ();
     my $count = 0;
@@ -390,6 +393,7 @@ if (!$TESTMODE) {
     }
 }
 
+TBDebugTimeStamp("rebooting/reloading finished");
 print STDOUT "Waiting for testbed nodes to finish rebooting ...\n";
 
 sleep(2);
@@ -406,6 +410,7 @@ foreach my $node ( @nodes ) {
     $waitstart{$node} = time;
 }
 
+TBDebugTimeStamp("waiting started");
 while ( @nodes ) {
     my $node = shift(@nodes);
 
@@ -476,6 +481,7 @@ while ( @nodes ) {
 
     print "*** Experiment will be terminated automatically.\n";
 }
+TBDebugTimeStamp("waiting finished");
 
 #
 # Now deal with virtual nodes.
@@ -493,6 +499,7 @@ if ( @vnodes ) {
 }
 
 print STDOUT "OS Setup Done!\n";
+TBDebugTimeStamp("os_setup finished");
 exit $failed;
 
 #

tbsetup/tbswapin.in

@@ -77,7 +77,9 @@ sub cleanup {
     SetExpState($pid, $eid, EXPTSTATE_SWAPPED);
 }
 
-print "Beginning swapin in for $pid/$eid. " .  TBTimeStamp() . "\n";
+print "Beginning swapin in for $pid/$eid\n";
+
+TBDebugTimeStamp("tbswapin started");
 
 if (! ($state = ExpState($pid, $eid))) {
     print STDERR "*** No such experiment $pid/$eid\n";
@@ -98,6 +100,7 @@ if (! SetExpState($pid, $eid, EXPTSTATE_ACTIVATING)) {
 
 # This does all the virtual to physical mapping and updating the DB state.
 print "Mapping to physical reality ...\n";
+TBDebugTimeStamp("assign_wrapper started");
 my $exitcode;
 if ($exitcode = system("assign_wrapper $pid $eid")) {
     print STDERR "*** Failed to map to reality.\n";
@@ -105,7 +108,8 @@ if ($exitcode = system("assign_wrapper $pid $eid")) {
     # Pass exit code through
     exit($exitcode >> 8);
 }
-print "Mapped to physical reality! " . TBTimeStamp() . "\n";
+TBDebugTimeStamp("assign_wrapper finished");
+print "Mapped to physical reality!\n";
 
 # Exit here if we are testing.
 if ($TESTMODE) {
@@ -128,12 +132,15 @@ if ($TESTMODE) {
 # long before the nodes reboot, but better safe than sorry)
 #
 print "Setting up mountpoints.\n";
+TBDebugTimeStamp("mountpoints started");
 if (system("exports_setup")) {
     print STDERR "*** Failed to setup mountpoints.\n";
     cleanup();
     exit(1);
 }
+TBDebugTimeStamp("mountpoints finished");
 
+TBDebugTimeStamp("named started");
 print "Setting up named maps.\n";
 if (system("named_setup")) {
     print STDERR "*** WARNING: Failed to add node names to named map.\n";
@@ -141,12 +148,14 @@ if (system("named_setup")) {
     # This is a non-fatal error.
     # 
 }
+TBDebugTimeStamp("named finished");
 
 #
 # Since it'll take a while for the nodes to reboot, we'll start now, and
 # wait for the os_setup to finish, down below
 #
 print "Resetting OS and rebooting.\n";
+TBDebugTimeStamp("os_setup started");
 if (!($os_setup_pid = fork())) { 
     exec("os_setup $pid $eid") or exit(1);
 } elsif ($os_setup_pid == -1) {
@@ -163,11 +172,13 @@ if (!($os_setup_pid = fork())) {
 #
 
 print "Setting up VLANs.\n";
+TBDebugTimeStamp("snmpit started");
 if (system("snmpit -t $pid $eid")) {
     print STDERR "*** Failed to set up VLANs.\n";
     cleanup();
     exit(1);
 }
+TBDebugTimeStamp("snmpit finished");
 
 #
 # An error now means that the VLANS need to be cleaned up.
@@ -175,12 +186,14 @@ if (system("snmpit -t $pid $eid")) {
 $cleanvlans = 1;
 
 print "Setting up email lists.\n";
+TBDebugTimeStamp("genelists started");
 if (system("genelists")) {
     print STDERR "*** WARNING: Failed to update email lists.\n";
     #
     # This is a non-fatal error.
     # 
 }
+TBDebugTimeStamp("genelists finished");
 
 #
 # OK, let's see how that os_setup did
@@ -199,6 +212,7 @@ if ($kid == $os_setup_pid) {
     cleanup;
     exit(1);
 }
+TBDebugTimeStamp("os_setup finished");
 
 #
 # Okay, start the event system now that we know all the nodes have
@@ -206,11 +220,13 @@ if ($kid == $os_setup_pid) {
 # in the background), so its not enough of a delay to worry about.
 # 
 print "Starting the event system.\n";
+TBDebugTimeStamp("eventsys_control started");
 if (system("eventsys_control start $pid $eid")) {
     print STDERR "*** Failed to start the event system.\n";
     cleanup;
     exit(1);
 }
+TBDebugTimeStamp("eventsys_control finished");
 
 # Accounting info.
 TBSetExpSwapTime($pid, $eid);
@@ -221,5 +237,6 @@ if (!SetExpState($pid, $eid, EXPTSTATE_ACTIVE)) {
     exit(1);
 }
 
-print "Swapin finished. " . TBTimeStamp() . "\n";
+print "Swapin finished.\n";
+TBDebugTimeStamp("tbswapin finished");
 exit(0);