ChangeLogTag:Wed Dec 3 16:11:39 1997 Carlos O'Ryan <coryan@macarena.cs.wustl.edu>

6 files changed, 133 insertions, 22 deletions

diff --git a/TAO/local/ChangeLog b/TAO/local/ChangeLog
index b1e3f0619f6..a8524d3cf7f 100644
--- a/TAO/local/ChangeLog
+++ b/TAO/local/ChangeLog
@@ -1,3 +1,13 @@
+Wed Dec  3 16:11:39 1997  Carlos O'Ryan  <coryan@macarena.cs.wustl.edu>
+
+	* tests/Latency.h: 
+	* tests/Latency.cpp: 
+	* bin/Event_Service/Event_Channel.cpp: 
+	* bin/Event_Service/Dispatching_Modules.i: 
+	* bin/Event_Service/Dispatching_Modules.h: 
+	  Use the new timestamps on the Events to track the movement of
+	  the events on the EC.
+
 Wed Dec 03 09:27:44 1997  David L. Levine  <levine@cs.wustl.edu>
 
 	* local/bin/Event_Service/Event_Channel.cpp: added
diff --git a/TAO/local/bin/Event_Service/Dispatching_Modules.h b/TAO/local/bin/Event_Service/Dispatching_Modules.h
index 5fc18f41a4a..974f83a5495 100644
--- a/TAO/local/bin/Event_Service/Dispatching_Modules.h
+++ b/TAO/local/bin/Event_Service/Dispatching_Modules.h
@@ -147,8 +147,8 @@ public:
   ACE_ES_Dispatch_Request (ACE_Push_Consumer_Proxy *consumer,
 			   const RtecEventComm::Time &time,
 			   RtecScheduler::handle_t rt_info);
-  // Set consumer_ to <consumer> and sets single_event_.time_ to
-  // <time>.  Sets use_single_event_ to 1.  <rt_info> describes the
+  // Set consumer_ to <consumer> and sets single_event_.creation_time_
+  // to <time>.  Sets use_single_event_ to 1.  <rt_info> describes the
   // method receiving this dispatch.
 
   ACE_ES_Dispatch_Request (ACE_Push_Consumer_Proxy *consumer,
diff --git a/TAO/local/bin/Event_Service/Dispatching_Modules.i b/TAO/local/bin/Event_Service/Dispatching_Modules.i
index 55bd1f0bd2f..f9d7ea5dde4 100644
--- a/TAO/local/bin/Event_Service/Dispatching_Modules.i
+++ b/TAO/local/bin/Event_Service/Dispatching_Modules.i
@@ -72,7 +72,7 @@ ACE_ES_Dispatch_Request::ACE_ES_Dispatch_Request (ACE_Push_Consumer_Proxy *consu
   single_event_ (),
   event_set_ ()
 {
-  single_event_.time_ = time;
+  single_event_.creation_time_ = time;
   single_event_.type_ = ACE_ES_EVENT_TIMEOUT;
 }
 
diff --git a/TAO/local/bin/Event_Service/Event_Channel.cpp b/TAO/local/bin/Event_Service/Event_Channel.cpp
index 15d53350245..ba6f29b4f72 100644
--- a/TAO/local/bin/Event_Service/Event_Channel.cpp
+++ b/TAO/local/bin/Event_Service/Event_Channel.cpp
@@ -414,6 +414,13 @@ ACE_Push_Supplier_Proxy::push (const RtecEventComm::EventSet &event,
   if (!this->connected ())
     ACE_THROW (RtecEventComm::Disconnected);
 
+  // @@ TOTAL HACK
+  ACE_hrtime_t ec_recv = ACE_OS::gethrtime ();
+  for (CORBA::ULong i = 0; i < event.length (); ++i)
+    {
+      ACE_OS::memcpy (&event[i].ec_recv_time_, &ec_recv,
+		      sizeof (RtecEventComm::Time));
+    }
   supplier_module_->push (this, event, _env);
 }
 
@@ -1041,6 +1048,13 @@ ACE_ES_Consumer_Module::push (const ACE_ES_Dispatch_Request *request,
   request->make_copy (event_set);
 
   // Forward the event set.
+  // @@ TOTAL HACK
+  ACE_hrtime_t ec_send = ACE_OS::gethrtime ();
+  for (CORBA::ULong i = 0; i < event_set.length (); ++i)
+    {
+      ACE_OS::memcpy (&event_set[i].ec_send_time_, &ec_send,
+		      sizeof (RtecEventComm::Time));
+    }
   request->consumer ()->push (event_set, _env);
   ACE_TIMEPROBE ("  leave ES_Consumer_Module::push");
 }
@@ -1154,8 +1168,8 @@ ACE_ES_Correlation_Module::push (ACE_ES_Consumer_Rep *consumer,
 int
 ACE_ES_Correlation_Module::schedule_timeout (ACE_ES_Consumer_Rep_Timeout *consumer)
 {
-  RtecEventComm::Time &interval = consumer->dependency ()->event_.time_;
-  RtecEventComm::Time &delay = consumer->dependency ()->event_.time_;
+  RtecEventComm::Time &interval = consumer->dependency ()->event_.creation_time_;
+  RtecEventComm::Time &delay = consumer->dependency ()->event_.creation_time_;
 
   // Store the preemption priority so we can cancel the correct timer.
   // The priority values may change during the process lifetime (e.g.,
@@ -1204,8 +1218,8 @@ ACE_ES_Correlation_Module::reschedule_timeout (ACE_ES_Consumer_Rep_Timeout *cons
     ACE_ERROR_RETURN ((LM_ERROR, "%p.\n", "ACE_ES_Disjunction_Group::reschedule_deadline"), -1);
   else
     {
-      RtecEventComm::Time &interval = consumer->dependency ()->event_.time_;
-      RtecEventComm::Time &delay = consumer->dependency ()->event_.time_;
+      RtecEventComm::Time &interval = consumer->dependency ()->event_.creation_time_;
+      RtecEventComm::Time &delay = consumer->dependency ()->event_.creation_time_;
 
       // Store the preemption priority so we can cancel the correct timer.
       // The priority values may change during the process lifetime (e.g.,
@@ -1772,7 +1786,7 @@ ACE_ES_Consumer_Rep_Timeout::execute (void)
     {
       CORBA::Environment __env;
       ACE_Time_Value tv = ACE_OS::gettimeofday ();
-      timeout_event_->time_ = tv.sec () * 10000000 + tv.usec () * 10;
+      timeout_event_->creation_time_ = tv.sec () * 10000000 + tv.usec () * 10;
       correlation_->correlation_module_->push (this, timeout_event_, __env);
       if (__env.exception () != 0)
 	ACE_ERROR ((LM_ERROR, "ACE_ES_Consumer_Rep_Timeout::execute: unexpected exception.\n"));
@@ -2744,7 +2758,7 @@ dump_event (const RtecEventComm::Event &event)
 	      (void*)event.source_,
 	      event.type_,
 	      // The divide-by-1 is for ACE_U_LongLong support.
-	      event.time_ / 1));
+	      event.creation_time_ / 1));
 }
 
 // ************************************************************
diff --git a/TAO/local/tests/Latency.cpp b/TAO/local/tests/Latency.cpp
index 9a6fedbc1c0..b10bf75206e 100644
--- a/TAO/local/tests/Latency.cpp
+++ b/TAO/local/tests/Latency.cpp
@@ -38,10 +38,6 @@ static int shutting_down = 0;
 // and talk directly to consumers.  For testing only :-)
 static Latency_Consumer **consumer;
 
-// This is a global variable, set up when the Event is created. Used
-// on round trip measurements.
-static ACE_hrtime_t event_push_time;
-
 // ************************************************************
 
 Latency_Consumer::Latency_Consumer (const int measure_jitter)
@@ -49,7 +45,16 @@ Latency_Consumer::Latency_Consumer (const int measure_jitter)
     min_latency_ (INT_MAX),
     max_latency_ (INT_MIN),
     total_latency_ (0),
-    total_pushes_ (0)
+    total_pushes_ (0),
+    min_to_ec_ (INT_MAX),
+    max_to_ec_ (INT_MIN),
+    sum_to_ec_ (0),
+    min_in_ec_ (INT_MAX),
+    max_in_ec_ (INT_MIN),
+    sum_in_ec_ (0),
+    min_from_ec_ (INT_MAX),
+    max_from_ec_ (INT_MIN),
+    sum_from_ec_ (0)
 {
 }
 
@@ -148,21 +153,52 @@ Latency_Consumer::push (const RtecEventComm::EventSet &events,
 	  if (measure_jitter_)
 	    {
 	      // @@ TOTAL HACK
-	      ACE_hrtime_t t; // = event_push_time;
-	      ACE_OS::memcpy (&t, &events[i].time_, sizeof (t));
+	      ACE_hrtime_t creation;
+	      ACE_OS::memcpy (&creation, &events[i].creation_time_,
+			      sizeof (creation));
+
+	      ACE_hrtime_t ec_recv;
+	      ACE_OS::memcpy (&ec_recv, &events[i].ec_recv_time_,
+			      sizeof (ec_recv));
+
+	      ACE_hrtime_t ec_send;
+	      ACE_OS::memcpy (&ec_send, &events[i].ec_send_time_,
+			      sizeof (ec_send));
 
-	      const ACE_hrtime_t elapsed = ACE_OS::gethrtime () - t;
+	      const ACE_hrtime_t now = ACE_OS::gethrtime ();
+	      const ACE_hrtime_t elapsed = now - creation;
 	      // Note: the division by 1 provides transparent support of
 	      // ACE_U_LongLong.
 	      ACE_Time_Value latency (elapsed / ACE_ONE_SECOND_IN_NSECS,
 				      (elapsed / 1 % ACE_ONE_SECOND_IN_NSECS) / 1000);
 
+	      const ACE_hrtime_t to_ec_nsecs = ec_recv - creation;
+	      ACE_Time_Value to_ec (to_ec_nsecs / ACE_ONE_SECOND_IN_NSECS,
+				    (to_ec_nsecs / 1 % ACE_ONE_SECOND_IN_NSECS) / 1000);
+	      
+	      const ACE_hrtime_t in_ec_nsecs = ec_send - ec_recv;
+	      ACE_Time_Value in_ec (in_ec_nsecs / ACE_ONE_SECOND_IN_NSECS,
+				    (in_ec_nsecs / 1 % ACE_ONE_SECOND_IN_NSECS) / 1000);
+
+	      const ACE_hrtime_t from_ec_nsecs = now - ec_send;
+	      ACE_Time_Value from_ec (from_ec_nsecs / ACE_ONE_SECOND_IN_NSECS,
+				      (from_ec_nsecs / 1 % ACE_ONE_SECOND_IN_NSECS) / 1000);
+
 	      if (! shutting_down)
 		{
+		  ++total_pushes_;
 		  if (min_latency_ > latency) min_latency_ = latency;
 		  if (max_latency_ < latency) max_latency_ = latency;
 		  total_latency_ += latency;
-		  ++total_pushes_;
+		  if (min_to_ec_ > to_ec) min_to_ec_ = to_ec;
+		  if (max_to_ec_ < to_ec) max_to_ec_ = to_ec;
+		  sum_to_ec_ += to_ec;
+		  if (min_in_ec_ > in_ec) min_in_ec_ = in_ec;
+		  if (max_in_ec_ < in_ec) max_in_ec_ = in_ec;
+		  sum_in_ec_ += in_ec;
+		  if (min_from_ec_ > from_ec) min_from_ec_ = from_ec;
+		  if (max_from_ec_ < from_ec) max_from_ec_ = from_ec;
+		  sum_from_ec_ += from_ec;
 		}
 	    }
 	}
@@ -211,6 +247,40 @@ Latency_Consumer::print_stats () /* const */
                   "%s: Latency in msec (min/max/avg): "
                     "%5.3f/%5.3f/%5.3f\n",
                   entry_point (), lat_min, lat_max, lat_avg));
+
+      double to_ec_min =
+	(min_to_ec_.sec () * 1000000.0 + min_to_ec_.usec ()) / 1000.0;
+      double to_ec_max =
+	(max_to_ec_.sec () * 1000000.0 + max_to_ec_.usec ()) / 1000.0;
+      double to_ec_avg = 
+        (sum_to_ec_.sec () * 1000000.0 + sum_to_ec_.usec ()) / total_pushes_ / 1000.0;
+      ACE_DEBUG ((LM_TRACE,
+                  "%s: From test to EC (min/max/avg): "
+		  "%5.3f/%5.3f/%5.3f\n",
+                  entry_point (), to_ec_min, to_ec_max, to_ec_avg));
+
+      double in_ec_min =
+	(min_in_ec_.sec () * 1000000.0 + min_in_ec_.usec ()) / 1000.0;
+      double in_ec_max =
+	(max_in_ec_.sec () * 1000000.0 + max_in_ec_.usec ()) / 1000.0;
+      double in_ec_avg = 
+        (sum_in_ec_.sec () * 1000000.0 + sum_in_ec_.usec ()) / total_pushes_ / 1000.0;
+      ACE_DEBUG ((LM_TRACE,
+                  "%s: In the EC (min/max/avg): "
+		  "%5.3f/%5.3f/%5.3f\n",
+                  entry_point (), in_ec_min, in_ec_max, in_ec_avg));
+
+      double from_ec_min =
+	(min_from_ec_.sec () * 1000000.0 + min_from_ec_.usec ()) / 1000.0;
+      double from_ec_max =
+	(max_from_ec_.sec () * 1000000.0 + max_from_ec_.usec ()) / 1000.0;
+      double from_ec_avg = 
+        (sum_from_ec_.sec () * 1000000.0 + sum_from_ec_.usec ()) / total_pushes_ / 1000.0;
+      ACE_DEBUG ((LM_TRACE,
+                  "%s: From EC to test (min/max/avg): "
+		  "%5.3f/%5.3f/%5.3f\n",
+                  entry_point (), from_ec_min, from_ec_max, from_ec_avg));
+
     }
 }
 
@@ -421,7 +491,8 @@ Latency_Supplier::push (const RtecEventComm::EventSet &events,
 	      // @@ TOTAL HACK
 	      // event_push_time = ACE_OS::gethrtime ();
 	      ACE_hrtime_t t = ACE_OS::gethrtime ();
-	      ACE_OS::memcpy (&event.time_, &t, sizeof (event.time_));
+	      ACE_OS::memcpy (&event.creation_time_, &t,
+			      sizeof (event.creation_time_));
 	    }
 
 	  // @@ ACE_TIMEPROBE_RESET;
@@ -718,7 +789,7 @@ main (int argc, char *argv [])
         CosNaming::NamingContext::_narrow (objref, ACE_TRY_ENV);
       ACE_CHECK_ENV;
 
-      ACE_Scheduler_Factory::use_config (naming_context);
+      ACE_Scheduler_Factory::use_config (naming_context.ptr ());
 
       // Allocate the timeprobe instance now, so we don't measure
       // the cost of doing it later.
@@ -750,7 +821,7 @@ main (int argc, char *argv [])
 	  sprintf (supplier_name, "supplier-%d", i+1);
 	  // Only the first supplier timestamps its messages.
 	  int master = (i==0);
-	  if (supplier [i]->open_supplier (ec,
+	  if (supplier [i]->open_supplier (ec.ptr (),
 					   supplier_name,
 					   master) == -1)
 	    ACE_ERROR_RETURN ((LM_ERROR, "Supplier open failed.\n"), -1);
@@ -765,7 +836,7 @@ main (int argc, char *argv [])
 	  char buf [BUFSIZ];
 	  sprintf (buf, "consumer-%d", i+1);
 
-	  if (consumer [i]->open_consumer (ec, buf) == -1)
+	  if (consumer [i]->open_consumer (ec.ptr (), buf) == -1)
 	    ACE_ERROR_RETURN ((LM_ERROR, "Someone was feeling introverted.\n"),
 			      -1);
 	}
diff --git a/TAO/local/tests/Latency.h b/TAO/local/tests/Latency.h
index 275da3af55b..e9384715a32 100644
--- a/TAO/local/tests/Latency.h
+++ b/TAO/local/tests/Latency.h
@@ -81,6 +81,22 @@ private:
   u_long total_pushes_;
   // Registers and counters for keeping track of latency statistics.
 
+  ACE_Time_Value min_to_ec_;
+  ACE_Time_Value max_to_ec_;
+  ACE_Time_Value sum_to_ec_;
+  // Statitics on time to get to the EC.
+
+  ACE_Time_Value min_in_ec_;
+  ACE_Time_Value max_in_ec_;
+  ACE_Time_Value sum_in_ec_;
+  // Statitics on time spent in the EC.
+
+  ACE_Time_Value min_from_ec_;
+  ACE_Time_Value max_from_ec_;
+  ACE_Time_Value sum_from_ec_;
+  // Statitics on time spent since the EC put the event on the wire
+  // and it gets here.
+
   ACE_CString entry_point_;
 };