Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timing tests drift refactor #2588

Merged
merged 6 commits into from
Sep 7, 2016
Merged

Conversation

bridadan
Copy link
Contributor

@bridadan bridadan commented Aug 30, 2016

This PR changes the way we typically do timing tests in the mbed-os tree.

Background

In the past, we've had tests that used the wait_us_auto host test in our testing tools (for reference, this is located here in the htrun tool: https://github.com/ARMmbed/htrun/blob/master/mbed_host_tests/host_tests/wait_us_auto.py)

The way this works is the device prints a key-value pair ({{tick;n}}) that is picked up by wait_us_auto. It logs the timestamp at which it received this data over the serial line. The device never actually stops printing these "tick" events. Instead what happens is the test "times-out", but then the host test determines the result of the test by combing through the "ticks" and measuring the amount of deviation between each event. If any one of these events deviated by more that 0.1 seconds, the test fails.

This approach is susceptible to the host PC being under load, especially if it can't read the serial port fast enough (ex. reliably within 0.1 seconds). This can cause tests to fail when in fact the device was printing the ticks on time.

New approach

This PR changes the approach a little bit. Instead of failing the test if any tick event deviates too much, it instead takes the average deviation and compares that against a maximum (0.05 seconds). It also compares the total time the test took against the following formula:

average_deviation_max * number_tick_events_received > (total_time - number_tick_events_received) / number_tick_events_received

If the above is true in addition to the average deviation being below the maximum, the test passes. This behavior is contained within a new host test called timing_drift_auto.

Changes

  • The test tests-integration-threaded_blinky was removed since it was a near duplicate of tests-mbedmicro-rtos-mbed-basic. It also had a high rate of drift due to the way it was written.
  • tests-mbed_drivers-ticker and tests-mbed_drivers-timeout are no longer printing in ISR context.
  • tests-mbed_drivers-wait_us uses a timer to measure how much longer it should "wait". This reduces the cumulative drift.
  • tests-mbedmicro-rtos-mbed-basic uses a signal now to print in a different thread. This reduces the cumulative drift.
  • All tests should now stop printing after 10 tick events instead of printing forever.
  • The following tests were changed to use the new host test timing_drift_auto:
    • tests-mbed_drivers-ticker
    • tests-mbed_drivers-timeout
    • tests-mbed_drivers-wait_us
    • tests-mbedmicro-rtos-mbed-basic
    • tests-mbedmicro-rtos-mbed-timer

@bridadan
Copy link
Contributor Author

bridadan commented Sep 1, 2016

/morph test

@mbed-bot
Copy link

mbed-bot commented Sep 1, 2016

Result: FAILURE

Your command has finished executing! Here's what you wrote!

/morph test

Output

mbed Build Number: 772

Test failed!

@bridadan
Copy link
Contributor Author

bridadan commented Sep 1, 2016

/morph test

@mbed-bot
Copy link

mbed-bot commented Sep 1, 2016

Result: FAILURE

Your command has finished executing! Here's what you wrote!

/morph test

Output

mbed Build Number: 773

Test failed!

@bridadan
Copy link
Contributor Author

bridadan commented Sep 1, 2016

So good news, bad news, and then more good news:

First good news: No timing test failures! 😄
Only bad news: Windows reset 4 of the boards (All 3 KL46Zs and an NRF52_DK) during the test 3 times
Second good news: We were running a USB logger, and I was able to confirm that the 4 test failures that occurred in this test all happened when those boards were being reset.

We're currently looking into why the boards were reset, but in the meantime these tests seem to indicate that they at least help stabilize the timing tests.

@mazimkhan Could you please sanity-check my changes? Thanks!

@bridadan
Copy link
Contributor Author

bridadan commented Sep 2, 2016

There is actually an issue with the wait_us test, please do not merge yet!

@bridadan
Copy link
Contributor Author

bridadan commented Sep 6, 2016

/morph test

@mbed-bot
Copy link

mbed-bot commented Sep 7, 2016

Result: SUCCESS

Your command has finished executing! Here's what you wrote!

/morph test

Output

mbed Build Number: 777

All builds and test passed!

The timing host tests reported success even if the total drift was
negative. This adds a check for this now.

The wait_us test now does not use a timer and just waits for 100000 us
between prints. This adds inherent drift, but it should still be well
under the limit.
@bridadan
Copy link
Contributor Author

bridadan commented Sep 7, 2016

I had to make one final test with the wait_us test, but that should be all good now. Here's the updated log for the wait_us test:

[1473257598.65][HTST][INF] host test executor ver. 1.1.0
[1473257598.65][HTST][INF] copy image onto target...
[1473257598.65][COPY][INF] Waiting up to 60 sec for '0240000028884e450037700f6bf0000d8021000097969900' mount point (current is 'E:')...
        1 file(s) copied.
[1473257607.40][HTST][INF] starting host test process...
[1473257608.05][CONN][INF] starting connection process...
[1473257608.05][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1473257608.05][CONN][INF] initializing serial port listener...
[1473257608.05][HTST][INF] setting timeout to: 60 sec
[1473257608.05][SERI][INF] serial(port=COM255, baudrate=9600, timeout=0, write_timeout=5)
[1473257608.05][PLGN][INF] Waiting up to 60 sec for '0240000028884e450037700f6bf0000d8021000097969900' serial port (current is 'COM255')...
[1473257608.25][SERI][INF] reset device using 'default' plugin...
[1473257608.50][SERI][INF] waiting 1.00 sec after reset
[1473257609.50][SERI][INF] wait for it...
[1473257609.50][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1473257609.50][CONN][INF] sending up to 2 __sync packets (specified with --sync=2)
[1473257609.50][CONN][INF] sending preamble 'd7ab8720-ee31-4820-a48b-d4c863f8f779'
[1473257609.50][SERI][TXD] {{__sync;d7ab8720-ee31-4820-a48b-d4c863f8f779}}
[1473257609.64][CONN][RXD] {{__sync;d7ab8720-ee31-4820-a48b-d4c863f8f779}}
[1473257609.64][CONN][INF] found SYNC in stream: {{__sync;d7ab8720-ee31-4820-a48b-d4c863f8f779}} it is #0 sent, queued...
[1473257609.64][HTST][INF] sync KV found, uuid=d7ab8720-ee31-4820-a48b-d4c863f8f779, timestamp=1473257609.640000
[1473257609.66][CONN][RXD] {{__version;1.3.0}}
[1473257609.66][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1473257609.68][CONN][RXD] {{__timeout;15}}
[1473257609.68][CONN][INF] found KV pair in stream: {{__timeout;15}}, queued...
[1473257609.68][HTST][INF] DUT greentea-client version: 1.3.0
[1473257609.68][HTST][INF] setting timeout to: 15 sec
[1473257609.72][CONN][RXD] {{__host_test_name;timing_drift_auto}}
[1473257609.72][CONN][INF] found KV pair in stream: {{__host_test_name;timing_drift_auto}}, queued...
[1473257609.73][HTST][INF] host test class: '<class 'timing_drift_auto.TimingDriftTest'>'
[1473257609.73][HTST][INF] host test setup() call...
[1473257609.73][HTST][INF] CALLBACKs updated
[1473257609.73][HTST][INF] host test detected: timing_drift_auto
[1473257609.74][CONN][RXD] {{__testcase_count;1}}
[1473257609.74][CONN][INF] found KV pair in stream: {{__testcase_count;1}}, queued...
[1473257609.77][CONN][RXD] >>> Running 1 test cases...
[1473257609.81][CONN][RXD] {{__testcase_name;Timers: wait_us}}
[1473257609.81][CONN][INF] found KV pair in stream: {{__testcase_name;Timers: wait_us}}, queued...
[1473257609.86][CONN][RXD] >>> Running case #1: 'Timers: wait_us'...
[1473257609.89][CONN][RXD] {{__testcase_start;Timers: wait_us}}
[1473257609.89][CONN][INF] found KV pair in stream: {{__testcase_start;Timers: wait_us}}, queued...
[1473257610.90][CONN][RXD] {{tick;0}}
[1473257610.90][CONN][INF] found KV pair in stream: {{tick;0}}, queued...
[1473257610.90][HTST][INF] tick! 1473257610.902000
[1473257611.91][CONN][RXD] {{tick;1}}
[1473257611.91][CONN][INF] found KV pair in stream: {{tick;1}}, queued...
[1473257611.91][HTST][INF] tick! 1473257611.910000
[1473257612.92][CONN][RXD] {{tick;2}}
[1473257612.92][CONN][INF] found KV pair in stream: {{tick;2}}, queued...
[1473257612.92][HTST][INF] tick! 1473257612.919000
[1473257613.93][CONN][RXD] {{tick;3}}
[1473257613.93][CONN][INF] found KV pair in stream: {{tick;3}}, queued...
[1473257613.93][HTST][INF] tick! 1473257613.928000
[1473257614.93][CONN][RXD] {{tick;4}}
[1473257614.94][CONN][INF] found KV pair in stream: {{tick;4}}, queued...
[1473257614.94][HTST][INF] tick! 1473257614.936000
[1473257615.94][CONN][RXD] {{tick;5}}
[1473257615.94][CONN][INF] found KV pair in stream: {{tick;5}}, queued...
[1473257615.94][HTST][INF] tick! 1473257615.945000
[1473257616.95][CONN][RXD] {{tick;6}}
[1473257616.95][CONN][INF] found KV pair in stream: {{tick;6}}, queued...
[1473257616.95][HTST][INF] tick! 1473257616.953000
[1473257617.96][CONN][RXD] {{tick;7}}
[1473257617.96][CONN][INF] found KV pair in stream: {{tick;7}}, queued...
[1473257617.96][HTST][INF] tick! 1473257617.962000
[1473257618.97][CONN][RXD] {{tick;8}}
[1473257618.97][CONN][INF] found KV pair in stream: {{tick;8}}, queued...
[1473257618.97][HTST][INF] tick! 1473257618.969000
[1473257619.98][CONN][RXD] {{tick;9}}
[1473257619.98][CONN][INF] found KV pair in stream: {{tick;9}}, queued...
[1473257619.98][HTST][INF] tick! 1473257619.978000
[1473257620.99][CONN][RXD] {{tick;10}}
[1473257620.99][CONN][INF] found KV pair in stream: {{tick;10}}, queued...
[1473257620.99][HTST][INF] tick! 1473257620.988000
[1473257621.04][CONN][RXD] {{__testcase_finish;Timers: wait_us;1;0}}
[1473257621.04][CONN][INF] found KV pair in stream: {{__testcase_finish;Timers: wait_us;1;0}}, queued...
[1473257621.09][CONN][RXD] >>> 'Timers: wait_us': 1 passed, 0 failed
[1473257621.13][CONN][RXD] >>> Test cases: 1 passed, 0 failed
[1473257621.14][CONN][RXD] {{max_heap_usage;0}}
[1473257621.14][CONN][INF] found KV pair in stream: {{max_heap_usage;0}}, queued...
[1473257621.14][HTST][ERR] orphan event in main phase: {{max_heap_usage;0}}, timestamp=1473257621.138000
[1473257621.16][CONN][RXD] {{__testcase_summary;1;0}}
[1473257621.16][CONN][INF] found KV pair in stream: {{__testcase_summary;1;0}}, queued...
[1473257621.18][CONN][RXD] {{end;success}}
[1473257621.18][CONN][INF] found KV pair in stream: {{end;success}}, queued...
[1473257621.18][HTST][INF] Received end event, timestamp: 1473257621.179000
[1473257621.18][HTST][INF] Start: 1473257610.902000
[1473257621.18][HTST][INF] Finish: 1473257620.988000
[1473257621.18][HTST][INF] Total time taken: 10.086000
[1473257621.18][HTST][INF] Total drift/Max total drift: 0.086000/0.500000
[1473257621.18][HTST][INF] Average drift/Max average drift: 0.008600/0.050000
[1473257621.18][HTST][INF] __notify_complete(True)
[1473257621.21][CONN][RXD] {{__exit;0}}
[1473257621.21][CONN][INF] found KV pair in stream: {{__exit;0}}, queued...
[1473257621.21][HTST][INF] __exit(0)
[1473257621.21][HTST][INF] __exit_event_queue received
[1473257621.21][HTST][INF] test suite run finished after 11.53 sec...
[1473257621.21][CONN][INF] received special even '__host_test_finished' value='True', finishing
[1473257621.22][HTST][INF] CONN exited with code: 0
[1473257621.22][HTST][INF] No events in queue
[1473257621.22][HTST][INF] stopped consuming events
[1473257621.22][HTST][INF] host test result() call skipped, received: True
[1473257621.22][HTST][INF] calling blocking teardown()
[1473257621.22][HTST][INF] teardown() finished
[1473257621.22][HTST][INF] {{result;success}}
mbedgt: checking for GCOV data...
mbedgt: mbed-host-test-runner: stopped and returned 'OK'
mbedgt: test on hardware with target id: 0240000028884e450037700f6bf0000d8021000097969900
mbedgt: test suite 'tests-mbed_drivers-wait_us' ...................................................... OK in 23.21 sec
        test case: 'Timers: wait_us' ................................................................. OK in 11.15 sec
mbedgt: test case summary: 1 pass, 0 failures
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.5156427567
mbedgt: test suite report:
+--------------+---------------+----------------------------+--------+--------------------+-------------+
| target       | platform_name | test suite                 | result | elapsed_time (sec) | copy_method |
+--------------+---------------+----------------------------+--------+--------------------+-------------+
| K64F-GCC_ARM | K64F          | tests-mbed_drivers-wait_us | OK     | 23.21              | shell       |
+--------------+---------------+----------------------------+--------+--------------------+-------------+
mbedgt: test suite results: 1 OK
mbedgt: test case report:
+--------------+---------------+----------------------------+-----------------+--------+--------+--------+--------------------+
| target       | platform_name | test suite                 | test case       | passed | failed | result | elapsed_time (sec) |
+--------------+---------------+----------------------------+-----------------+--------+--------+--------+--------------------+
| K64F-GCC_ARM | K64F          | tests-mbed_drivers-wait_us | Timers: wait_us | 1      | 0      | OK     | 11.15              |
+--------------+---------------+----------------------------+-----------------+--------+--------+--------+--------------------+
mbedgt: test case results: 1 OK
mbedgt: completed in 23.48 sec

@sg- sg- merged commit 2a2cf25 into ARMmbed:master Sep 7, 2016
theotherjimmy added a commit that referenced this pull request Sep 19, 2016
Release mbed-os-5.1.4

Changes:

New Targets:
2504: [Disco_F769NI] adding new target [#2504]
2654: DELTA_DFBM_NQ620 platform porting [#2654]
2615: [MTM_MTCONNECT04S] Added support for MTM_MTCONNECT04S [#2615]
2548: Nucleof303ze [#2548]

Fixes:

2678: Fixing NCS36510 compile on Linux #2678
2657: [MAX326xx] Removed echoing of characters and carriage return. #2657
2651: Use lp_timer to count time in the deepsleep tests #2651
2645: NUCLEO_F446ZE - Enable mbed5 release version #2645
2643: Fix thread self termination #2643
2634: Updated USBHost for library changes #2634
2633: Updated USBDevice to use Callback #2633
2630: Test names not dependent on disk location of root #2630
2624: CFSTORE Bugfix for realloc() moving KV area and cfstore_file_t data structures not being updated correctly #2624
2623: DISCO_L476VG - Add Serial Flow Control pins + add SERIAL_FC macro #2623
2617: STM32F2xx - Enable Serial Flow Control #2617
2613: Correctly providing directories to build_apis #2613
2607: Fix uvisor memory tracing #2607
2604: Tools - Fix fill section size variation #2604
2601: Adding ON Semiconductor copyright notice to source and header files. #2601
2597: [HAL] Fixed "intrinsic is deprecated" warnings #2597
2596: [HAL] Improve memory tracer #2596
2594: Fix TCPServer constructor #2594
2593: Add app config command line switch for test and make #2593
2589: [NUC472] Fix heap configuration error with armcc #2589
2588: Timing tests drift refactor #2588
2587: add PTEx pins as option for SPI on Hexiwear - for SD Card Interface #2587
2584: Set size of callback irq array to IrqCnt #2584
2583: github issue and PR templates #2583
2582: [GCC_CR] fix runtime hang for baremetal build #2582
2580: lwip - Add check for previously-bound socket #2580
2579: lwip - Fix handling of max sockets in socket_accept #2579
2578: Fix double free in NanostackInterface #2578
2576: Add smoke test that builds example programs with mbed-cli #2576
2575: tools-config! -  Allow an empty or mal-formed config to be passed to the config system #2575
2562: Fix GCC lazy init race condition and add test #2562
2559: [utest]: Allow the linker to remove any part of utest if not used #2559
2545: Added define guards for SEQUENTIAL_FLASH_JOURNAL_MAX_LOGGED_BLOBS so  #2545
2538: STM32F4xx - Add support of ADC internal channels (Temp, VRef, VBat) #2538
2521: [NUCLEO_F207ZG] Add MBED5 capability #2521
2514: Updated FlexCan and SAI SDK drivers #2514
2487: Runtime dynamic memory tracing #2487
2442: Malloc heap info #2442
2419: [STM32F1] Add asynchronous serial #2419
2393: [tools] Prevent trace-backs from incomplete args #2393
2245: Refactor export subsystem #2245
2130: stm32 : reduce number of device.h files #2130
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants