[HDDS-6696] BackgroundService schedules tasks back-to-back as it doesn't wait for task completion

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.3.0
• Assignee: Unassigned
• Reporter: Siyao Meng
• Created: 03/May/22 22:02
• Updated: 25/Mar/23 20:45

Description

HDDS-4231 removed the task result collection from PeriodicalTask#run(). This causes run() to return immediately after task dispatch.

As a side effect, the exec.scheduleWithFixedDelay() no longer works as intended (that the specified interval is supposed to be the one between the end of first task execution and the start of the next task).

This makes it effectively the same as exec.scheduleAtFixedRate(), which might not be desired: Currently a very long running BackgroundService (i.e. run time exceeding the interval) will be triggered back-to-back. See attached unit test HDDS-6696.repro.001.patch for a proof/repro.

Note: Found this bug together with erose while working on HDDS-6371, where we utilized BackgroundService.

CC ljain

Repro unit test execution log. We can see that tasks are run back-to-back. Was expecting 3s wait after each task run ended

2022-05-03 15:04:40,516 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(43)) - Starting DummyTask run 0, thread ID: 11
2022-05-03 15:04:45,522 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(49)) - Ended DummyTask run 0, thread ID: 11
2022-05-03 15:04:45,523 [DummyService#0] WARN  utils.BackgroundService (BackgroundService.java:lambda$run$0(121)) - DummyService Background task execution took 5007803417ns > 1000000000ns(timeout)
2022-05-03 15:04:45,523 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(43)) - Starting DummyTask run 1, thread ID: 11
2022-05-03 15:04:50,528 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(49)) - Ended DummyTask run 1, thread ID: 11
2022-05-03 15:04:50,529 [DummyService#0] WARN  utils.BackgroundService (BackgroundService.java:lambda$run$0(121)) - DummyService Background task execution took 5005770375ns > 1000000000ns(timeout)
2022-05-03 15:04:50,529 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(43)) - Starting DummyTask run 2, thread ID: 11
2022-05-03 15:04:55,533 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(49)) - Ended DummyTask run 2, thread ID: 11
2022-05-03 15:04:55,534 [DummyService#0] WARN  utils.BackgroundService (BackgroundService.java:lambda$run$0(121)) - DummyService Background task execution took 5005325917ns > 1000000000ns(timeout)
2022-05-03 15:04:55,535 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(43)) - Starting DummyTask run 3, thread ID: 11
2022-05-03 15:05:00,541 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(49)) - Ended DummyTask run 3, thread ID: 11
2022-05-03 15:05:00,542 [DummyService#0] WARN  utils.BackgroundService (BackgroundService.java:lambda$run$0(121)) - DummyService Background task execution took 5006824166ns > 1000000000ns(timeout)
2022-05-03 15:05:00,542 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(43)) - Starting DummyTask run 4, thread ID: 11
2022-05-03 15:05:05,547 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(49)) - Ended DummyTask run 4, thread ID: 11
2022-05-03 15:05:05,547 [DummyService#0] WARN  utils.BackgroundService (BackgroundService.java:lambda$run$0(121)) - DummyService Background task execution took 5005403125ns > 1000000000ns(timeout)
2022-05-03 15:05:05,548 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(43)) - Starting DummyTask run 5, thread ID: 11
2022-05-03 15:05:05,561 [main] INFO  utils.BackgroundService (BackgroundService.java:shutdown(136)) - Shutting down service DummyService
2022-05-03 15:05:10,556 [DummyService#0] WARN  utils.BackgroundService (TestBackgroundService.java:call(49)) - Ended DummyTask run 5, thread ID: 11
2022-05-03 15:05:10,557 [DummyService#0] WARN  utils.BackgroundService (BackgroundService.java:lambda$run$0(121)) - DummyService Background task execution took 5008964208ns > 1000000000ns(timeout)

Issue Links

• is caused by: HDDS-4231 Background Service blocks on task results
• is related to: HDDS-6548 HDDS Stability Fixes and Improvements