INC-0007 Priority Inversion

07 / the gate

The release had been two hours from shipping for two hours.

[ALERT] INC-0007 — Release gate blocked, no progress 2h11m
[INFO ] gate task priority: P0
[INFO ] gate task state: BLOCKED on m-db
[INFO ] m-db holder: running
[INFO ] m-db holder: preempted
[INFO ] m-db holder: running
[INFO ] m-db holder: preempted
[WARN ] m-db held 2h11m, longest hold in 90d: 40ms

Nothing was deadlocked. The holder of m-db was alive and scheduled and making forward progress in slices too short to finish anything.

Bob read the log over Andy’s shoulder for about four seconds.

“Your highest-priority task is waiting on your lowest-priority task.”

“That’s backwards.”

“That’s the name.” He pulled up a chair, which meant this was going to take a while. “P0 needs the lock. Something small and unimportant has it. And something in the middle — busy, harmless, correctly configured — keeps knocking the small thing off the CPU before it can let go. Every one of the three is behaving exactly as designed.”

Andy looked at the task table. Four tasks, four priorities, four mutexes, and one line in the incident header telling him where the wait edge pointed.

“So I find who holds m-db.”

“And what priority they’re at,” Bob said. “That’s the part you’re going to want to write down.”

evidence retained

The task running at P1 holds m-tmp.
m-log is not held by the P0 task.
t-render holds m-io.
t-audit does not run at P3.
Whatever holds m-log, it is not running at P3.
t-billing runs at P1.
The P0 task does not hold m-db — it is waiting on it.

messages bob

Bob 16:40

Four of everything now. The board is bigger but the rules haven't changed: one priority and one mutex per task.

Bob 16:41

Left columns are tasks and priorities. Rows are mutexes and priorities.

Bob 16:43

The header already tells you the gate is blocked on m-db. So the answer is whoever is holding it.

Bob 16:44

Format: task, priority, holds.

table scheduler classes

fault

Release gate blocked

wait edge

P0 → m-db

severity

SEV-1

Skip the grid, go to the answer

	t-audit	t-render	t-billing	t-gc	P0	P1	P2	P3
m-io
m-db
m-log
m-tmp
P0
P1
P2
P3

answer input incident response

Question: Which task holds the mutex the release gate is waiting on — task, priority, and the mutex it holds?

operator answer

07 / after the inversion

t-gc — the garbage collector, the least important thing in the system — held m-db at P3.

t-render, the release gate, sat at P0 and waited for it.

And t-billing at P1, doing ordinary invoice work, became runnable roughly every eleven milliseconds and preempted t-gc each time. The collector got its slice back, did four microseconds of work, and lost the CPU again.

The highest-priority task in the system was, in practice, running at the priority of the lowest.

sched-timeline — INC-0007

  P0  t-render   ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░  blocked on m-db
  P1  t-billing  ██░░██░░██░░██░░██░░██░░██░░██░░  runnable, preempts
  P2  t-audit    ░░██░░░░░░██░░░░░░██░░░░░░██░░░░
  P3  t-gc       ░░░░█░░░░░░░█░░░░░░░█░░░░░░░█░░░  holds m-db

                 └── 4µs slices, never reaches release ──┘

  ► m-db acquired  14:29:06.118   by t-gc (P3)
  ► m-db released  —
  ► t-render waiting 2h11m at P0
  ► no priority inheritance configured on m-db

07 / loose thread

The fix was a scheduler flag nobody had needed before: let the holder inherit the waiter’s priority until it lets go. Ten minutes of work.

Andy spent the rest of the afternoon on the part that was not the fix, which was why t-gc had been at P3 at all. It had shipped at P1. Somebody had moved it.

git — sched/classes.yaml

  $ git log --show-signature -1 sched/classes.yaml

  commit  7c41ae0  sched: lower t-gc to P3 to reduce db contention
  Date:   96 days after last recorded activity for this key
  gpg:    Good signature from "maintainer_key=r.sato"
  gpg:    Primary key fingerprint: 4F19 8A2C 77D0 …
  Reviewed-by: —
  ────────────────────────────────────────────────────────────
  ► signature verified
  ► author not found in directory

07 / the obvious thing

Andy wrote it in his notes the way he would have written it in a postmortem, because it was not a suspicion, it was just true:

a good signature proves someone had the key
it does not prove someone was there

Rin’s key had signed a one-line change to a scheduler class three months after Rin stopped existing as far as the company was concerned. The commit was correct. The signature was correct. The change was even defensible — t-gc really was hammering the database.

He asked Bob whether offboarding revoked keys.

Bob said offboarding was a form, and forms were filled in by people, and then he went to get more coffee and did not come back.

NEXT INCIDENT →