ChangeLogTag:Mon Sep 25 17:09:58 UTC 2006 Edward R. Mulholland <emulholl@atl.lmco.com>

6 files changed, 167 insertions, 49 deletions

diff --git a/TAO/ChangeLog b/TAO/ChangeLog
index f1aa361c7af..650d9e20c5b 100644
--- a/TAO/ChangeLog
+++ b/TAO/ChangeLog
@@ -1,3 +1,17 @@
+Mon Sep 25 17:09:58 UTC 2006  Edward R. Mulholland  <emulholl@atl.lmco.com>
+
+        * tests/Timeout/client.cpp:
+        * tests/Timeout/run_test.pl:
+        * tests/Timeout/test_i.cpp:
+        * tests/Timeout/README.expected_behavior:
+        * tests/Timeout/README:
+
+          Made relatively modest changes to track statistics on per type
+          of timeout.  Also added a file README.expected_behavior that
+          carefully describes the timeout behavior that we should observe
+          on a proper real-time platform.  Please address comments and
+          questions to Gautam Thaker <gthaker@atl.lmco.com>.
+
 Fri Sep 22 21:29:26 UTC 2006  Jeff Parsons <j.parsons@vanderbilt.edu>
 
         * tao/DynamicAny/DynAnyFactory.h:
diff --git a/TAO/tests/Timeout/README b/TAO/tests/Timeout/README
index 4528b52fdcd..b8a5bee950b 100644
--- a/TAO/tests/Timeout/README
+++ b/TAO/tests/Timeout/README
@@ -1,16 +1,19 @@
 # $Id$
 
-	A simple test for timeouts.  The client sets each one of the
+        A simple test for timeouts.  The client sets each one of the
 policy overrides (object, thread and ORB) and issues requests using
 those policies.  The requests take a client controlled amount of time
 on the server.
 
-	As the client increases the duration of the request the
+        As the client increases the duration of the request the
 requests should start to timeout.
 
-	To run it do:
+Please see the file README.expected_behavior for a more detailed
+description of what to expect and what has been observed on real-time Linux and non real-time Linux operating systems.
+
+        To run it do:
 
 $ server -o test.ior
 $ client -k file://test.ior -l 5 -h 15
 
-	or use the run_test.pl script.
+        or use the run_test.pl script.
diff --git a/TAO/tests/Timeout/README.expected_behavior b/TAO/tests/Timeout/README.expected_behavior
new file mode 100644
index 00000000000..0b2c8fa6586
--- /dev/null
+++ b/TAO/tests/Timeout/README.expected_behavior
@@ -0,0 +1,59 @@
+# $Id$
+
+This note documents results of my attempts to very carefully examine
+behaviour of Timeouts in TAO on real-time OS (such as Linux with RT
+patches) and to obtain a precise understand of behavior of timeouts.
+
+
+I would like to document expected  behavior precisely for each types of
+timeouts.
+
+I tested with min_timeout = 20msec  and max_timout = 40 msec.  This gives:
+
+
+      TimeBase::TimeT mid_value =
+        // convert from msec to "TimeT" (0.1 usec units)
+        10000 * (min_timeout + max_timeout) / 2;
+      CORBA::Any any_orb;
+      any_orb <<= mid_value;            // 30 msec
+      CORBA::Any any_thread;
+      any_thread <<= mid_value + 10000; // midvalue + 1 msec = 31 msec
+      CORBA::Any any_object;
+      any_object <<= mid_value + 20000; // midvalue + 2 msec = 32 msec
+
+Given this, exactly how many timeout at the ORB, thread, and object
+level should I expect to observe?
+
+If we assume communications to take some small delta_t value as compared
+to 20-40msec intervals, I am expecting:
+
+ 0 out of 21 timeouts with no     TIMEOUT policy
+10 out of 20 timeouts with ORB    TIMEOUT policy = 30 msec
+ 9 out of 20 timeouts with Thread TIMEOUT policy = 31 msec
+ 8 out of 20 timeouts with object TIMEOUT policy = 32 msec
+
+There are 21 calls with "no timeout" rather than 20 due to the extra
+call to the server at the end just before the call to "shutdown" method.
+
+This results in a total of 27 timeouts and 54 w/o timeouts.
+
+Running this on Linux kernel 2.6.14Uniproc PREEMPT (Ingo Molnar patches)
+the actual values match precisely. (The client.cpp is modified to track
+each type of invocation separately.)
+
+in_time_count[none]=    21  timeout_count[none]=    0
+in_time_count[orb]=     10  timeout_count[orb]=     10
+in_time_count[thread]=  11  timeout_count[thread]=  9
+in_time_count[object]=  12  timeout_count[object]=  8
+
+For a total of 27 timeouts and 54 w/o timeouts.
+
+However, when I run the test of Linux 2.4.21-37.EL I observe
+
+12 timeouts and 69 w/o timeout, since this is a non RT kernel. Thus,
+please be aware of this issue when this test is run.
+
+Gautam H. Thaker
+Lockheed Martin Advanced Technology Labs
+gthaker@atl.lmco.com
+May 2006
diff --git a/TAO/tests/Timeout/client.cpp b/TAO/tests/Timeout/client.cpp
index 7d0ff876ea7..0a0748e1cd5 100644
--- a/TAO/tests/Timeout/client.cpp
+++ b/TAO/tests/Timeout/client.cpp
@@ -44,15 +44,18 @@ parse_args (int argc, char *argv[])
                            argv [0]),
                           -1);
       }
-  // Indicates sucessful parsing of the command line
+  // Indicates successful parsing of the command line
   return 0;
 }
 
-static int timeout_count = 0;
-static int in_time_count = 0;
+enum TO_TYPE {none = 0, orb1 = 1, thread1 = 2, object1 = 3};
+char *to_type_names[4] ={"none", "orb", "thread", "object"};
+
+static int timeout_count[4] = {0, 0, 0, 0};
+static int in_time_count[4] = {0, 0, 0, 0};
 
 void
-send_echo (CORBA::ORB_ptr orb,
+send_echo (TO_TYPE ctype, CORBA::ORB_ptr orb,
            Simple_Server_ptr server,
            CORBA::Long t
            ACE_ENV_ARG_DECL)
@@ -62,19 +65,19 @@ send_echo (CORBA::ORB_ptr orb,
       server->echo (0, t ACE_ENV_ARG_PARAMETER);
       ACE_TRY_CHECK;
 
-      in_time_count++;
+      in_time_count[ctype]++;
     }
   ACE_CATCH (CORBA::TIMEOUT, timeout)
     {
-      timeout_count++;
+      timeout_count[ctype]++;
 
       // Trap this exception and continue...
-      // ACE_DEBUG ((LM_DEBUG,
-      //             "==> Trapped a TIMEOUT exception (expected)\n"));
+      ACE_DEBUG ((LM_DEBUG,
+                  "==> Trapped a TIMEOUT exception (expected)\n"));
 
       // Sleep so the server can send the reply...
-      ACE_Time_Value tv (max_timeout / 1000,
-                         (max_timeout % 1000) * 1000);
+      ACE_Time_Value tv (max_timeout / 1000, // max_timeout is in msec, so get seconds
+                         (max_timeout % 1000) * 1000); // and usec
 
       // This is a non-standard TAO call that's used to give the
       // client ORB a chance to cleanup the reply that's come back
@@ -132,14 +135,14 @@ int main (int argc, char* argv[])
       ACE_TRY_CHECK;
 
       TimeBase::TimeT mid_value =
-        10000 * (min_timeout + max_timeout) / 2;
+        10000 * (min_timeout + max_timeout) / 2; // convert from msec to "TimeT" (0.1 usec units)
 
       CORBA::Any any_orb;
       any_orb <<= mid_value;
       CORBA::Any any_thread;
-      any_thread <<= mid_value + 10000;
+      any_thread <<= mid_value + 10000; // midvalue + 1 msec
       CORBA::Any any_object;
-      any_object <<= mid_value + 20000;
+      any_object <<= mid_value + 20000; // midvalue + 2 msec
 
       CORBA::PolicyList policy_list (1);
       policy_list.length (1);
@@ -166,14 +169,14 @@ int main (int argc, char* argv[])
                   "client (%P) testing from %d to %d milliseconds\n",
                   min_timeout, max_timeout));
 
-      for (CORBA::Long t = min_timeout; t != max_timeout; ++t)
-        {
-          //ACE_DEBUG ((LM_DEBUG,
-          //            "\n================================\n"
-          //            "Trying with timeout = %d\n", t));
+      for (CORBA::Long t = min_timeout; t < max_timeout; ++t)
+       {
+         ACE_DEBUG ((LM_DEBUG,
+                     "\n================================\n"
+                     "Trying with timeout = %d msec\n", t));
 
-          // ACE_DEBUG ((LM_DEBUG,
-          //            "Cleanup ORB/Thread/Object policies\n"));
+         ACE_DEBUG ((LM_DEBUG,
+                     "Cleanup ORB/Thread/Object policies\n"));
 
           policy_list.length (0);
           policy_manager->set_policy_overrides (policy_list,
@@ -185,11 +188,14 @@ int main (int argc, char* argv[])
                                                 ACE_ENV_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
-          send_echo (orb.in (), server.in (), t ACE_ENV_ARG_PARAMETER);
+          send_echo (none, orb.in (), server.in (), t ACE_ENV_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
-          // ACE_DEBUG ((LM_DEBUG,
-          //             "client(%P) Set the ORB policies\n"));
+
+
+
+          ACE_DEBUG ((LM_DEBUG,
+                      "client(%P) Set the ORB policies\n"));
 
           policy_list.length (1);
           policy_list[0] =
@@ -203,14 +209,20 @@ int main (int argc, char* argv[])
                                                 ACE_ENV_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
-          send_echo (orb.in (), server.in (), t ACE_ENV_ARG_PARAMETER);
+          send_echo (orb1, orb.in (), server.in (), t ACE_ENV_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
           policy_list[0]->destroy (ACE_ENV_SINGLE_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
-          // ACE_DEBUG ((LM_DEBUG,
-          //             "client(%P) Set the thread policies\n"));
+
+
+
+
+
+
+          ACE_DEBUG ((LM_DEBUG,
+                      "client(%P) Set the thread policies\n"));
 
           policy_list.length (1);
           policy_list[0] =
@@ -224,21 +236,27 @@ int main (int argc, char* argv[])
                                                 ACE_ENV_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
-          send_echo (orb.in (), server.in (), t ACE_ENV_ARG_PARAMETER);
+          send_echo (thread1, orb.in (), server.in (), t ACE_ENV_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
           policy_list[0]->destroy (ACE_ENV_SINGLE_ARG_PARAMETER);
           ACE_TRY_CHECK;
 
-          // ACE_DEBUG ((LM_DEBUG,
-          //            "client(%P) Use the object policies\n"));
-          send_echo (orb.in (), timeout_server.in (), t ACE_ENV_ARG_PARAMETER);
+
+
+
+
+
+
+          ACE_DEBUG ((LM_DEBUG,
+                      "client(%P) Use the object policies\n"));
+          send_echo (object1, orb.in (), timeout_server.in (), t ACE_ENV_ARG_PARAMETER);
           ACE_TRY_CHECK;
         }
 
-      // ACE_DEBUG ((LM_DEBUG,
-      //             "\n\n\nclient(%P) Test completed, "
-      //             "resynch with server\n"));
+      ACE_DEBUG ((LM_DEBUG,
+                  "\n\n\nclient(%P) Test completed, "
+                  "resynch with server\n"));
       policy_list.length (0);
       policy_manager->set_policy_overrides (policy_list,
                                             CORBA::SET_OVERRIDE
@@ -249,22 +267,32 @@ int main (int argc, char* argv[])
                                             ACE_ENV_ARG_PARAMETER);
       ACE_TRY_CHECK;
 
-      send_echo (orb.in (), server.in (), 0 ACE_ENV_ARG_PARAMETER);
+      send_echo (none, orb.in (), server.in (), 0 ACE_ENV_ARG_PARAMETER);
       ACE_TRY_CHECK;
 
       server->shutdown (ACE_ENV_SINGLE_ARG_PARAMETER);
       ACE_TRY_CHECK;
 
-      if (timeout_count == 0)
+      int timeout_count_total = 0;
+      int in_time_count_total = 0;
+      for (int i = 0; i < 4; i++) {
+        timeout_count_total += timeout_count[i];
+        in_time_count_total += in_time_count[i];
+        ACE_DEBUG ((LM_DEBUG, "in_time_count[%s]= %d timeout_count[%s]= %d\n",
+                    to_type_names[i], in_time_count[i],
+                    to_type_names[i], timeout_count[i]));
+      }
+
+      if (timeout_count_total == 0)
         ACE_ERROR ((LM_ERROR,
-                    "ERROR: No messaged timed out\n"));
+                    "ERROR: No messages timed out\n"));
 
-      if (in_time_count == 0)
+      if (in_time_count_total == 0)
         ACE_ERROR ((LM_ERROR,
-                    "ERROR: No messages on time\n"));
+                    "ERROR: No messages on time (within time limit)\n"));
 
-      ACE_DEBUG ((LM_DEBUG, "In time = %d, timed out = %d\n",
-                  in_time_count, timeout_count));
+      ACE_DEBUG ((LM_DEBUG, "in_time_count_total = %d, timeout_count_total = %d\n",
+                  in_time_count_total, timeout_count_total));
 
       orb->destroy (ACE_ENV_SINGLE_ARG_PARAMETER);
       ACE_TRY_CHECK;
diff --git a/TAO/tests/Timeout/run_test.pl b/TAO/tests/Timeout/run_test.pl
index 4cffcf35568..5e7238864fe 100755
--- a/TAO/tests/Timeout/run_test.pl
+++ b/TAO/tests/Timeout/run_test.pl
@@ -19,13 +19,15 @@ if (PerlACE::is_vxworks_test()) {
 else {
     $SV = new PerlACE::Process ("server", "-o $iorfile");
 }
-$CL = new PerlACE::Process ("client", "-ORBDebugLevel 0 -k file://$iorfile -l 2 -h 28");
+$CL = new PerlACE::Process ("client", "-ORBDebugLevel 0 -k file://$iorfile -l 20 -h 40");
 
 
 $SV->Spawn ();
 
+# if (PerlACE::waitforfile_timed ($iorfile,
+#                         $PerlACE::wait_interval_for_process_creation) == -1) {
 if (PerlACE::waitforfile_timed ($iorfile,
-                        $PerlACE::wait_interval_for_process_creation) == -1) {
+                        10) == -1) { # wait for 10 seconds
     print STDERR "ERROR: cannot find file <$iorfile>\n";
     $SV->Kill ();
     exit 1;
diff --git a/TAO/tests/Timeout/test_i.cpp b/TAO/tests/Timeout/test_i.cpp
index 00d5ddfd698..d145a925fd4 100644
--- a/TAO/tests/Timeout/test_i.cpp
+++ b/TAO/tests/Timeout/test_i.cpp
@@ -2,13 +2,17 @@
 
 #include "test_i.h"
 #include "ace/OS_NS_unistd.h"
+#include "ace/High_Res_Timer.h"
 
 ACE_RCSID(Timeout, test_i, "$Id$")
 
+ACE_High_Res_Timer sleep_duration;
+
+
 Simple_Server_i::Simple_Server_i (CORBA::ORB_ptr orb)
   : orb_ (CORBA::ORB::_duplicate (orb))
 {
-
+  sleep_duration.calibrate();
 }
 
 CORBA::Long
@@ -19,9 +23,17 @@ Simple_Server_i::echo (CORBA::Long x,
 {
   ACE_Time_Value tv (msecs / 1000, (msecs % 1000) * 1000);
 
-  // ACE_DEBUG ((LM_DEBUG, "server (%P) Sleeping for %d msecs\n",
-  //             tv.msec ()));
+  ACE_DEBUG ((LM_DEBUG, "server (%P) will request sleep for %d sec and %d msecs.\n",
+              tv.sec(), tv.msec ()));
+
+  sleep_duration.reset();
+  sleep_duration.start();
   ACE_OS::sleep (tv);
+  sleep_duration.stop();
+  ACE_hrtime_t usec;
+  sleep_duration.elapsed_microseconds(usec);
+  ACE_DEBUG ((LM_DEBUG, "server (%P) actually slept for %d sec and %d msecs.\n",
+              usec/1000000, (usec % 1000000)/1000));
 
   return x;
 }