Add the scheduling module
Three replicas of one application against one PostgreSQL database, proving duplicate @Scheduled execution and then removing it with ShedLock: 24 executions where 8 were due, then 7 for 7 ticks. Also measured: @SchedulerLock without @EnableSchedulerLock does nothing and warns about nothing; spring.task.scheduling.pool.size=1 does not starve a fixedRate job but delays it and fires 35 of 40 executions in a burst; and a node whose clock is 40 seconds fast takes a live lock unless the provider uses usingDbTime().
This commit is contained in:
17
scheduling/docs/output/clock-skew.txt
Normal file
17
scheduling/docs/output/clock-skew.txt
Normal file
@@ -0,0 +1,17 @@
|
||||
== One lock, two holders: what usingDbTime() prevents ==
|
||||
|
||||
lockAtMostFor = 30s, both callers ask for the same lock name.
|
||||
|
||||
JdbcTemplateLockProvider WITHOUT usingDbTime()
|
||||
node with a correct clock : acquired
|
||||
node with a clock 40s fast : ACQUIRED -- two holders at the same time
|
||||
|
||||
JdbcTemplateLockProvider WITH usingDbTime()
|
||||
node with a correct clock : acquired
|
||||
node with a clock 40s fast : refused
|
||||
|
||||
Without usingDbTime() the expiry comparison happens against the calling
|
||||
JVM's clock, so a node that is ahead by more than lockAtMostFor considers
|
||||
every live lock expired. With it, both the write and the comparison happen
|
||||
in the database, and there is only one clock in the system.
|
||||
|
||||
12
scheduling/docs/output/scheduler-pool-1.txt
Normal file
12
scheduling/docs/output/scheduler-pool-1.txt
Normal file
@@ -0,0 +1,12 @@
|
||||
== spring.task.scheduling.pool.size=1 (the default) ==
|
||||
|
||||
over 8 seconds, three @Scheduled methods on one application
|
||||
slow() fixedRate 2000 ms, sleeps 1800 ms : 5 executions
|
||||
fast() fixedRate 200 ms : 40 executions
|
||||
throwing() fixedRate 300 ms, always throws : 27 executions
|
||||
distinct scheduler threads : 1 [scheduling-1]
|
||||
|
||||
longest gap between two fast() executions : 1995 ms (200 ms was the schedule)
|
||||
fast() executions that started within 20 ms
|
||||
of the previous one (the catch-up burst) : 35
|
||||
|
||||
18
scheduling/docs/output/scheduler-pool-4.txt
Normal file
18
scheduling/docs/output/scheduler-pool-4.txt
Normal file
@@ -0,0 +1,18 @@
|
||||
== spring.task.scheduling.pool.size=4 ==
|
||||
|
||||
over 8 seconds, three @Scheduled methods on one application
|
||||
slow() fixedRate 2000 ms, sleeps 1800 ms : 5 executions
|
||||
fast() fixedRate 200 ms : 41 executions
|
||||
throwing() fixedRate 300 ms, always throws : 27 executions
|
||||
distinct scheduler threads : 4 [scheduling-1, scheduling-2, scheduling-3, scheduling-4]
|
||||
|
||||
longest gap between two fast() executions : 200 ms (200 ms was the schedule)
|
||||
fast() executions that started within 20 ms
|
||||
of the previous one (the catch-up burst) : 0
|
||||
|
||||
throwing() kept its schedule after every failure. Spring wraps a scheduled
|
||||
method in TaskUtils.LOG_AND_SUPPRESS_ERROR_HANDLER, so each exception is
|
||||
logged by o.s.s.s.TaskUtils$LoggingErrorHandler as "Unexpected error
|
||||
occurred in scheduled task" and then discarded. A raw
|
||||
ScheduledExecutorService would have cancelled the task at the first one.
|
||||
|
||||
8
scheduling/docs/output/tests.txt
Normal file
8
scheduling/docs/output/tests.txt
Normal file
@@ -0,0 +1,8 @@
|
||||
[INFO] Running com.ankurm.scheduling.SingleSchedulerThreadTest
|
||||
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 10.10 s -- in com.ankurm.scheduling.SingleSchedulerThreadTest
|
||||
[INFO] Running com.ankurm.scheduling.LargerSchedulerPoolTest
|
||||
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.422 s -- in com.ankurm.scheduling.LargerSchedulerPoolTest
|
||||
[INFO] Running com.ankurm.scheduling.ClockSkewTest
|
||||
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 5.964 s -- in com.ankurm.scheduling.ClockSkewTest
|
||||
[INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0
|
||||
[INFO] BUILD SUCCESS
|
||||
37
scheduling/docs/output/three-replicas-locked.txt
Normal file
37
scheduling/docs/output/three-replicas-locked.txt
Normal file
@@ -0,0 +1,37 @@
|
||||
profile=locked replicas=3 run-for=30s job rate=3s job duration=PT0.2S replica-3 clock skew=0s
|
||||
|
||||
-- every execution, in order --
|
||||
instance_id | started_at
|
||||
-------------+--------------
|
||||
replica-2 | 22:49:29.233
|
||||
replica-3 | 22:49:31.931
|
||||
replica-3 | 22:49:34.925
|
||||
replica-3 | 22:49:37.934
|
||||
replica-3 | 22:49:40.934
|
||||
replica-3 | 22:49:43.925
|
||||
replica-3 | 22:49:46.934
|
||||
(7 rows)
|
||||
|
||||
-- executions per replica --
|
||||
instance_id | count
|
||||
-------------+-------
|
||||
replica-2 | 1
|
||||
replica-3 | 6
|
||||
(2 rows)
|
||||
|
||||
-- pairs of executions that overlapped (a second replica started while the first was still working) --
|
||||
overlapping_pairs
|
||||
-------------------
|
||||
0
|
||||
(1 row)
|
||||
|
||||
first | first_at | second | second_at
|
||||
-------+----------+--------+-----------
|
||||
(0 rows)
|
||||
|
||||
-- the lock row --
|
||||
name | locked_by | locked_at | lock_until
|
||||
---------------+-----------+--------------+--------------
|
||||
nightlyReport | unknown | 17:19:46.921 | 17:19:47.921
|
||||
(1 row)
|
||||
|
||||
60
scheduling/docs/output/three-replicas-unlocked.txt
Normal file
60
scheduling/docs/output/three-replicas-unlocked.txt
Normal file
@@ -0,0 +1,60 @@
|
||||
profile=unlocked replicas=3 run-for=30s job rate=3s job duration=PT0.2S replica-3 clock skew=0s
|
||||
|
||||
-- every execution, in order --
|
||||
instance_id | started_at
|
||||
-------------+--------------
|
||||
replica-1 | 22:48:54.564
|
||||
replica-3 | 22:48:54.752
|
||||
replica-2 | 22:48:55.052
|
||||
replica-1 | 22:48:57.551
|
||||
replica-3 | 22:48:57.736
|
||||
replica-2 | 22:48:58.030
|
||||
replica-1 | 22:49:00.551
|
||||
replica-3 | 22:49:00.736
|
||||
replica-2 | 22:49:01.030
|
||||
replica-1 | 22:49:03.551
|
||||
replica-3 | 22:49:03.736
|
||||
replica-2 | 22:49:04.030
|
||||
replica-1 | 22:49:06.551
|
||||
replica-3 | 22:49:06.736
|
||||
replica-2 | 22:49:07.030
|
||||
replica-1 | 22:49:09.551
|
||||
replica-3 | 22:49:09.736
|
||||
replica-2 | 22:49:10.030
|
||||
replica-1 | 22:49:12.551
|
||||
replica-3 | 22:49:12.736
|
||||
replica-2 | 22:49:13.030
|
||||
replica-1 | 22:49:15.551
|
||||
replica-3 | 22:49:15.736
|
||||
replica-2 | 22:49:16.030
|
||||
(24 rows)
|
||||
|
||||
-- executions per replica --
|
||||
instance_id | count
|
||||
-------------+-------
|
||||
replica-1 | 8
|
||||
replica-2 | 8
|
||||
replica-3 | 8
|
||||
(3 rows)
|
||||
|
||||
-- pairs of executions that overlapped (a second replica started while the first was still working) --
|
||||
overlapping_pairs
|
||||
-------------------
|
||||
8
|
||||
(1 row)
|
||||
|
||||
first | first_at | second | second_at
|
||||
-----------+--------------+-----------+--------------
|
||||
replica-1 | 22:48:54.564 | replica-3 | 22:48:54.752
|
||||
replica-1 | 22:48:57.551 | replica-3 | 22:48:57.736
|
||||
replica-1 | 22:49:00.551 | replica-3 | 22:49:00.736
|
||||
replica-1 | 22:49:03.551 | replica-3 | 22:49:03.736
|
||||
replica-1 | 22:49:06.551 | replica-3 | 22:49:06.736
|
||||
replica-1 | 22:49:09.551 | replica-3 | 22:49:09.736
|
||||
(6 rows)
|
||||
|
||||
-- the lock row --
|
||||
name | locked_by | locked_at | lock_until
|
||||
------+-----------+-----------+------------
|
||||
(0 rows)
|
||||
|
||||
Reference in New Issue
Block a user