cockroachdb / cockroachdb/cockroach

`SELECT FOR UPDATE SKIP LOCKED` skips unlocked rows sometimes?

Open
#121,917 31 comments 1 reaction 0 assignees View on GitHub
A-read-committed A-sql-optimizer branch-release-23.2 branch-release-24.1 branch-release-24.2 C-performance O-community T-sql-queries v24.1.5 X-blathers-triaged
Dominant language
Go
Stars
32.5k
Forks
4.1k
PR merge metrics
PR metrics pending

Description

**Describe the problem**

I'm working on a job queue system backed by CRDB and I've run into a situation I don't understand. I'm hoping someone can shed some light on it for me.

**To Reproduce**

1. Set up a CRDB Serverless cluster.
2. Clone the repro code in [this repo](https://github.com/asg0451/crdbtestjobs).
3. Run with `DATABASE_URL="" NUM_WORKERS=2 go run .`

The program sets up a jobs table (see [schema.sql](https://github.com/asg0451/crdbtestjobs/blob/master/schema.sql)), seeds it with a few jobs, then runs some workers that poll for work using `SELECT FOR UPDATE SKIP LOCKED` [here](https://github.com/asg0451/crdbtestjobs/blob/05356fb1b86ad24fe56dae7b371b250814d0025b/query.sql#L2)

**Expected behavior**

I expect each worker to grab a job, "process" it, then grab a new one, until no jobs remain. However, observing the log output, you can see that frequently workers fail to find jobs. In fact, It seems like after the first job each gets, it fails to see a new job while the other is working one one. Why is this?

Example run (annotated):
```
time=2024-04-08T00:29:46.725-04:00 level=DEBUG msg="running schema.sql"
time=2024-04-08T00:29:47.175-04:00 level=DEBUG msg="resetting jobs"
time=2024-04-08T00:29:48.629-04:00 level=INFO msg="job found" worker=1 job="{String:a Valid:true}"
time=2024-04-08T00:29:48.673-04:00 level=INFO msg="job found" worker=0 job="{String:b Valid:true}" // See here they both got jobs
time=2024-04-08T00:29:53.888-04:00 level=INFO msg="job finished" worker=0 job="{ID:{Bytes:[42 4 203 147 205 42 74 144 146 202 156 73 71 160 90 207] Valid:true} Name:{String:b Valid:true} CreatedAt:{Time:2024-04-08 04:29:47.29262 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-08 04:29:48.443138 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 0 Valid:true}}"
time=2024-04-08T00:29:53.888-04:00 level=INFO msg="job finished" worker=1 job="{ID:{Bytes:[24 96 114 86 121 83 76 129 168 179 161 17 215 75 124 18] Valid:true} Name:{String:a Valid:true} CreatedAt:{Time:2024-04-08 04:29:47.29262 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-08 04:29:48.422372 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 1 Valid:true}}"
time=2024-04-08T00:29:54.371-04:00 level=INFO msg="no job found" worker=0 // but now worker 0 can't find any while 1 is working on its
time=2024-04-08T00:29:54.371-04:00 level=INFO msg="job found" worker=1 job="{String:d Valid:true}"
time=2024-04-08T00:29:54.848-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:55.349-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:55.800-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:56.251-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:56.739-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:57.176-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:57.656-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:58.117-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:58.586-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:59.029-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:29:59.475-04:00 level=INFO msg="job finished" worker=1 job="{ID:{Bytes:[98 32 63 71 154 255 64 96 191 82 227 157 177 117 4 16] Valid:true} Name:{String:d Valid:true} CreatedAt:{Time:2024-04-08 04:29:47.29262 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-08 04:29:54.199079 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 1 Valid:true}}"
time=2024-04-08T00:29:59.484-04:00 level=INFO msg="no job found" worker=0 // ditto
time=2024-04-08T00:29:59.938-04:00 level=INFO msg="job found" worker=1 job="{String:c Valid:true}"
time=2024-04-08T00:29:59.939-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:00.412-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:00.875-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:01.346-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:01.799-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:02.235-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:02.745-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:03.181-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:03.655-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:04.124-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:04.538-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:04.969-04:00 level=INFO msg="no job found" worker=0
time=2024-04-08T00:30:05.029-04:00 level=INFO msg="job finished" worker=1 job="{ID:{Bytes:[143 160 240 141 130 52 77 159 151 19 223 198 14 146 153 33] Valid:true} Name:{String:c Valid:true} CreatedAt:{Time:2024-04-08 04:29:47.29262 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-08 04:29:59.789133 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 1 Valid:true}}"
time=2024-04-08T00:30:05.400-04:00 level=INFO msg="job found" worker=0 job="{String:f Valid:true}" // worker 0 wins the race this time and now worker 1 can't find a job!
time=2024-04-08T00:30:05.431-04:00 level=INFO msg="no job found" worker=1
time=2024-04-08T00:30:05.850-04:00 level=INFO msg="no job found" worker=1
time=2024-04-08T00:30:06.246-04:00 level=INFO msg="no job found" worker=1
time=2024-04-08T00:30:06.655-04:00 level=INFO msg="no job found" worker=1
(ctrl-c for brevity)
```

Contrast this with postgres's behaviour under the same code:
```
time=2024-04-08T02:42:40.602-04:00 level=DEBUG msg="running schema.sql"
time=2024-04-08T02:42:41.026-04:00 level=DEBUG msg="resetting jobs"
time=2024-04-08T02:42:42.392-04:00 level=INFO msg="job found" worker=2 job="{String:a Valid:true}"
time=2024-04-08T02:42:42.392-04:00 level=INFO msg="job found" worker=0 job="{String:c Valid:true}"
time=2024-04-08T02:42:42.392-04:00 level=INFO msg="job found" worker=1 job="{String:b Valid:true}"
time=2024-04-08T02:42:47.547-04:00 level=INFO msg="job finished" worker=2 job="{ID:{Bytes:[123 153 228 234 250 118 67 31 188 172 62 47 39 114 235 127] Valid:true} Name:{String:a Valid:true} CreatedAt:{Time:2024-04-07 23:42:41.218606 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-07 23:42:42.258571 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 2 Valid:true}}"
time=2024-04-08T02:42:47.547-04:00 level=INFO msg="job finished" worker=0 job="{ID:{Bytes:[55 177 105 201 234 84 68 211 134 237 144 62 45 182 176 121] Valid:true} Name:{String:c Valid:true} CreatedAt:{Time:2024-04-07 23:42:41.218606 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-07 23:42:42.258597 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 0 Valid:true}}"
time=2024-04-08T02:42:47.620-04:00 level=INFO msg="job finished" worker=1 job="{ID:{Bytes:[217 121 73 159 166 146 79 234 140 118 76 52 225 118 36 173] Valid:true} Name:{String:b Valid:true} CreatedAt:{Time:2024-04-07 23:42:41.218606 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-07 23:42:42.258517 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 1 Valid:true}}"
time=2024-04-08T02:42:47.982-04:00 level=INFO msg="job found" worker=0 job="{String:d Valid:true}"
time=2024-04-08T02:42:47.987-04:00 level=INFO msg="job found" worker=2 job="{String:e Valid:true}"
time=2024-04-08T02:42:48.034-04:00 level=INFO msg="job found" worker=1 job="{String:f Valid:true}"
time=2024-04-08T02:42:53.091-04:00 level=INFO msg="job finished" worker=0 job="{ID:{Bytes:[174 45 184 28 42 93 76 98 145 129 73 191 190 117 226 255] Valid:true} Name:{String:d Valid:true} CreatedAt:{Time:2024-04-07 23:42:41.218606 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-07 23:42:47.938799 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 0 Valid:true}}"
time=2024-04-08T02:42:53.091-04:00 level=INFO msg="job finished" worker=2 job="{ID:{Bytes:[76 229 28 127 149 214 68 210 174 220 73 184 30 206 11 105] Valid:true} Name:{String:e Valid:true} CreatedAt:{Time:2024-04-07 23:42:41.218606 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-07 23:42:47.935604 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 2 Valid:true}}"
time=2024-04-08T02:42:53.111-04:00 level=INFO msg="job finished" worker=1 job="{ID:{Bytes:[151 115 250 132 130 210 75 164 130 102 233 183 252 28 183 50] Valid:true} Name:{String:f Valid:true} CreatedAt:{Time:2024-04-07 23:42:41.218606 +0000 UTC InfinityModifier:finite Valid:true} CompletedAt:{Time:2024-04-07 23:42:48.009649 +0000 UTC InfinityModifier:finite Valid:true} CompletedBy:{String:cc/crdbtestjobs 1 Valid:true}}"
time=2024-04-08T02:42:53.540-04:00 level=INFO msg="no job found" worker=1
time=2024-04-08T02:42:53.540-04:00 level=INFO msg="no job found" worker=2
time=2024-04-08T02:42:53.551-04:00 level=INFO msg="no job found" worker=0
(they actually did them all)
```

As you can see, postgres does not have this issue at all.

**Additional data / screenshots**
Everything is in the linked repo

**Environment:**
- CockroachDB version: Serverless, AWS v23.2.3
- Server OS: ?
- Client app golang crdbpgxv5

See #167582 for the likely cause.

Jira issue: CRDB-37619

EDIT: All of a sudden this stopped happening for NUM_WORKERS=2 -- both of them reliably got jobs. Running with NUM_WORKERS=3 exhibits the issue again. Idk what changed.

Epic CRDB-65887

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.