diff --git a/README.md b/README.md index 78580c9..308f7ce 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,7 @@ # spring-async-demo -Companion code for the asynchronous execution series on [ankurm.com](https://ankurm.com). Each +Companion code for the asynchronous execution and scheduling series on +[ankurm.com](https://ankurm.com). Each directory is a self-contained Maven project for one article, with its own `pom.xml`, its own numbered documentation chapters, and its own captured output under `docs/output/` — regenerated by that module's `scripts/run-all.sh`, never typed by hand. @@ -8,6 +9,7 @@ by that module's `scripts/run-all.sh`, never typed by hand. | Module | Article | What it demonstrates | |---|---|---| | [`async/`](async/README.md) | [@Async in Spring Boot 4: Executors, Virtual Threads and the Self-Invocation Trap](https://ankurm.com/spring-boot-4-async-executors-virtual-threads/) | Which thread a method actually ran on, in every case where the answer is not the one you expect | +| [`scheduling/`](scheduling/README.md) | [@Scheduled, ShedLock and Distributed Cron: Scheduling That Survives Three Replicas](https://ankurm.com/spring-scheduled-shedlock-distributed-cron/) | Three replicas against one database running the same job three times, then one row and one conditional UPDATE fixing it | ## Common ground @@ -20,6 +22,15 @@ one: the name of the thread that ran the work, returned by the code itself. Timi fast synchronous call from an asynchronous one, which is why `@Async` failures survive so long in production. +The two modules share a mechanism, which is why they live together: both `@Async` and ShedLock's +default `PROXY_METHOD` intercept mode are Spring AOP proxies. Every proxy limitation the `async` +module measures — self-invocation, `final` methods — applies unchanged to a +`@SchedulerLock` method, and silently produces an unlocked job rather than a synchronous one. + +The `scheduling` module also needs a database. `scheduling/scripts/postgres.sh` unpacks a +throwaway PostgreSQL 14 into `target/` with no Docker and no root, which is how its transcripts +were produced; `docker-compose.yml` is there for anyone who would rather use Docker. + ## Licence MIT — see [LICENSE](LICENSE). diff --git a/scheduling/Dockerfile b/scheduling/Dockerfile new file mode 100644 index 0000000..e02cda4 --- /dev/null +++ b/scheduling/Dockerfile @@ -0,0 +1,15 @@ +# Used only by docker-compose.yml. The committed transcripts under docs/output/ were produced +# without Docker, by scripts/three-replicas.sh against the PostgreSQL that scripts/postgres.sh +# unpacks into target/. +FROM eclipse-temurin:25-jdk AS build +WORKDIR /src +COPY pom.xml . +RUN --mount=type=cache,target=/root/.m2 \ + apt-get update && apt-get install -y --no-install-recommends maven && \ + mvn -B -q dependency:go-offline +COPY src ./src +RUN --mount=type=cache,target=/root/.m2 mvn -B -q -DskipTests package + +FROM eclipse-temurin:25-jre +COPY --from=build /src/target/scheduling-1.0.jar /app.jar +ENTRYPOINT ["java", "-jar", "/app.jar"] diff --git a/scheduling/README.md b/scheduling/README.md new file mode 100644 index 0000000..8da2bfe --- /dev/null +++ b/scheduling/README.md @@ -0,0 +1,70 @@ +# scheduling + +Companion project for **@Scheduled, ShedLock and Distributed Cron: Scheduling That Survives Three +Replicas** on [ankurm.com](https://ankurm.com). + +Three replicas of one Spring Boot application run against one PostgreSQL database, and the +`job_execution` table records who ran what and when. Counting rows is the measurement. + +## Verified stack + +| Component | Version | Source of the number | +|---|---|---| +| JDK | 25.0.4.1+1 (Temurin) | `java -version` | +| Spring Boot | 4.1.1 | `maven-metadata.xml` on Maven Central | +| Spring Framework | 7.0.9 | `spring-boot-dependencies-4.1.1.pom` | +| ShedLock | 7.9.0 | `maven-metadata.xml`; **not managed by Boot**, so it is pinned in `pom.xml` | +| PostgreSQL | 14.24 | the broker the transcripts ran against; `docker-compose.yml` uses 17 | + +## Quickstart + +```bash +scripts/postgres.sh start # throwaway PostgreSQL 14 on :55432, no Docker, no root +scripts/three-replicas.sh unlocked # 24 executions where 8 were due +scripts/three-replicas.sh locked # 7 executions for 7 ticks +mvn test # scheduler-pool and clock-skew evidence +scripts/run-all.sh # regenerates every docs/output/ file +``` + +With Docker instead: + +```bash +docker compose up --build # unlocked +PROFILE=locked docker compose up --build # locked +``` + +## Profiles + +| Profile | What is active | Result | +|---|---|---| +| `unlocked` | `@SchedulerLock` on the job, and nothing else | every replica runs every tick | +| `locked` | `LockConfiguration`: `@EnableSchedulerLock` + a `LockProvider` with `usingDbTime()` | one execution per tick | +| `appclock` | the same, with a `LockProvider` that has no `usingDbTime()` | used by the clock-skew experiment | +| `poolprobe` | three competing `@Scheduled` methods | used by the scheduler-pool tests | + +## Documentation + +| Chapter | What it settles | +|---|---| +| [01 Three replicas, three executions](docs/01-three-replicas-three-executions.md) | The failure, and why `@SchedulerLock` alone does nothing | +| [02 The lock](docs/02-the-lock.md) | How one row and one conditional `UPDATE` fix it, and what the two durations mean | +| [03 One scheduler thread](docs/03-one-scheduler-thread.md) | `pool.size=1`: the same execution count, arriving in a burst | +| [04 Clock skew](docs/04-clock-skew.md) | A 40-second-fast node taking a live lock, and `usingDbTime()` refusing it | +| [05 When not to use a lock](docs/05-when-not-to-use-a-lock.md) | Idempotence, Kubernetes `CronJob`, Quartz, and a pre-ship checklist | + +## Captured output + +| File | What it shows | +|---|---| +| [`three-replicas-unlocked.txt`](docs/output/three-replicas-unlocked.txt) | 8 + 8 + 8 executions, 9 overlapping pairs, an empty lock table | +| [`three-replicas-locked.txt`](docs/output/three-replicas-locked.txt) | 7 executions, 0 overlaps, one lock row | +| [`scheduler-pool-1.txt`](docs/output/scheduler-pool-1.txt) | 40 executions, longest gap 1995 ms, 35 of them in a burst | +| [`scheduler-pool-4.txt`](docs/output/scheduler-pool-4.txt) | 41 executions, longest gap 201 ms, no burst | +| [`clock-skew.txt`](docs/output/clock-skew.txt) | Two holders of one lock, and `usingDbTime()` preventing it | +| [`tests.txt`](docs/output/tests.txt) | The test run behind the last three | + +## A note on the database + +`scripts/postgres.sh` downloads the PostgreSQL 14 `.deb` packages and unpacks them into +`target/pg` — no Docker, no root, no system-wide install. It exists because the transcripts had to +be reproducible on a machine with neither. If you have Docker, `docker-compose.yml` is simpler. diff --git a/scheduling/docker-compose.yml b/scheduling/docker-compose.yml new file mode 100644 index 0000000..701340c --- /dev/null +++ b/scheduling/docker-compose.yml @@ -0,0 +1,51 @@ +# Three replicas and one database, which is the smallest deployment in which a @Scheduled method +# misbehaves. Run `docker compose up --scale app=3` if you would rather set the replica count +# from the command line; the three named services below exist so that each one gets a stable +# INSTANCE_ID in the transcript. +# +# docker compose up --build +# docker compose exec db psql -U app -d shedlockdemo -c \ +# "select instance_id, count(*) from job_execution group by instance_id" +# +# SPRING_PROFILES_ACTIVE=unlocked reproduces the duplicate executions; switch it to `locked` to +# watch the count collapse to one per tick. + +services: + db: + image: postgres:17 + environment: + POSTGRES_USER: app + POSTGRES_DB: shedlockdemo + POSTGRES_HOST_AUTH_METHOD: trust + ports: ["5432:5432"] + healthcheck: + test: ["CMD-SHELL", "pg_isready -U app -d shedlockdemo"] + interval: 2s + timeout: 3s + retries: 20 + + replica-1: &replica + build: . + depends_on: + db: { condition: service_healthy } + environment: + DB_URL: jdbc:postgresql://db:5432/shedlockdemo + DB_USER: app + INSTANCE_ID: replica-1 + SPRING_PROFILES_ACTIVE: ${PROFILE:-unlocked} + + replica-2: + <<: *replica + environment: + DB_URL: jdbc:postgresql://db:5432/shedlockdemo + DB_USER: app + INSTANCE_ID: replica-2 + SPRING_PROFILES_ACTIVE: ${PROFILE:-unlocked} + + replica-3: + <<: *replica + environment: + DB_URL: jdbc:postgresql://db:5432/shedlockdemo + DB_USER: app + INSTANCE_ID: replica-3 + SPRING_PROFILES_ACTIVE: ${PROFILE:-unlocked} diff --git a/scheduling/docs/01-three-replicas-three-executions.md b/scheduling/docs/01-three-replicas-three-executions.md new file mode 100644 index 0000000..5b3c8f3 --- /dev/null +++ b/scheduling/docs/01-three-replicas-three-executions.md @@ -0,0 +1,75 @@ +[README](../README.md) · next: [The lock](02-the-lock.md) + +# 1. Three replicas, three executions + +`@Scheduled` is a per-JVM timer. It has no idea that other JVMs exist. Scale a deployment to +three replicas and every `@Scheduled` method in the application runs three times per tick, on +three machines, at almost the same instant. + +That is the whole problem, and it is worth seeing rather than reading. `scripts/three-replicas.sh` +starts three copies of this application against one PostgreSQL database, lets the 3-second +schedule tick for 30 seconds, and counts. + +From [`docs/output/three-replicas-unlocked.txt`](output/three-replicas-unlocked.txt): + +``` +-- executions per replica -- + instance_id | count +-------------+------- + replica-1 | 8 + replica-2 | 8 + replica-3 | 8 + +-- pairs of executions that overlapped -- + overlapping_pairs +------------------- + 8 + + 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 +``` + +Twenty-four executions where eight were due, and eight of them started while another replica was +still inside the method — 188 milliseconds apart in the first pair, against a job that only takes +200 milliseconds. Anything in that method which +is not idempotent is now a support ticket: a second invoice email, a double refund, two rows +where the unique constraint you did not add would have saved you. + +## The part that makes it hard to spot + +`ReportJob` is annotated `@SchedulerLock` in this run. Look at the end of the same transcript: + +``` +-- the lock row -- + name | locked_by | locked_at | lock_until +------+-----------+-----------+------------ +(0 rows) +``` + +The annotation is present, the lock table exists, the application started cleanly, and nothing +was ever locked. `@SchedulerLock` on its own is inert: it needs `@EnableSchedulerLock` to install +the interceptor and a `LockProvider` bean to have somewhere to record the lock. In this module +both live on `LockConfiguration`, which is `@Profile("locked")`. + +There is no warning for the missing half. That is the single most important sentence in this +module — an application with the annotation and without the plumbing behaves exactly like an +application with no locking at all, and it looks locked in code review. + +## Reproducing it + +```bash +scripts/postgres.sh start # a throwaway PostgreSQL 14, no Docker, no root +scripts/three-replicas.sh unlocked +scripts/three-replicas.sh locked +``` + +or, with Docker: + +```bash +docker compose up --build # PROFILE=locked docker compose up --build +``` + +next: [The lock](02-the-lock.md) diff --git a/scheduling/docs/02-the-lock.md b/scheduling/docs/02-the-lock.md new file mode 100644 index 0000000..007bfc9 --- /dev/null +++ b/scheduling/docs/02-the-lock.md @@ -0,0 +1,90 @@ +prev: [Three replicas, three executions](01-three-replicas-three-executions.md) · [README](../README.md) · next: [One scheduler thread](03-one-scheduler-thread.md) + +# 2. The lock + +Activate `LockConfiguration` and the same 30-second run produces this +([`docs/output/three-replicas-locked.txt`](output/three-replicas-locked.txt)): + +``` +-- executions per replica -- + instance_id | count +-------------+------- + replica-2 | 1 + replica-3 | 6 + +-- pairs of executions that overlapped -- + overlapping_pairs +------------------- + 0 + +-- the lock row -- + name | locked_by | locked_at | lock_until +---------------+-----------+--------------+-------------- + nightlyReport | unknown | 17:19:46.921 | 17:19:47.921 +``` + +Seven executions for seven ticks, no overlap. The mechanism is one row in one table and a +conditional `UPDATE`: acquire means "set `lock_until` to a future time **where** `lock_until` is +already in the past", and only one replica's update can win because the row is locked for the +duration of that statement. + +Three things in that transcript deserve attention. + +## ShedLock does not distribute work + +Six of the seven executions are `replica-3`. The lock is not a queue and there is no round-robin: +whichever replica's timer fires first each tick takes the lock, and on a stable cluster that is +overwhelmingly the same replica — here `replica-2` won the first tick and then never won +another. This is correct behaviour for "run exactly once" and +completely wrong if what you actually wanted was "spread the work across the cluster". For that +you want a work queue, not a lock. + +## `locked_by` is not identity + +It reads `unknown` above. ShedLock fills that column with the host name, and the host name of the +container that produced this transcript does not resolve, so it falls back. It is a diagnostic +field, never read back for correctness — but it does mean that on Kubernetes you often get a +column full of pod hashes or of `unknown`, and it is worth setting something meaningful if you +plan to use it during an incident. + +## The timestamps are in a different time zone from your own + +`locked_at` reads `17:19:46` while the execution recorded at the same moment in the same file +reads `22:49:46`. That is not a +bug; it is `usingDbTime()` doing its job. With it, the timestamps are written by PostgreSQL in +UTC, whereas `started_at` is written by the application in the JVM's zone. Anyone eyeballing the +`shedlock` table next to the application's own tables will see a five-and-a-half-hour discrepancy +and think the lock is stale. It is not. + +## The two durations + +```java +@SchedulerLock(name = "nightlyReport", lockAtMostFor = "PT20S", lockAtLeastFor = "PT1S") +``` + +**`lockAtMostFor`** is the answer to "the holder was `kill -9`'d; how long before somebody else +may run this?" It must be longer than the longest the job could possibly take, because when it +expires the lock is available whether or not the job finished. Set it to five minutes for a job +that normally takes ten seconds, and accept a five-minute gap after a crash — that is the trade, +and there is no setting that avoids it. + +**`lockAtLeastFor`** keeps the lock held for a minimum period after a fast job finishes. It exists +for clock skew and for schedules where two replicas' timers fire within milliseconds of each +other: without it, a job that completes in 20 ms releases the lock in time for the next replica's +tick to pick it up, and you are back to two executions. + +`@EnableSchedulerLock(defaultLockAtMostFor = ...)` has no default value in the annotation, so it +must be supplied. That is deliberate: there is no safe guess. + +## `interceptMode` + +ShedLock 7 defaults to `PROXY_METHOD`. The `PROXY_SCHEDULER` mode that most tutorials still show +is deprecated, and its own Javadoc says it "requires a reflection hack to work well with Spring +6.2". Leave the default alone. + +Because `PROXY_METHOD` is a Spring AOP proxy, everything from +[the `@Async` article](https://ankurm.com/spring-boot-4-async-executors-virtual-threads/) applies +here too: a `@SchedulerLock` method called from inside its own class is not locked, and a `final` +method is not locked. + +next: [One scheduler thread](03-one-scheduler-thread.md) diff --git a/scheduling/docs/03-one-scheduler-thread.md b/scheduling/docs/03-one-scheduler-thread.md new file mode 100644 index 0000000..023bacb --- /dev/null +++ b/scheduling/docs/03-one-scheduler-thread.md @@ -0,0 +1,56 @@ +prev: [The lock](02-the-lock.md) · [README](../README.md) · next: [Clock skew](04-clock-skew.md) + +# 3. One scheduler thread + +`spring.task.scheduling.pool.size` defaults to **1**. Every `@Scheduled` method in the +application shares that one thread. + +The expected consequence is that a slow job starves the others. What actually happens is more +interesting, and considerably worse. + +Three scheduled methods — one that sleeps 1800 ms on a 2000 ms schedule, one on a 200 ms +schedule, one that throws — running for eight seconds. First with the default single thread +([output](output/scheduler-pool-1.txt)), then with four +([output](output/scheduler-pool-4.txt)): + +| | pool.size=1 | pool.size=4 | +|---|---|---| +| `fast()` executions | 40 | 41 | +| longest gap between two `fast()` executions | **1995 ms** | 201 ms | +| `fast()` executions starting within 20 ms of the previous one | **35** | 0 | +| distinct scheduler threads | 1 | 4 | + +The execution *count* is the same. A `fixedRate` schedule does not skip a tick it could not run: +the missed executions accumulate and are then fired back to back the moment the thread is free. +Thirty-five of the forty executions arrived in a burst. + +So the metric everyone has — "the job ran 40 times, as expected" — is green, while the job's +actual behaviour is two seconds of silence followed by thirty-five invocations in a few +milliseconds. If that job calls a rate-limited API, or opens a database connection each time, the +burst is the incident. + +## What to set + +- **`spring.task.scheduling.pool.size`**: at least the number of `@Scheduled` methods that can + overlap. It costs a handful of mostly idle threads. +- **`fixedDelay` instead of `fixedRate`** where "every N seconds" really means "N seconds after + the last one finished". `fixedDelay` schedules the next run only after the current one + completes, so it cannot accumulate a backlog to burst through. +- **`spring.threads.virtual.enabled=true`** replaces the pool with a `SimpleAsyncTaskScheduler` + over virtual threads, which removes the shared-thread problem entirely. It also removes the + bound: `spring.task.scheduling.pool.size` is one of the properties Boot's own metadata marks + as having no effect when virtual threads are on. + +## An exception does not stop the schedule + +`throwing()` threw on all 27 of its executions and kept its schedule. Spring wraps a scheduled +method in `TaskUtils.LOG_AND_SUPPRESS_ERROR_HANDLER`, so the exception is logged by +`o.s.s.s.TaskUtils$LoggingErrorHandler` as `Unexpected error occurred in scheduled task` and +discarded. A raw `ScheduledExecutorService` would have cancelled the task after the first +failure — which is where the folklore comes from, and it does not apply to `@Scheduled`. + +The flip side is that a job which has been failing since the last deploy produces nothing but a +recurring `ERROR` line. Supply your own `SchedulingConfigurer` with an error handler if you want +a metric. + +next: [Clock skew](04-clock-skew.md) diff --git a/scheduling/docs/04-clock-skew.md b/scheduling/docs/04-clock-skew.md new file mode 100644 index 0000000..0c374f1 --- /dev/null +++ b/scheduling/docs/04-clock-skew.md @@ -0,0 +1,56 @@ +prev: [One scheduler thread](03-one-scheduler-thread.md) · [README](../README.md) · next: [When not to use a lock](05-when-not-to-use-a-lock.md) + +# 4. Clock skew, and what `usingDbTime()` is for + +```java +JdbcTemplateLockProvider.Configuration.builder() + .withJdbcTemplate(new JdbcTemplate(dataSource)) + .usingDbTime() + .build(); +``` + +Without `usingDbTime()`, each replica writes `lock_until` from its own clock and compares +`lock_until` against its own clock. The lock is then only as good as the agreement between three +machines about what time it is. + +Three replicas racing is not a proof, because a race can go either way. `ClockSkewTest` drives +the `LockProvider` directly instead, so the two acquisitions are ordered by the test and the only +variable is what the second caller believes the time to be +([`docs/output/clock-skew.txt`](output/clock-skew.txt)): + +``` +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 +``` + +A node whose clock is ahead by more than `lockAtMostFor` considers every live lock expired. It +takes the lock while somebody else is holding it, and the whole mechanism silently stops working +— for that node only, which is why it presents as "it usually runs once". + +The skew is simulated with ShedLock's own `ClockProvider.setClock(...)`, which is what the +provider reads for "now" on the non-database path. That is also the cheapest way to test this on +your own code: no NTP fiddling and no root. + +`usingDbTime()` moves both the write and the comparison into a SQL statement, so there is exactly +one clock in the system. It is supported on PostgreSQL, MySQL, MariaDB, MS SQL, Oracle, DB2, HSQL +and H2. + +**Use it.** Forty seconds of skew is not exotic — a VM resuming from a snapshot, a container on a +host with a broken NTP client, or a laptop that just woke up will all do it, and cloud instances +drift more than people expect. + +## What it does not fix + +`usingDbTime()` makes expiry decisions consistent. It does not shorten the window created by a +crash: if a holder dies, the lock still stays held until `lockAtMostFor` elapses. Nor does it help +if your `lockAtMostFor` is shorter than the job — in that case the lock expires legitimately, a +second replica starts, and both run. Size `lockAtMostFor` against the worst case, not the average. + +next: [When not to use a lock](05-when-not-to-use-a-lock.md) diff --git a/scheduling/docs/05-when-not-to-use-a-lock.md b/scheduling/docs/05-when-not-to-use-a-lock.md new file mode 100644 index 0000000..55cf8f4 --- /dev/null +++ b/scheduling/docs/05-when-not-to-use-a-lock.md @@ -0,0 +1,46 @@ +prev: [Clock skew](04-clock-skew.md) · [README](../README.md) + +# 5. When not to use a lock + +ShedLock is small, it has one dependency on your database, and it solves the stated problem. It +is still worth asking whether the problem should exist. + +**Make the job idempotent instead.** A lock is a way of avoiding a second execution. Idempotence +is a way of not caring about one. If the job's work can be keyed — "mark invoices dated +2026-09-01 as sent, where they are not already marked" — then three replicas running it produce +one outcome and you have removed a distributed-systems dependency rather than adding one. This is +almost always the better engineering, and it is almost never what the article you searched for +suggests. + +**A lock is not a guarantee of exactly-once.** It is a guarantee of at-most-one-per-lock-window, +which is different. If the holder dies halfway, the job did not complete and nothing retries it — +ShedLock has no notion of failure, only of expiry. Pairing it with a job table that records +completion is what makes "exactly once" true, and at that point the job table is doing most of +the work. + +**Consider the scheduler you already have.** A Kubernetes `CronJob` runs one pod per schedule and +needs no lock, no library and no table; it costs you a pod start per run and the schedule lives +outside the application. Quartz in clustered mode owns misfire policy, persistence and recovery, +at the price of eleven tables and a great deal of configuration. ShedLock sits between them: it +adds a lock to the scheduler you already have, and deliberately adds nothing else. + +**A lock provider needs its store to be consistent.** The JDBC provider is safe because a +conditional `UPDATE` on one row is atomic in every relational database. The Redis provider is +safe on a single instance and, as its own documentation notes, is subject to the well-known +argument about locks over Redis replication. If your store is eventually consistent, your lock +is too. + +## A short checklist for the version you ship + +- `@EnableSchedulerLock` present, and a `LockProvider` bean present — without both, the + annotation does nothing ([chapter 1](01-three-replicas-three-executions.md)) +- `usingDbTime()` on ([chapter 4](04-clock-skew.md)) +- `lockAtMostFor` longer than the worst-case run time, and you have accepted the gap it implies + after a crash +- `lockAtLeastFor` non-zero for any job shorter than the interval between two replicas' timers +- `spring.task.scheduling.pool.size` raised above 1 ([chapter 3](03-one-scheduler-thread.md)) +- the lock names are unique per job — two jobs sharing a name share a lock, and one of them stops + running +- the method carrying `@SchedulerLock` is called from outside its own class, and is not `final` + +[README](../README.md) diff --git a/scheduling/docs/output/clock-skew.txt b/scheduling/docs/output/clock-skew.txt new file mode 100644 index 0000000..bd3d27f --- /dev/null +++ b/scheduling/docs/output/clock-skew.txt @@ -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. + diff --git a/scheduling/docs/output/scheduler-pool-1.txt b/scheduling/docs/output/scheduler-pool-1.txt new file mode 100644 index 0000000..803a924 --- /dev/null +++ b/scheduling/docs/output/scheduler-pool-1.txt @@ -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 + diff --git a/scheduling/docs/output/scheduler-pool-4.txt b/scheduling/docs/output/scheduler-pool-4.txt new file mode 100644 index 0000000..522de41 --- /dev/null +++ b/scheduling/docs/output/scheduler-pool-4.txt @@ -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. + diff --git a/scheduling/docs/output/tests.txt b/scheduling/docs/output/tests.txt new file mode 100644 index 0000000..23431a6 --- /dev/null +++ b/scheduling/docs/output/tests.txt @@ -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 diff --git a/scheduling/docs/output/three-replicas-locked.txt b/scheduling/docs/output/three-replicas-locked.txt new file mode 100644 index 0000000..c2557f2 --- /dev/null +++ b/scheduling/docs/output/three-replicas-locked.txt @@ -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) + diff --git a/scheduling/docs/output/three-replicas-unlocked.txt b/scheduling/docs/output/three-replicas-unlocked.txt new file mode 100644 index 0000000..be4e959 --- /dev/null +++ b/scheduling/docs/output/three-replicas-unlocked.txt @@ -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) + diff --git a/scheduling/pom.xml b/scheduling/pom.xml new file mode 100644 index 0000000..bf290da --- /dev/null +++ b/scheduling/pom.xml @@ -0,0 +1,68 @@ + + 4.0.0 + + + org.springframework.boot + spring-boot-starter-parent + 4.1.1 + + + + com.ankurm + scheduling + 1.0 + jar + + + 25 + UTF-8 + + 7.9.0 + + + + + org.springframework.boot + spring-boot-starter + + + + org.springframework.boot + spring-boot-starter-jdbc + + + org.postgresql + postgresql + + + + net.javacrumbs.shedlock + shedlock-spring + ${shedlock.version} + + + net.javacrumbs.shedlock + shedlock-provider-jdbc-template + ${shedlock.version} + + + + org.springframework.boot + spring-boot-starter-test + test + + + + + + + org.springframework.boot + spring-boot-maven-plugin + + + + diff --git a/scheduling/scripts/postgres.sh b/scheduling/scripts/postgres.sh new file mode 100755 index 0000000..314a1c2 --- /dev/null +++ b/scheduling/scripts/postgres.sh @@ -0,0 +1,47 @@ +#!/usr/bin/env bash +# Starts a throwaway PostgreSQL 14 on port 55432 with no Docker and no root. +# +# On a Debian/Ubuntu machine the .deb packages can simply be downloaded and unpacked into a +# prefix; PostgreSQL does not need to be installed system-wide and refuses to run as root anyway. +# This is how docs/output/ was produced. If you have Docker, docker-compose.yml is easier. +# +# scripts/postgres.sh start|stop|psql +set -euo pipefail +cd "$(dirname "$0")/.." +PREFIX="$PWD/target/pg" +PGROOT="$PREFIX/root" +PGDATA="$PREFIX/data" +export PATH="$PGROOT/usr/lib/postgresql/14/bin:$PATH" +export LD_LIBRARY_PATH="$PGROOT/usr/lib/x86_64-linux-gnu:$PGROOT/lib/x86_64-linux-gnu:${LD_LIBRARY_PATH:-}" + +install_pg() { + mkdir -p "$PREFIX/debs" "$PGROOT" + ( cd "$PREFIX/debs" + for p in postgresql-14 postgresql-client-14 postgresql-common postgresql-client-common \ + libpq5 libllvm14 libicu70 libssl3 libxslt1.1 libxml2 libedit2 libbsd0 libmd0 \ + zlib1g liblz4-1 libzstd1 libtinfo6 libncurses6 libcom-err2 libkrb5-3 libk5crypto3 \ + libkrb5support0 libgssapi-krb5-2 libkeyutils1 libsasl2-2 libldap-2.5-0 libgnutls30 \ + libnettle8 libhogweed6 libgmp10 libp11-kit0 libtasn1-6 libidn2-0 libunistring2 libffi8; do + apt-get download "$p" >/dev/null 2>&1 || true + done + for d in *.deb; do dpkg -x "$d" "$PGROOT" 2>/dev/null || true; done ) +} + +case "${1:-start}" in + start) + [ -x "$PGROOT/usr/lib/postgresql/14/bin/initdb" ] || install_pg + if [ ! -d "$PGDATA" ]; then + initdb -D "$PGDATA" -U app --auth=trust -E UTF8 >/dev/null + fi + pg_ctl -D "$PGDATA" -o "-p 55432 -k $PREFIX -c listen_addresses=127.0.0.1" \ + -l "$PREFIX/pg.log" start >/dev/null 2>&1 || true + for _ in $(seq 1 30); do pg_isready -h 127.0.0.1 -p 55432 >/dev/null 2>&1 && break; sleep 1; done + psql -h 127.0.0.1 -p 55432 -U app -d postgres -tc \ + "select 1 from pg_database where datname='shedlockdemo'" | grep -q 1 || \ + psql -h 127.0.0.1 -p 55432 -U app -d postgres -q -c "create database shedlockdemo" + pg_isready -h 127.0.0.1 -p 55432 + ;; + stop) pg_ctl -D "$PGDATA" stop -m fast >/dev/null 2>&1 || true ;; + psql) shift; psql -h 127.0.0.1 -p 55432 -U app -d shedlockdemo "$@" ;; + *) echo "usage: $0 start|stop|psql" >&2; exit 2 ;; +esac diff --git a/scheduling/scripts/run-all.sh b/scheduling/scripts/run-all.sh new file mode 100755 index 0000000..bcb8177 --- /dev/null +++ b/scheduling/scripts/run-all.sh @@ -0,0 +1,16 @@ +#!/usr/bin/env bash +# Regenerates every file under docs/output/. Takes about three minutes: two three-replica runs of +# 30 seconds each plus the test suite, and three JVMs need roughly ten seconds to start on a +# small box. +set -euo pipefail +cd "$(dirname "$0")/.." +mkdir -p docs/output +scripts/postgres.sh start >/dev/null + +mvn -B -q -DskipTests package +mvn -B test 2>&1 | grep -E 'Running |Tests run:|BUILD ' > docs/output/tests.txt + +scripts/three-replicas.sh unlocked > docs/output/three-replicas-unlocked.txt +scripts/three-replicas.sh locked > docs/output/three-replicas-locked.txt + +echo "regenerated:"; ls -1 docs/output diff --git a/scheduling/scripts/three-replicas.sh b/scheduling/scripts/three-replicas.sh new file mode 100755 index 0000000..395c8e9 --- /dev/null +++ b/scheduling/scripts/three-replicas.sh @@ -0,0 +1,52 @@ +#!/usr/bin/env bash +# Starts three replicas of the application against one database, lets the schedule tick, and +# tallies who ran the job. +# +# scripts/three-replicas.sh unlocked # no @EnableSchedulerLock: every replica runs it +# scripts/three-replicas.sh locked # ShedLock with usingDbTime() +# scripts/three-replicas.sh appclock 40 # ShedLock without usingDbTime(), replica-3 40s fast +# +# Environment: +# RUN_FOR seconds to let the schedule tick (default 30; three JVMs need ~10s to start) +# JOB_DURATION ISO-8601 duration the job sleeps for (default PT0.2S) +set -euo pipefail +cd "$(dirname "$0")/.." +PROFILE="${1:-unlocked}" +SKEW_SECONDS="${2:-0}" +RUN_FOR="${RUN_FOR:-30}" +JOB_DURATION="${JOB_DURATION:-PT0.2S}" +JAR=target/scheduling-1.0.jar +PSQL=(scripts/postgres.sh psql) + +[ -f "$JAR" ] || mvn -B -q -DskipTests package + +"${PSQL[@]}" -q -c "delete from job_execution" -c "delete from shedlock" >/dev/null 2>&1 || true + +pids=() +for n in 1 2 3; do + skew=() + if [ "$SKEW_SECONDS" != "0" ] && [ "$n" = "3" ]; then + skew=(-Dclock.skew="PT${SKEW_SECONDS}S") + fi + java -Dspring.profiles.active="$PROFILE" -DINSTANCE_ID="replica-$n" \ + -Djob.duration="$JOB_DURATION" "${skew[@]}" \ + -jar "$JAR" > "target/replica-$n.log" 2>&1 & + pids+=($!) +done + +sleep "$RUN_FOR" +for p in "${pids[@]}"; do kill "$p" 2>/dev/null || true; done +wait 2>/dev/null || true + +echo "profile=$PROFILE replicas=3 run-for=${RUN_FOR}s job rate=3s job duration=$JOB_DURATION replica-3 clock skew=${SKEW_SECONDS}s" +echo +echo "-- every execution, in order --" +"${PSQL[@]}" -c "select instance_id, to_char(started_at,'HH24:MI:SS.MS') as started_at from job_execution order by started_at" +echo "-- executions per replica --" +"${PSQL[@]}" -c "select instance_id, count(*) from job_execution group by instance_id order by instance_id" +OVERLAP="b.id > a.id and b.instance_id <> a.instance_id and b.started_at < a.started_at + interval '$JOB_DURATION'" +echo "-- pairs of executions that overlapped (a second replica started while the first was still working) --" +"${PSQL[@]}" -c "select count(*) as overlapping_pairs from job_execution a join job_execution b on $OVERLAP" +"${PSQL[@]}" -c "select a.instance_id as first, to_char(a.started_at, 'HH24:MI:SS.MS') as first_at, b.instance_id as second, to_char(b.started_at, 'HH24:MI:SS.MS') as second_at from job_execution a join job_execution b on $OVERLAP order by a.started_at limit 6" +echo "-- the lock row --" +"${PSQL[@]}" -c "select name, locked_by, to_char(locked_at,'HH24:MI:SS.MS') as locked_at, to_char(lock_until,'HH24:MI:SS.MS') as lock_until from shedlock" diff --git a/scheduling/src/main/java/com/ankurm/scheduling/AppClockLockConfiguration.java b/scheduling/src/main/java/com/ankurm/scheduling/AppClockLockConfiguration.java new file mode 100644 index 0000000..a206d5e --- /dev/null +++ b/scheduling/src/main/java/com/ankurm/scheduling/AppClockLockConfiguration.java @@ -0,0 +1,33 @@ +package com.ankurm.scheduling; + +import javax.sql.DataSource; + +import net.javacrumbs.shedlock.core.LockProvider; +import net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateLockProvider; +import net.javacrumbs.shedlock.spring.annotation.EnableSchedulerLock; + +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.context.annotation.Profile; +import org.springframework.jdbc.core.JdbcTemplate; + +/** + * The same lock provider without {@code usingDbTime()}, so {@code lock_until} is computed from + * each replica's own clock via {@code ClockProvider.now()}. + * + *

Used only by the clock-skew experiment. Do not copy it into anything real. + * + *

See docs/04-clock-skew.md. + */ +@Configuration(proxyBeanMethods = false) +@Profile("appclock") +@EnableSchedulerLock(defaultLockAtMostFor = "PT30S") +public class AppClockLockConfiguration { + + @Bean + public LockProvider lockProvider(DataSource dataSource) { + return new JdbcTemplateLockProvider(JdbcTemplateLockProvider.Configuration.builder() + .withJdbcTemplate(new JdbcTemplate(dataSource)) + .build()); + } +} diff --git a/scheduling/src/main/java/com/ankurm/scheduling/ExecutionLog.java b/scheduling/src/main/java/com/ankurm/scheduling/ExecutionLog.java new file mode 100644 index 0000000..47c02f0 --- /dev/null +++ b/scheduling/src/main/java/com/ankurm/scheduling/ExecutionLog.java @@ -0,0 +1,39 @@ +package com.ankurm.scheduling; + +import java.time.Instant; +import java.util.List; +import java.util.Map; + +import org.springframework.jdbc.core.JdbcTemplate; +import org.springframework.stereotype.Component; + +/** Append-only record of who ran what and when, shared by all three replicas. */ +@Component +public class ExecutionLog { + + private final JdbcTemplate jdbc; + + public ExecutionLog(JdbcTemplate jdbc) { + this.jdbc = jdbc; + } + + public void record(String jobName, String instanceId, Instant startedAt) { + this.jdbc.update("insert into job_execution (job_name, instance_id, started_at) values (?, ?, ?)", + jobName, instanceId, java.sql.Timestamp.from(startedAt)); + } + + public List> all() { + return this.jdbc.queryForList( + "select instance_id, started_at from job_execution order by started_at"); + } + + public int count() { + Integer n = this.jdbc.queryForObject("select count(*) from job_execution", Integer.class); + return (n != null) ? n : 0; + } + + public void clear() { + this.jdbc.update("delete from job_execution"); + this.jdbc.update("delete from shedlock"); + } +} diff --git a/scheduling/src/main/java/com/ankurm/scheduling/LockConfiguration.java b/scheduling/src/main/java/com/ankurm/scheduling/LockConfiguration.java new file mode 100644 index 0000000..48fce44 --- /dev/null +++ b/scheduling/src/main/java/com/ankurm/scheduling/LockConfiguration.java @@ -0,0 +1,45 @@ +package com.ankurm.scheduling; + +import javax.sql.DataSource; + +import net.javacrumbs.shedlock.core.LockProvider; +import net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateLockProvider; +import net.javacrumbs.shedlock.spring.annotation.EnableSchedulerLock; + +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.context.annotation.Profile; +import org.springframework.jdbc.core.JdbcTemplate; + +/** + * The entire difference between the two runs in docs/output/. + * + *

{@code defaultLockAtMostFor} has no default value in the annotation, so it must be supplied. + * That is deliberate on ShedLock's part: it is the answer to “how long may this lock stay + * held if the holder dies without releasing it”, and there is no safe guess. + * + *

{@code interceptMode} defaults to {@code PROXY_METHOD} in ShedLock 7. The older + * {@code PROXY_SCHEDULER} that most tutorials still show is deprecated — its own Javadoc + * says it “requires a reflection hack to work well with Spring 6.2”. + * + *

See docs/02-the-lock.md. + */ +@Configuration(proxyBeanMethods = false) +@Profile("locked") +@EnableSchedulerLock(defaultLockAtMostFor = "PT30S") +public class LockConfiguration { + + /** + * {@code usingDbTime()} makes the database compute {@code lock_until}, so the lock survives + * clock skew between replicas. Without it, every replica writes a timestamp taken from its + * own clock, and a replica whose clock runs slow will consider a live lock expired. + * docs/output/clock-skew.txt is that experiment. + */ + @Bean + public LockProvider lockProvider(DataSource dataSource) { + return new JdbcTemplateLockProvider(JdbcTemplateLockProvider.Configuration.builder() + .withJdbcTemplate(new JdbcTemplate(dataSource)) + .usingDbTime() + .build()); + } +} diff --git a/scheduling/src/main/java/com/ankurm/scheduling/PoolProbeJob.java b/scheduling/src/main/java/com/ankurm/scheduling/PoolProbeJob.java new file mode 100644 index 0000000..e4db1a1 --- /dev/null +++ b/scheduling/src/main/java/com/ankurm/scheduling/PoolProbeJob.java @@ -0,0 +1,98 @@ +package com.ankurm.scheduling; + +import java.util.List; +import java.util.concurrent.ConcurrentSkipListSet; +import java.util.concurrent.CopyOnWriteArrayList; +import java.util.concurrent.atomic.AtomicInteger; + +import org.springframework.context.annotation.Profile; +import org.springframework.scheduling.annotation.Scheduled; +import org.springframework.stereotype.Component; + +/** + * Two scheduled methods sharing whatever scheduler the application has, plus one that always + * throws. + * + *

{@code spring.task.scheduling.pool.size} defaults to 1. The interesting + * part is what that does to a {@code fixedRate} job when another job occupies the thread: it is + * not skipped. The missed ticks accumulate and are then executed back to back the moment the + * thread frees up. Counting executions therefore shows nothing; the evidence is in the gaps + * between them. + * + *

See docs/03-one-scheduler-thread.md. + */ +@Component +@Profile("poolprobe") +public class PoolProbeJob { + + /** Millisecond timestamps of every fast() execution, in order. */ + private final List fastAt = new CopyOnWriteArrayList<>(); + + private final AtomicInteger slowRuns = new AtomicInteger(); + + private final AtomicInteger throwingRuns = new AtomicInteger(); + + private final ConcurrentSkipListSet schedulerThreads = new ConcurrentSkipListSet<>(); + + @Scheduled(fixedRate = 2000, initialDelay = 0) + public void slow() throws InterruptedException { + this.slowRuns.incrementAndGet(); + this.schedulerThreads.add(Thread.currentThread().getName()); + Thread.sleep(1800); + } + + @Scheduled(fixedRate = 200, initialDelay = 0) + public void fast() { + this.fastAt.add(System.currentTimeMillis()); + this.schedulerThreads.add(Thread.currentThread().getName()); + } + + /** + * Throws on every execution. A raw {@code ScheduledExecutorService} cancels a task after the + * first failure; Spring wraps scheduled methods in an error handler that logs and suppresses, + * so the schedule continues. Counted rather than assumed. + */ + @Scheduled(fixedRate = 300, initialDelay = 0) + public void throwing() { + this.throwingRuns.incrementAndGet(); + throw new IllegalStateException("scheduled method #" + this.throwingRuns.get() + " failed"); + } + + public int fastRuns() { + return this.fastAt.size(); + } + + /** The longest interval the fast job went without running, in milliseconds. */ + public long longestGapMillis() { + List at = List.copyOf(this.fastAt); + long worst = 0; + for (int i = 1; i < at.size(); i++) { + worst = Math.max(worst, at.get(i) - at.get(i - 1)); + } + return worst; + } + + /** Executions that started within 20 ms of the previous one: the catch-up burst. */ + public long burstExecutions() { + List at = List.copyOf(this.fastAt); + long burst = 0; + for (int i = 1; i < at.size(); i++) { + if (at.get(i) - at.get(i - 1) < 20) { + burst++; + } + } + return burst; + } + + public int slowRuns() { + return this.slowRuns.get(); + } + + public int throwingRuns() { + return this.throwingRuns.get(); + } + + public ConcurrentSkipListSet schedulerThreads() { + return this.schedulerThreads; + } +} diff --git a/scheduling/src/main/java/com/ankurm/scheduling/ReportJob.java b/scheduling/src/main/java/com/ankurm/scheduling/ReportJob.java new file mode 100644 index 0000000..cdb1d1f --- /dev/null +++ b/scheduling/src/main/java/com/ankurm/scheduling/ReportJob.java @@ -0,0 +1,54 @@ +package com.ankurm.scheduling; + +import java.time.Duration; +import java.time.Instant; + +import net.javacrumbs.shedlock.spring.annotation.SchedulerLock; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import org.springframework.beans.factory.annotation.Value; +import org.springframework.scheduling.annotation.Scheduled; +import org.springframework.stereotype.Component; + +/** + * The job every distributed-cron article is really about: something that must happen once per + * tick across the whole cluster, not once per replica. + * + *

It records every execution in {@code job_execution}, tagged with the instance that ran it. + * Counting rows per tick is the measurement. + * + *

The {@code @SchedulerLock} annotation below is present in every profile. On its own it does + * nothing at all: it needs {@code @EnableSchedulerLock} to install the interceptor and a + * {@code LockProvider} bean to have somewhere to put the lock. Both live in + * {@link LockConfiguration}, which is only active under the {@code locked} profile. An + * application missing either of them starts cleanly, logs nothing, and runs the job on every + * replica — which is the failure this module exists to reproduce. + */ +@Component +public class ReportJob { + + private static final Logger log = LoggerFactory.getLogger(ReportJob.class); + + private final ExecutionLog executions; + + private final String instanceId; + + private final Duration work; + + public ReportJob(ExecutionLog executions, @Value("${instance.id:unknown}") String instanceId, + @Value("${job.duration:PT0.2S}") Duration work) { + this.executions = executions; + this.instanceId = instanceId; + this.work = work; + } + + @Scheduled(fixedRateString = "${job.rate:PT3S}") + @SchedulerLock(name = "nightlyReport", lockAtMostFor = "PT20S", lockAtLeastFor = "PT1S") + public void run() throws InterruptedException { + Instant startedAt = Instant.now(); + log.info("nightlyReport running on {} at {}", this.instanceId, startedAt); + this.executions.record("nightlyReport", this.instanceId, startedAt); + Thread.sleep(this.work); + } +} diff --git a/scheduling/src/main/java/com/ankurm/scheduling/SchedulingApplication.java b/scheduling/src/main/java/com/ankurm/scheduling/SchedulingApplication.java new file mode 100644 index 0000000..a161662 --- /dev/null +++ b/scheduling/src/main/java/com/ankurm/scheduling/SchedulingApplication.java @@ -0,0 +1,38 @@ +package com.ankurm.scheduling; + +import java.time.Clock; +import java.time.Duration; + +import net.javacrumbs.shedlock.core.ClockProvider; + +import org.springframework.boot.SpringApplication; +import org.springframework.boot.autoconfigure.SpringBootApplication; +import org.springframework.scheduling.annotation.EnableScheduling; + +/** + * Three replicas of this application run against one PostgreSQL database. + * + *

{@code @EnableScheduling} is here; {@code @EnableSchedulerLock} deliberately is not. It + * lives on {@link LockConfiguration}, which is {@code @Profile("locked")}. The scheduled job + * carries its {@code @SchedulerLock} annotation in both profiles, so the only difference between + * the run that executes three times and the run that executes once is whether one + * {@code @Configuration} class is active. + * + *

See docs/01-three-replicas-three-executions.md. + */ +@SpringBootApplication +@EnableScheduling +public class SchedulingApplication { + + public static void main(String[] args) { + // -Dclock.skew=PT-40S shifts this replica's idea of "now" backwards by 40 seconds. + // ShedLock reads the wall clock through ClockProvider, so this is enough to simulate a + // machine whose NTP has drifted -- without needing root to change the system clock. + String skew = System.getProperty("clock.skew"); + if (skew != null) { + ClockProvider.setClock(Clock.offset(Clock.systemUTC(), Duration.parse(skew))); + System.out.println("clock.skew applied: " + skew + " -> now=" + ClockProvider.now()); + } + SpringApplication.run(SchedulingApplication.class, args); + } +} diff --git a/scheduling/src/main/resources/application.yaml b/scheduling/src/main/resources/application.yaml new file mode 100644 index 0000000..6d54fac --- /dev/null +++ b/scheduling/src/main/resources/application.yaml @@ -0,0 +1,24 @@ +spring: + application: + name: scheduling + datasource: + url: ${DB_URL:jdbc:postgresql://127.0.0.1:55432/shedlockdemo} + username: ${DB_USER:app} + password: ${DB_PASSWORD:} + sql: + init: + mode: always + # spring.task.scheduling.pool.size defaults to 1. Left alone here on purpose: see + # docs/03-one-scheduler-thread.md for what that costs, measured. + +instance: + id: ${INSTANCE_ID:local} +job: + rate: PT3S + duration: PT0.2S + +logging: + level: + root: WARN + com.ankurm.scheduling: INFO + net.javacrumbs.shedlock: INFO diff --git a/scheduling/src/main/resources/schema.sql b/scheduling/src/main/resources/schema.sql new file mode 100644 index 0000000..975d61e --- /dev/null +++ b/scheduling/src/main/resources/schema.sql @@ -0,0 +1,18 @@ +-- Both tables are created by every replica at startup, so every statement is IF NOT EXISTS. +-- The shedlock table's shape is fixed by ShedLock: name, lock_until, locked_at, locked_by. +-- lock_until and locked_at must be timestamps; with usingDbTime() they are written by the +-- database, so their precision and time zone are the database's, not the JVM's. +create table if not exists shedlock ( + name varchar(64) not null, + lock_until timestamp not null, + locked_at timestamp not null, + locked_by varchar(255) not null, + primary key (name) +); + +create table if not exists job_execution ( + id serial primary key, + job_name varchar(64) not null, + instance_id varchar(64) not null, + started_at timestamp not null +); diff --git a/scheduling/src/test/java/com/ankurm/scheduling/Capture.java b/scheduling/src/test/java/com/ankurm/scheduling/Capture.java new file mode 100644 index 0000000..f9101a3 --- /dev/null +++ b/scheduling/src/test/java/com/ankurm/scheduling/Capture.java @@ -0,0 +1,23 @@ +package com.ankurm.scheduling; + +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; + +/** Writes a transcript under docs/output/. */ +final class Capture { + + private Capture() { + } + + static void write(String fileName, String heading, String body) { + Path dir = Path.of(System.getProperty("user.dir"), "docs", "output"); + try { + Files.createDirectories(dir); + Files.writeString(dir.resolve(fileName), "== " + heading + " ==\n\n" + body + "\n"); + } + catch (IOException ex) { + throw new IllegalStateException("could not write " + fileName, ex); + } + } +} diff --git a/scheduling/src/test/java/com/ankurm/scheduling/ClockSkewTest.java b/scheduling/src/test/java/com/ankurm/scheduling/ClockSkewTest.java new file mode 100644 index 0000000..920b21a --- /dev/null +++ b/scheduling/src/test/java/com/ankurm/scheduling/ClockSkewTest.java @@ -0,0 +1,106 @@ +package com.ankurm.scheduling; + +import java.time.Clock; +import java.time.Duration; +import java.time.Instant; +import java.util.Optional; + +import javax.sql.DataSource; + +import net.javacrumbs.shedlock.core.ClockProvider; +import net.javacrumbs.shedlock.core.LockConfiguration; +import net.javacrumbs.shedlock.core.LockProvider; +import net.javacrumbs.shedlock.core.SimpleLock; +import net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateLockProvider; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; + +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.boot.test.context.SpringBootTest; +import org.springframework.jdbc.core.JdbcTemplate; +import org.springframework.test.context.ActiveProfiles; + +import static org.assertj.core.api.Assertions.assertThat; + +/** + * What {@code usingDbTime()} is actually for. + * + *

Driving the {@code LockProvider} directly rather than through three replicas, because the + * three-replica run is a race and a race cannot prove a negative. Here the two acquisitions are + * ordered by the test, and the only thing that changes between them is what the second caller + * believes the time to be. + * + *

See docs/04-clock-skew.md. + */ +@SpringBootTest(properties = "job.rate=PT1H") +@ActiveProfiles("locked") +class ClockSkewTest { + + private static final String LOCK_NAME = "skewProbe"; + + @Autowired + private JdbcTemplate jdbc; + + @AfterEach + void resetClock() { + ClockProvider.setClock(Clock.systemUTC()); + this.jdbc.update("delete from shedlock where name = ?", LOCK_NAME); + } + + @Test + void withAppTimeAFastClockStealsALiveLock() { + LockProvider provider = provider(false); + Optional first = acquire(provider); + assertThat(first).isPresent(); + + // A second node whose clock is 40 seconds fast, asking for the same lock while the first + // holder is still working. + ClockProvider.setClock(Clock.offset(Clock.systemUTC(), Duration.ofSeconds(40))); + Optional second = acquire(provider); + + assertThat(second).isPresent(); + Capture.write("clock-skew.txt", "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. + """); + } + + @Test + void withDbTimeTheSameFastClockIsRefused() { + LockProvider provider = provider(true); + assertThat(acquire(provider)).isPresent(); + + ClockProvider.setClock(Clock.offset(Clock.systemUTC(), Duration.ofSeconds(40))); + + assertThat(acquire(provider)).isEmpty(); + } + + private Optional acquire(LockProvider provider) { + return provider.lock(new LockConfiguration(ClockProvider.now(), LOCK_NAME, + Duration.ofSeconds(30), Duration.ZERO)); + } + + private LockProvider provider(boolean dbTime) { + DataSource dataSource = this.jdbc.getDataSource(); + JdbcTemplateLockProvider.Configuration.Builder builder = + JdbcTemplateLockProvider.Configuration.builder() + .withJdbcTemplate(new JdbcTemplate(dataSource)); + if (dbTime) { + builder = builder.usingDbTime(); + } + return new JdbcTemplateLockProvider(builder.build()); + } +} diff --git a/scheduling/src/test/java/com/ankurm/scheduling/LargerSchedulerPoolTest.java b/scheduling/src/test/java/com/ankurm/scheduling/LargerSchedulerPoolTest.java new file mode 100644 index 0000000..cb6f229 --- /dev/null +++ b/scheduling/src/test/java/com/ankurm/scheduling/LargerSchedulerPoolTest.java @@ -0,0 +1,37 @@ +package com.ankurm.scheduling; + +import org.junit.jupiter.api.Test; + +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.boot.test.context.SpringBootTest; +import org.springframework.test.context.ActiveProfiles; + +import static org.assertj.core.api.Assertions.assertThat; + +/** The same three jobs with four scheduler threads. One property; the schedule is kept. */ +@SpringBootTest(properties = { "job.rate=PT1H", "spring.task.scheduling.pool.size=4" }) +@ActiveProfiles("poolprobe") +class LargerSchedulerPoolTest { + + @Autowired + private PoolProbeJob job; + + @Test + void fourThreadsKeepTheFastJobOnItsSchedule() throws Exception { + Thread.sleep(8000); + + assertThat(this.job.longestGapMillis()).isLessThan(600); + assertThat(this.job.burstExecutions()).isZero(); + assertThat(this.job.throwingRuns()).isGreaterThan(15); + + Capture.write("scheduler-pool-4.txt", "spring.task.scheduling.pool.size=4", + SingleSchedulerThreadTest.report(this.job) + """ + + 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. + """); + } +} diff --git a/scheduling/src/test/java/com/ankurm/scheduling/SingleSchedulerThreadTest.java b/scheduling/src/test/java/com/ankurm/scheduling/SingleSchedulerThreadTest.java new file mode 100644 index 0000000..3889ea5 --- /dev/null +++ b/scheduling/src/test/java/com/ankurm/scheduling/SingleSchedulerThreadTest.java @@ -0,0 +1,52 @@ +package com.ankurm.scheduling; + +import org.junit.jupiter.api.Test; + +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.boot.test.context.SpringBootTest; +import org.springframework.test.context.ActiveProfiles; + +import static org.assertj.core.api.Assertions.assertThat; + +/** + * The Boot default, {@code spring.task.scheduling.pool.size=1}. + * + *

The naive expectation is that the 200 ms job runs fewer times. It does not: {@code fixedRate} + * accumulates its missed ticks and fires them in a burst when the thread is released. The damage + * is to the schedule, not to the count, which is why this is so easy to miss in a metric. + */ +@SpringBootTest(properties = { "job.rate=PT1H", "spring.task.scheduling.pool.size=1" }) +@ActiveProfiles("poolprobe") +class SingleSchedulerThreadTest { + + @Autowired + private PoolProbeJob job; + + @Test + void oneSlowJobWrecksTheOtherJobsSchedule() throws Exception { + Thread.sleep(8000); + + assertThat(this.job.schedulerThreads()).hasSize(1); + assertThat(this.job.longestGapMillis()).isGreaterThan(1000); + assertThat(this.job.burstExecutions()).isGreaterThan(3); + + Capture.write("scheduler-pool-1.txt", "spring.task.scheduling.pool.size=1 (the default)", + report(this.job)); + } + + static String report(PoolProbeJob job) { + return """ + over 8 seconds, three @Scheduled methods on one application + slow() fixedRate 2000 ms, sleeps 1800 ms : %d executions + fast() fixedRate 200 ms : %d executions + throwing() fixedRate 300 ms, always throws : %d executions + distinct scheduler threads : %d %s + + longest gap between two fast() executions : %d ms (200 ms was the schedule) + fast() executions that started within 20 ms + of the previous one (the catch-up burst) : %d + """.formatted(job.slowRuns(), job.fastRuns(), job.throwingRuns(), + job.schedulerThreads().size(), job.schedulerThreads(), + job.longestGapMillis(), job.burstExecutions()); + } +}