Hi hackers,

While looking at making the syslogger cheaper for chatty workloads I
found some low hanging fruit. The pipe to the collector is still the
64 kB Linux default.  Backends block in write() once it fills, and
it can fill fast when multiple backends log multi-chunk messages at
once.

The attached asks for 1 MB when the pipe is created.  If the kernel
refuses it tries smaller sizes but never shrinks the pipe.  If nothing
is accepted the original default remains.

Maybe we want to parameterize this, but 1 MB is the default max for an
unprivileged process and it seemed simpler to not add another knob.
Especially since it is allocated once per cluster, not per backend.

Clusters that log little will not notice.  The win is for statement
logging, pgaudit, auto_explain and the like.

I tested on a 16 core Linux box, -O2, no asserts, logs on tmpfs, with
master and patched interleaved and the median of five pairs.

pgbench -S with log_min_duration_statement = 0:

  clients  tps               p50             p99                collector
  8         92904 ->  92798   80 ->  80 us    105 ->   105 us   60% -> 60%
  32       160340 -> 163960  185 -> 183 us    462 ->   458 us   60% -> 39%
  64       156641 -> 158428  353 -> 377 us   1906 ->   878 us   46% -> 32%
  96       152793 -> 152424  387 -> 509 us  10728 ->  2009 us   46% -> 29%

The collector wakes less often and reads more each time, so it uses a
third less CPU.  At 64 clients and up the box is oversubscribed and
the collector loses its core for longer than 64 kB lasts.  The bigger
pipe halves the tail and the median rises, since those backends now
compete for cores instead of sleeping in write().

Bursts of RAISE LOG from plpgsql at a fixed rate with pgbench -R, so
what changes is time blocked in write().  Last column is collector
CPU.

  burst         clients  rate  avg latency (ms)  p99 (ms)      coll.
  200 x 3800 B  32        60    6.87 ->  3.60    18.0 ->  9.8   27%
  200 x 3800 B  32       180   19.38 -> 14.36    82.0 -> 80.8   77%
  10 x 64000 B  16        90    4.57 ->  2.45    11.9 ->  5.0   25%
  10 x 3800 B   32      4000    2.90 ->  0.34    18.9 ->  2.7   89%

The patch won every pair on average latency.  The 38 kB bursts in the
last row fit in the old pipe by themselves, so what matters is what
all backends have outstanding together.

With the collector pinned at 99% throughput stays within 1%.  I also
tried 256 kB.  It gets the CPU saving but only a third of the burst
gain, so I went with 1 MB.

This is all Linux only, since F_SETPIPE_SZ is.

A similar idea for Windows would be to increase the size passed to
CreatePipe(...)[1].  I haven't tried that out as I do not have a Windows
machine to test it on.

[1]: 
https://learn.microsoft.com/en-us/windows/win32/api/namedpipeapi/nf-namedpipeapi-createpipe

Regards,
-- Sehrope Sarkuni
Founder & CEO | JackDB, Inc. | https://www.jackdb.com/

Attachment: 0001-Enlarge-the-syslogger-pipe-with-F_SETPIPE_SZ.patch
Description: Binary data

Reply via email to