[
https://issues.apache.org/jira/browse/HDDS-6696?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-6696:
-----------------------------
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]
{code:title=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)
{code}
was:
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]
> BackgroundService schedules tasks back-to-back as it doesn't wait for task
> completion
> -------------------------------------------------------------------------------------
>
> Key: HDDS-6696
> URL: https://issues.apache.org/jira/browse/HDDS-6696
> Project: Apache Ozone
> Issue Type: Bug
> Affects Versions: 1.3.0
> Reporter: Siyao Meng
> Priority: Major
> Attachments: HDDS-6696.repro.001.patch
>
>
> 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]
> {code:title=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)
> {code}
--
This message was sent by Atlassian Jira
(v8.20.7#820007)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
