Postgres - Monitoring Time-Based Slot Lag

STATUS

#

This is a work in progress.

TODO

#

• Handle non-movement
• Ensure data persistence between runs
• Alert separately when the slot is stuck, meaning $l$ has not moved for a set time while $w_{t_n} > l_{t_n}$
• Clean up old samples where wal < lsn? is that right?
• Add notes
  • stuck slot alerting. That is a separate concern not covered here.
  • The error rate (accuracy) is at most one sampling interval and should be set to well beneath any alert threshold
  • debezium heartbeat is required in order to track slot progress. if a consumer does not confirm lsn vs wal then an unrelated db or table could progress independent of the slot causing a false lag
• consider adding metrics for consumer and produce rates and treating them as a normalized ratio which can then be considered a deriviative funciton to determine if and when consumer lag will overcome production

Overview

#

We will use linear interpolation to estimate time-based lag of Postgres replica slots to the WAL.

Variables

#

• $t_n$ is the time of the $n$-th sample
• $w_{t_n}$ is the WAL position at $t_n$
• $l_{t_n}$ is the slot LSN at $t_n$
• $\Delta w_n$ is the WAL produced between samples $n-1$ and $n$
• $\Delta l_n$ is the WAL consumed by the slot between samples $n-1$ and $n$
• $\mathit{lag}_n$ is the time-based lag of the slot at $t_n$

Any variable computed at sample $n$ needs at least one earlier sample, so none of them exist at $n = 0$. $\Delta w_n$ and $\Delta l_n$ compare sample $n$ with sample $n-1$. $\mathit{lag}n$ looks back for the earlier sample where the WAL was still at or below the slot’s position $l{t_n}$. If no sample goes back that far, the lag cannot be computed yet.

The data points do not carry a timestamp via metadata, so we use $t_{now}$ at the time of sampling to approximate time.

Sample set

#

Let us consider the following sample set

Example scenario

#

Consider $t_4 = 50$

The slot has consumed the WAL up to position 50. The time-based lag is how long ago the WAL was at that position. Let $t^*$ be the time at which the WAL was at position $l_{t_4}$. Then the lag is

We never sampled the WAL at position 50, so we have to estimate $t^*$ from the samples around it.

1. Find the samples on either side

#

The WAL position never decreases, so we look for the last sample where the WAL had not yet passed 50. From the table, $w_{t_3} = 10$ and $w_{t_4} = 100$, so the WAL passed 50 somewhere between $t_3$ and $t_4$.

$t_2$ also has $w_{t_2} = 10$, but the WAL did not move between $t_2$ and $t_3$. The latest sample is the one that matters, because that is the last time we know the WAL was still at 10. In general, the lower sample is

2. Work out how far through that interval the WAL reached 50

#

Between $t_3$ and $t_4$ the WAL moved from 10 to 100

To reach the slot’s position it only had to move from 10 to 50

So the WAL reached 50 at this fraction of the way through the interval

3. Convert the fraction to a time

#

We assume the WAL grew at a steady rate between the two samples. This is the linear interpolation. Under that assumption the same fraction of the WAL growth takes the same fraction of the time. The interval is

so the WAL reached 50 this long after $t_3$

which puts $t^*$ at

4. Compute the lag

#

The slot is about 11.11 time units behind the WAL.

Example Code

#

The pseudocode below is Scheme . query-row stands in for whatever Postgres client you use, and returns one row as a list. Each sample is a list (t w l), and the samples are kept in a vector, oldest first.

;; One sample of t (seconds), w (WAL position in bytes) and l (slot position in bytes).
(define sample-sql
  "SELECT extract(epoch FROM clock_timestamp())        AS t, -- now, in seconds since 1970
          pg_wal_lsn_diff(pg_current_wal_lsn(), '0/0') AS w, -- the WAL's position as a byte count
          pg_wal_lsn_diff(confirmed_flush_lsn, '0/0')  AS l  -- the slot's position as a byte count
     FROM pg_replication_slots                              -- one row per replication slot
    WHERE slot_name = $1                                    -- $1 is the slot we are watching
  ")

;; Run the query for one slot and get back one sample, the list (t w l).
(define (take-sample conn slot-name)
  (query-row conn sample-sql slot-name))

;; Read the parts of a sample (t w l) by position.
(define (sample-t s) (car s))    ; 1st item, t
(define (sample-w s) (cadr s))   ; 2nd item, w
(define (sample-l s) (caddr s))  ; 3rd item, l

;; k = the latest sample at or before n where the WAL was at or below l.
;; #f when no sample goes back that far.
(define (find-k samples n l)
  (let loop ((i n))                                     ; start at the newest sample, i = n
    (cond ((< i 0) #f)                                  ; ran out of samples, so there is no k
          ((<= (sample-w (vector-ref samples i)) l) i)  ; WAL at or below l, so this is k
          (else (loop (- i 1))))))                      ; otherwise try the sample before

;; t* = the time the WAL was at position l, interpolated between samples a and b.
(define (interpolate-time a b l)
  (let ((f (/ (- l (sample-w a))                        ; how far the WAL had to move, l - w_a
              (- (sample-w b) (sample-w a)))))          ; divided by how far it did move, w_b - w_a
    (+ (sample-t a)                                     ; start at t_a
       (* f (- (sample-t b) (sample-t a))))))           ; and add the same fraction of the time, t_b - t_a

;; lag_n for the newest sample n.
;; 0 when the slot has caught up, #f when the lag cannot be computed yet.
(define (lag samples)
  (let* ((n   (- (vector-length samples) 1))            ; index of the newest sample
         (s-n (vector-ref samples n))                   ; the newest sample itself
         (l   (sample-l s-n)))                          ; where the slot is now, l_n
    (if (>= l (sample-w s-n))                           ; the slot has reached the WAL
        0                                               ; so there is no lag
        (let ((k (find-k samples n l)))                 ; find the sample just before the WAL passed l
          (and k                                        ; no k means no lag yet, so return #f
               (- (sample-t s-n)                        ; lag = t_n
                  (interpolate-time (vector-ref samples k)        ; minus t*, found between
                                    (vector-ref samples (+ k 1))  ; samples k and k+1
                                    l)))))))

Running lag over the sample set up to $t_4$ returns 100/9, the same as the example scenario.

Because $k$ is the latest sample with $w_{t_k} \le l_{t_n}$, the next sample has $w_{t_{k+1}} > l_{t_n}$. So the WAL always moved between samples $k$ and $k+1$, and interpolate-time never divides by zero.

Postgres functions and columns

#

A note on the pg_lsn data type

#

pg_current_wal_lsn() and confirmed_flush_lsn both return the pg_lsn data type, written as two hex numbers separated by a slash, such as 16/B374D848. It is a 64-bit position in the WAL, but Postgres has no cast from pg_lsn to bigint or numeric. bigint is signed, so it could not hold the full unsigned range of an LSN. Subtracting two LSNs gives the number of bytes between them as a numeric, so subtracting '0/0' is how we turn an LSN into a number. pg_wal_lsn_diff(x, '0/0') and x - '0/0' give the same result.