diff options
author | emulholl <emulholl@ae88bc3d-4319-0410-8dbf-d08b4c9d3795> | 2006-09-25 17:20:36 +0000 |
---|---|---|
committer | emulholl <emulholl@ae88bc3d-4319-0410-8dbf-d08b4c9d3795> | 2006-09-25 17:20:36 +0000 |
commit | 109f5339d6165ff7e51611a7001efa0c31ef4636 (patch) | |
tree | 14acca3c520e72a2fe15ce70a7da38a5e9db57c4 | |
parent | d8c23877a07e448adf58ab3bf5baa4567f8681a5 (diff) | |
download | ATCD-109f5339d6165ff7e51611a7001efa0c31ef4636.tar.gz |
ChangeLogTag:Mon Sep 25 17:09:58 UTC 2006 Edward R. Mulholland <emulholl@atl.lmco.com>
-rw-r--r-- | TAO/ChangeLog | 14 | ||||
-rw-r--r-- | TAO/tests/Timeout/README | 11 | ||||
-rw-r--r-- | TAO/tests/Timeout/README.expected_behavior | 59 | ||||
-rw-r--r-- | TAO/tests/Timeout/client.cpp | 108 | ||||
-rwxr-xr-x | TAO/tests/Timeout/run_test.pl | 6 | ||||
-rw-r--r-- | TAO/tests/Timeout/test_i.cpp | 18 |
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; } |