bthrottler test fails

[vlm]

macOS Sierra, Apple LLVM version 7.3.0 (clang-703.0.31).

[vlm@nala:~/sustrik/dsock (master)]> ./tests/bthrottler 
Assertion failed: (elapsed > 80 && elapsed < 100), function main, file tests/bthrottler.c, line 42.
Abort trap: 6
[vlm@nala:~/sustrik/dsock (master)]> 

[sustrik]

What's the elapsed value?

[vlm]

102 — 106

[reqshark]

reporting same elapsed value range at 80-100 check. my bthrottler and mthrottler tests fail every time on osx. here's what it looks like after inserted printf() of elapsed above failed asserts:

=====================================
   dsock 2b42d7b: ./test-suite.log
=====================================

# TOTAL: 17
# PASS:  15
# SKIP:  0
# XFAIL: 0
# FAIL:  2
# XPASS: 0
# ERROR: 0

.. contents:: :depth: 2

FAIL: tests/bthrottler
======================

Assertion failed: (elapsed > 130 && elapsed < 150), function main, file tests/bthrottler.c, line 62.

printf elapsed: 168 on line: `assert(elapsed > 130 && elapsed < 150);`

FAIL tests/bthrottler (exit status: 134)

FAIL: tests/mthrottler
======================

Assertion failed: (elapsed > 80 && elapsed < 100), function main, file tests/mthrottler.c, line 49.

printf elapsed: 107 on line: `assert(elapsed > 80 && elapsed < 100);`

FAIL tests/mthrottler (exit status: 134)

Note: after several runs bthrottler failed once at 80-100 check, all other times bthrottler fails at 130-150 check. mthrottler fails at 80-100 check.

[sustrik]

Similar issue happens on Travis btw and, IIRC, it happens only with OSX builds.

One possibility is that OSX it just imprecise with timeouts and we should make the intervals larger.

Another possibility is that there's a problem with using mach_absolute_time().

@reqshark: I have no OSX box. Can you edit libdill.c, now() function. So that gettimeofday() version is used instaead of mach_absolute_time()? Does it make the tests succeed?

[reqshark]

switching to gettimeofday() makes mthrottler test pass about 50% of the time, but it also widens elapsed value range.

bthrottler still fails every time with less consistent elapsed range than mach_absolute_time()

seems more like it's the first possibility.

Also Happy New Year!

[sustrik]

Happy New Year to you too!

To double check that it's really OSX at fault here, I've created 'timeouts' branch of libdill which prints out expected timeouts and actually observed ones. Can you run it with one of the failing tests and paste the output?

[sustrik]

Here are some results from libdill tests on Travis. Doesn't look that bad:

timeout: 50 elapsed: 50 timeout: 50 elapsed: 51 timeout: 50 elapsed: 55 timeout: 0 elapsed: 0 timeout: 0 elapsed: 0 timeout: 0 elapsed: 0 timeout: 50 elapsed: 53 timeout: 50 elapsed: 51 timeout: 50 elapsed: 55 timeout: 10 elapsed: 12 timeout: 10 elapsed: 13 timeout: 10 elapsed: 10 timeout: 10 elapsed: 14 timeout: 51 elapsed: 54 timeout: 0 elapsed: 0 timeout: 100 elapsed: 105 timeout: 50 elapsed: 55 timeout: 50 elapsed: 55 timeout: 10 elapsed: 13 timeout: 100 elapsed: 105 timeout: 100 elapsed: 102 timeout: 50 elapsed: 54 timeout: 46 elapsed: 47 timeout: 30 elapsed: 30 timeout: 100 elapsed: 101 timeout: 50 elapsed: 55 timeout: 45 elapsed: 47 timeout: 100 elapsed: 105 timeout: 10 elapsed: 12 timeout: 8 elapsed: 11 timeout: 7 elapsed: 9 timeout: 8 elapsed: 10 timeout: 10 elapsed: 11 timeout: 10 elapsed: 11 timeout: 10 elapsed: 11 timeout: 10 elapsed: 11 timeout: 10 elapsed: 12 timeout: 10 elapsed: 12 timeout: 9 elapsed: 9 timeout: 10 elapsed: 12 timeout: 156 elapsed: 160 timeout: 153 elapsed: 157

[reqshark]

tests/bthrottler.log:

Assertion failed: (elapsed > 130 && elapsed < 150), function main, file tests/bthrottler.c, line 63.
timeout: 10 elapsed: 11
timeout: 10 elapsed: 13
timeout: 10 elapsed: 12
timeout: 10 elapsed: 11
timeout: 10 elapsed: 11
timeout: 10 elapsed: 10
timeout: 10 elapsed: 12
timeout: 10 elapsed: 10
timeout: 10 elapsed: 12
at assert(elapsed > 80 && elapsed < 110); elapsed: 102
timeout: 10 elapsed: 13
timeout: 10 elapsed: 12
timeout: 10 elapsed: 13
timeout: 10 elapsed: 12
timeout: 10 elapsed: 12
timeout: 10 elapsed: 13
timeout: 10 elapsed: 10
timeout: 10 elapsed: 12
timeout: 10 elapsed: 11
timeout: 10 elapsed: 12
timeout: 10 elapsed: 11
timeout: 10 elapsed: 10
timeout: 9 elapsed: 9
timeout: 10 elapsed: 13
at assert(elapsed > 130 && elapsed < 150); elapsed: 164
FAIL tests/bthrottler (exit status: 134)

tests/mthrottler.log:

Assertion failed: (elapsed > 80 && elapsed < 100), function main, file tests/mthrottler.c, line 50.
timeout: 10 elapsed: 13
timeout: 10 elapsed: 12
timeout: 10 elapsed: 11
timeout: 10 elapsed: 10
timeout: 10 elapsed: 12
timeout: 10 elapsed: 11
timeout: 10 elapsed: 11
timeout: 10 elapsed: 10
timeout: 10 elapsed: 10
at assert(elapsed > 80 && elapsed < 100); elapsed: 101
FAIL tests/mthrottler (exit status: 134)

observations:

• on mthrottler test, occasionally elapsed value looks like within threshold, yet assert fails? at assert(elapsed > 80 && elapsed < 110); elapsed: 101 EDIT: oops, I printed here incorrect assert, it's really assert(elapsed > 80 && elapsed < 100);

• saw new test failure with that change to libdill:

=====================================
   dsock 2b42d7b: ./test-suite.log
=====================================

# TOTAL: 17
# PASS:  14
# SKIP:  0
# XFAIL: 0
# FAIL:  3
# XPASS: 0
# ERROR: 0

.. contents:: :depth: 2

FAIL: tests/crlf
================

Assertion failed: (rc == 0), function client, file tests/crlf.c, line 48.
rc: -1
FAIL tests/crlf (exit status: 134)

[reqshark]

sorry ignore first observation (about mthrottler), i printed wrong assert range in test output

[reqshark]

here's another observation, when bthrottler assert fails:

• total timeout: 10+10+10+10+10+10+10+10+10+10+10+10+9+10 = 139

• total elapsed: 13+12+13+12+12+13+10+12+11+12+11+10+9+13 = 163

• elapsed at assert: 164

[sustrik]

I see. The error adds up. I've written the throttling algorithm in haste, so it should be reviewed. It's also possible that it's the test that's wrong, not the throttler.

[reqshark]

ok I got it to pass on osx, see here https://github.com/sustrik/dsock/pull/25