Michael: Hello and welcome to Postgres.FM, a weekly show about

all things PostgreSQL.

I am Michael, founder of pgMustard, and this is Nik, founder

of Postgres.AI.

Hello Nik, how's it going?

Nikolay: Hello Michael, everything's all right.

Let's discuss logs.

Everyone loves to deal with logs, right?

Michael: What do you mean?

Nikolay: Well, I mean, if you have a huge server, a lot of logs,

so good to deal with them.

Michael: Well, I guess we're blessed in Postgres with a few ways

that we don't always have to check logs, right?

There are some system views that we can look at various information.

Nikolay: For example corruption, right?

There's no such view.

Michael: Yeah, yeah there was a but there's quite a few things

that there's no such view.

Well there's quite a lot of information that's put in the logs

and isn't available elsewhere.

So it is important.

And when I say is put in the logs, actually quite often it isn't

even put in the logs unless you change some settings.

So I thought it was, you had this good idea to discuss all of

the things that most people should change in terms of what to

log so that we can then check the logs for issues and when we're

doing performance analysis and that kind of thing.

Nikolay: Yeah, So I think system views, ideally we should for

everything we should have both system views and detailed logging.

Michael: Oh both?

Nikolay: Yeah, because like think about special statements, we

have normalized queries only, it's not possible to have there

every query with all parameters because cardinality will be insane.

Michael: But equally, I think it's quite often not possible to

have every query logged to the logs, right?

Like there's also limitations there.

Nikolay: Exactly.

So pros and cons of both approaches.

Cumulative metrics, they are good.

You can visualize, you can see spikes, everything, but they lack

details.

And same for example, temporary files, right?

We can see at high level, we can see from the pg_stat_database

that, okay, we generate a lot of temporary files.

Queries generate a lot of temporary files, some queries.

We can go down to pg_stat_statements and see which query groups

or normalized queries produce those temporary files.

It's already super helpful.

But obviously, the same normalized query, if you take 1 set of

parameters, it can produce gigabytes of temporary files.

Another set of parameters, it can produce 0 temporary files.

Depending on parameters, it can be very different.

So we need examples, and this is exactly when we need to look

at the logs.

But at the same time, if we log everything, observer effect is

not a joke.

And I must confess, several big clients suffered from observer

effect when I decided to log too much.

And it caused downtime and it was not pleasant experience.

So we always need to think about observer effect.

Those who say log everything, log all queries, they just don't

deal with really heavy loaded systems, unfortunately.

Yeah.

Just try to do it in heavy loaded systems, which has like 100,

000 TPS.

And that's it.

You will put down everything very quickly, you will learn it's

not the way to go.

So we need to limit the amount of logging, but we cannot avoid

logging because we need examples.

So my approach is to combine both things.

Michael: Yeah, it's a balance, isn't it?

We need to record enough information to be able to diagnose issues

when they occur, but not so much that there's excessive overhead.

So it's a balancing act.

Nikolay: Right.

And you need to think, like it's better to think in advance what

to log, because if some incident happened, you somehow mitigated

it.

You want to do a root cause analysis, but logs lack this information.

So you can only guess and you can guess quite well if you have

a lot of experience, but still it's better to have logging

tuned properly in advance.

And I see Postgres in the latest few years, like improving defaults,

but still defaults are not enough usually.

We tune some defaults for our clients always.

I mean, we tune some log related settings to have more logging.

Michael: Yeah, in my research for this I found 3 different parameters

that were all either introduced or had the default changed from

off to some version of on all in Postgres 15.

So I was kind of expecting a gradual improvement in this over

time but it seems almost, I don't know if it's a coincidence

or not, but 1 major version where quite a few things are improved

and I haven't seen a whole lot of movement in other areas unfortunately.

Nikolay: Yeah you're probably right, Defaults changed in 15,

you mean log_checkpoints and autovacuum related to 10 minutes,

which is enormous still, like it's huge value.

And what was the third?

Michael: And there's a new log startup progress interval.

Nikolay: But it's new, it's not a default change.

But decision was made to not to
introduce it being turned off

by default decision, which is a
great decision.

I agree.

And it's quite like 10 seconds,
right?

So every 10.

Yeah, let's discuss everything,
everything we have, right?

Let's let's, Let's start from something,
move to different topic.

But I agree, so 15 was revolutionary
in terms of bringing good

defaults in logging.

Michael: In some areas, yeah.

Nikolay: Yeah, And also worth mentioning
Postgres log, it's always

a single log.

So you can imagine if we had ability
to separate streams of logging,

for example, slow queries could
go in 1 place, maybe to faster

disks, or maybe to...

There is a like this idea, very
old idea, that some logging should

go not to local disk but straight
to some storage over network

UDP and that's it like send it
So we could log a lot of more

stuff.

Although when you ask guys who
support, I don't know, like Elastic

or something, which is receiving
a lot of logging from different

systems, they also would like to
limit, you know?

Or Splunk, for example.

Splunk is an old commercial enterprise
system for logs.

They can deal with huge volumes,
but always still cautious about

how much you are going to send
to them.

Michael: Yeah.

It's a good point, though.

Other databases do have...

I'm pretty sure MySQL has a separate
slow query log, because

I've seen people familiar with
MySQL asking about where's Postgres'

slow query log?

Nikolay: Yeah, it's not a big change,
it could be like, I think

it could be, I mean it's easy to
implement, but I imagine how

much of Infrastructure changes
needed to be done in all the systems

if slow query log would be separated
What do you think

Michael: what what I'm missing
something though?

What's the benefit of having it
separated out?

Nikolay: You can put it to different
disks, faster disks for

example, analysis wise also it's
easier

Michael: Because the volume is
likely to be so much higher than

the other

Nikolay: Yeah, maybe Some rotation
policies could be different.

And analysis wise, the nature of
like, I see a bunch of logs,

which are related to query optimization.

And I also see a bunch of log messages,
which are related to

like startup, autovacuum, checkpointing,
like more like not

about query processing, but everything
else, right?

And separation of them is, to me,
it sounds reasonable.

So I Imagine it would be possible
if like, what do you think?

Imagine there is a new setting
which says everything related

to query processing, including
log_min_duration_statement based,

Everything that can contain a query
text, actually.

Everything.

Like, for example, slow queries
exceeding log_min_duration_statement.

Queries generated temporary files.

Queries which are slow because
they are waiting for other queries

and logged after deadlock_timeout
1 second by default, right?

Imagine all of them go in 1 place,
everything else stays in the

old place.

But it's optional.

You can decide to choose

Michael: it or not.

Yeah, I haven't thought long and
hard about it, but I do quite

like the simplicity of everything
being in 1 place.

But it can also be helpful, right?

I understand how if you're not
worried about slow queries and

you're looking for other things,
they can be really noisy and

get in the way.

And in a heavy-loading environment,
it would just be impossible

without tools to then get anything
useful out of that.

But like an autovacuum could be
the cause of some slow, like

some issue that you're facing with
query performance.

Or checkpoint could be the cause.

And maybe in a less heavily loaded
environment where you're reviewing

it manually seeing that in in order
might help you debugging

like what's actually happening
here

Nikolay: yeah makes sense makes
sense and also some errors Should

we like, what will happen with
queries which are erroring out?

Yeah.

But, but still like, it could be
a choice, right?

Because people who are interested
in errors, corruption related

errors, I hope we will discuss
them as well.

And maybe a checkpointer behavior
and so on, and less interested

in query processing itself.

They often say, you know, like
your huge query is being logged

just because they are exceeding
1 second, they make our log really

hard to read.

Yeah.

Well,

Michael: hard to read manually,
right?

With tools you can filter to the
bits.

Nikolay: Or with DuckDB you can
have CSV and talk to it through

DuckDB queries, which I think is
a great idea.

Quite a new and great idea.

Michael: But I like this almost
as a way of splitting our conversation.

You mentioned the performance related
stuff and everything else.

Where do you want to start with
1 of those?

Nikolay: Yeah, we already talked
about log_checkpoints.

Let's maybe talk about this.

So in 15 it was changed to on and that's it, that's great.

I mean, it's easy.

Like I think everyone needs it.

And finally in 15, how long ago it was?

3 years ago.

Michael: Yeah, nearly.

Nikolay: It was realized that everyone should have it, everyone.

Michael: So our advice to people would be, if you're on a version

older than that, turn it on.

Nikolay: 100% so.

Michael: If it's not already.

Nikolay: Yeah, and another thing happened in 2015, it's related

to autovacuum logging.

So log_autovacuum_min_duration was always, I think before that

it was minus 1.

So it means the vacuum is not logged at all.

And it was changed to 10 minutes.

In my opinion, it's not enough.

10 minutes is way too long.

It should be 10 seconds.

In some places we set it to 0 to see everything.

Of course, I can imagine, especially if you have many workers,

you also tuned the autovacuum_naptime to very low value so

they sleep less between work.

And this, or workers sleep less, right?

In this case, I imagine amount of logging from a vacuum workers

might be substantial.

But at least like 10 seconds or a few seconds threshold, it's

good.

Because if you have a lot of tables, 10 minutes, you will miss

a lot of details, interesting details.

Michael: And it's not that frequent.

The thing if we go back to that, you know, recording enough information

to diagnose issues without excessive overhead, the overhead of

logging all of your autovacuums, unless you have, as you say,

really, like, yeah, very low nap time and maybe lots and lots

of tape, like, maybe you've got thousands of tapes, thousands

of schemas, like if they've multiplied out, I think I heard somebody

that was talking about having millions of objects in their Database.

Nikolay: All right, do you remember if you have, for example,

naptime 1 second, You have 10 workers, for example, and you

have longer running Transaction holding extreme horizon, so the

vacuum cannot Delete some dead Tuples.

How often those workers will visit this Table, which needs processing?

Maybe they will do it in loop, right?

Michael: Yeah, good point.

I don't know.

Nikolay: And if Table is very small, then quickly process it,

sleep 1 second, again process it, sleep 1 second, so it will

be a lot of spam, right?

Unless there is additional logic
in autovacuum, I'm not 100%

remembering.

It would be good to double check.

Michael: Worth checking, but also
to once per second, when we're

talking about logging, when we're
talking about potentially,

it's also still not that bad.

Nikolay: But 10 workers, Thousands
tables.

I can imagine something like this.

But also, nobody...

Like, default nap time is 1 minute.

And default number of workers is
3.

Yeah.

So I...

Anyway, like, I definitely...

We always recommend to our clients
to see more of the vacuum

work in logs.

It's really helpful, especially
during some incidents, after

some incidents, we have this useful
information to understand

what happened in terms of data
that cannot be deleted.

It also reports xmin horizon, by
the way.

It reports it like, it reports
the delta between current xmin

and xmin horizon, so it's super
useful.

Yeah.

Michael: Nice, so just to be clear,
anything, if you're on older

than 15, make sure you have this
set to something so that you're

actually logging autovacuum at
all.

And even if you're on 15 or above,
consider lowering it substantially

from the default.

Nikolay: Yeah, 1 more thing here
is that if we don't have activity

at all, in this case, it will be
producing some log entries which

are probably not super useful.

Michael: If we don't have any autovacuum
activity or any any

kind of updates, delete.

Nikolay: Yeah, or maybe SELECT
only during some long time.

Michael: But that was the argument
for not having checkpoint

logging on, if there's a silent
database.

Nikolay: There was a battle about
it, yeah.

Michael: Yeah, but we're talking
about very, very few log entries

in the grand scheme of things still?

Nikolay: I just mean if you, for
example, if you build some service,

if you have lots of databases or
you build a platform for other

people.

Michael: Sure, sure.

Nikolay: And you can imagine like
many of them will have databases

which are not super active, but
logging has costs.

If you have, say you have like
10,000 databases and 9,000 of

them are not super active and you
will be paying for this disk

space for logs, right?

This will make you think differently
and try to save.

But this is exactly like, this
is different situation compared

to, okay, I have 1 database, it's
hot startup, AI startup, it's

growing.

It's a single like monolith or
few monolith or shard, it doesn't

matter.

And we need to understand our workload
really well.

In this case, we need to log everything,
right?

Michael: Yeah, I get what you mean.

But going back to the, let's say
the platform that has 10, 000

of which 9, 000 are quiet, in that
case why not rotate the, like,

just delete logs more often?

Nikolay: Good point, So yeah, if
you, for example, understand

that you're going to log something
that's probably in not loaded

system is not super useful, but
you know the maximum amount of

that already, how many lines it
will be, and you know it will

be rotated so there is just constant
price for each node that

you're going to accept.

And logs also can be compressed
really well.

Yeah I agree, I agree with this
point as well.

I just wanted us not to forget
about different perspectives people

might have.

Michael: Yeah, great.

Nikolay: 1 big pet versus huge
cattle you need to take care of.

So yeah.

Good.

What about autovacuum?

That's it, right?

So we need to know details, especially
about larger tables, especially

when autovacuum is blocked.

And if you're, for example, a backend
developer, I think it's

interesting for you as well, because
it may sound autovacuum

is just some, okay, it's a garbage
collector in Postgres, right?

But if you think, like, if you
have chances to deal with performance

of system you develop, garbage
collection part is very important

because every time you deleted
or updated something or had INSERT

with ROLLBACK, you produce dead
tuples.

And basically, if you deleted something,
COMMIT, return to your

application code something, but
it's only half of work done.

autovacuum will do the remaining
half of work, so to speak.

And you definitely want to know
when it happened, in which volumes.

At some point you will need probably
to process a lot of rows,

like delete millions of rows.

We had an episode about this.

And people keep asking, I saw comments
yesterday, comments like,

okay, deletes, what about updates?

Well, similar, similar updates
also, like they produce new tuple,

they mark old tuple as dead, but
the process of what exactly

will clean it.

And we need to understand its behavior.

And if we want to move really fast,
We need to take care of cleaning,

otherwise we will see a lot of
huge gaps in storage.

Space won't be reclaimed, it won't
be reused very quickly, and

this is called bloat, right?

So we don't want this.

So we need to understand garbage
collection and Postgres, which

is called autovacuum.

Yeah, this is like, that's why
you want autovacuum logging,

even if it's, even if you are not
DBA, but just backend developer.

This was my point.

Michael: Yeah.

And, And it's just like you mentioned
at the beginning, there

are system views where we can look
at when was the last time

autovacuum ran on each table,
which is useful.

But you can't see the couple of
times before that, or...

Nikolay: You don't see details.

How many...

Yes, exactly.

Was it in the horizon a problem,
actually?

Yeah.

I think, by the way, is there some
work in progress to extend

it?

Michael: I don't know.

Nikolay: Because it's worth extending
I think.

pg_stat_all_tables or pg_stat_user_tables.

It's useful, but it's just a counter
and last timestamp.

Not enough.

2 counters, 2 last timestamps.

Or manual and automatic vacuuming.

Okay, good.

In the same release, just to close
with Postgres 15, it was this

log startup process interval.

I don't think it's for backend
engineers.

It's more for DBAs because if they
tune checkpointer behavior

and distance between checkpoints
is huge, significant.

In this case, startup can, might
take long time and it's great

that now we have this setting and
as you said Default is quite

good.

So we can not to think about it
at all Yeah, what's next?

Michael: What about log_statement?

We talked about that in a recent
episode as well.

The default there is none, right?

Nikolay: Yeah, exactly.

And I like to recommend people
to set DDL, to put DDL there just

to trace all schema changes.

When it was done, who did it.

Of course, actor may overwrite
it.

Unless, yeah, so, but it's good
to have some default there.

And I think there's a there's an
ability actually to forbid overriding,

right, some settings.

Michael: So I think there's 2,
there's almost 2 categories here,

right?

You're talking about almost the
security element of it.

But I think even if we, even if
we assume it's general case,

it's still extremely useful to
see when DDL changes were happening

in the context of everything else.

Nikolay: The timestamp, exact,
exact query.

For example, it may save you time
in future if you, for example,

start dealing with logical replication,
doing some experiments,

and it's blocked by DDL.

But you can trace when exactly
it happened and which DDL it was,

which is great.

Michael: Or even look back historically
over the past 30 days

and be like, which days do people
run DDL on which ones don't

they you know that you could plan
an upgrade around when it's

unlikely to have DDL happening.

Nikolay: It's super helpful in
various incident analysis when

you have deployment and something
went wrong.

We discussed it many times.

DDL may be a reason if it cooked
not properly, it may be a reason

for downtime or some issues.

And if you have log_statement equal
DDL, you can trace it.

Yes.

Yeah.

At least after the incident happened.

So, definitely DDL is a good idea.

Michael: And the cost is very low,
right?

How much DDL are you running on
your system?

Nikolay: It's not thousand per
second, definitely.

Michael: No.

I hope.

You

Nikolay: know, I see systems which
have DDL as a part of their

normal workload coming from users.

It happens.

Well, for example, if it's a multi-tenant
system, which creates

tables for each customer and if
they extend functionality, they

also create something.

Also temporary tables, which I
don't like at all.

Like I avoid temporary tables at
all costs, but people use them

and temporary table creation is
also DDL.

Michael: Yeah, good point.

Nikolay: So I can imagine that
there are cases when it can happen,

like we have a storm of DDL coming
to logs, but for me it's kind

of edge case rather than normal.

Michael: So, great.

Yeah.

On the security side, I wondered
about connections and disconnections

are both off by default.

Nikolay: I don't think it's what
this this is sometimes I see

people turn it on.

It depends on the particular system.

In many cases, it's off.

It's all by off by default.

And this information is usually
most interesting.

It looks most interesting to DBAs,
DBREs, not Backend developers.

Let's move on closer to workloads
and query optimization maybe.

Michael: Yeah, and I think we did
have an episode either about

pgaudit or about, did we do it
specifically about pgaudit or

about security or something like
that?

So I'll link up that episode because
I think that covers probably

the more interesting parts of the
DBA side of things.

Nikolay: Sounds good.

Yeah, maybe Let's talk about log_lock_waits before we focus

on workload analysis.

So it's also part of workload analysis,
just specific part related

to logs.

And we also discussed it recently,
I remember.

And this is definitely what we
recommend turning on because it's

off by default.

Yeah, because it's helpful.

Also during incidents, that's helpful.

If, if you're developing your app,
didn't think about multi-session

concurrency control properly and
blocking situations, you might

have incidents, spike of active
sessions, or maybe even downtime

caused by heavy lock contention.

And having logs related to this
is really helpful.

Really helpful, because without
it, you can only diagnose something

in runtime.

Okay, you see there's a spike of
exclusive locks.

So, With log_lock_waits, you will
see that some session tried

to run some query, but it was blocked
by another session.

And it was waiting, our query,
was waiting longer than

deadlock_timeout, which is by default 1
second.

So if you, for example, try to
update 1 row, but there is no

transaction which is not committed
yet, it may be already updated

this row, but it's not committed,
and we need to wait until commit

or Rollback for the transaction.

And our update lasts, like, waiting
period lasts 1 second.

In some systems it may be longer
or less longer if deadlock_timeout

was adjusted.

And this gets logged and you see,
okay, our session process ID

with executing query this was waiting
for long and it was waiting

for those process IDs.

Unfortunately we don't see details
about those sessions.

This is disadvantage.

But it's already half of the coin
visible.

Michael: Yeah well imagine trying
to debug without this, it just

seems to me, reproducing ordering
for locking issues just seems

to me to be so difficult without
this kind of information.

Nikolay: Yeah, also it's helpful
if you have deadlock issues,

and you try to understand your
system better, this kind of logging

is helpful.

I cannot say it will answer all
your questions, unfortunately.

I had cases when deadlock troubleshooting
was extremely challenging,

and we had logging, we had everything,
but it was still challenging.

Sometimes It's really challenging.

You need to go to application code
understand what exactly It's

doing but it's already something
and it's better to have it always

Michael: Yeah, and this to me seems
like a no-brainer.

The trickier 1, balance-wise, seems
to be the time, whether to

reduce it from 1 second or increase
it.

And that seems quite loaded because
it's doing 2 things, right?

It's determining at what time lock
waits get logged, but also

at what time deadlocks get picked.

Nikolay: Deadlock detection happens.

Michael: Yeah, so it's doing 2
things.

Nikolay: I can, I understand the
decision from engineering perspective?

It was like, where should we log
it?

Oh, this is where we're checking
it.

It's good time to log it exactly
at that time.

So I can imagine this decision,
why it happened.

But I agree with you, there is
some lack of flexibility a little

bit.

But also it's protecting us from
huge volumes.

Like let's talk a little bit about
observer effect.

Here I don't see it actually.

So at each session, like there
is this like 1 second delay, basically

by default, 1 second delay before
it gets logged.

If we have a lot of sessions okay
how many?

100?

100 active sessions.

Michael: Max connections.

Nikolay: Yeah we might have 100
of these messages per second.

Well it's significant volume But
I think on this server with

100 active sessions and I hope
with many more cores, I think

disks are already quite powerful
so they can handle 100 entries

per second for this type of logging.

But it might contribute in some
cases, I think.

Again, in some edge or corner cases,
it might contribute a lot.

So it's worth understanding.

But personally, I've never seen
the case when we decided to turn

it off.

And I think it should be on by
default, but it's off by default.

So advice from us, turn it on.

Michael: Yeah, good 1.

Nikolay: What's next?

Michael: Should we move on to performance
things?

Nikolay: Yeah, maybe temporary
files first.

Michael: Yeah, good 1.

Kind of bridge the gap a little
bit.

Nikolay: Yeah and by default it's
disabled minus 1.

Michael: Yes so this is when in
fact actually I looked into it

this this is logging when the temporary
file gets deleted interestingly

But what's happening is when a
query is using some temporary

storage, for example, if a sort
spills to disk or doesn't have

enough working memory available
to do a hash join or any operation

that uses temporary data.

So I had this under performance
but I guess it is also just general

system-wide tuning as well around
config parameters like work_mem

and hash_mem multiplier more recently
as well.

Nikolay: Yeah, yeah.

Yeah, I can imagine many queries
will start producing a lot of

logs if they need temporary files.

It's so multi-sided question to
me, because if you produce, so

if you try to save on log, logging
of temporary file generation

cases, deletion cases, as you said,
you already have issues with

dealing with disk.

The query processing itself was
dealing with disk.

It's better to capture that info
and try to optimize it as soon

as possible.

But will I put 0 there?

0 means let's log all the cases
even if it's just 8 kilobytes.

Maybe no, but what I would do,
what we usually recommend, I'm

sharing 3 pieces of advice today.

We say minus 1 is definitely not
good.

And of course, in some cases, if
you don't see temporary file

generated right now, looking at
pg_stat_activity or pg_stat_statements,

because they also have temporary
file written and read a couple

of columns, so you can see it there
as well.

If you don't see a big problem
right now, maybe okay, maybe not,

let's not log it.

But why not to be prepared for
future, right?

Michael: Yeah, I would say the
opposite.

I'd say if you're not seeing them
right now, you could even afford

to set it to 0 because you're just
not going to get much volume.

Nikolay: What if tomorrow memory
is not enough and we start logging

very tiny amount, tiny numbers
and it will be a lot of cases?

Michael: Well, depends if you've
if you've tuned work_mem, even

if work_mem is the default 4MB,
it would only be logging most

likely queries that are using more
than 4MB of memory and sorts

and things, so how many of those
per second are you realistically

running?

It seems unlikely to me that it's
going to be super high volume.

Nikolay: First of all, work_mem
should be increased.

Yes.

Right.

But if you keep it very low and
suddenly you, you changed like

data volumes become bigger and
bigger and for like for hash operations

ordering we need more and more
at some point we slightly exceed

4 gigabytes 4 megabytes and many
of processes do it for example

boom you you need to generate temporary
files and you you like

log_temp_files equals 0 add
some text on it additional text,

right?

My approach is different.

I If we don't see it right now,
but we grow This is scary moment

for me.

I would prefer seeing very heavily
loaded systems already having

some temporary files.

And we understand them.

And we go from quite significant
value, like 10 megabytes, And

we go down in stages.

Restart is not needed, by the way,
for all settings we discussed

today.

So far, restart is not needed,
which is perfect for going in

iterations gradually, right?

So we gradually descend to 0, but
maybe not to 0, maybe 200 kilobytes

or something.

Michael: But what's the difference?

Like it's on.

Are you going to get temporary
files that are 100 kilobytes?

Nikolay: Well, if we put 100 kilobytes
to log_temp_files, we

will see only the cases which exceeded.

Michael: Yeah, but what I mean
is if work_mem is 4MB and hash_mem_multiplier

is 2 by default, we're only realistically
going to have temp

files that are more roughly, very
roughly 4MB to 8MB.

Nikolay: I understood you.

Well, obviously we think about
it differently and I'm not sure

who is right.

You think when memory is not enough,
everything goes to temporary

file.

I think when memory is not enough,
only Delta goes to temporary

file, which is a

Michael: good, Good point.

I think it's actually different
in 2 different cases.

So, for example, like sorts, I
think it's all or nothing.

But I think, for example, with
bitmap scans that have non exact

Nikolay: Michael, we have homework
to do.

Yeah.

Michael: It's a good point, though.

You're right.

There probably are some operations.

I think including bit scans

Nikolay: In this Interesting question.

Yeah, I Talk to some hackers.

It might sound very simple actually.

Michael: I'm pretty sure with sorts
it's all or nothing.

But it's a good point that going
down in stages makes a load

of sense.

And I was just trying to say I
feel like you can skip it if you've

currently got it.

Nikolay: SERGEY VASILYEVICH Yeah.

Why go down or nothing?

I understand this logic, yeah.

Michael: But for me, low is almost as good as 0.

Like, there's no difference realistically.

It's 100 kilobytes, great.

If that makes things much safer in extremely heavily loaded systems

with lots of potential max connections, great, low is still good.

Nikolay: Yeah.

But again, this is a useful parameter because if you have cases

when, we discussed it in the beginning already, when you have

cases you can see some normalized query but you need examples

to understand how to reproduce it and then decide what to do

with it.

Raise work_mem globally, locally, this will be a question.

Michael: 1 user, for like an analytics user, that kind of thing.

Nikolay: Right, right, right, yeah.

Yeah, so okay, good.

And memory management might be quite challenging, like it's sometimes

not trivial.

Good, So let's talk about the main part of query analysis.

It's pg_stat_statements is not enough, right?

So you need to either have quite low log_min_duration_statement,

at least 1 second, preferably lower, like half a second, maybe

100 milliseconds, to capture more cases of slow queries and then

optimize them.

Right?

Michael: Yeah, absolutely.

And I like your point about them being examples.

So it's not necessarily that the average of that query is going

to be running in 100 milliseconds.

We want to catch the outliers.

Like, what are the parameters for that query that mean it does

tend to run over 100 milliseconds?

So we get those examples.

It's perfect.

Nikolay: And

Michael: again, 1 that we can lower in stages?

Nikolay: Yeah, definitely.

So I will start if never, like if it's big unknown, like from

5 seconds and go down.

Doesn't make any sense to start with really large value because

I assume we talk about OLTP systems where, for example, 10 seconds

is already an absolutely slow query.

I usually see 1 or half a second as a value being used these days.

And if you already performed a lot of optimization efforts and

you want to improve even further, you can go down.

But maybe, maybe it's worth it instead of this.

Oh, before we go there, there's actually an idea you can go down

to 0 but switch to sampling.

There is statement-level sampling and transaction-level sampling,

which is supported since a few
years ago.

Michael: Yeah, you can have 2 levels,
can't you?

You can set log_min_duration_statement
to, let's say, 100 milliseconds,

and that will log everything above
100.

Then you can have like a second
threshold that is log_min_duration_sample

that's like, you could say
10 milliseconds and then you

separately set a log_statement_sample_rate
to, you could say

like 0.1 and that would do 10%
or 0.01, it would do 1%.

And that would log, let's say,
1% of the statements that were

between 10 and 100 milliseconds.

So, yeah, it would be a way of,
like, capturing some examples.

Nikolay: Yeah, like 1% of everything,
and everything, like, 100%

if it's above the old log_min_duration_statement threshold.

And this was added in Postgres
13, I think it was adjusted later.

14, so we can say it's already
almost all versions.

Michael: All supported versions,
yeah.

Nikolay: All supported versions,
yeah.

Actually, 13 is the oldest already,
wow.

Yeah, time flies.

Good, good.

So we talked about this, but there's
also idea instead of logging

queries, let's log them with plans.

And just jump straight to using
auto_explain and just not to

use what we just discussed.

Log_min_duration_statement and
log_min_duration_sample, blah, blah,

blah.

So just auto_explain brings plans,
which is great.

And...

Michael: Yeah, and it also does
log the statement, so you do

still get the query.

But you could, in theory, have
a third setting, you could have

a third value, so you might want
to log the queries above 100

milliseconds, and you have a separate
threshold for logging auto_explain

plans at a different threshold
if you wanted to.

Nikolay: It was you who surprised
me a lot a couple of years

ago when you said auto_explain
support sampling for ages.

Yeah.

I haven't noticed somehow.

Yeah, but it's great.

You can log every plan, execution
with plan.

You log actual execution with plan,
but only 1% samples of it,

right?

Michael: Yeah, so this is slightly
different though, I think,

because with the sampling on the
log_min_duration_statement,

I get the impression it's well,
I'm not sure maybe maybe this

is a question I get impression
it's tracking them all but only

logging a percentage of them.

So you're then saving yourself
from an overhead around logging.

Because

Nikolay: it's...

SLAVOJ Yes, calculate metrics and
then log to disk.

Michael: SIMON Exactly.

So there's the observer effect
of observing, of tracking timings,

and then there's the second observer
effect of actually logging.

Whereas with auto_explain, the
sampling, you don't even measure

a certain proportion of the, so
you, it is, it's subtly different,

I think.

Nikolay: Yeah.

What would you recommend?

Like we can have so many options
here and worth saying we can,

it's quite flexible.

We tune it all.

And then you think, okay, this
is a big complex system.

We have so much logging.

We log everything.

Not everything, sometimes same,
sometimes not.

But then you think, actually, you
know what?

I still need to do such statements
because I want reliable, higher

level metrics to understand.

Because I identify 10 queries I
need to work on, but where to

start?

What is the most influential in
various terms?

Like I need to produce a Statement
Stone to realize that.

And I connect on by query ID and
query ID in auto_explain is supported

only since version 16, I think.

So this was a big missing piece
before 16.

But once you're on 16 or 17 or
maybe already 18 beta 1, I don't

know, then you connect by query
ID and you see, okay, based on

log analysis, I see these plans
need my work, need attention

or these queries, But I'm choosing
this one because I see it's

like 25% of all time spent based
on pg_stat_statements.

And this is a great way.

So this brings us to the idea that
having logs is not enough.

Michael: Yeah, well, they're kind
of serving slightly different

purposes, aren't they?

Because if a query is taking 25%
of total CPU, like if it's just

taking 25% of our resources, It
would probably be relatively

easy to reproduce that.

If we grab the query, grab an example
that's, you know, relatively

slow, and run EXPLAIN ANALYZE
with all the parameters on that,

we'll probably get a slow query
plan.

But where auto-explain comes into
its own is if queries are only

every, like, if they're slow sometimes
but not always.

If there's very specific.

Exactly.

It's cases like that that might
be difficult to diagnose.

Maybe they happen at certain times
or with, you know, in cases

that you're struggling to put your
finger on.

Getting the plan at that moment
is extremely helpful.

And it's not always possible.

Nikolay: Do you think auto_explain
should be in a different log?

Michael: I mean I still...

Nikolay: Let me...

I maybe already mentioned this
recipe in the past, I used it.

So you have a tmpfs disk, RAM
disk.

Yeah.

Like gigabyte, we have memory,
so 1 gigabyte.

And log goes there.

And you quickly rotate it to ensure
it's not filled up.

And send it somewhere to storage.

And it would be great to have separate
log for such very bloaty

things like auto_explain, right?

Michael: Well, and that's the big
difference between auto_explain

and just logging the query.

Because even queries can get long,
but query plans can be ridiculously

big.

Like the largest one I think I've
seen was getting close to 100

megabytes of

Nikolay: text.

Just one.

Michael: Just one query plan.

Okay, a lot of that was like, there
was a lot of like whitespace

and a lot of repeated

Nikolay: identifiers.

It should be compressed, immediately
compressed and sent over

network.

But compressed by whom?

Logging collector or?

Yeah.

That's an interesting question.

Michael: So it is the big downside
in terms of volume.

Nikolay: So we see so much power
we have right now for observability

and query processing, query optimization,
but still it feels

like in heavily loaded systems,
it's hard to have, like, it's

not super hard, but there are opportunities
to improve.

100% so.

Michael: Yeah.

And if you've got a bit of, if
you've not got issues right now

it's great to set a bunch of these
and you can afford to set

things like auto_explain up if
you've got overhead if you've

got headroom you can set these
things up in advance and then

change them if that if you start
to get into you know the 90%

of CPU being used you can look
into things you can do to reduce

those.

But I really like a quote, I think
somebody was at an Oracle

conference and somebody asked,
what's all the overhead of all

of the performance analysis Oracle's
doing.

Oh yeah, of

Nikolay: course, Stanel Potter.

Michael: Ah, nice.

Nikolay: Yeah, he said something like, I can pay like 10% or

something overhead, but save like 90% thanks to my optimization

based on those information.

Michael: Yes, I think it's along those lines.

I think if you have this information.

Nikolay: It's very exposition, you know, like, if you have this,

but you're not going to use it, you're losing, right, additionally.

But if you are definitely like, you are going to allocate your

resources to optimize, ready to pay this penalty like or tax,

but because I know I will optimize and I will be on a better

spot after it.

Michael: Yeah, exactly, it's not a liability, it's an asset at

that point.

Nikolay: And those 10% they will shrink, thanks to my optimization.

Compared to initial latencies, they may become smaller, right?

Michael: Maybe, if they're a percentage, I've got a feeling some

of them are fixed.

Nikolay: But if we are not sure that we will be able to optimize,

I can understand that it can sound risky to pay this additional

price without a reliable outcome.

Who knows how successful we will be.

But again, all of these things, except putting auto_explain to

shared_preload_libraries, you can share them on fly.

So it's so great.

You can temporarily lower all thresholds during a week or 2 while

you're optimizing, for example, and then get back to your normal

and do it like every quarter, for example, like routine optimization.

So cycles of optimization.

Also if it's non-production or something, you can be more aggressive

in going down with thresholds and having more, to see more, yeah.

Michael: It feels like 1 last thing on auto_explain.

The thing in the docs and quite a few experts will recommend

is turning off the timing parameter.

So you collect the EXPLAIN ANALYZE information but without per

node operation, like per node timings.

It does reduce the overhead, of course.

But it also reduces the, like, fidelity of those plans and it

is quite useful.

Nikolay: Well, yeah, I don't agree with you.

For me, for me, most valuable is structure and buffers, as usual.

Michael: Of course, I get that they're more useful, But I think

quite often in a lot of environments collecting the timing information

is also worth it.

Nikolay: Well, yeah.

You had a post long ago about this, but we also had a whole episode

about auto_explain.

Do you remember?

Michael: Yeah.

I'll link up the relevant episodes.

It's a

Nikolay: big topic.

AutoExpand has many settings to tune, so it's a big topic.

Good, I think maybe that's it, right?

Michael: Yes, definitely.

Thanks so much, Nikolay.

Catch you next week.

Nikolay: Yeah, Bye-bye.