Update timing tests to be robust.

In the new approach the host controls the device activity when the test
should start, finish and pass/fail status is send to device. Also deprecate
the test cases which can't accurately test.

TESTS/host_tests/timing_drift_auto.py

@@ -16,91 +16,125 @@ limitations under the License.
 """
 
 from mbed_host_tests import BaseHostTest
+import time
 
 
-class TimingDriftTest(BaseHostTest):
+class TimingDriftSync(BaseHostTest):
-    """ This test is reading single characters from stdio
+    """
-        and measures time between their occurrences.
+    This works as master-slave fashion
+    1) Device says its booted up and ready to run the test, wait for host to respond
+    2) Host sends the message to get the device current time i.e base time
+
+    #
+    # *
+    #   *                   |
+    #<---* DUT<- base_time  | - round_trip_base_time ------
+    #   *                   |                              |
+    # *                    -                               |
+    #                      -                               |
+    #                       |                              |
+    #                       |                              |
+    #                       | - measurement_stretch        | - nominal_time
+    #                       |                              |
+    #                       |                              |
+    #                      -                               |
+    # *                    -                               |
+    #   *                   |                              |
+    #<---* DUT <-final_time | - round_trip_final_time------
+    #   *                   |
+    # *                    -
+    #
+    #
+    # As we increase the measurement_stretch, the error because of transport delay diminishes.
+    # The values of measurement_stretch is propotional to round_trip_base_time(transport delays)
+    # by factor time_measurement_multiplier.This multiplier is used is 80 to tolerate 2 sec of
+    # transport delay and test time ~ 180 secs
+    #
+    # Failure in timing can occur if we are ticking too fast or we are ticking too slow, hence we have
+    # min_range and max_range. if we cross on either side tests would be marked fail. The range is a function of
+    # tolerance/acceptable drift currently its 5%.
+    #
+
     """
     __result = None
+    mega = 1000000.0
+    max_measurement_time = 180
 
-    # This is calculated later: average_drift_max * number of tick events
+    # this value is obtained for measurements when there is 0 transport delay and we want accurancy of 5%
-    total_drift_max = None
+    time_measurement_multiplier = 80
 
-    average_drift_max = 0.05
+    def _callback_timing_drift_check_start(self, key, value, timestamp):
-    ticks = []
+        self.round_trip_base_start = timestamp
-    start_time = None
+        self.send_kv("base_time", 0)
-    finish_time = None
-    dut_seconds_passed = None
-    total_time = None
-    total_drift = None
-    average_drift = None
 
-    def _callback_result(self, key, value, timestamp):
+    def _callback_base_time(self, key, value, timestamp):
-        # We should not see result data in this test
+        self.round_trip_base_end = timestamp
-        self.__result = False
+        self.device_time_base = float(value)
+        self.round_trip_base_time = self.round_trip_base_end - self.round_trip_base_start
 
-    def _callback_end(self, key, value, timestamp):
+        self.log("Device base time {}".format(value))
-        """ {{end;%s}}} """
+        measurement_stretch = (self.round_trip_base_time * self.time_measurement_multiplier) + 5
-        self.log("Received end event, timestamp: %f" % timestamp)
-        self.notify_complete(result=self.result(print_stats=True))
 
+        if measurement_stretch > self.max_measurement_time:
+            self.log("Time required {} to determine device timer is too high due to transport delay, skipping".format(measurement_stretch))
+        else:
+            self.log("sleeping for {} to measure drift accurately".format(measurement_stretch))
+            time.sleep(measurement_stretch)
+        self.round_trip_final_start = time.time()
+        self.send_kv("final_time", 0)
 
-    def _callback_tick(self, key, value, timestamp):
+    def _callback_final_time(self, key, value, timestamp):
-        """ {{tick;%d}}} """
+        self.round_trip_final_end = timestamp
-        self.log("tick! %f" % timestamp)
+        self.device_time_final = float(value)
-        self.ticks.append((key, value, timestamp))
+        self.round_trip_final_time = self.round_trip_final_end - self.round_trip_final_start
+        self.log("Device final time {} ".format(value))
 
+        # compute the test results and send to device
+        results = "pass" if self.compute_parameter() else "fail"
+        self.send_kv(results, "0")
 
     def setup(self):
-        self.register_callback("end", self._callback_end)
+        self.register_callback('timing_drift_check_start', self._callback_timing_drift_check_start)
-        self.register_callback('tick', self._callback_tick)
+        self.register_callback('base_time', self._callback_base_time)
+        self.register_callback('final_time', self._callback_final_time)
 
+    def compute_parameter(self, failure_criteria=0.05):
+        nominal_time = (self.round_trip_final_start + self.round_trip_final_end) / 2.0 - (self.round_trip_base_start + self.round_trip_base_end) / 2.0
+        transport_error = self.round_trip_final_time / 2.0 + self.round_trip_base_time / 2.0
 
-    def result(self, print_stats=True):        
+        min_range = nominal_time * (1 - failure_criteria)
-        self.dut_seconds_passed = len(self.ticks) - 1
+        max_range = nominal_time * (1 + failure_criteria)
 
-        if self.dut_seconds_passed < 1:
+        device_time = (self.device_time_final - self.device_time_base) / self.mega
-            if print_stats:
-                self.log("FAIL: failed to receive at least two tick events")
-            self.__result = False
-            return self.__result
 
-        self.total_drift_max = self.dut_seconds_passed * self.average_drift_max
+        min_pass_value = (device_time - transport_error)
+        max_pass_value = (device_time + transport_error)
 
-        self.start_time = self.ticks[0][2]
+        self.log("Compute host events")
-        self.finish_time = self.ticks[-1][2]
+        self.log("Transport delay 0: {}".format(self.round_trip_base_time))
-        self.total_time = self.finish_time - self.start_time
+        self.log("Transport delay 1: {}".format(self.round_trip_final_time))
-        self.total_drift = self.total_time - self.dut_seconds_passed
+        self.log("Transport dealy avg : {} ".format(transport_error))
-        self.average_drift = self.total_drift / self.dut_seconds_passed
+        self.log("DUT base time : {}".format(self.device_time_base))
+        self.log("DUT end time  : {}".format(self.device_time_final))
+        self.log("Actual Time : {}".format(device_time))
+        self.log("Nominal Time : {}".format(nominal_time))
 
-        if print_stats:
+        self.log("min_pass : {} , max_pass : {}".format(min_pass_value, max_pass_value))
-            self.log("Start: %f" % self.start_time)
+        self.log("min_range : {} , max_range : {}".format(min_range, max_range))
-            self.log("Finish: %f" % self.finish_time)
-            self.log("Total time taken: %f" % self.total_time)
 
-            total_drift_ratio_string = "Total drift/Max total drift: %f/%f"
+        if (min_pass_value >= min_range) and (max_pass_value <= max_range):
-            self.log(total_drift_ratio_string % (self.total_drift,
+            self.log("Test passed !!!")
-                                                 self.total_drift_max))
+            self.__result = True
-                                                 
+        elif (min_pass_value > max_range) or (max_pass_value < min_pass_value):
-            average_drift_ratio_string = "Average drift/Max average drift: %f/%f"
+            self.log("Time outside of passing range. Timing drift seems to be present !!!")
-            self.log(average_drift_ratio_string % (self.average_drift,
-                                                   self.average_drift_max))
-        
-
-        if abs(self.total_drift) > self.total_drift_max:
-            if print_stats:
-                self.log("FAIL: Total drift exceeded max total drift")
-            self.__result = False
-        elif self.average_drift > self.average_drift_max:
-            if print_stats:
-                self.log("FAIL: Average drift exceeded max average drift")
             self.__result = False
         else:
-            self.__result = True
+            self.log("Test inconclusive due to transport delay, retrying")
-        
+            self.__result = False
         return self.__result
 
+    def result(self):
+        return self.__result
 
     def teardown(self):
         pass

TESTS/mbed_drivers/ticker/main.cpp

@@ -14,13 +14,31 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+
+
+/*
+ * Tests is to measure the accuracy of Ticker over a period of time
+ *
+ *
+ * 1) DUT would start to update callback_trigger_count every milli sec, in 2x callback we use 2 tickers
+ *    to update the count alternatively.
+ * 2) Host would query what is current count base_time, Device responds by the callback_trigger_count
+ * 3) Host after waiting for measurement stretch. It will query for device time again final_time.
+ * 4) Host computes the drift considering base_time, final_time, transport delay and measurement stretch
+ * 5) Finally host send the results back to device pass/fail based on tolerance.
+ * 6) More details on tests can be found in timing_drift_auto.py
+ */
+
 #include "mbed.h"
 #include "greentea-client/test_env.h"
 #include "utest/utest.h"
+#include "unity/unity.h"
 
 using namespace utest::v1;
 
-static const int ONE_SECOND_MS = 1000;
+#define ONE_MILLI_SEC 1000
+volatile uint32_t callback_trigger_count = 0;
+static const int test_timeout = 240;
 static const int total_ticks = 10;
 
 DigitalOut led1(LED1);
@@ -32,49 +50,33 @@ Ticker *ticker2;
 volatile int ticker_count = 0;
 volatile bool print_tick = false;
 
-void send_kv_tick() {
+void ticker_callback_1_switch_to_2(void);
-    if (ticker_count <= total_ticks) {
+void ticker_callback_2_switch_to_1(void);
-        print_tick = true;
-    }
-}
 
 void ticker_callback_0(void) {
-    static int fast_ticker_count = 0;
+    ++callback_trigger_count;
-    if (fast_ticker_count >= ONE_SECOND_MS) {
-        send_kv_tick();
-        fast_ticker_count = 0;
-        led1 = !led1;
-    }
-    fast_ticker_count++;
 }
 
-void ticker_callback_1(void) {
+void ticker_callback_1_led(void) {
     led1 = !led1;
-    send_kv_tick();
 }
 
 void ticker_callback_2_led(void) {
     led2 = !led2;
 }
 
-void ticker_callback_2(void) {
-    ticker_callback_2_led();
-    send_kv_tick();
-}
-
-void ticker_callback_1_switch_to_2(void);
-void ticker_callback_2_switch_to_1(void);
-
 void ticker_callback_1_switch_to_2(void) {
+    ++callback_trigger_count;
     ticker1->detach();
-    ticker1->attach(ticker_callback_2_switch_to_1, 1.0);
+    ticker1->attach_us(ticker_callback_2_switch_to_1, ONE_MILLI_SEC);
-    ticker_callback_1();
+    ticker_callback_1_led();
 }
 
 void ticker_callback_2_switch_to_1(void) {
+    ++callback_trigger_count;
     ticker2->detach();
-    ticker2->attach(ticker_callback_1_switch_to_2, 1.0);
+    ticker2->attach_us(ticker_callback_1_switch_to_2, ONE_MILLI_SEC);
-    ticker_callback_2();
+    ticker_callback_2_led();
 }
 
 void wait_and_print() {
@@ -87,28 +89,54 @@ void wait_and_print() {
 }
 
 void test_case_1x_ticker() {
-    led1 = 0;
-    led2 = 0;
-    ticker_count = 0;
-    ticker1->attach_us(ticker_callback_0, ONE_SECOND_MS);
-    wait_and_print();
-}
 
-void test_case_2x_ticker() {
+    char _key[11] = { };
-    led1 = 0;
+    char _value[128] = { };
-    led2 = 0;
+    uint8_t results_size = 0;
-    ticker_count = 0;
+
-    ticker1->attach(&ticker_callback_1, 1.0);
+    greentea_send_kv("timing_drift_check_start", 0);
-    ticker2->attach(&ticker_callback_2_led, 2.0);
+    ticker1->attach_us(&ticker_callback_0, ONE_MILLI_SEC);
-    wait_and_print();
+
+    // wait for 1st signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    // wait for 2nd signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    //get the results from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+
+    TEST_ASSERT_EQUAL_STRING_MESSAGE("pass", _key,"Host side script reported a fail...");
+
 }
 
 void test_case_2x_callbacks() {
+    char _key[11] = { };
+    char _value[128] = { };
+    uint8_t results_size = 0;
+
     led1 = 0;
     led2 = 0;
-    ticker_count = 0;
+    callback_trigger_count = 0;
-    ticker1->attach(ticker_callback_1_switch_to_2, 1.0);
+
-    wait_and_print();
+    greentea_send_kv("timing_drift_check_start", 0);
+    ticker1->attach_us(ticker_callback_1_switch_to_2, ONE_MILLI_SEC);
+
+    // wait for 1st signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    // wait for 2nd signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    //get the results from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+
+    TEST_ASSERT_EQUAL_STRING_MESSAGE("pass", _key,"Host side script reported a fail...");
+
 }
 
 utest::v1::status_t one_ticker_case_setup_handler_t(const Case *const source, const size_t index_of_case) {
@@ -136,16 +164,16 @@ utest::v1::status_t two_ticker_case_teardown_handler_t(const Case *const source,
 // Test cases
 Case cases[] = {
     Case("Timers: 1x ticker", one_ticker_case_setup_handler_t,test_case_1x_ticker, one_ticker_case_teardown_handler_t),
-    Case("Timers: 2x tickers", two_ticker_case_setup_handler_t, test_case_2x_ticker, two_ticker_case_teardown_handler_t),
     Case("Timers: 2x callbacks", two_ticker_case_setup_handler_t,test_case_2x_callbacks, two_ticker_case_teardown_handler_t),
 };
 
 utest::v1::status_t greentea_test_setup(const size_t number_of_cases) {
-    GREENTEA_SETUP((total_ticks + 5) * 3, "timing_drift_auto");
+    GREENTEA_SETUP(test_timeout, "timing_drift_auto");
     return greentea_test_setup_handler(number_of_cases);
 }
 
-Specification specification(greentea_test_setup, cases, greentea_test_teardown_handler);
+Specification specification(greentea_test_setup, cases,
+        greentea_test_teardown_handler);
 
 int main() {
     Harness::run(specification);

TESTS/mbed_drivers/timeout/main.cpp

@@ -14,54 +14,75 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+
+
+/*
+ * Tests is to measure the accuracy of Timeout over a period of time
+ *
+ *
+ * 1) DUT would start to update callback_trigger_count every milli sec
+ * 2) Host would query what is current count base_time, Device responds by the callback_trigger_count
+ * 3) Host after waiting for measurement stretch. It will query for device time again final_time.
+ * 4) Host computes the drift considering base_time, final_time, transport delay and measurement stretch
+ * 5) Finally host send the results back to device pass/fail based on tolerance.
+ * 6) More details on tests can be found in timing_drift_auto.py
+ *
+ */
+
 #include "mbed.h"
 #include "greentea-client/test_env.h"
 #include "utest/utest.h"
+#include "unity/unity.h"
+#include "strings.h"
 
 using namespace utest::v1;
 
-Timeout timeout;
+#define ONE_MILLI_SEC 1000
-DigitalOut led(LED1);
+
 volatile int ticker_count = 0;
-volatile bool print_tick = false;
+volatile uint32_t callback_trigger_count = 0;
-static const int total_ticks = 10;
+static const int test_timeout = 240;
-const int ONE_SECOND_US = 1000000;
+Timeout timeout;
 
-void send_kv_tick() {
+void set_incremeant_count() {
-    if (ticker_count <= total_ticks) {
+    timeout.attach_us(set_incremeant_count, ONE_MILLI_SEC);
-        timeout.attach_us(send_kv_tick, ONE_SECOND_US);
+    ++callback_trigger_count;
-        print_tick = true;
-    }
 }
 
-void wait_and_print() {
+void test_case_timeout() {
-    while(ticker_count <= total_ticks) {
+
-        if (print_tick) {
+    char _key[11] = { };
-            print_tick = false;
+    char _value[128] = { };
-            greentea_send_kv("tick", ticker_count++);
+    uint8_t results_size = 0;
-            led = !led;
+
-        }
+    greentea_send_kv("timing_drift_check_start", 0);
-    }
+    timeout.attach_us(set_incremeant_count, ONE_MILLI_SEC);
+
+    // wait for 1st signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    // wait for 2nd signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    //get the results from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+
+    TEST_ASSERT_EQUAL_STRING_MESSAGE("pass", _key,"Host side script reported a fail...");
 }
 
-void test_case_ticker() {
+// Test casess
-    timeout.attach_us(send_kv_tick, ONE_SECOND_US);
+Case cases[] = { Case("Timers: toggle on/off", test_case_timeout), };
-    wait_and_print();
-}
-
-// Test cases
-Case cases[] = {
-    Case("Timers: toggle on/off", test_case_ticker),
-};
 
 utest::v1::status_t greentea_test_setup(const size_t number_of_cases) {
-    GREENTEA_SETUP(total_ticks + 5, "timing_drift_auto");
+    GREENTEA_SETUP(test_timeout, "timing_drift_auto");
     return greentea_test_setup_handler(number_of_cases);
 }
 
-Specification specification(greentea_test_setup, cases, greentea_test_teardown_handler);
+Specification specification(greentea_test_setup, cases,
+        greentea_test_teardown_handler);
 
 int main() {
     Harness::run(specification);
 }
-

TESTS/mbedmicro-rtos-mbed/basic/main.cpp

@@ -1,38 +1,89 @@
+/*
+ * Copyright (c) 2013-2017, ARM Limited, All Rights Reserved
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may
+ * not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+
+/*
+ * Tests is to measure the accuracy of Thread::wait() over a period of time
+ *
+ *
+ * 1) DUT would start to update callback_trigger_count every milli sec
+ * 2) Host would query what is current count base_time, Device responds by the callback_trigger_count
+ * 3) Host after waiting for measurement stretch. It will query for device time again final_time.
+ * 4) Host computes the drift considering base_time, final_time, transport delay and measurement stretch
+ * 5) Finally host send the results back to device pass/fail based on tolerance.
+ * 6) More details on tests can be found in timing_drift_auto.py
+ *
+ */
+
 #include "mbed.h"
 #include "greentea-client/test_env.h"
 #include "rtos.h"
+#include "unity/unity.h"
 
 #if defined(MBED_RTOS_SINGLE_THREAD)
 #error [NOT_SUPPORTED] test not supported
 #endif
 
 #define TEST_STACK_SIZE 768
+#define ONE_MILLI_SEC 1000
 
-#define SIGNAL_PRINT_TICK 0x01
+volatile uint32_t callback_trigger_count = 0;
 
-DigitalOut led1(LED1);
+static const int test_timeout = 240;
+bool test_result = false;
 
-const int total_ticks = 10;
+void update_tick_thread() {
-
+    while (true) {
-void print_tick_thread() {
+        Thread::wait(1);
-    for (int i = 0; i <= total_ticks; i++) {
+        ++callback_trigger_count;
-      Thread::signal_wait(SIGNAL_PRINT_TICK);
-      greentea_send_kv("tick", i);
-      led1 = !led1;
     }
 }
 
+void gt_comm_wait_thread() {
+    char _key[11] = { };
+    char _value[128] = { };
+
+    greentea_send_kv("timing_drift_check_start", 0);
+
+    // wait for 1st signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    // wait for 2nd signal from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+    greentea_send_kv(_key, callback_trigger_count * ONE_MILLI_SEC);
+
+    //get the results from host
+    greentea_parse_kv(_key, _value, sizeof(_key), sizeof(_value));
+
+    if (strcmp("pass", _key) == 0) {
+        test_result = true;
+    }
+    TEST_ASSERT_EQUAL_STRING_MESSAGE("pass", _key, "expected host to send pass...");
+}
+
 int main() {
-    GREENTEA_SETUP(total_ticks + 5, "timing_drift_auto");
+    GREENTEA_SETUP(test_timeout, "timing_drift_auto");
+    Thread tick_thread(osPriorityHigh, TEST_STACK_SIZE);
+    Thread gt_conn_thread(osPriorityNormal, TEST_STACK_SIZE);
 
-    Thread tick_thread(osPriorityNormal, TEST_STACK_SIZE);
+    tick_thread.start(update_tick_thread);
-    tick_thread.start(print_tick_thread);
+    gt_conn_thread.start(gt_comm_wait_thread);
+    gt_conn_thread.join();
 
-    for (int i = 0; i <= total_ticks; i++) {
+    GREENTEA_TESTSUITE_RESULT(test_result);
-        Thread::wait(1000);
-        tick_thread.signal_set(SIGNAL_PRINT_TICK);
-    }
-
-    tick_thread.join();
-    GREENTEA_TESTSUITE_RESULT(1);
 }