1
0:0:0,06 --> 0:0:2,6799998
Michael: Hello and welcome to Postgres.FM,
a weekly show about

2
0:0:2,6799998 --> 0:0:3,6799998
all things PostgreSQL.

3
0:0:3,6799998 --> 0:0:5,04
I am Michael founder of pgMustard.

4
0:0:5,14 --> 0:0:7,64
I'm joined as always by Nik, founder
of PostgresAI.

5
0:0:7,64 --> 0:0:8,299999
Hey Nik.

6
0:0:8,86 --> 0:0:9,66
Nikolay: Hello Michael.

7
0:0:11,28 --> 0:0:14,86
Michael: And we have a special
guest Fabrízio Mello, who is owner

8
0:0:14,86 --> 0:0:18,68
of Timbira, software engineer at
PlanetScale and creator of pg_stat_log,

9
0:0:19,14 --> 0:0:21,34
which is a new extension that we're
going to be talking about

10
0:0:21,34 --> 0:0:21,84
today.

11
0:0:22,02 --> 0:0:23,04
Welcome Fabrízio.

12
0:0:24,66 --> 0:0:26,32
We're really glad you could join
us.

13
0:0:26,32 --> 0:0:29,86
So pg_stat_log, do you want to give
us a little bit of what it

14
0:0:29,86 --> 0:0:32,58
is and why you started work on
it.

15
0:0:33,4 --> 0:0:37,7
Fabrízio: Well, pg_stat_log, it's
supposed to be an extension.

16
0:0:39,12 --> 0:0:46,98
That solves, at least tries to
solve, a very tricky problem on

17
0:0:46,98 --> 0:0:52,08
Postgres observability, that is,
collect information about your

18
0:0:52,08 --> 0:0:55,94
logs in several different ways.

19
0:0:55,94 --> 0:1:3,98
For example, you need to check
your logs for an error.

20
0:1:4,34 --> 0:1:9,58
For example, your application is
erroring out for some reason

21
0:1:9,58 --> 0:1:13,86
and you need to check what the
error is happening after some

22
0:1:13,86 --> 0:1:15,08
deploy or something.

23
0:1:15,24 --> 0:1:20,32
You need to go search the logs,
grab the logs, and depending

24
0:1:20,32 --> 0:1:26,82
on where your Postgres is running,
it can be even tricky, right?

25
0:1:27,1 --> 0:1:32,12
Because you have managed service
containers and all of different

26
0:1:32,12 --> 0:1:33,66
environments running Postgres.

27
0:1:34,34 --> 0:1:40,32
So you can have a bunch of different
ways to go to the logs and

28
0:1:40,32 --> 0:1:41,4
look for some.

29
0:1:42,18 --> 0:1:46,520004
And pg_stat_log is essentially
a view.

30
0:1:46,56 --> 0:1:52,16
It's a pg_stat view inside Postgres
that you collect counters,

31
0:1:52,42 --> 0:1:55,7
collect information about what
is happening in your log.

32
0:1:56,4 --> 0:2:6,9
It is grouped by backend types,
user ID, database ID, SQL error

33
0:2:6,9 --> 0:2:8,96
code, and error level.

34
0:2:9,24 --> 0:2:14,14
And you can configure pg_stat_log
to collect different error levels,

35
0:2:14,76 --> 0:2:20,44
depending on how much information
you want to process those

36
0:2:20,44 --> 0:2:20,94
counters.

37
0:2:21,6 --> 0:2:24,34
So essentially a brief introduction
is this.

38
0:2:24,34 --> 0:2:25,58
So make your life easier.

39
0:2:25,58 --> 0:2:32,1
Instead of you go to jump into
weird tools to access log, you

40
0:2:32,1 --> 0:2:35,58
have all the information you need,
the least basic information

41
0:2:36,14 --> 0:2:39,36
inside your Postgres, then you
can attach some monitor to it

42
0:2:39,96 --> 0:2:41,34
and collect this information.

43
0:2:41,68 --> 0:2:46,08
And for example, see over the time,
error rate based on

44
0:2:46,08 --> 0:2:47,94
a specific application, for example.

45
0:2:49,38 --> 0:2:52,36
If you collect information for
a given user.

46
0:2:53,1 --> 0:2:55,2
Nikolay: So I agree with you.

47
0:2:55,2 --> 0:2:59,16
This is a big gap in Postgres observability
that we cannot understand

48
0:2:59,34 --> 0:3:2,5
error rates beyond a couple of
things.

49
0:3:2,5 --> 0:3:6,68
There is a rollback counter, like
transaction xact_commit, xact_

50
0:3:6,68 --> 0:3:9,36
rollback, 2 counters in pg_stat_
database.

51
0:3:9,56 --> 0:3:12,1
But what if some other error happened,
right?

52
0:3:12,16 --> 0:3:14,16
And also, what kind of error?

53
0:3:14,38 --> 0:3:18,24
Is it just like uniqueness violation
or it's corruption, like

54
0:3:18,24 --> 0:3:23,6
codes, there are 3 codes for like
most painful codes, XX000,

55
0:3:24,52 --> 0:3:26,6
XX001, XX002.

56
0:3:27,1 --> 0:3:30,04
You mentioned error codes, there
is a registry of error codes,

57
0:3:30,04 --> 0:3:34,64
but it's not possible to monitor
them other than just going to

58
0:3:34,64 --> 0:3:35,14
logs.

59
0:3:35,54 --> 0:3:40,22
But logs, I agree with you, it's
hard to reach them often.

60
0:3:40,46 --> 0:3:43,28
But also they contain sometimes
personal data.

61
0:3:43,78 --> 0:3:47,9
This PII, for example, Our stack
for PostgresAI, companies come

62
0:3:47,9 --> 0:3:52,04
to us to analyze health of database,
and we don't deal with logs

63
0:3:52,04 --> 0:3:53,16
directly, never.

64
0:3:53,22 --> 0:3:56,04
Because we don't want to tell them
we deal with PII, because

65
0:3:56,04 --> 0:4:0,42
everything we deal with is just
metadata, some counters, And

66
0:4:0,42 --> 0:4:2,54
we want error rates like that,
right?

67
0:4:2,78 --> 0:4:5,74
Grouped by, as you mentioned, by
multiple things.

68
0:4:5,74 --> 0:4:7,92
For me, the most interesting is
error codes.

69
0:4:7,92 --> 0:4:12,32
I want to know exactly, like, in
the past month, did we have

70
0:4:12,32 --> 0:4:14,98
any XX codes in this database or
not?

71
0:4:15,04 --> 0:4:16,41998
It's not possible to answer.

72
0:4:16,92 --> 0:4:20,1
It's insane that it's not possible
to answer, right?

73
0:4:20,54 --> 0:4:23,24
There's another thing which is
not possible to answer.

74
0:4:23,26 --> 0:4:24,6
It's queries per 2nd.

75
0:4:25,58 --> 0:4:26,88
Not possible to answer.

76
0:4:26,94 --> 0:4:30,32
You can extract it from pg_stat_database,
but it's maybe not the

77
0:4:30,32 --> 0:4:31,58
whole iceberg, right?

78
0:4:32,32 --> 0:4:33,74
Yeah, but it's a different story.

79
0:4:33,74 --> 0:4:37,32
I'm also thinking, why is it not
like, why nobody's attacking

80
0:4:37,32 --> 0:4:38,86
this missing piece?

81
0:4:39,06 --> 0:4:39,92
But that's great.

82
0:4:39,92 --> 0:4:43,14
So you built this extension and
1st question, you mentioned all

83
0:4:43,14 --> 0:4:46,6
these things to group by, why there
is no query ID there?

84
0:4:47,78 --> 0:4:52,02
Fabrízio: I think just because
I didn't add it yet, maybe for

85
0:4:52,02 --> 0:4:54,84
the next version we can introduce
a query ID.

86
0:4:55,52 --> 0:5:0,34
We are jumbling the query and providing
the query ID, we can

87
0:5:0,7 --> 0:5:4,3
collect and store that as a new
key for this.

88
0:5:4,82 --> 0:5:8,3
Nikolay: Because I want to know
which, for example, which queries

89
0:5:8,8 --> 0:5:9,78
had these errors.

90
0:5:10,58 --> 0:5:11,04
Right?

91
0:5:11,04 --> 0:5:11,82
Fabrízio: That makes sense.

92
0:5:11,82 --> 0:5:12,54
Makes sense.

93
0:5:12,9 --> 0:5:15,06
Nikolay: Maybe it's expensive in
terms of overhead.

94
0:5:15,06 --> 0:5:18,56
We can discuss overhead slightly
later maybe because it's a big

95
0:5:18,56 --> 0:5:19,06
topic.

96
0:5:19,28 --> 0:5:23,7
But another question I had, why
did you call it pg_stat_log, not

97
0:5:23,7 --> 0:5:25,54
pg_stat_errors or something?

98
0:5:27,72 --> 0:5:32,06
Fabrízio: Because we can collect
normal log messages as well.

99
0:5:33,1 --> 0:5:40,64
So I created this configuration,
min error level, that you can

100
0:5:40,64 --> 0:5:45,52
define what is the minimum error
level you can, you want to collect.

101
0:5:46,34 --> 0:5:49,7
Nikolay: Not only error, also warnings
and notices like...

102
0:5:49,9 --> 0:5:50,4
Fabrízio: Everything.

103
0:5:50,66 --> 0:5:51,88
You can collect everything.

104
0:5:51,96 --> 0:5:56,08
The default is a warning, error
level is error, but you can define

105
0:5:56,68 --> 0:5:59,0
any error level.

106
0:5:59,14 --> 0:5:59,94
Even debug.

107
0:6:0,78 --> 0:6:2,3
Michael: I think default is warning.

108
0:6:3,3 --> 0:6:4,78
Fabrízio: Oh, default is warning,
sorry.

109
0:6:5,28 --> 0:6:9,76
Michael: Which is the same as,
you had a really good caveat section

110
0:6:9,76 --> 0:6:10,82
in the README.

111
0:6:11,84 --> 0:6:15,96
You mentioned about log_min_messages
as well, which also defaults

112
0:6:16,16 --> 0:6:16,94
to warning.

113
0:6:17,42 --> 0:6:21,44
So by default, both match, which
is nice.

114
0:6:21,74 --> 0:6:24,62
But if you want more than warnings,
you also need to change that

115
0:6:24,62 --> 0:6:26,98
because otherwise they don't end
up in the logs in the 1st place

116
0:6:26,98 --> 0:6:28,14
and you're using that hook.

117
0:6:28,14 --> 0:6:30,52
I think it's really cool for all
the reasons Nik mentioned,

118
0:6:30,52 --> 0:6:32,2
but also potentially for more.

119
0:6:32,2 --> 0:6:35,28
I feel like there's probably quite
a few things that are warnings

120
0:6:35,36 --> 0:6:39,58
in the logs that probably a lot
of maybe managed service users

121
0:6:39,58 --> 0:6:42,74
or maybe users in general just
don't ever notice because they

122
0:6:42,74 --> 0:6:44,94
don't think to look in the logs
for warnings.

123
0:6:45,18 --> 0:6:50,42
So I think exposing those via some
Monitoring tools or other

124
0:6:50,42 --> 0:6:52,2
tools could be really useful as
well.

125
0:6:52,2 --> 0:6:55,24
Just show you you do have warnings
going on in your logs, by

126
0:6:55,24 --> 0:6:55,86
the way

127
0:6:57,72 --> 0:7:0,58
Nikolay: Let's name the core of
the problem the root of the problem

128
0:7:0,58 --> 0:7:6,9
there are like all SREs know methodologies
like USE, right? Brendan

129
0:7:6,9 --> 0:7:12,18
Gregg's USE and four golden signals
We cannot apply them to Postgres

130
0:7:12,18 --> 0:7:15,76
right now without digging the logs
all the time.

131
0:7:16,12 --> 0:7:20,58
And this is insane that they cannot
apply basic methodologies,

132
0:7:20,92 --> 0:7:24,74
because all of them include question,
do we have a spike of errors,

133
0:7:24,74 --> 0:7:25,24
right?

134
0:7:25,52 --> 0:7:26,48
We cannot answer.

135
0:7:26,48 --> 0:7:28,4
Let's go grab logs and answer.

136
0:7:28,44 --> 0:7:32,08
It's an insane situation, which
means that demand in this tool

137
0:7:32,08 --> 0:7:33,0
is huge.

138
0:7:33,48 --> 0:7:34,74
Everyone needs it.

139
0:7:35,68 --> 0:7:39,64
Fabrízio: Yeah, you can get rid
of some complex stack like Logstash,

140
0:7:39,8 --> 0:7:40,3
and

141
0:7:40,68 --> 0:7:42,04
Nikolay: Yeah, exactly.

142
0:7:42,12 --> 0:7:42,7
And all

143
0:7:42,7 --> 0:7:47,46
Fabrízio: this stuff, Kibana, and
just have your simple view

144
0:7:47,62 --> 0:7:52,86
and a postgres_exporter or something
collecting time to time information

145
0:7:52,96 --> 0:7:56,08
from this view and send out to
Prometheus.

146
0:7:56,32 --> 0:7:57,84
Grafana or something.

147
0:7:58,86 --> 0:7:59,36
Nikolay: Exactly.

148
0:7:59,38 --> 0:8:1,48
Like you can analyze it inside
database.

149
0:8:1,5 --> 0:8:3,36
I saw weird extensions.

150
0:8:4,14 --> 0:8:6,04
Fabrízio: Yeah, using R2, your
pg_ash.

151
0:8:8,06 --> 0:8:8,84
Nikolay: Yeah, like that.

152
0:8:8,84 --> 0:8:12,7
Like just self-collecting samples
and understand buckets and

153
0:8:12,7 --> 0:8:13,14
so on.

154
0:8:13,14 --> 0:8:13,88
It's possible.

155
0:8:14,06 --> 0:8:19,1
But also, Because of lacking this
observability piece, I saw

156
0:8:19,54 --> 0:8:23,5
long ago, like RDS had it as well,
extensions like foreign data

157
0:8:23,5 --> 0:8:27,8
wrappers over logs just to bring
this visibility about errors

158
0:8:27,8 --> 0:8:33,78
and something to SQL context, which
is like absolutely crazy

159
0:8:33,96 --> 0:8:34,46
thing.

160
0:8:34,9 --> 0:8:38,6
So yeah, that's great and it's
great to have it, but everywhere

161
0:8:38,6 --> 0:8:42,24
we discussed it so far, and this
podcast won't be an exclusion,

162
0:8:42,8 --> 0:8:46,98
I say this must be, I'm not asking,
I'm just saying, this must

163
0:8:46,98 --> 0:8:47,6
be in core.

164
0:8:47,6 --> 0:8:48,1
So.

165
0:8:48,9 --> 0:8:52,76
Fabrízio: Yeah, what I was about
to ask you why do you want do

166
0:8:52,76 --> 0:8:54,64
you think this should be in core?

167
0:8:54,64 --> 0:9:0,28
It truly in core not as an extension
because my plan right now

168
0:9:0,28 --> 0:9:5,88
is package this as a contrib module
and submit it upstream.

169
0:9:6,5 --> 0:9:9,82
I didn't do it yet just for final
review.

170
0:9:10,64 --> 0:9:12,08
Michael: Like pg_stat_statements.

171
0:9:12,44 --> 0:9:12,8
Nikolay: Right.

172
0:9:12,8 --> 0:9:13,04
Fabrízio: Yeah.

173
0:9:13,04 --> 0:9:14,28
Like pg_stat_statements.

174
0:9:15,14 --> 0:9:16,42
Like pg_stat_statements.

175
0:9:16,72 --> 0:9:17,58
Nikolay: That's great.

176
0:9:17,64 --> 0:9:20,78
I think this is the absolute minimum
that needs to be done.

177
0:9:21,0 --> 0:9:25,24
But I also think pg_stat_statements should
be in core to avoid this

178
0:9:25,24 --> 0:9:27,34
friction of creating extensions.

179
0:9:27,94 --> 0:9:32,54
And this should be in core just
because, Again, any serious methodology

180
0:9:33,18 --> 0:9:37,2
includes error analysis, and it's
not available without digging

181
0:9:37,2 --> 0:9:37,7
logs.

182
0:9:38,26 --> 0:9:42,18
And digging logs is not always
possible because it has a PII

183
0:9:42,18 --> 0:9:44,56
and not all people have access
to it.

184
0:9:45,04 --> 0:9:47,72
Not all external people or internal
people sometimes don't have

185
0:9:47,72 --> 0:9:51,1
access because there is PII, like
emails or something, right?

186
0:9:51,4 --> 0:9:54,56
We just don't need to know basic
things like error rates.

187
0:9:54,86 --> 0:9:59,8
Without building this stack with
Kibana or something, I never

188
0:9:59,8 --> 0:10:1,24
saw it working really well.

189
0:10:1,5 --> 0:10:5,28
I saw many companies build this,
But the only thing I saw that

190
0:10:5,28 --> 0:10:9,74
was working quite well was Splunk,
which costs millions of dollars.

191
0:10:10,08 --> 0:10:13,44
Splunk costs millions of dollars
and requires a whole team to

192
0:10:13,44 --> 0:10:13,68
manage.

193
0:10:13,68 --> 0:10:16,76
It's a great piece of software,
super expensive.

194
0:10:17,42 --> 0:10:21,66
I don't see any startup that could
afford it actually, in terms

195
0:10:21,66 --> 0:10:24,64
of money and people allocated to
manage it.

196
0:10:24,66 --> 0:10:25,94
So it should be simple.

197
0:10:26,26 --> 0:10:28,1
Like error analysis must be simple.

198
0:10:28,1 --> 0:10:30,96
That's why it must be in core,
available to everyone.

199
0:10:31,78 --> 0:10:35,94
Fabrízio: And you know that, talking
about simplicity, this extension

200
0:10:37,46 --> 0:10:40,62
was something that I wanted to
work for a long time.

201
0:10:41,72 --> 0:10:46,04
And the main reason I didn't start
it many years ago was because,

202
0:10:46,06 --> 0:10:51,44
oh, I need to build an entire pg_
stat_statements-like extension.

203
0:10:52,92 --> 0:10:56,96
With serializing the information
to somewhere, and then

204
0:10:56,96 --> 0:10:59,76
deserializing information and all
of those.

205
0:11:0,04 --> 0:11:1,62
It's a lot of work, right?

206
0:11:1,72 --> 0:11:4,84
And then I always have something
else to do.

207
0:11:4,84 --> 0:11:5,9
And I never do.

208
0:11:6,18 --> 0:11:14,62
Then the new feature Postgres released
on PG 18, Custom Cumulative

209
0:11:15,06 --> 0:11:15,56
Stats.

210
0:11:16,46 --> 0:11:20,38
That is great because open the
doors for the extension authors

211
0:11:20,38 --> 0:11:24,56
to create their own statistics
like that.

212
0:11:24,66 --> 0:11:27,74
And then the statistics collector
of Postgres, you do the job

213
0:11:27,74 --> 0:11:30,56
to collect your statistics.

214
0:11:31,3 --> 0:11:37,2
So it abstracts a lot of complexity
of dealing with a lot of

215
0:11:37,2 --> 0:11:40,02
memory, serializing, deserializing
stuff.

216
0:11:40,32 --> 0:11:44,22
And Postgres, and on the extension
side, we need to deal only

217
0:11:44,22 --> 0:11:49,2
with the business logic of the
thing, what you want to collect,

218
0:11:49,3 --> 0:11:49,8
right?

219
0:11:50,42 --> 0:11:53,98
So this is 1 of the reasons that
I started.

220
0:11:54,64 --> 0:11:59,28
The 2nd reason is, okay, I need
to try more AI tools because

221
0:11:59,28 --> 0:12:4,14
I'm an old guy trying new AI stuff
and then I tried it.

222
0:12:4,54 --> 0:12:9,22
And the 3rd reason because Nik
liked it very much and pushed

223
0:12:9,22 --> 0:12:9,92
me a bit.

224
0:12:9,92 --> 0:12:13,24
Okay, we need to do this, we need
to have this in core.

225
0:12:13,32 --> 0:12:14,68
So let's do this.

226
0:12:15,04 --> 0:12:20,42
Then I bootstrap the 1st version
and then Nik, helping me using

227
0:12:20,6 --> 0:12:25,84
AI tools, reviewing, testing, and
all of the edge cases.

228
0:12:25,84 --> 0:12:33,28
So now we have a good state of
code that is good enough to send

229
0:12:33,28 --> 0:12:36,42
to upstream like a contrib module
like pg_stat_statements.

230
0:12:37,28 --> 0:12:41,54
Those are 1 of the reasons that
I decided to do this right now.

231
0:12:42,04 --> 0:12:46,38
It means that this extension won't
work for example, with PG

232
0:12:46,38 --> 0:12:52,86
17, 16 only on PG 18 and next versions.

233
0:12:54,28 --> 0:12:54,78
Michael: Nice.

234
0:12:54,84 --> 0:12:57,94
I saw you already added 19 support
as well.

235
0:12:58,04 --> 0:13:1,1
Was that much additional work or
was that relatively straightforward

236
0:13:1,18 --> 0:13:1,92
in the end?

237
0:13:2,64 --> 0:13:5,14
Fabrízio: I think it was only 1

238
0:13:7,66 --> 0:13:8,16
Nikolay: macro,

239
0:13:9,24 --> 0:13:10,96
Fabrízio: only 1 small piece of
code.

240
0:13:10,96 --> 0:13:13,14
It's just 1 commit to make it work.

241
0:13:13,14 --> 0:13:15,34
The most part of it.

242
0:13:15,34 --> 0:13:20,7
The issue is the same Because some
internal data structures was

243
0:13:21,04 --> 0:13:26,32
renamed or moved around and then
I just used a macro or two to

244
0:13:26,32 --> 0:13:29,84
make it compatible either on 18
or 19.

245
0:13:30,54 --> 0:13:34,46
Even on main Postgres branch is
compatible right now.

246
0:13:35,2 --> 0:13:36,24
Michael: Nice, perfect.

247
0:13:36,98 --> 0:13:39,02
Fabrízio: For the 20 development
cycle.

248
0:13:39,96 --> 0:13:40,84
Nikolay: That's good.

249
0:13:40,84 --> 0:13:44,78
Let's talk a little bit about overhead
and observer effect.

250
0:13:45,3 --> 0:13:47,58
What's the price of having all
those counters?

251
0:13:49,2 --> 0:13:53,36
Fabrízio: I did some very basic
benchmarks.

252
0:13:55,44 --> 0:14:1,36
The overhead I saw, setting the
min error level to log everything

253
0:14:1,72 --> 0:14:8,22
and run some pgbench synthetic
workload I max around 2-3%

254
0:14:9,52 --> 0:14:10,22
of overhead

255
0:14:11,32 --> 0:14:14,36
Nikolay: What was QPS and how many
log messages per 2nd?

256
0:14:16,1 --> 0:14:17,54
Fabrízio: Come on, I don't...

257
0:14:17,68 --> 0:14:21,64
I think I have this information
in the issue.

258
0:14:22,92 --> 0:14:23,94
Nikolay: Yeah, I'm very curious.

259
0:14:24,52 --> 0:14:25,96
Maybe I want to dig myself.

260
0:14:26,68 --> 0:14:27,94
I just need to find time.

261
0:14:32,22 --> 0:14:34,92
Michael: Just to be clear though,
the default here is warning

262
0:14:34,92 --> 0:14:37,88
and we're, but we're all saying
that it would be useful at warning

263
0:14:37,88 --> 0:14:40,74
or even error, it would still be
extremely useful.

264
0:14:40,84 --> 0:14:45,42
So presumably at those levels,
it's going to be near 0 overhead.

265
0:14:45,72 --> 0:14:46,76
Fabrízio: Yes, exactly.

266
0:14:47,54 --> 0:14:47,72
Yeah.

267
0:14:47,72 --> 0:14:50,72
I tested on the worst case scenario.

268
0:14:51,58 --> 0:14:55,96
1 of the worst case scenario, logging
everything and then collecting

269
0:14:56,04 --> 0:14:56,54
everything.

270
0:14:57,62 --> 0:15:3,12
And then now I discovered something
that I'm working on because

271
0:15:3,18 --> 0:15:8,42
we need to configure the capacity
of how many lines we collect,

272
0:15:9,02 --> 0:15:14,54
how many entries we collect in
this pg_stat_log, like pg_stat_statements.

273
0:15:15,08 --> 0:15:18,52
Nikolay: And pg_stat_statements
is 5000 by default, pg_stat_statements

274
0:15:18,52 --> 0:15:19,26
dot max.

275
0:15:19,94 --> 0:15:20,84
Fabrízio: Yeah, exactly.

276
0:15:21,58 --> 0:15:24,72
And then a new different entry
came.

277
0:15:25,52 --> 0:15:28,38
I'm not doing O(1) now, brute
forcing.

278
0:15:28,68 --> 0:15:30,12
And this make expensive.

279
0:15:31,06 --> 0:15:35,74
I have 1 entry that should be discarded,
be dropped and not collected

280
0:15:35,76 --> 0:15:38,3
because my list is full.

281
0:15:38,68 --> 0:15:41,92
My list of entries that I'm collecting
right now is full.

282
0:15:42,38 --> 0:15:49,02
So this, I think Nik advised me
to create this dropped information

283
0:15:49,34 --> 0:15:54,06
on the pg_stat_log_info() to see
how many messages were not collected.

284
0:15:55,76 --> 0:16:1,36
And when we reach to this point,
then the performance is even

285
0:16:1,36 --> 0:16:1,86
worse.

286
0:16:2,42 --> 0:16:5,82
The overhead is like 27% or 30%.

287
0:16:6,76 --> 0:16:13,78
So I'm here working the main algorithm
to don't be so expensive.

288
0:16:14,62 --> 0:16:15,12
Nikolay: Right.

289
0:16:15,14 --> 0:16:18,74
We talk about overhead here on
the edge case when it's basically

290
0:16:18,74 --> 0:16:22,22
a stress load, when we have a lot
of log messages happening.

291
0:16:23,0 --> 0:16:27,72
Then it's worth noticing that these
messages go to logs as well,

292
0:16:27,72 --> 0:16:28,22
right?

293
0:16:28,74 --> 0:16:32,9
If we have so many log messages,
we have observer effects there

294
0:16:32,9 --> 0:16:33,4
anyway.

295
0:16:34,18 --> 0:16:37,22
Fabrízio: Yes, you have problem
anyway because your log is...

296
0:16:37,34 --> 0:16:38,86
Nikolay: All queries, this is simple.

297
0:16:38,86 --> 0:16:42,86
Let's set log_statement to all,
and let's go.

298
0:16:42,86 --> 0:16:46,22
This is how you can put your server
down If it's loaded.

299
0:16:46,82 --> 0:16:51,76
So it means that overhead you introduce
is like sister or brother

300
0:16:51,76 --> 0:16:54,02
overhead of what we already have
in logs.

301
0:16:54,64 --> 0:16:56,78
We're just slightly amplifying
it.

302
0:16:56,82 --> 0:17:1,2
When amplifying, not badly, because
overhead from Writing to

303
0:17:1,2 --> 0:17:3,14
disk is high.

304
0:17:3,6 --> 0:17:8,08
If you write 1000 lines per 2nd
through a logging collector,

305
0:17:8,48 --> 0:17:10,26
you will notice this.

306
0:17:11,12 --> 0:17:12,04
And I know it.

307
0:17:12,04 --> 0:17:13,08
You will notice it.

308
0:17:13,08 --> 0:17:17,54
If you increment some count 1000
times per 2nd, you also probably

309
0:17:17,64 --> 0:17:19,26
will notice it, but less.

310
0:17:20,06 --> 0:17:20,34
So

311
0:17:20,34 --> 0:17:21,14
Fabrízio: we should

312
0:17:21,5 --> 0:17:24,12
Nikolay: log less, this should
be a rule, right?

313
0:17:24,12 --> 0:17:27,88
And exploring overhead on edge
case makes sense just to understand

314
0:17:28,94 --> 0:17:29,86
how much is...

315
0:17:29,86 --> 0:17:33,18
Maybe we should explore with flame
graphs as well in normal conditions,

316
0:17:33,34 --> 0:17:36,0
like how much is going to these
functions.

317
0:17:36,76 --> 0:17:38,4
Also, contention risks.

318
0:17:38,4 --> 0:17:41,1
Obviously you have some lightweight
lock introduced, right?

319
0:17:41,6 --> 0:17:45,18
Fabrízio: Yes, I have some lightweight
lock introduced, but The

320
0:17:45,18 --> 0:17:51,24
good news is that this is processed
by a stats collector, because

321
0:17:51,96 --> 0:17:54,64
it's done on the stats collector
side.

322
0:17:55,08 --> 0:17:59,34
But anyway, it's using the hot
path of the emit_log_hook.

323
0:17:59,34 --> 0:18:1,48
So it creates contention.

324
0:18:1,84 --> 0:18:4,32
But mostly CPU contention.

325
0:18:4,78 --> 0:18:8,5
Memory contention is not too much,
but it's more CPU contention.

326
0:18:9,06 --> 0:18:12,08
It's not disk contention because
we are not writing anything

327
0:18:12,24 --> 0:18:14,08
on this, on the extension.

328
0:18:14,44 --> 0:18:19,7
It's done on the stats collector
when you shut down server and

329
0:18:19,82 --> 0:18:23,76
start the server because this is
done by another subsystem, not

330
0:18:23,76 --> 0:18:25,06
in the extension itself.

331
0:18:25,38 --> 0:18:30,06
We have a new abstraction that
Custom Cumulative Stats is created

332
0:18:30,06 --> 0:18:32,8
that is great for extension developers.

333
0:18:33,9 --> 0:18:34,94
Michael: Yeah, that's important.

334
0:18:35,06 --> 0:18:39,4
So it means like a safe restart,
like not a crash, the stats

335
0:18:39,4 --> 0:18:40,1
will persist.

336
0:18:41,46 --> 0:18:41,96
Yeah.

337
0:18:43,32 --> 0:18:43,4733
Yeah.

338
0:18:43,4733 --> 0:18:45,64
But on crash it would be lost,
which makes sense.

339
0:18:46,24 --> 0:18:46,74
Fabrízio: Yes.

340
0:18:47,24 --> 0:18:48,96
It behaves like PG stats.

341
0:18:50,22 --> 0:18:52,36
Nikolay: I think also granularity
matters, right?

342
0:18:52,36 --> 0:18:55,96
Because you have some only some
limited number of aggregated

343
0:18:56,12 --> 0:18:57,02
entries, right?

344
0:18:57,7 --> 0:19:2,78
So aggregate by error code, by
database, user and severity level,

345
0:19:2,78 --> 0:19:3,28
right?

346
0:19:3,54 --> 0:19:7,26
But if we, for example, have very
volatile situation, I don't

347
0:19:7,26 --> 0:19:11,82
know, like maybe a lot of users
we have, or maybe a lot of databases.

348
0:19:12,6 --> 0:19:17,08
So we have a lot of entries, we
probably don't want them, right?

349
0:19:17,08 --> 0:19:22,5
For example, my 1st thought is
maybe I don't want warnings, right?

350
0:19:22,5 --> 0:19:24,72
Because it's too much, too much
information.

351
0:19:24,72 --> 0:19:26,86
And I know I will be paying for
this overhead.

352
0:19:27,62 --> 0:19:29,08
Maybe I want only errors.

353
0:19:29,34 --> 0:19:33,34
But at the same time, I know some
warnings I definitely would

354
0:19:33,34 --> 0:19:34,3
like to see.

355
0:19:34,3 --> 0:19:40,22
For example, a warning about glibc
collation mismatch, like suggesting

356
0:19:40,24 --> 0:19:43,38
that maybe we have some corruption,
silent corruption and so

357
0:19:43,38 --> 0:19:43,88
on.

358
0:19:43,94 --> 0:19:46,54
These were warnings I definitely
would love to catch.

359
0:19:47,22 --> 0:19:49,94
Also, there are some errors I definitely
would like to ignore.

360
0:19:49,94 --> 0:19:53,04
For example, uniqueness violation
counter is good.

361
0:19:53,04 --> 0:19:57,62
But what if we start that database
and it says this very famous

362
0:19:58,2 --> 0:20:1,52
error message, FATAL: the database
system is starting up.

363
0:20:1,72 --> 0:20:2,16
It's not

364
0:20:2,16 --> 0:20:2,56
Michael: an error

365
0:20:2,56 --> 0:20:3,06
Nikolay: actually.

366
0:20:4,16 --> 0:20:7,5
It's just like a quintal bit, but
it seems like an error and

367
0:20:7,5 --> 0:20:9,06
we can have spike of errors.

368
0:20:9,28 --> 0:20:12,08
Which means that, imagine we have
all of that.

369
0:20:12,44 --> 0:20:16,8
To properly tune alerts, I probably
should make some decisions around

370
0:20:16,8 --> 0:20:17,3
filtering.

371
0:20:17,64 --> 0:20:19,86
What I want, what I don't want,
right?

372
0:20:19,94 --> 0:20:23,1
And maybe it should be done not
later but sooner maybe I should

373
0:20:23,1 --> 0:20:26,1
just cut some messages and this
could be some like filtering

374
0:20:26,98 --> 0:20:30,54
Fabrízio: yeah some filtering
configuration yeah make a lot

375
0:20:30,54 --> 0:20:30,72
of

376
0:20:30,72 --> 0:20:34,26
Nikolay: I just give these warnings
shut them down so anything

377
0:20:34,26 --> 0:20:37,5
like this it's more maybe wouldn't
let make life easier because

378
0:20:37,5 --> 0:20:41,72
usually what I don't want is some
frequent noise for me.

379
0:20:41,72 --> 0:20:45,98
And in this case, if we can discard
it, it makes the tool more

380
0:20:45,98 --> 0:20:47,06
lightweight, right?

381
0:20:47,92 --> 0:20:49,2
So overhead lower.

382
0:20:49,74 --> 0:20:51,76
Just brainstorming a little bit.

383
0:20:52,88 --> 0:20:58,04
Fabrízio: You can also create some
filtering for a specific user

384
0:20:58,04 --> 0:21:1,6
you want only to track information
about a specific user.

385
0:21:4,22 --> 0:21:6,66
Nikolay: But this is only later,
because you track all

386
0:21:6,66 --> 0:21:7,16
Fabrízio: users.

387
0:21:7,2 --> 0:21:9,38
Nikolay: I can't say I want only
this user.

388
0:21:9,38 --> 0:21:11,08
There is no such filtering.

389
0:21:11,54 --> 0:21:15,26
Anyway, so you mentioned this cumulative
statistics mechanism

390
0:21:15,34 --> 0:21:18,16
appeared in Postgres 18, And this
is great.

391
0:21:18,16 --> 0:21:22,0
Postgres once again became even
more extendable, extensible,

392
0:21:22,06 --> 0:21:22,56
right?

393
0:21:22,7 --> 0:21:23,54
Which is good.

394
0:21:24,6 --> 0:21:28,08
I noticed you registered kind ID,
I don't know, 28, right?

395
0:21:28,08 --> 0:21:29,98
The kind of statistics.

396
0:21:31,72 --> 0:21:33,48
Right now the process is very interesting.

397
0:21:33,62 --> 0:21:35,96
You go to wiki page and put it
there, right?

398
0:21:37,74 --> 0:21:42,26
27 was pg_stat_plans from Lukas,
right?

399
0:21:42,26 --> 0:21:48,36
I think now you 28 also after you,
who came, spock, pg_stat_login, right?

400
0:21:48,46 --> 0:21:49,74
I think, yeah.

401
0:21:49,74 --> 0:21:53,04
29 is spock and then number 30
is pg_stat_login.

402
0:21:53,52 --> 0:21:57,48
So we have only 4 lines right now
because this is super fresh.

403
0:21:58,28 --> 0:22:1,2
And you were number 2 actually
among these 4.

404
0:22:1,2 --> 0:22:1,98
That's great.

405
0:22:2,08 --> 0:22:3,66
I have 2 questions, actually.

406
0:22:3,74 --> 0:22:9,0
I know there were some attempts
to create such like this thing,

407
0:22:9,0 --> 0:22:11,1
like cumulative counters for errors.

408
0:22:11,4 --> 0:22:16,86
1 of them was called extension,
or was called logerrors, right?

409
0:22:17,52 --> 0:22:22,32
And I'm just curious, what are
the benefits from switching?

410
0:22:22,36 --> 0:22:24,36
Because we use logerrors in a
few places.

411
0:22:25,02 --> 0:22:27,1
I understand the internal benefit.

412
0:22:27,18 --> 0:22:29,54
You use it in an official way right
now.

413
0:22:30,04 --> 0:22:34,44
And I suspect data in your extension
will survive restarts, unlike

414
0:22:34,44 --> 0:22:35,14
logerrors.

415
0:22:36,1 --> 0:22:37,4
This is what I see easily.

416
0:22:38,04 --> 0:22:41,2
Because they needed to implement
their own piece of shared memory

417
0:22:41,2 --> 0:22:43,02
and all the machinery around it,
right?

418
0:22:43,14 --> 0:22:45,86
Maybe it will survive as well if
they implemented it.

419
0:22:45,86 --> 0:22:46,56
What else?

420
0:22:47,32 --> 0:22:51,52
If, obviously, you take care of
warnings and your granularity

421
0:22:51,74 --> 0:22:56,2
is better, maybe you will introduce
query ideas, which will be

422
0:22:56,2 --> 0:22:59,36
nice, but dangerous and expensive,
right?

423
0:23:0,14 --> 0:23:1,0
Like what else?

424
0:23:1,0 --> 0:23:2,96
What's the benefit?

425
0:23:3,82 --> 0:23:3,84
Fabrízio: So.

426
0:23:3,84 --> 0:23:7,12
I wasn't aware about this extension
that you are mentioning?

427
0:23:7,68 --> 0:23:8,66
I don't remember.

428
0:23:8,76 --> 0:23:11,14
Nikolay: Yeah, logerrors, 1 word
without underscore.

429
0:23:11,78 --> 0:23:12,76
Fabrízio: Ah, logerrors.

430
0:23:12,8 --> 0:23:13,82
Okay, I found.

431
0:23:15,06 --> 0:23:17,78
Nikolay: So, it's all I can answer
for you.

432
0:23:17,96 --> 0:23:22,48
The main benefit will be if it
goes to core or at least as contrib

433
0:23:22,48 --> 0:23:26,08
module, this will become packaging
much easier.

434
0:23:26,78 --> 0:23:27,66
Fabrízio: Yes, absolutely.

435
0:23:28,4 --> 0:23:28,9
Nikolay: Yeah.

436
0:23:30,18 --> 0:23:30,3
Yeah.

437
0:23:30,3 --> 0:23:34,84
And since you chose this new approach,
but what are the chances?

438
0:23:34,84 --> 0:23:40,1
Obviously Postgres 19 is already
past beta 1, beta 2 is coming,

439
0:23:40,46 --> 0:23:42,94
so cannot be included in Postgres
19.

440
0:23:43,26 --> 0:23:45,12
Do you have plans for Postgres
20?

441
0:23:45,72 --> 0:23:47,12
Fabrízio: Yeah, for Postgres 20.

442
0:23:48,22 --> 0:23:49,36
For sure next year.

443
0:23:49,36 --> 0:23:50,14
Next year, yeah.

444
0:23:50,14 --> 0:23:51,82
I will publish it for next year.

445
0:23:51,82 --> 0:23:52,32
Yes.

446
0:23:53,16 --> 0:23:53,92
Nikolay: That's great.

447
0:23:54,02 --> 0:23:57,4
I'm definitely willing to support
with any more testing and so

448
0:23:57,4 --> 0:23:57,7
on.

449
0:23:57,7 --> 0:23:59,52
I just want this to be there.

450
0:23:59,54 --> 0:24:2,82
Because so many clusters I observed,
which needed.

451
0:24:3,82 --> 0:24:8,5
And I just, honestly, like, when
we needed to analyze performance

452
0:24:8,72 --> 0:24:11,3
using usually pgFouine and then
pgBadger.

453
0:24:11,6 --> 0:24:12,1
Fabrízio: pgFouine.

454
0:24:12,34 --> 0:24:14,92
Nikolay: I love it was pgFouine,
you remember?

455
0:24:14,92 --> 0:24:15,58
And PHP.

456
0:24:17,12 --> 0:24:18,14
Fabrízio: Yes, I remember.

457
0:24:18,14 --> 0:24:19,22
You need to laugh.

458
0:24:20,94 --> 0:24:22,18
Nikolay: Yeah, Perl, pgBadger.

459
0:24:22,66 --> 0:24:27,1
And I remember guys who said, we're
going to switch on a logging

460
0:24:27,28 --> 0:24:29,08
or everything for 5 minutes.

461
0:24:29,18 --> 0:24:32,28
It will be hard for everybody,
but we need it because we need

462
0:24:32,28 --> 0:24:33,7
to see the whole thing.

463
0:24:37,74 --> 0:24:41,1
And now we have pg_stat_statements,
pg_wait_sampling, pg_stat_kcache,

464
0:24:42,04 --> 0:24:46,42
and also another approach, like
Active Session History approach.

465
0:24:46,42 --> 0:24:46,92
Great.

466
0:24:47,26 --> 0:24:49,9
But errors are still a problem,
right?

467
0:24:50,28 --> 0:24:52,74
And I just don't want to deal with
logs like that.

468
0:24:53,4 --> 0:24:57,1
I want them to be a mechanism when
we already understood what's

469
0:24:57,1 --> 0:24:59,58
happening at high level and we
need examples.

470
0:25:0,04 --> 0:25:4,22
Then I want to go to logs, but
the scale of the problem, like

471
0:25:4,22 --> 0:25:6,9
to triage the problem, I don't
need logs.

472
0:25:7,58 --> 0:25:8,08
Fabrízio: Yeah.

473
0:25:8,2 --> 0:25:8,7
Excellent.

474
0:25:9,84 --> 0:25:10,94
Thanks for the question.

475
0:25:11,12 --> 0:25:17,2
I think, do you have enough tools
now, you don't need pg

476
0:25:17,2 --> 0:25:17,7
Badger?

477
0:25:18,26 --> 0:25:18,76
Excellent.

478
0:25:19,54 --> 0:25:21,92
Nikolay: I haven't touched it maybe
5 years.

479
0:25:22,06 --> 0:25:22,58
I don't need it.

480
0:25:22,58 --> 0:25:23,44
Fabrízio: Yeah, me neither.

481
0:25:24,62 --> 0:25:25,94
It's been more than 5 years.

482
0:25:26,8 --> 0:25:29,82
Nikolay: But in bigger companies
I deal with, we usually have

483
0:25:29,82 --> 0:25:34,14
some already flow to process logs
either from RDS, CloudWatch,

484
0:25:34,7 --> 0:25:36,6
pull them, put them somewhere.

485
0:25:36,96 --> 0:25:40,22
So they have it, but they usually
have it not because of Postgres,

486
0:25:40,24 --> 0:25:41,62
but for everything, right?

487
0:25:42,24 --> 0:25:46,26
So some log collector and analysis,
Elastic, Kibana, all this,

488
0:25:46,26 --> 0:25:46,76
right?

489
0:25:47,14 --> 0:25:48,78
But I touch it less and less.

490
0:25:50,14 --> 0:25:52,12
And I don't need it too often.

491
0:25:52,12 --> 0:25:56,54
So yeah, this is, once this is
there, at least this contrib module,

492
0:25:57,58 --> 0:26:0,8
life will become much easier when
we have incidents, right?

493
0:26:0,8 --> 0:26:2,98
And we need to quickly understand
what's happening.

494
0:26:3,52 --> 0:26:4,62
Michael has now.

495
0:26:4,9 --> 0:26:8,32
Michael: I actually think this
is more interesting, not necessarily

496
0:26:8,6 --> 0:26:14,38
from an incident point of view,
than from an ongoing minor issues

497
0:26:14,38 --> 0:26:17,72
in the background type, things
that would go unnoticed otherwise.

498
0:26:18,26 --> 0:26:22,24
I think incidents, normally somebody's
on the Zoom who can access

499
0:26:22,24 --> 0:26:25,34
the logs and can check, does have
access to those things.

500
0:26:25,52 --> 0:26:29,1
But I'm thinking the warnings that
are building up over time

501
0:26:29,1 --> 0:26:32,48
that people aren't noticing, or
the errors that are, they're

502
0:26:32,48 --> 0:26:35,28
affecting some users but not enough
to complain about.

503
0:26:35,28 --> 0:26:36,58
Like those kinds of things.

504
0:26:36,58 --> 0:26:40,04
What are our 10, what are this
application's top 10 errors this

505
0:26:40,04 --> 0:26:41,78
month or this year or whatever?

506
0:26:42,04 --> 0:26:45,26
I think that's super interesting,
even outside of incidents.

507
0:26:45,28 --> 0:26:47,96
Maybe it helps with incidents too,
but I like the offering.

508
0:26:48,76 --> 0:26:53,82
Nikolay: Inside incidents, usually
it's messy and the incident

509
0:26:53,86 --> 0:26:55,28
produces a lot of logs.

510
0:26:55,28 --> 0:26:57,08
It's really hard to deal with them.

511
0:26:57,28 --> 0:26:58,94
You need tooling, you need expertise.

512
0:26:59,06 --> 0:27:2,7
Of course AI helps to process in
large amounts, But when you

513
0:27:2,7 --> 0:27:7,0
have a lot of basically bytes to
process, to fetch a few numbers,

514
0:27:7,54 --> 0:27:8,86
it's easy to make mistakes.

515
0:27:9,66 --> 0:27:13,52
And LLM makes mistakes when you
feed too much information to

516
0:27:13,52 --> 0:27:13,98
it.

517
0:27:13,98 --> 0:27:18,96
If you have very structured counters,
It's great.

518
0:27:19,12 --> 0:27:20,34
Also, log can rotate.

519
0:27:20,38 --> 0:27:23,94
You can analyze the wrong log file
in the middle of rotation

520
0:27:23,94 --> 0:27:25,28
or something, and so on.

521
0:27:25,58 --> 0:27:30,2
And storing those counters in some
time series, like snapshots,

522
0:27:30,64 --> 0:27:33,46
over time is so much easier, so
much more manageable.

523
0:27:33,52 --> 0:27:35,58
And in general Postgres moves in
this direction.

524
0:27:35,58 --> 0:27:39,84
For example, we had checkpoints
and autovacuum, most data only

525
0:27:39,84 --> 0:27:40,44
in logs.

526
0:27:40,46 --> 0:27:43,68
Now it's slowly moving to the pg_stat
system.

527
0:27:43,68 --> 0:27:49,16
For example, finally, pg_stat_bgwriter,
which always collected

528
0:27:49,18 --> 0:27:53,8
information not about bgwriter,
but checkpointer and backends

529
0:27:53,82 --> 0:27:54,38
as well.

530
0:27:54,38 --> 0:27:57,04
Now it's already reorganized, so
there's pg_stat_checkpointer,

531
0:27:57,56 --> 0:28:0,88
there's pg_stat_bgwriter, it's more
obvious.

532
0:28:0,88 --> 0:28:3,58
And it's easier for LLM actually
to analyze what's happening

533
0:28:3,58 --> 0:28:5,98
because naming matters a lot right
now.

534
0:28:5,98 --> 0:28:7,98
That's why I asked pg_stat_log.

535
0:28:8,14 --> 0:28:12,66
Is it like, I wish there was specifically
pg_stat_errors because

536
0:28:12,66 --> 0:28:14,6
they all have errors, what kind
of, right?

537
0:28:14,6 --> 0:28:17,12
But I understand the reasoning,
warnings and everything.

538
0:28:17,12 --> 0:28:18,14
I understand that.

539
0:28:18,56 --> 0:28:23,66
So counter-efficient, the process
of analysis efficient, that's

540
0:28:23,84 --> 0:28:24,34
important.

541
0:28:24,4 --> 0:28:25,12
And complete.

542
0:28:26,0 --> 0:28:28,04
That's also important.

543
0:28:28,86 --> 0:28:29,62
And fast.

544
0:28:29,68 --> 0:28:33,96
Yeah, you can immediately understand
when exactly the spike happened

545
0:28:34,04 --> 0:28:35,28
without grepping.

546
0:28:36,46 --> 0:28:38,3
Fabrízio: Happens often again about
overhead.

547
0:28:38,48 --> 0:28:43,64
I think the overhead introduced
by this extension is way less

548
0:28:43,64 --> 0:28:45,96
than pg_stat_statements, for
example.

549
0:28:47,52 --> 0:28:49,26
Nikolay: That's an interesting
statement.

550
0:28:49,26 --> 0:28:53,54
We should maybe somehow with benchmarks
think about it.

551
0:28:53,54 --> 0:28:54,56
Yeah, that's interesting.

552
0:28:54,86 --> 0:28:56,44
Why do you think so, by the way?

553
0:28:57,74 --> 0:29:2,06
Fabrízio: Because of what we do
in the extension, it's a very

554
0:29:2,06 --> 0:29:3,02
simple hash.

555
0:29:6,04 --> 0:29:9,34
Yeah, but pg_stat_statements need to normalize
the query and do a lot

556
0:29:9,34 --> 0:29:10,08
of other stuff.

557
0:29:10,08 --> 0:29:10,78
Oh, yes.

558
0:29:11,32 --> 0:29:11,82
Yeah.

559
0:29:12,74 --> 0:29:14,0
And it takes time.

560
0:29:14,54 --> 0:29:15,46
It's a few cycles.

561
0:29:16,5 --> 0:29:18,9
Nikolay: I proposed the introduction
of query ID, right?

562
0:29:18,9 --> 0:29:20,78
You don't need to normalize, right?

563
0:29:21,22 --> 0:29:22,7
Fabrízio: No, I don't need to normalize.

564
0:29:23,8 --> 0:29:26,44
Nikolay: Yeah, because in logs
we also compute query ID mechanism,

565
0:29:26,52 --> 0:29:27,02
right?

566
0:29:27,44 --> 0:29:30,64
Michael: On the query ID front,
I think 1 of the downsides is

567
0:29:30,64 --> 0:29:33,84
it would balloon the number of
entries you would need.

568
0:29:33,84 --> 0:29:39,78
Like you've currently got the max
entries to 1024, which feels

569
0:29:39,92 --> 0:29:43,44
not that high, but actually if
you think about how many people

570
0:29:43,44 --> 0:29:46,56
actually run multiple databases
on the same server and actually

571
0:29:46,56 --> 0:29:49,04
have like thousands of users is
probably pretty low.

572
0:29:49,04 --> 0:29:52,08
Probably most people have a few
users that are doing a lot of

573
0:29:52,08 --> 0:29:56,48
volume and each of those things
you mentioned is probably fairly

574
0:29:56,48 --> 0:29:59,92
low cardinality so that by the
time they all multiply it's probably

575
0:29:59,92 --> 0:30:3,28
still below 1000 which is great
But if you add query ID into

576
0:30:3,28 --> 0:30:6,26
that as well, that's a much bigger
number.

577
0:30:7,08 --> 0:30:7,58
Fabrízio: Yes.

578
0:30:8,76 --> 0:30:12,44
1, 1 thinking about introducing
this, the query ID, maybe it

579
0:30:12,44 --> 0:30:13,34
can be optional.

580
0:30:13,86 --> 0:30:17,02
A Boolean configuration that you
can turn off.

581
0:30:18,26 --> 0:30:22,96
And then you always have the query
ID and we issue don't collect

582
0:30:22,96 --> 0:30:24,94
query ID to be 0 for example.

583
0:30:27,64 --> 0:30:30,6
Michael: So what's the downside
of being What's the downside

584
0:30:30,6 --> 0:30:33,68
of increase if I increase max entries
by a lot?

585
0:30:33,68 --> 0:30:37,94
I guess that's just more shared
memory and slightly more delay

586
0:30:38,2 --> 0:30:40,3
on writing it out on restart.

587
0:30:40,52 --> 0:30:41,74
Are there any other downsides?

588
0:30:43,66 --> 0:30:48,3
Fabrízio: It is a map in memory
that you to the time of how many

589
0:30:48,3 --> 0:30:49,7
entries on your CPU.

590
0:30:51,86 --> 0:30:55,88
And yes, but writing to the disk,
I don't think unless you have,

591
0:30:56,98 --> 0:30:57,54
you know, not

592
0:30:57,54 --> 0:30:58,54
Nikolay: a lot of bytes.

593
0:30:59,34 --> 0:31:5,32
Fabrízio: Yeah, no, because I'm
not writing any text, only integers.

594
0:31:6,04 --> 0:31:6,84
It's written.

595
0:31:8,26 --> 0:31:9,64
Michael: It's very tiny.

596
0:31:10,2 --> 0:31:13,82
Nikolay: Regarding query ID, pg_wait_sampling
also has this as

597
0:31:13,82 --> 0:31:14,32
optional.

598
0:31:15,04 --> 0:31:17,92
Fabrízio: This parameter you can
enable profiling per query,

599
0:31:17,92 --> 0:31:19,54
so similar approach.

600
0:31:20,28 --> 0:31:22,32
Nikolay: And I think it's even
off by default.

601
0:31:23,2 --> 0:31:24,74
I think so, maybe I'm wrong.

602
0:31:25,08 --> 0:31:28,6
And we usually enable it because
the information from pg_wait_sampling

603
0:31:29,06 --> 0:31:33,2
is super useful, and we want it
to per query.

604
0:31:34,14 --> 0:31:35,16
So, yeah.

605
0:31:36,38 --> 0:31:36,88
Cool.

606
0:31:37,98 --> 0:31:41,48
Michael: Maybe add query ID, but
also bump the default way up if

607
0:31:41,48 --> 0:31:46,0
there's very little overhead to
having 10, 000 or more I don't

608
0:31:46,0 --> 0:31:48,14
see why that should be limited.

609
0:31:49,66 --> 0:31:50,62
What do you think?

610
0:31:51,6 --> 0:31:52,64
Fabrízio: Thanks for asking this.

611
0:31:52,64 --> 0:31:54,88
This was an arbitrary number

612
0:31:56,04 --> 0:31:56,72
Nikolay: that I got

613
0:31:56,72 --> 0:32:0,44
Fabrízio: from my, probably should
increase this and maybe match

614
0:32:0,44 --> 0:32:4,6
with, for example, pg_stat_statements
because it don't require

615
0:32:4,6 --> 0:32:5,66
too much memory.

616
0:32:6,4 --> 0:32:7,08
Be honest.

617
0:32:7,12 --> 0:32:7,62
Michael: Yeah.

618
0:32:7,76 --> 0:32:8,2
Nice.

619
0:32:8,2 --> 0:32:10,76
I noticed you labeled it version
0.1.

620
0:32:11,68 --> 0:32:15,2
What else do you need in terms
of getting it to a version you

621
0:32:15,2 --> 0:32:18,32
could commit to Postgres or 1.0
or whatever, however you want

622
0:32:18,32 --> 0:32:20,04
to define like production ready.

623
0:32:20,46 --> 0:32:24,48
Fabrízio: The thing that it's blocking
it's submit is this issue

624
0:32:24,48 --> 0:32:31,48
that I find in the worst case when
we have all the entries allocated

625
0:32:31,64 --> 0:32:35,38
and then new entries entering the
dropped message.

626
0:32:35,38 --> 0:32:38,9
I will not collect information
because I don't have enough capacity

627
0:32:39,12 --> 0:32:39,8
to collect.

628
0:32:41,14 --> 0:32:43,68
And this is another worst case in
the corner.

629
0:32:43,86 --> 0:32:44,7
It's simple.

630
0:32:44,96 --> 0:32:48,94
And then I found that overhead,
it's not great.

631
0:32:48,94 --> 0:32:53,74
It increased by 27, 30% of overhead.

632
0:32:54,06 --> 0:32:55,68
And actually it was not great.

633
0:32:57,44 --> 0:33:2,14
I think just this for now, a starting
point.

634
0:33:2,5 --> 0:33:5,2
Maybe query IDs, something to
discuss with the community, I

635
0:33:5,2 --> 0:33:5,92
don't know.

636
0:33:6,6 --> 0:33:11,14
There are ongoing work in the past,
there was ongoing work in

637
0:33:11,14 --> 0:33:12,6
the past, work in progress.

638
0:33:13,66 --> 0:33:15,96
PR, no, maybe it's a patch.

639
0:33:17,86 --> 0:33:24,12
We introduced pg_stat_log_error
or something.

640
0:33:25,48 --> 0:33:32,0
It was proposed by Joe
Conway, And they collected this

641
0:33:32,54 --> 0:33:33,54
old discussion.

642
0:33:34,46 --> 0:33:40,08
They collected the file name, the
source code file name, the

643
0:33:40,08 --> 0:33:45,26
line number, where it was coming
from, that I don't think for

644
0:33:45,26 --> 0:33:46,58
real use case.

645
0:33:47,64 --> 0:33:53,6
It's a good idea, I mean, for SREs,
DBREs, or people that actually

646
0:33:53,6 --> 0:33:54,4
use it.

647
0:33:54,4 --> 0:33:58,5
I don't know if it's useful to
know where is the C file that

648
0:33:58,5 --> 0:33:59,56
the SQLSTATE came.

649
0:33:59,88 --> 0:34:0,68
I don't know.

650
0:34:0,96 --> 0:34:5,24
Maybe I'm wrong, but I thought
that was not useful.

651
0:34:5,9 --> 0:34:12,22
And then I started by the base
stuff to really observe the log.

652
0:34:12,26 --> 0:34:15,84
A backend type, what's the database
ID?

653
0:34:16,52 --> 0:34:21,72
What is the error level and SQL
error code?

654
0:34:22,42 --> 0:34:25,34
Because I think this is the basic
information we need.

655
0:34:25,52 --> 0:34:26,9
Now that's enough information, right?

656
0:34:26,9 --> 0:34:27,44
Yeah, right.

657
0:34:27,44 --> 0:34:27,94
Yeah.

658
0:34:28,66 --> 0:34:30,14
And be an option.

659
0:34:31,56 --> 0:34:33,26
Nikolay: File is always the same.

660
0:34:33,26 --> 0:34:35,7
It only can change after rotation,
right?

661
0:34:36,1 --> 0:34:39,1
Fabrízio: Not the log file, the
source code file.

662
0:34:39,38 --> 0:34:39,88
Sorry.

663
0:34:40,52 --> 0:34:41,4
The C file.

664
0:34:42,1 --> 0:34:44,24
Something dot C inside Postgres.

665
0:34:44,54 --> 0:34:45,6
And the line number.

666
0:34:45,98 --> 0:34:47,34
Because we have this information.

667
0:34:48,92 --> 0:34:49,74
Nikolay: So I see.

668
0:34:49,74 --> 0:34:54,34
So we have some error code, for
example, my favorite, XX001, for

669
0:34:54,34 --> 0:34:55,08
example, right?

670
0:34:55,08 --> 0:34:57,34
I think it's some corruption or
something, right?

671
0:34:57,62 --> 0:34:58,3
Or 002.

672
0:34:59,24 --> 0:35:2,64
And we know that in Postgres source
code, it happens and it can

673
0:35:2,64 --> 0:35:4,82
occur in 5 places, for example.

674
0:35:5,38 --> 0:35:10,14
And we want to know exact location
among those 5, right?

675
0:35:10,4 --> 0:35:12,26
I think this can be useful.

676
0:35:12,44 --> 0:35:15,46
It reminds me, like when programming,
you troubleshoot with printlining,

677
0:35:15,68 --> 0:35:16,18
right?

678
0:35:16,2 --> 0:35:21,34
And you have like, problem happened,
problem, test, test, or

679
0:35:21,34 --> 0:35:22,54
like something.

680
0:35:22,54 --> 0:35:25,66
And then you think, oh, they're
all this, you need to start distinguishing

681
0:35:25,88 --> 0:35:26,38
them, right?

682
0:35:26,38 --> 0:35:30,92
You say, okay, test 1, test 2,
test 3, and then which 1 of them

683
0:35:30,92 --> 0:35:31,78
fired, right?

684
0:35:31,78 --> 0:35:35,04
I can see it may be useful, but
again, what overhead?

685
0:35:35,8 --> 0:35:37,18
What's the price, right?

686
0:35:38,86 --> 0:35:42,4
Fabrízio: Yeah, the price is we
need to store variable-sized

687
0:35:42,94 --> 0:35:43,44
strings.

688
0:35:45,04 --> 0:35:51,54
The line number is not a problem,
but the source code file name,

689
0:35:51,54 --> 0:35:56,0
it's a string with a variable size,
then it can increase the

690
0:35:56,0 --> 0:35:56,5
memory.

691
0:35:59,84 --> 0:36:3,06
Depending on how many entries you
store.

692
0:36:4,84 --> 0:36:10,7
But yeah, the source code file
names are not very big names.

693
0:36:11,5 --> 0:36:17,22
But I don't remember if you have
multiple file names, equal file

694
0:36:17,22 --> 0:36:18,54
names with different directories.

695
0:36:19,88 --> 0:36:20,54
I don't think so.

696
0:36:20,54 --> 0:36:21,8
Nikolay: I think it might happen.

697
0:36:22,28 --> 0:36:23,18
Fabrízio: It might happen.

698
0:36:23,18 --> 0:36:31,84
So if we start only the file.c,
line number 1000, and then you

699
0:36:31,84 --> 0:36:33,46
have 2 files the same name.

700
0:36:33,46 --> 0:36:37,2
Nikolay: Can be compared somehow
I think quite easily so to a

701
0:36:37,2 --> 0:36:40,1
few bytes only but is it really
needed?

702
0:36:41,32 --> 0:36:45,66
Maybe no, but it's a nice feature
I can imagine like to trace

703
0:36:45,66 --> 0:36:46,9
the exact location.

704
0:36:47,6 --> 0:36:53,12
What I'm concerned about, not about
additional bytes, but it

705
0:36:53,12 --> 0:36:57,66
will amplify number of entries
significantly.

706
0:36:58,4 --> 0:37:2,86
If it's a common, if this error
is popular and we have 100 locations,

707
0:37:2,92 --> 0:37:7,16
so now we have 100 different errors
basically, right?

708
0:37:7,44 --> 0:37:8,92
But it's interesting.

709
0:37:9,0 --> 0:37:10,06
It's interesting anyway.

710
0:37:11,26 --> 0:37:11,68
Yeah.

711
0:37:11,68 --> 0:37:15,04
We should have it and this information
should be present in logs.

712
0:37:15,04 --> 0:37:16,9
This is very detailed information.

713
0:37:16,96 --> 0:37:18,7
Go to logs and troubleshoot.

714
0:37:19,34 --> 0:37:23,9
It's the level of this extension,
we just want counters to observe

715
0:37:23,94 --> 0:37:25,16
holistically everything.

716
0:37:25,44 --> 0:37:25,84
Right?

717
0:37:25,84 --> 0:37:28,3
Then if you identify the spike,
go to logs.

718
0:37:29,14 --> 0:37:32,28
Now the problem is we cannot identify
spikes at all.

719
0:37:32,56 --> 0:37:33,28
So we're...

720
0:37:34,12 --> 0:37:34,62
Yeah.

721
0:37:35,38 --> 0:37:35,74
Yeah.

722
0:37:35,74 --> 0:37:38,34
So I agree with you, it's too verbose
stuff.

723
0:37:38,5 --> 0:37:38,9102
Yeah.

724
0:37:38,9102 --> 0:37:42,94
Okay, it was some kind of brainstorming
session, a little bit.

725
0:37:43,28 --> 0:37:46,56
What I think would help is If somebody
starts using it, maybe

726
0:37:46,56 --> 0:37:49,28
not in production right away, but
in some benchmarking, like

727
0:37:49,28 --> 0:37:53,48
I'm going to start using it in
some benchmarking activities in

728
0:37:53,48 --> 0:37:54,72
lab environment, right?

729
0:37:54,72 --> 0:37:56,26
So 1st, like low risk.

730
0:37:56,48 --> 0:37:58,5
If it crashes, I will let you know.

731
0:37:59,06 --> 0:38:2,14
But eventually I think the production,
it should be a production.

732
0:38:4,02 --> 0:38:5,4
Fabrízio: It could be very useful.

733
0:38:5,8 --> 0:38:10,58
Nowadays it's packaged for Debian
and RPM on the PGDG repositories.

734
0:38:12,5 --> 0:38:14,88
So it's available there.

735
0:38:16,26 --> 0:38:20,76
I can provide some Docker images,
but a Docker image is very

736
0:38:20,76 --> 0:38:21,26
simple.

737
0:38:21,94 --> 0:38:27,78
You can pick a PG 18 and just install
a new package there, pgdg

738
0:38:27,88 --> 0:38:28,54
is there.

739
0:38:29,16 --> 0:38:32,58
Nikolay: Cool, but also Postgres
20 development already started,

740
0:38:32,64 --> 0:38:34,3
so we're already inside it.

741
0:38:34,3 --> 0:38:35,34
Let's go there.

742
0:38:35,8 --> 0:38:36,04
Let's

743
0:38:36,04 --> 0:38:36,38
Fabrízio: publish it.

744
0:38:36,38 --> 0:38:37,78
Yes, let's go there.

745
0:38:38,4 --> 0:38:39,78
Nikolay: You know, let's get familiar
with it.

746
0:38:39,78 --> 0:38:41,12
I want it to be in core.

747
0:38:41,12 --> 0:38:42,1
This is a great start.

748
0:38:43,78 --> 0:38:45,68
Fabrízio: Yeah, it should be.

749
0:38:46,22 --> 0:38:48,58
Michael: Was there anything you
wanted to mention that we haven't

750
0:38:48,58 --> 0:38:49,46
asked about?

751
0:38:49,6 --> 0:38:53,14
Maybe some of the caveats that
you wrote about or anything else?

752
0:38:53,8 --> 0:39:1,88
Fabrízio: 1 thing that everybody
can potentially ask is, it requires

753
0:39:1,88 --> 0:39:8,5
a Postgres restart because I need to
allocate shared memory.

754
0:39:9,24 --> 0:39:13,36
So there's no way nowadays in Postgres
to do this without something.

755
0:39:15,04 --> 0:39:18,0
I think this is 1 of the reasons
that Nik would love to have

756
0:39:18,0 --> 0:39:22,06
this truly in core, then we don't
need to restart Postgres.

757
0:39:23,04 --> 0:39:25,52
But it depends on how it is implemented,
right?

758
0:39:25,52 --> 0:39:29,7
Because there are some configurations
that we, when we change

759
0:39:29,7 --> 0:39:31,5698
it, it will restart anyways.

760
0:39:31,645 --> 0:39:34,24
Nikolay: Yeah, this is definitely
why I think pg_stat_statements

761
0:39:34,24 --> 0:39:35,28
should be in core as well.

762
0:39:35,28 --> 0:39:38,2
We still have cases when it's not
installed and it's not present

763
0:39:38,2 --> 0:39:40,74
in shared preload libraries, so
we need a restart.

764
0:39:44,44 --> 0:39:47,14
Michael: And this requires shared
preload as well, doesn't it?

765
0:39:48,34 --> 0:39:51,22
Fabrízio: And there's only another
caveat that we didn't talk

766
0:39:51,22 --> 0:39:56,56
about is the parallel query, right,
because there are different

767
0:39:56,6 --> 0:39:58,68
backend types, parallel queries.

768
0:39:59,6 --> 0:40:3,3
There are like normal client in
backend that is the leader,

769
0:40:3,92 --> 0:40:7,24
and then there will be a parallel
worker or something.

770
0:40:8,94 --> 0:40:12,02
So don't count twice in the message
maybe.

771
0:40:13,04 --> 0:40:13,08
Yeah.

772
0:40:13,08 --> 0:40:15,14
So I'm not filtering anything.

773
0:40:15,18 --> 0:40:21,1
I just collecting on the log because
it go to the log the information.

774
0:40:21,74 --> 0:40:27,24
It passed through the emit_log_hook
hook and then I capture it,

775
0:40:27,44 --> 0:40:29,68
the leader and also the parallel
workers.

776
0:40:30,18 --> 0:40:34,18
So we filled a monitoring tool
and thought that I have parallel

777
0:40:34,76 --> 0:40:40,62
workers, maybe you should filter
it out, but double count something.

778
0:40:42,1 --> 0:40:44,64
It's 1 caveat, it is on the README.

779
0:40:46,86 --> 0:40:48,34
Michael: Yeah, I thought it was
really interesting.

780
0:40:48,34 --> 0:40:49,96
I thought that was a good 1 to
call out.

781
0:40:49,96 --> 0:40:52,44
And I thought the other 1 that
was interesting for monitoring

782
0:40:52,44 --> 0:40:56,78
tools was the fact that database
name or username could be null.

783
0:40:56,98 --> 0:41:2,46
And that's expected, like some
errors happen before there's a

784
0:41:2,46 --> 0:41:3,62
context of having a database?

785
0:41:3,62 --> 0:41:5,58
Like that's something I would have
forgotten to do.

786
0:41:5,58 --> 0:41:8,98
So for example, I knew I wanted
to monitor 1 database on Postgres.

787
0:41:9,18 --> 0:41:11,68
I would have filtered by that and
only looked for errors, but

788
0:41:11,68 --> 0:41:15,78
I need that database name or null.

789
0:41:15,94 --> 0:41:18,34
And then I look at errors across
both of those.

790
0:41:18,34 --> 0:41:19,08
Fabrízio: So that

791
0:41:19,08 --> 0:41:20,86
Michael: was a really good call
out I thought.

792
0:41:21,1 --> 0:41:21,88
Nice 1.

793
0:41:22,12 --> 0:41:25,76
Fabrízio: I didn't thought too
much, but maybe another thing

794
0:41:25,76 --> 0:41:30,36
that's interesting to collect and
aggregate is application name.

795
0:41:31,38 --> 0:41:34,46
Nikolay: Oh, it's Pandora box.

796
0:41:35,08 --> 0:41:35,74
Fabrízio: Yeah, I know.

797
0:41:35,74 --> 0:41:40,02
Nikolay: There is a great idea
that, well, what about client

798
0:41:40,02 --> 0:41:42,54
address and IP address and so on.

799
0:41:42,54 --> 0:41:43,7
It could go far.

800
0:41:43,86 --> 0:41:48,98
There's a great idea that all such
extensions like pg_stat_statements,

801
0:41:49,22 --> 0:41:54,14
pg_stat_kcache, pg_wait_sampling,
and let's say pg_stat_log, they all

802
0:41:54,14 --> 0:41:57,84
must have an additional extensibility
piece so I could define

803
0:41:57,84 --> 0:41:59,16
my own dimensions.

804
0:42:0,9 --> 0:42:7,12
For example, if my query contains
a comment which says, this

805
0:42:7,12 --> 0:42:11,42
query originated from this part
of application and anything,

806
0:42:11,48 --> 0:42:13,34
I just can tag my queries.

807
0:42:13,94 --> 0:42:20,34
If those tags could be extracted
from comments and allow me to

808
0:42:20,34 --> 0:42:26,98
group by tag value inside pg_stat_
statements or any such

809
0:42:26,98 --> 0:42:27,48
extension.

810
0:42:27,92 --> 0:42:28,94
This would be great.

811
0:42:30,04 --> 0:42:31,58
This is a big lacking piece.

812
0:42:32,36 --> 0:42:36,94
And right now, the way to go is
to avoid the cumulative statistics

813
0:42:37,08 --> 0:42:41,38
approach completely and just use,
instead of counters, just use

814
0:42:41,38 --> 0:42:41,88
sampling.

815
0:42:43,32 --> 0:42:46,88
You can implement the same in Active
Session history approach.

816
0:42:46,88 --> 0:42:50,14
You sample pg_stat_activity,
you have these comments, you

817
0:42:50,14 --> 0:42:52,8
extract outside of Postgres, right?

818
0:42:52,8 --> 0:42:59,04
And then you can finally answer,
okay, I/O wait event, we mostly

819
0:42:59,04 --> 0:43:3,48
spend 90% of I/O registered in
wait event was in this piece

820
0:43:3,48 --> 0:43:6,92
of application, this part, because
it was tagged.

821
0:43:8,0 --> 0:43:10,26
In the case of your extension,
same thing.

822
0:43:10,26 --> 0:43:14,94
If something is erroring out, group
by database, group by user,

823
0:43:15,1 --> 0:43:18,12
Even application level, it's great,
but sometimes we need some

824
0:43:18,12 --> 0:43:19,94
custom segmentation.

825
0:43:21,94 --> 0:43:24,3
And now it's like it's difficult
right now.

826
0:43:25,76 --> 0:43:31,12
This is maybe future of all those
extensions to have custom tagging

827
0:43:31,12 --> 0:43:31,62
mechanism.

828
0:43:33,82 --> 0:43:34,32
Maybe.

829
0:43:36,14 --> 0:43:39,84
These discussions, I know people
and myself, we discussed it

830
0:43:39,84 --> 0:43:40,64
over years.

831
0:43:41,06 --> 0:43:44,68
You actually, Fabrízio, is a part
of the ground group where we

832
0:43:44,68 --> 0:43:46,48
discussed it, I think, a couple
of times.

833
0:43:48,68 --> 0:43:49,18
Great.

834
0:43:49,74 --> 0:43:50,68
Thank you for coming.

835
0:43:50,68 --> 0:43:51,66
I enjoyed it.

836
0:43:51,66 --> 0:43:54,98
I wish all the best to this extension
and all your work.

837
0:43:55,58 --> 0:43:56,66
Fabrízio: Thank you very much.

838
0:43:58,08 --> 0:43:58,68
Nikolay: Thank you.

839
0:43:58,68 --> 0:43:59,12
Thank you.

840
0:43:59,12 --> 0:43:59,72
I hope

841
0:43:59,72 --> 0:44:1,9
Michael: absolutely good luck for
version 20.