Sporadic semaphore timing issue on NCS36510

[geky]

The event queue tests have been sporadically picking up an error of 65 milliseconds in the semaphore wait call with the NCS36510.

Here is one example of the failure in #3368 (comment):

[1481229975.74][CONN][RXD] >>> Running case #8: 'Testing call_every'...
[1481229975.78][CONN][INF] found KV pair in stream: {{__testcase_start;Testing call_every}}, queued...
[1481229977.24][CONN][RXD] :73::FAIL: Values Not Within Delta 2 Expected 1400 Was 1465
[1481229977.29][CONN][INF] found KV pair in stream: {{__testcase_finish;Testing call_every;0;1}}, queued...
[1481229977.37][CONN][RXD] >>> 'Testing call_every': 0 passed, 1 failed with reason 'Assertion Failed'

Type: Bug
Priority: Minor
Target: NCS36510
Toolchain: At least IAR
mbed OS sha: 1b019c3

cc @bridadan

[geky]

I put together a test that narrows down the bug to an issue with semaphore timing:
https://github.com/geky/mbed/blob/ncs36510-timing/TESTS/events/timing/main.cpp

Unfortunately it does take ~2 hours for issues to crop up, and seems to be non-deterministic...

[1481652774.74][CONN][RXD] delay 80ms => error 64904us
[1481652774.81][CONN][RXD] :42::FAIL: Values Not Within Delta 2000 Expected 144904 Was 80000

[bridadan]

cc @maclobdell @pradeep-gr @radhika-raghavendran

[ciarmcom]

ARM Internal Ref: IOTMORF-656

[geky]

Looks like @bridadan's intuition was correct, the Timer class itself is the problem. Narrowed down the tests so they complete much faster now:
https://github.com/geky/mbed/blob/ncs36510-timing/TESTS/events/timing/main.cpp

It looks like the issue may be in this function:
https://github.com/ARMmbed/mbed-os/blob/master/targets/TARGET_ONSEMI/TARGET_NCS36510/ncs36510_us_ticker_api.c#L109

[maclobdell]

@geky is the issue the semaphore timing (which I assume uses ticks generated by systick interrupt) or is the issue that the test uses us_ticker_read to check the semaphore timing? In the failing case, is it consistently 65ms shorter than expected. @radhika-raghavendran @pradeep-gr - is there any possible condition that could sometimes cause us_ticker_read function to return a value that is smaller than expected?

[maclobdell]

@geky Please share more information about this issue.