Test failure in bdlmt_eventscheduler.t

[greghogan]

bde 3.110.0.3
bde-tools 3.110.0.0

This failure is very intermittent. Only the output from the failed execution is copied below.

$ while ctest -VV -R '(bdlmt_eventscheduler\.t)'; do :; done
UpdateCTestConfiguration  from :/tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/build/DartConfiguration.tcl
UpdateCTestConfiguration  from :/tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/build/DartConfiguration.tcl
Test project /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/build
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 392
    Start 392: bdlmt_eventscheduler.t

392: Test command: /gnu/store/65i3nhcwmz0p8rqbg48gaavyky4g4hwk-python-3.9.9/bin/python3.9 "/gnu/store/van5j8ddlvsrwqjf9j7jvw4c722jl43c-bloomberg-bde-tools-3.110.0.0/bin/bde_runtest.py" "/tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/build/bdlmt_eventscheduler.t"
392: Test timeout computed to be: 10000000
392: [17:35:42] TEST START
392: [17:35:52] CASE  1: SUCCESS
392: [17:35:56] CASE  2: SUCCESS
392: [17:36:00] CASE  3: SUCCESS
392: [17:36:02] CASE  4: FAILURE (rc 3)
392: TEST /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp CASE 4
392: Error /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp(2324): 1 == testObj1.numExecuted()    (failed)
392: Error /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp(2329): 1 == testObj1.numExecuted()    (failed)
392: testObj1.numExecuted(): 0
392: Error /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp(2276): 1 == testObj1.numExecuted()    (failed)
392: Error, non-zero test status = 3.
392: 
392: [17:36:02] CASE  5: SUCCESS
392: [17:36:02] CASE  7: SUCCESS
392: [17:36:03] CASE  8: SUCCESS
392: [17:36:04] CASE  6: SUCCESS
392: [17:36:05] CASE 10: SUCCESS
392: [17:36:07] CASE  9: SUCCESS
392: [17:36:07] CASE 11: SUCCESS
392: [17:36:08] CASE 13: SUCCESS
392: [17:36:09] CASE 14: SUCCESS
392: [17:36:12] CASE 12: SUCCESS
392: [17:36:16] CASE 15: SUCCESS
392: [17:36:16] CASE 17: SUCCESS
392: [17:36:16] CASE 18: SUCCESS
392: [17:36:17] CASE 19: SUCCESS
392: [17:36:17] CASE 20: SUCCESS
392: [17:36:17] CASE 21: SUCCESS
392: [17:36:17] CASE 22: SUCCESS
392: [17:36:17] CASE 23: SUCCESS
392: [17:36:17] CASE 24: SUCCESS
392: [17:36:17] CASE 25: SUCCESS
392: [17:36:17] CASE 26: SUCCESS
392: [17:36:17] CASE 27: SUCCESS
392: [17:36:18] CASE 16: SUCCESS
392: [17:36:23] CASE 29: SUCCESS
392: [17:36:24] CASE 28: SUCCESS
392: [17:36:26] CASE 30: SUCCESS
392: [17:36:26] CASE 32: SUCCESS
392: [17:36:34] CASE 31: SUCCESS
1/1 Test #392: bdlmt_eventscheduler.t ...........***Failed   53.00 sec
[17:35:42] TEST START
[17:35:52] CASE  1: SUCCESS
[17:35:56] CASE  2: SUCCESS
[17:36:00] CASE  3: SUCCESS
[17:36:02] CASE  4: FAILURE (rc 3)
TEST /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp CASE 4
Error /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp(2324): 1 == testObj1.numExecuted()    (failed)
Error /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp(2329): 1 == testObj1.numExecuted()    (failed)
testObj1.numExecuted(): 0
Error /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp(2276): 1 == testObj1.numExecuted()    (failed)
Error, non-zero test status = 3.

[17:36:02] CASE  5: SUCCESS
[17:36:02] CASE  7: SUCCESS
[17:36:03] CASE  8: SUCCESS
[17:36:04] CASE  6: SUCCESS
[17:36:05] CASE 10: SUCCESS
[17:36:07] CASE  9: SUCCESS
[17:36:07] CASE 11: SUCCESS
[17:36:08] CASE 13: SUCCESS
[17:36:09] CASE 14: SUCCESS
[17:36:12] CASE 12: SUCCESS
[17:36:16] CASE 15: SUCCESS
[17:36:16] CASE 17: SUCCESS
[17:36:16] CASE 18: SUCCESS
[17:36:17] CASE 19: SUCCESS
[17:36:17] CASE 20: SUCCESS
[17:36:17] CASE 21: SUCCESS
[17:36:17] CASE 22: SUCCESS
[17:36:17] CASE 23: SUCCESS
[17:36:17] CASE 24: SUCCESS
[17:36:17] CASE 25: SUCCESS
[17:36:17] CASE 26: SUCCESS
[17:36:17] CASE 27: SUCCESS
[17:36:18] CASE 16: SUCCESS
[17:36:23] CASE 29: SUCCESS
[17:36:24] CASE 28: SUCCESS
[17:36:26] CASE 30: SUCCESS
[17:36:26] CASE 32: SUCCESS
[17:36:34] CASE 31: SUCCESS


0% tests passed, 1 tests failed out of 1

Label Time Summary:
all                       =  53.00 sec*proc (1 test)
all.t                     =  53.00 sec*proc (1 test)
bdl                       =  53.00 sec*proc (1 test)
bdl.t                     =  53.00 sec*proc (1 test)
bdlmt                     =  53.00 sec*proc (1 test)
bdlmt.t                   =  53.00 sec*proc (1 test)
bdlmt_eventscheduler      =  53.00 sec*proc (1 test)
bdlmt_eventscheduler.t    =  53.00 sec*proc (1 test)

Total Test time (real) =  54.69 sec

The following tests FAILED:
	392 - bdlmt_eventscheduler.t (Failed)
Errors while running CTest

[mversche]

internal tracking 170729958

[t3nsor]

Hi, I haven't been able to reproduce this yet. May I know what build configuration you are using?

[greghogan]

The UFID is set to opt_dbg_exc_mt_64_shr_cpp17. The build system is GNU Guix. If you search the following build log for starting phase you will see the commands executed during the build.

zhl6k25qlxsb60m5z4342n1jn17pw7-bloomberg-bde-3.110.0.3.drv.gz

Hardware is an AWS r6i.xlarge with 4 vCPU running Amazon Linux 2.

I have now seen errors on case 4 (as above) and case 2. Running the test executable directly so as to capture the verbose output (and ignoring successful results; the failures are highly intermittent):

$ while ./bdlmt_eventscheduler.t 2 -v -v -v; do :; done
TEST /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp CASE 2

TESTING 'scheduleEvent' and 'scheduleRecurringEvent'
====================================================
TestAllocator [0]: Allocated 2104 bytes at 0x531ce0.
TestAllocator [1]: Allocated 720 bytes at 0x5325a0.
TestAllocator [2]: Allocated 1424 bytes at 0x5328f0.
TestAllocator [3]: Allocated 2104 bytes at 0x532f00.
TestAllocator [4]: Allocated 752 bytes at 0x5337c0.
TestAllocator [5]: Allocated 1488 bytes at 0x533b30.
TestAllocator [6]: Allocated 256 bytes at 0x5341e0.
TestAllocator [7]: Allocated 496 bytes at 0x5343c0.
TestAllocator [8]: Allocated 976 bytes at 0x5346f0.
TestAllocator [9]: Allocated 224 bytes at 0x534c00.
TestAllocator [10]: Allocated 432 bytes at 0x534dc0.
TestAllocator [11]: Allocated 848 bytes at 0x5350b0.
TestAllocator [12]: Allocated 240 bytes at 0x5355a0.
TestAllocator [13]: Allocated 464 bytes at 0x5357d0.
TestAllocator [14]: Allocated 1680 bytes at 0x535a80.
TestAllocator [15]: Allocated 256 bytes at 0x536370.
TestAllocator [16]: Allocated 912 bytes at 0x536610.
TestAllocator [17]: Allocated 80 bytes at 0x536ae0.
CLOCK specified at line 6201 executed 100 milliseconds after it was scheduled
CLOCK specified at line 6202 executed 200 milliseconds after it was scheduled
CLOCK specified at line 6203 executed 300 milliseconds after it was scheduled
CLOCK specified at line 6204 executed 400 milliseconds after it was scheduled
CLOCK specified at line 6205 executed 500 milliseconds after it was scheduled
EVENT specified at line 6207 executed 600 milliseconds after it was scheduled
EVENT specified at line 6208 executed 700 milliseconds after it was scheduled
EVENT specified at line 6209 executed 800 milliseconds after it was scheduled
EVENT specified at line 6210 executed 900 milliseconds after it was scheduled
CLOCK specified at line 6201 executed 100 milliseconds after it was scheduled
CLOCK specified at line 6202 executed 200 milliseconds after it was scheduled
CLOCK specified at line 6203 executed 300 milliseconds after it was scheduled
CLOCK specified at line 6204 executed 400 milliseconds after it was scheduled
CLOCK specified at line 6205 executed 500 milliseconds after it was scheduled
EVENT specified at line 6212 executed 600 milliseconds after it was scheduled
EVENT specified at line 6213 executed 700 milliseconds after it was scheduled
EVENT specified at line 6214 executed 800 milliseconds after it was scheduled
EVENT specified at line 6215 executed 900 milliseconds after it was scheduled
CLOCK specified at line 6201 executed 100 milliseconds after it was scheduled
CLOCK specified at line 6202 executed 200 milliseconds after it was scheduled
CLOCK specified at line 6203 executed 300 milliseconds after it was scheduled
CLOCK specified at line 6204 executed 400 milliseconds after it was scheduled
CLOCK specified at line 6205 executed 500 milliseconds after it was scheduled
EVENT specified at line 6217 executed 600 milliseconds after it was scheduled
EVENT specified at line 6218 executed 700 milliseconds after it was scheduled
EVENT specified at line 6219 executed 800 milliseconds after it was scheduled
EVENT specified at line 6220 executed 900 milliseconds after it was scheduled
TestAllocator [17]: Deallocated 80 bytes at 0x536ae0.
testObject.d_line = 6201
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 339513089)
testObject.d_numExecuted = 3
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239423352)

testObject.d_line = 6202
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 439500442)
testObject.d_numExecuted = 3
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239428562)

testObject.d_line = 6203
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 539497832)
testObject.d_numExecuted = 3
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239433888)

testObject.d_line = 6204
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 639492291)
testObject.d_numExecuted = 3
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239434126)

testObject.d_line = 6205
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 739494087)
testObject.d_numExecuted = 3
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239438008)

testObject.d_line = 6207
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168222, 839422276)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239438403)

testObject.d_line = 6208
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168222, 939422240)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239441275)

testObject.d_line = 6209
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168223, 39422264)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239444461)

testObject.d_line = 6210
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168223, 139422288)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239445102)

testObject.d_line = 6212
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168223, 839422276)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239447041)

testObject.d_line = 6213
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168223, 939422300)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239447330)

testObject.d_line = 6214
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168224, 39422324)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239447615)

testObject.d_line = 6215
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168224, 139422228)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239453151)

testObject.d_line = 6217
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168224, 839422395)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239453439)

testObject.d_line = 6218
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168224, 939422300)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239455440)

testObject.d_line = 6219
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 39422204)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239458716)

testObject.d_line = 6220
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 139422347)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239459101)

testObject.d_line = 6222
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 839422395)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239459429)

testObject.d_line = 6223
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 939422300)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239459793)

testObject.d_line = 6224
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 39422204)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239460065)

testObject.d_line = 6225
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 139422347)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239465010)

testObject.d_line = 6227
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 839422157)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239465264)

testObject.d_line = 6228
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 939422538)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239465543)

testObject.d_line = 6229
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168227, 39422443)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239471774)

testObject.d_line = 6230
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168227, 139422347)
testObject.d_numExecuted = 0
testObject.d_executionTime = 0
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168222, 239472000)

TestAllocator [8]: Deallocated 976 bytes at 0x5346f0.
TestAllocator [7]: Deallocated 496 bytes at 0x5343c0.
TestAllocator [6]: Deallocated 256 bytes at 0x5341e0.
TestAllocator [5]: Deallocated 1488 bytes at 0x533b30.
TestAllocator [4]: Deallocated 752 bytes at 0x5337c0.
TestAllocator [3]: Deallocated 2104 bytes at 0x532f00.
TestAllocator [16]: Deallocated 912 bytes at 0x536610.
TestAllocator [15]: Deallocated 256 bytes at 0x536370.
TestAllocator [14]: Deallocated 1680 bytes at 0x535a80.
TestAllocator [13]: Deallocated 464 bytes at 0x5357d0.
TestAllocator [12]: Deallocated 240 bytes at 0x5355a0.
TestAllocator [11]: Deallocated 848 bytes at 0x5350b0.
TestAllocator [10]: Deallocated 432 bytes at 0x534dc0.
TestAllocator [9]: Deallocated 224 bytes at 0x534c00.
TestAllocator [2]: Deallocated 1424 bytes at 0x5328f0.
TestAllocator [1]: Deallocated 720 bytes at 0x5325a0.
TestAllocator [0]: Deallocated 2104 bytes at 0x531ce0.

==================================================
                TEST ALLOCATOR STATE
--------------------------------------------------
        Category	Blocks	Bytes
        --------	------	-----
          IN USE	0	0
             MAX	18	15456
           TOTAL	18	15456
      MISMATCHES	0
   BOUNDS ERRORS	0
--------------------------------------------------
  Test case 2: PASSED
TestAllocator [0]: Allocated 2104 bytes at 0x531cc0.
TestAllocator [1]: Allocated 720 bytes at 0x5325a0.
TestAllocator [2]: Allocated 1424 bytes at 0x533b30.
TestAllocator [3]: Allocated 2104 bytes at 0x535a00.
TestAllocator [4]: Allocated 752 bytes at 0x5337c0.
TestAllocator [5]: Allocated 1488 bytes at 0x5328d0.
TestAllocator [6]: Allocated 224 bytes at 0x534c00.
TestAllocator [7]: Allocated 432 bytes at 0x534dc0.
TestAllocator [8]: Allocated 848 bytes at 0x5350b0.
TestAllocator [9]: Allocated 256 bytes at 0x536370.
TestAllocator [10]: Allocated 496 bytes at 0x5343c0.
TestAllocator [11]: Allocated 80 bytes at 0x5356f0.
EVENT specified at line 6291 executed 100 milliseconds after it was scheduled
EVENT specified at line 6293 executed 100 milliseconds after it was scheduled
EVENT specified at line 6294 executed 100 milliseconds after it was scheduled
EVENT specified at line 6295 executed 100 milliseconds after it was scheduled
EVENT specified at line 6296 executed 100 milliseconds after it was scheduled
CLOCK specified at line 6298 executed 100 milliseconds after it was scheduled
CLOCK specified at line 6299 executed 100 milliseconds after it was scheduled
CLOCK specified at line 6300 executed 100 milliseconds after it was scheduled
TestAllocator [11]: Deallocated 80 bytes at 0x5356f0.
testObject.d_line = 6291
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168225, 240178854)
testObject.d_numExecuted = 1
testObject.d_executionTime = 1000000
testObject.d_delayed = 0
testObject.d_referenceTime = (1669168225, 140179440)

testObject.d_line = 6293
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 240340512)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 1
testObject.d_referenceTime = (1669168225, 140186511)

testObject.d_line = 6294
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 240359578)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 1
testObject.d_referenceTime = (1669168225, 140188771)

testObject.d_line = 6295
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 240361278)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 1
testObject.d_referenceTime = (1669168225, 140189048)

testObject.d_line = 6296
testObject.d_isClock = 0
testObject.d_periodicInterval = (0, 0)
testObject.d_expectedTimeAtExecution = (1669168226, 240362718)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 1
testObject.d_referenceTime = (1669168225, 140191011)

testObject.d_line = 6298
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168227, 240365572)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 1
testObject.d_referenceTime = (1669168225, 140191304)

testObject.d_line = 6299
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168227, 240367400)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 1
testObject.d_referenceTime = (1669168225, 140193848)

testObject.d_line = 6300
testObject.d_isClock = 1
testObject.d_periodicInterval = (1, 0)
testObject.d_expectedTimeAtExecution = (1669168227, 240368918)
testObject.d_numExecuted = 1
testObject.d_executionTime = 0
testObject.d_delayed = 1
testObject.d_referenceTime = (1669168225, 140199887)

TestAllocator [10]: Deallocated 496 bytes at 0x5343c0.
TestAllocator [9]: Deallocated 256 bytes at 0x536370.
TestAllocator [5]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator [4]: Deallocated 752 bytes at 0x5337c0.
TestAllocator [3]: Deallocated 2104 bytes at 0x535a00.
TestAllocator [8]: Deallocated 848 bytes at 0x5350b0.
TestAllocator [7]: Deallocated 432 bytes at 0x534dc0.
TestAllocator [6]: Deallocated 224 bytes at 0x534c00.
TestAllocator [2]: Deallocated 1424 bytes at 0x533b30.
TestAllocator [1]: Deallocated 720 bytes at 0x5325a0.
TestAllocator [0]: Deallocated 2104 bytes at 0x531cc0.

==================================================
                TEST ALLOCATOR STATE
--------------------------------------------------
        Category	Blocks	Bytes
        --------	------	-----
          IN USE	0	0
             MAX	12	10928
           TOTAL	12	10928
      MISMATCHES	0
   BOUNDS ERRORS	0
--------------------------------------------------
  Test case 2: PASSED

Testing with chrono-clocks.
TestAllocator default [0]: Allocated 8000 bytes at 0x536d00.
TestAllocator default [1]: Allocated 8000 bytes at 0x538ca0.
TestAllocator default [2]: Allocated 8000 bytes at 0x53ac40.
TestAllocator default [3]: Allocated 8000 bytes at 0x53cbe0.
TestAllocator [0]: Allocated 2104 bytes at 0x531cc0.
TestAllocator [1]: Allocated 720 bytes at 0x5325a0.
TestAllocator [2]: Allocated 1424 bytes at 0x533b10.
TestAllocator [3]: Allocated 2104 bytes at 0x535a00.
TestAllocator [4]: Allocated 752 bytes at 0x5337c0.
TestAllocator [5]: Allocated 1488 bytes at 0x5328d0.
TestAllocator [6]: Allocated 256 bytes at 0x536370.
TestAllocator [7]: Allocated 496 bytes at 0x5343c0.
TestAllocator [8]: Allocated 976 bytes at 0x5346f0.
TestAllocator [9]: Allocated 80 bytes at 0x534fd0.
TestAllocator [9]: Deallocated 80 bytes at 0x534fd0.
Checking results for system clock
Expected 19 callbacks, got 19
Expected 0 got 69106 (69106)
Expected 500000000 got 500070008 (70008)
Expected 1000000000 got 1000055410 (55410)
Expected 1500000000 got 1500055130 (55130)
Expected 2000000000 got 2000055297 (55297)
Expected 2500000000 got 2499999682 (-318)
Error /tmp/guix-build-bloomberg-bde-3.110.0.3.drv-0/source/groups/bdl/bdlmt/bdlmt_eventscheduler.t.cpp(834): d_callTimes[i] >= d_startTime + (d_interval * i)    (failed)
Expected 3000000000 got 3000055319 (55319)
Expected 3500000000 got 3500055254 (55254)
Expected 4000000000 got 4000055079 (55079)
Expected 4500000000 got 4500000587 (587)
Expected 5000000000 got 5000055532 (55532)
Expected 5500000000 got 5500054970 (54970)
Expected 6000000000 got 6000055578 (55578)
Expected 6500000000 got 6500055126 (55126)
Expected 7000000000 got 7000055250 (55250)
Expected 7500000000 got 7500054893 (54893)
Expected 8000000000 got 8000055477 (55477)
Expected 8500000000 got 8500055066 (55066)
Expected 9000000000 got 9000055174 (55174)
Checking results for steady clock
Expected 16 callbacks, got 16
Expected 0 got 54136 (54136)
Expected 600000000 got 600074828 (74828)
Expected 1200000000 got 1200061631 (61631)
Expected 1800000000 got 1800059433 (59433)
Expected 2400000000 got 2400062298 (62298)
Expected 3000000000 got 3000040414 (40414)
Expected 3600000000 got 3600064653 (64653)
Expected 4200000000 got 4200069716 (69716)
Expected 4800000000 got 4800063677 (63677)
Expected 5400000000 got 5400061567 (61567)
Expected 6000000000 got 6000040448 (40448)
Expected 6600000000 got 6600063605 (63605)
Expected 7200000000 got 7200063210 (63210)
Expected 7800000000 got 7800059537 (59537)
Expected 8400000000 got 8400062250 (62250)
Expected 9000000000 got 9000040284 (40284)
Checking results for another clock
Expected 31 callbacks, got 31
Expected 0 got 51008 (51008)
Expected 300000000 got 300072518 (72518)
Expected 600000000 got 600071564 (71564)
Expected 900000000 got 900060682 (60682)
Expected 1200000000 got 1200058213 (58213)
Expected 1500000000 got 1500035823 (35823)
Expected 1800000000 got 1800055880 (55880)
Expected 2100000000 got 2100060925 (60925)
Expected 2400000000 got 2400058874 (58874)
Expected 2700000000 got 2700066317 (66317)
Expected 3000000000 got 3000037084 (37084)
Expected 3300000000 got 3300056562 (56562)
Expected 3600000000 got 3600061209 (61209)
Expected 3900000000 got 3900056900 (56900)
Expected 4200000000 got 4200066332 (66332)
Expected 4500000000 got 4500050658 (50658)
Expected 4800000000 got 4800060554 (60554)
Expected 5100000000 got 5100068074 (68074)
Expected 5400000000 got 5400058244 (58244)
Expected 5700000000 got 5700062937 (62937)
Expected 6000000000 got 6000037049 (37049)
Expected 6300000000 got 6300062716 (62716)
Expected 6600000000 got 6600060270 (60270)
Expected 6900000000 got 6900057738 (57738)
Expected 7200000000 got 7200059801 (59801)
Expected 7500000000 got 7500035538 (35538)
Expected 7800000000 got 7800056011 (56011)
Expected 8100000000 got 8100060397 (60397)
Expected 8400000000 got 8400058835 (58835)
Expected 8700000000 got 8700064589 (64589)
Expected 9000000000 got 9000036952 (36952)
Checking results for half speed clock
Expected 17 callbacks, got 17
Expected 0 got 12148 (12148)
Expected 250000000 got 250011922 (11922)
Expected 500000000 got 500012134 (12134)
Expected 750000000 got 750019206 (19206)
Expected 1000000000 got 1000012141 (12141)
Expected 1250000000 got 1250011961 (11961)
Expected 1500000000 got 1500011998 (11998)
Expected 1750000000 got 1750019274 (19274)
Expected 2000000000 got 2000012230 (12230)
Expected 2250000000 got 2250011809 (11809)
Expected 2500000000 got 2500012249 (12249)
Expected 2750000000 got 2750011985 (11985)
Expected 3000000000 got 3000011997 (11997)
Expected 3250000000 got 3250011780 (11780)
Expected 3500000000 got 3500012207 (12207)
Expected 3750000000 got 3750012032 (12032)
Expected 4000000000 got 4000012197 (12197)
TestAllocator [8]: Deallocated 976 bytes at 0x5346f0.
TestAllocator [7]: Deallocated 496 bytes at 0x5343c0.
TestAllocator [6]: Deallocated 256 bytes at 0x536370.
TestAllocator [5]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator [4]: Deallocated 752 bytes at 0x5337c0.
TestAllocator [3]: Deallocated 2104 bytes at 0x535a00.
TestAllocator [2]: Deallocated 1424 bytes at 0x533b10.
TestAllocator [1]: Deallocated 720 bytes at 0x5325a0.
TestAllocator [0]: Deallocated 2104 bytes at 0x531cc0.

==================================================
                TEST ALLOCATOR STATE
--------------------------------------------------
        Category	Blocks	Bytes
        --------	------	-----
          IN USE	0	0
             MAX	10	10400
           TOTAL	10	10400
      MISMATCHES	0
   BOUNDS ERRORS	0
--------------------------------------------------
TestAllocator default [3]: Deallocated 8000 bytes at 0x53cbe0.
TestAllocator default [2]: Deallocated 8000 bytes at 0x53ac40.
TestAllocator default [1]: Deallocated 8000 bytes at 0x538ca0.
TestAllocator default [0]: Deallocated 8000 bytes at 0x536d00.

Negative Testing.
TestAllocator default [4]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [5]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [6]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [7]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [8]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [9]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [10]: Allocated 256 bytes at 0x536370.
TestAllocator default [10]: Deallocated 256 bytes at 0x536370.
TestAllocator default [9]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [8]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [7]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [6]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [5]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [4]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [11]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [12]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [13]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [14]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [15]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [16]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [16]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [15]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [14]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [13]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [12]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [11]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [17]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [18]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [19]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [20]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [21]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [22]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [22]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [21]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [20]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [19]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [18]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [17]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [23]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [24]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [25]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [26]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [27]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [28]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [29]: Allocated 256 bytes at 0x536370.
TestAllocator default [29]: Deallocated 256 bytes at 0x536370.
TestAllocator default [28]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [27]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [26]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [25]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [24]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [23]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [30]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [31]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [32]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [33]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [34]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [35]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [35]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [34]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [33]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [32]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [31]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [30]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [36]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [37]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [38]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [39]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [40]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [41]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [41]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [40]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [39]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [38]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [37]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [36]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [42]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [43]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [44]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [45]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [46]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [47]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [48]: Allocated 256 bytes at 0x536370.
TestAllocator default [48]: Deallocated 256 bytes at 0x536370.
TestAllocator default [47]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [46]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [45]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [44]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [43]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [42]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [49]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [50]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [51]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [52]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [53]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [54]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [54]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [53]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [52]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [51]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [50]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [49]: Deallocated 2104 bytes at 0x535a00.
TestAllocator default [55]: Allocated 2104 bytes at 0x535a00.
TestAllocator default [56]: Allocated 720 bytes at 0x5325a0.
TestAllocator default [57]: Allocated 1424 bytes at 0x533b10.
TestAllocator default [58]: Allocated 2104 bytes at 0x531cc0.
TestAllocator default [59]: Allocated 752 bytes at 0x5337c0.
TestAllocator default [60]: Allocated 1488 bytes at 0x5328d0.
TestAllocator default [60]: Deallocated 1488 bytes at 0x5328d0.
TestAllocator default [59]: Deallocated 752 bytes at 0x5337c0.
TestAllocator default [58]: Deallocated 2104 bytes at 0x531cc0.
TestAllocator default [57]: Deallocated 1424 bytes at 0x533b10.
TestAllocator default [56]: Deallocated 720 bytes at 0x5325a0.
TestAllocator default [55]: Deallocated 2104 bytes at 0x535a00.
Error, non-zero test status = 1.

==================================================
                TEST ALLOCATOR default STATE
--------------------------------------------------
        Category	Blocks	Bytes
        --------	------	-----
          IN USE	0	0
             MAX	7	32000
           TOTAL	61	110096
      MISMATCHES	0
   BOUNDS ERRORS	0
--------------------------------------------------

==================================================
                TEST ALLOCATOR test STATE
--------------------------------------------------
        Category	Blocks	Bytes
        --------	------	-----
          IN USE	0	0
             MAX	0	0
           TOTAL	0	0
      MISMATCHES	0
   BOUNDS ERRORS	0
--------------------------------------------------

[t3nsor]

I think I know the cause of the test failure you're seeing on case 4. However, I can't reproduce the test failure you reported on case 2. One theory is that it's related to the fact that the test driver computes d_startTime with nanosecond precision, but bdlmt_eventscheduler uses microsecond precision internally. If this theory is correct, then if we adjust the test driver so that it truncates d_startTime to microsecond precision prior to passing it to bdlmt_eventscheduler, the failure should not occur.

Can you add the following at the beginning of ChronoRecurringTest's constructor, before the line d_callTimes.reserve(1000);, and check whether it still fails case 2? If so, please show the output under -v -v (that's two -vs, not three).

        if constexpr (std::is_same<CLOCK, std::chrono::system_clock>::value) {
            static_assert(std::is_same<typename CLOCK::period, std::nano>::value);
            const Tp adjustedStartTime = std::chrono::ceil<std::chrono::microseconds>(d_startTime);
            if (veryVerbose) {
                cout << "adjusting d_startTime from " << d_startTime.time_since_epoch().count() << " to " << adjustedStartTime.time_since_epoch().count() << '\n';
            }
            d_startTime = adjustedStartTime;
        }