1
0:0:0,06 --> 0:0:2,06
Nikolay: Hello, hello, this is
Postgres.FM.

2
0:0:2,1399999 --> 0:0:6,2599998
My name is Nik, PostgresAI, and
as usual, my co-host is Michael

3
0:0:6,2599998 --> 0:0:6,8799996
of pgMustard.

4
0:0:7,12 --> 0:0:7,8999996
Hi, Michael.

5
0:0:8,5 --> 0:0:9,26
Michael: Hi, Nik.

6
0:0:9,5199995 --> 0:0:12,86
Nikolay: And we have a great guest
today, Dmitry, who is a very

7
0:0:12,86 --> 0:0:16,88
experienced DBA, originally Oracle,
now Postgres, already many

8
0:0:16,88 --> 0:0:17,36
years.

9
0:0:17,36 --> 0:0:18,14
Hi, Dmitry.

10
0:0:19,02 --> 0:0:21,24
Dmitry: Hi, thanks for inviting.

11
0:0:21,4 --> 0:0:22,36
Nikolay: Thank you for coming.

12
0:0:22,36 --> 0:0:26,24
So we have, I think, very, like
for me it was surprise when you

13
0:0:26,24 --> 0:0:30,48
did it, when you built this tool,
and I didn't expect that it's

14
0:0:30,48 --> 0:0:31,9
coming to Postgres ecosystem.

15
0:0:32,72 --> 0:0:36,96
But obviously it's something new
and in the area which is in

16
0:0:36,96 --> 0:0:39,04
my personal key interests lately.

17
0:0:39,14 --> 0:0:43,58
So active session history analysis,
wait event analysis, but

18
0:0:43,58 --> 0:0:47,22
you did it very differently compared
to what we usually did with

19
0:0:47,22 --> 0:0:50,94
pg_wait_sampling or other tools,
performance insights in RDS.

20
0:0:51,68 --> 0:0:52,92
So it's a great tool.

21
0:0:52,92 --> 0:0:53,82
Where to start?

22
0:0:54,62 --> 0:0:57,739998
Dmitry: Yeah, so I think we can
start with the time when I first

23
0:0:57,739998 --> 0:1:1,52
started working with Postgres,
as I started switching from Oracle.

24
0:1:1,98 --> 0:1:6,42
When Oracle, 1 of my favorite topics
always and tasks was performance

25
0:1:6,42 --> 0:1:7,36
related investigations.

26
0:1:8,14 --> 0:1:12,08
And when I switched to Postgres,
of course, I start looking for

27
0:1:12,08 --> 0:1:16,6
similar tasks and understood that
the way of Postgres troubleshooting

28
0:1:16,64 --> 0:1:19,46
is very different from how it's
done in Oracle.

29
0:1:19,92 --> 0:1:25,58
And definitely the felt lack of
tooling, lack of a standard approach

30
0:1:25,58 --> 0:1:26,42
and so on.

31
0:1:26,68 --> 0:1:27,18
Okay.

32
0:1:27,26 --> 0:1:30,7
So after some time, I realized
that there are some tools that

33
0:1:30,7 --> 0:1:35,66
can bring similar kind of feeling,
let's say what I had in Oracle.

34
0:1:35,74 --> 0:1:40,6
And I'm talking about the weight
event analysis because I know

35
0:1:40,6 --> 0:1:42,56
in Oracle world, it's a given thing.

36
0:1:42,56 --> 0:1:43,06
Yeah.

37
0:1:43,1 --> 0:1:43,58
Yeah.

38
0:1:43,58 --> 0:1:44,84
Nikolay: I'm going to interrupt.

39
0:1:45,3 --> 0:1:48,72
So when did this switch happen
from Oracle to Postgres for you?

40
0:1:48,82 --> 0:1:51,52
Dmitry: Recently I checked, it
happened 10 years ago.

41
0:1:51,76 --> 0:1:53,0
Nikolay: 2016 roughly.

42
0:1:53,1 --> 0:1:59,54
I remember very well a big stream
of, like, big wave of people

43
0:1:59,54 --> 0:2:3,54
coming from Oracle in 2013-14 and
all of them were complaining

44
0:2:3,54 --> 0:2:5,24
about lack of wait event analysis.

45
0:2:5,28 --> 0:2:8,45999
This is how 2 columns were added
to pg_stat_activity.

46
0:2:8,56 --> 0:2:12,26
It was like maybe a couple of years
before basically your switch

47
0:2:12,26 --> 0:2:16,36
and you also had this same feeling
like these tools are needed.

48
0:2:17,06 --> 0:2:20,64
Dmitry: Yeah, Because when you
work with Oracle since, I don't

49
0:2:20,64 --> 0:2:24,82
know, 2002 or something like that,
it's a given way of troubleshooting.

50
0:2:25,08 --> 0:2:29,48
Any Oracle guideline, any book,
any training official, non-official

51
0:2:29,76 --> 0:2:32,34
says that just open the active
session history.

52
0:2:32,38 --> 0:2:36,62
And so it's a, it's a first, it's
a gate that you go through

53
0:2:36,62 --> 0:2:37,86
and you start with.

54
0:2:38,42 --> 0:2:41,92
And so I try to use the same approach
with Postgres because for

55
0:2:41,92 --> 0:2:47,24
me it was so obvious why it's a
way to analyze the performance.

56
0:2:47,5 --> 0:2:51,82
Because basically what's the wait
event says you say you so why

57
0:2:51,82 --> 0:2:56,12
it was slow where the session spend
the time session or database

58
0:2:56,12 --> 0:3:1,84
in general so you do not need to
guess was it's I or CPU basically

59
0:3:1,84 --> 0:3:3,08
where it spent time.

60
0:3:3,08 --> 0:3:5,1
So it just says very rarely.

61
0:3:5,2 --> 0:3:6,84
So then why it happened that way.

62
0:3:6,84 --> 0:3:10,52
So you need to investigate, but
at least you know where, because

63
0:3:10,52 --> 0:3:14,98
the regular approach in progress
just can say that this query

64
0:3:14,98 --> 0:3:20,58
was slow In average, or with some
hacking, you can get some precise

65
0:3:20,58 --> 0:3:24,74
numbers of the execution, but it
does not give the idea why it

66
0:3:24,74 --> 0:3:25,46
was slow.

67
0:3:25,58 --> 0:3:29,48
Okay, yes, you can use the explain
analyze to see where in the

68
0:3:29,48 --> 0:3:32,9
plan you spend the time, but again,
it does not explain why sometimes

69
0:3:33,22 --> 0:3:36,8
this join takes I don't know 1
second or sometimes 10 seconds

70
0:3:36,82 --> 0:3:42,52
from the plan perspective it looks
the same and the tooling

71
0:3:42,54 --> 0:3:45,74
for wait event analysis evolved
year by year.

72
0:3:46,08 --> 0:3:48,46
And so we have the pg_wait_sampling.

73
0:3:49,7 --> 0:3:55,76
And since they introduced the new
event tracing as well, so it

74
0:3:55,76 --> 0:4:2,18
became really a tool that gives
really good data, good source

75
0:4:2,2 --> 0:4:3,84
for wait sampling analysis.

76
0:4:4,4 --> 0:4:8,4
And I use it everywhere where I
manage Postgres.

77
0:4:8,48 --> 0:4:12,54
And if it's self-hosted Postgres
for sure, I will, I will convince

78
0:4:12,6 --> 0:4:14,94
the owner of this Postgres to install
pg_wait_sampling.

79
0:4:15,24 --> 0:4:17,46
It's a default way of analyzing.

80
0:4:18,26 --> 0:4:21,46
On all my dashboards, it's the
first panel you see when you open

81
0:4:21,46 --> 0:4:22,94
any dashboard that I created.

82
0:4:22,94 --> 0:4:25,22
So it's a wait event analysis.

83
0:4:25,68 --> 0:4:28,5
I convinced all my colleagues to
use this approach.

84
0:4:28,62 --> 0:4:29,82
You convinced me

85
0:4:30,06 --> 0:4:34,4
Nikolay: To put this ASH graph
on the top of the first dashboard,

86
0:4:34,4 --> 0:4:38,54
which I resisted initially because
the first dashboard for me

87
0:4:38,54 --> 0:4:42,72
was seen as very shallow and very
wide, troubleshooting where

88
0:4:42,72 --> 0:4:46,68
you identify areas, but you convinced
me to put ASH graph on

89
0:4:46,68 --> 0:4:47,62
the very top.

90
0:4:47,86 --> 0:4:48,98
And now I'm convinced.

91
0:4:49,04 --> 0:4:50,26
Yeah, it's a great idea.

92
0:4:50,46 --> 0:4:54,44
So it's very quickly helps you
understand like some pain points

93
0:4:54,44 --> 0:4:55,22
for performance.

94
0:4:57,18 --> 0:4:59,76
Dmitry: Yeah, I have a, I will
try to make it brief.

95
0:4:59,76 --> 0:5:3,62
2 examples when it's the wait event
analysis shines.

96
0:5:4,16 --> 0:5:8,22
So 1 was, there was a migration,
hardware migration from, from

97
0:5:8,72 --> 0:5:11,42
let's call it this old hardware
to new hardware.

98
0:5:11,82 --> 0:5:14,28
The data files stored in the storage
appliance.

99
0:5:14,28 --> 0:5:15,32
So we just remounted.

100
0:5:15,32 --> 0:5:17,12
So the data layout was the same.

101
0:5:17,12 --> 0:5:20,82
Everything was the same in terms
of the data layer, storage layer,

102
0:5:21,1 --> 0:5:26,14
but the hardware, the compute part
changed and changed to the

103
0:5:26,14 --> 0:5:26,98
highest spec.

104
0:5:27,38 --> 0:5:31,28
So the number of virtual cores
increased, the clock increased,

105
0:5:31,28 --> 0:5:32,22
everything increased.

106
0:5:32,52 --> 0:5:33,86
All tests were good.

107
0:5:34,0 --> 0:5:38,1
When we start loading production,
so we see the really huge degradation

108
0:5:38,16 --> 0:5:42,54
in performance and so what you
would think.

109
0:5:42,66 --> 0:5:45,42
So the plan flip or something
like that, but you have the same,

110
0:5:45,42 --> 0:5:46,84
absolutely everything is the same.

111
0:5:46,84 --> 0:5:48,1
Just hardware is different.

112
0:5:48,12 --> 0:5:51,1
So it basically cannot be planned,
because the parameters are

113
0:5:51,1 --> 0:5:51,74
the same.

114
0:5:51,74 --> 0:5:55,52
Nikolay: So your slide deck has
very interesting example, very

115
0:5:55,52 --> 0:5:59,44
simple, so anyone can understand
about contractors doing some

116
0:5:59,44 --> 0:5:59,94
work.

117
0:6:0,04 --> 0:6:2,9
So in this very example, you right
now, describe right now, it's

118
0:6:2,9 --> 0:6:6,02
like basically you hired a different
team and do, and say, do

119
0:6:6,02 --> 0:6:8,3
the same work, but it does it very
differently.

120
0:6:8,3 --> 0:6:8,8
Right.

121
0:6:9,56 --> 0:6:10,06
Yeah.

122
0:6:10,58 --> 0:6:15,7
So that example, I just to explain
what like those who haven't

123
0:6:15,7 --> 0:6:16,2
seen.

124
0:6:16,46 --> 0:6:19,28
So it's a simple, like there are
contractors, they say, we are

125
0:6:19,28 --> 0:6:23,26
busy, we spend so much time, and
without wait event analysis,

126
0:6:23,52 --> 0:6:24,86
you just know they are busy.

127
0:6:24,86 --> 0:6:28,12
But what they exactly were busy
with, you don't know.

128
0:6:28,66 --> 0:6:31,74
And in this case, okay, they were
busy with I/O or something

129
0:6:31,74 --> 0:6:32,48
else, right?

130
0:6:33,82 --> 0:6:34,86
Dmitry: And yeah, exactly.

131
0:6:35,2 --> 0:6:39,22
Nikolay: Switching hardware, you
see different picture and so

132
0:6:39,36 --> 0:6:41,44
what was in the end of that story?

133
0:6:42,74 --> 0:6:46,7
Dmitry: So, the problem was LWLock
Manager, so you know, it's

134
0:6:46,7 --> 0:6:49,42
1 of your favorite LWLocks.

135
0:6:51,18 --> 0:6:54,24
Nikolay: A lot of dots are connected
here because we spoke about

136
0:6:54,24 --> 0:6:58,1
so many problems which are explored
with wait event analysis

137
0:6:58,62 --> 0:6:59,76
on this very podcast.

138
0:6:59,9 --> 0:7:3,28
So, right Michael, you remember
lock manager?

139
0:7:4,2 --> 0:7:5,12
Michael: Yeah, of course.

140
0:7:5,14 --> 0:7:9,28
It feels like whenever there's
like a system-wide issue, it's

141
0:7:9,28 --> 0:7:11,76
such a great starting point, right?

142
0:7:12,66 --> 0:7:14,34
Dmitry: That's sorry, I...

143
0:7:15,48 --> 0:7:18,48
That's the reason, next case, when
I would say that's on lower

144
0:7:18,48 --> 0:7:18,98
level.

145
0:7:19,7 --> 0:7:22,36
Nikolay: Let me first disagree
with Michael, because I agree

146
0:7:22,36 --> 0:7:23,92
on 1 side, system-wide.

147
0:7:24,14 --> 0:7:26,76
But on the other side, more and
more I think we just don't have

148
0:7:26,76 --> 0:7:28,48
this tool yet, but it should exist.

149
0:7:28,98 --> 0:7:31,04
On pgMustard we should have it.

150
0:7:31,86 --> 0:7:36,34
We have plan analysis and for 1
call it would be great to see

151
0:7:36,34 --> 0:7:37,94
wait event profile as well.

152
0:7:38,4 --> 0:7:43,78
Because imagine we were holding,
like we were blocked by log

153
0:7:43,78 --> 0:7:45,6
acquisition which were pending.

154
0:7:46,1 --> 0:7:49,7
You will see a lot of time spent,
buffer numbers are low, and

155
0:7:49,7 --> 0:7:51,32
that's it, you need to guess.

156
0:7:51,42 --> 0:7:54,56
With wait event analysis for
a single query execution, you

157
0:7:54,56 --> 0:7:57,8
will see, okay, this was lock wait
event type.

158
0:7:57,8 --> 0:8:0,38
Michael: But wait, but I think
this is where we get into the

159
0:8:0,38 --> 0:8:3,48
core of what Dmitry's done, which
is cool, which is moving from

160
0:8:3,48 --> 0:8:4,66
sampling to tracing.

161
0:8:5,14 --> 0:8:8,76
I think when it historically has
been reliant on...

162
0:8:9,72 --> 0:8:11,3
I do think it's really important.

163
0:8:11,58 --> 0:8:13,22
Maybe I'm wrong, but my understanding
is that sampling...

164
0:8:13,26 --> 0:8:16,08
Nikolay: I also thought this, like
this is what expectation I

165
0:8:16,08 --> 0:8:16,78
had as well.

166
0:8:16,78 --> 0:8:18,94
It's about a single backend tracing.

167
0:8:19,34 --> 0:8:21,88
But let's move on and hear what
Dmitry will say.

168
0:8:22,04 --> 0:8:22,54
Exactly.

169
0:8:23,92 --> 0:8:27,9
Dmitry: Yeah, just the next case
when the wait event really saved

170
0:8:27,9 --> 0:8:28,98
a lot of time.

171
0:8:29,14 --> 0:8:33,08
And when this single backend analysis,
I mean, it's single backend

172
0:8:33,08 --> 0:8:34,02
analysis case.

173
0:8:34,02 --> 0:8:37,28
It does not work only on the instance
level.

174
0:8:37,28 --> 0:8:39,88
It's on the single backend that
also works.

175
0:8:40,08 --> 0:8:43,68
I would have the case, I got the
complaint that sometimes query

176
0:8:43,74 --> 0:8:48,82
takes from few milliseconds and
it's killed with 1 second timeout.

177
0:8:48,82 --> 0:8:53,44
We have, I don't know, 100 calls,
10 of them failed with 1 second

178
0:8:53,5 --> 0:8:57,1
timeout and the query is primary
key lookup.

179
0:8:57,26 --> 0:9:0,84
So you cannot, they cannot mess
up with the plan for this case.

180
0:9:0,84 --> 0:9:4,9
So it's just a B-tree primary key
lookup, very simple.

181
0:9:5,2 --> 0:9:8,42
It's not join nothing, so just
very simple lookup.

182
0:9:8,48 --> 0:9:10,96
Nikolay: And it's not lock manager
contention because exactly

183
0:9:10,96 --> 0:9:14,62
lock manager contention, in many
cases, it's primary key lookup.

184
0:9:14,64 --> 0:9:15,32
It was not that.

185
0:9:15,32 --> 0:9:15,82
Dmitry: Yeah.

186
0:9:16,08 --> 0:9:16,4
Okay.

187
0:9:16,4 --> 0:9:20,08
So you open the dashboard so you
don't see any spikes of any

188
0:9:20,08 --> 0:9:21,28
specific wait events.

189
0:9:21,28 --> 0:9:25,74
So it's definitely very low, a
low level with some specific backend

190
0:9:25,86 --> 0:9:26,36
problem.

191
0:9:26,58 --> 0:9:30,96
So I also captured just in case
the explainer, the plan was the

192
0:9:30,96 --> 0:9:31,24
same.

193
0:9:31,24 --> 0:9:34,16
So everything was the same, But
sometimes it goes from a few

194
0:9:34,16 --> 0:9:37,06
milliseconds to 1 second, and I
start sampling.

195
0:9:37,2 --> 0:9:41,72
So I make some custom scripts that
will just catch the needed

196
0:9:41,72 --> 0:9:43,52
backend and start sampling.

197
0:9:43,52 --> 0:9:49,36
And I saw that when it's slow on
I/O, I mean, I saw the I/O,

198
0:9:49,56 --> 0:9:53,9
I mean, look how it can be, just
a very simple read.

199
0:9:53,94 --> 0:9:56,7
So it just reads very few blocks
from disk.

200
0:9:57,1 --> 0:9:59,96
So next step, so I probably understood
with the wait event

201
0:9:59,96 --> 0:10:3,9
analysis it's nothing else but
just slow I/O for some cases.

202
0:10:4,34 --> 0:10:8,04
And with the eBPF and tracing these
backends, I understood that's

203
0:10:8,04 --> 0:10:11,26
a problem with the long tail latency
on the storage appliance

204
0:10:11,26 --> 0:10:12,14
that we use.

205
0:10:12,16 --> 0:10:15,54
Sometimes it goes from 1 millisecond
to tens milliseconds.

206
0:10:16,0 --> 0:10:20,32
And indeed if you're not lucky
enough and you need to read these

207
0:10:20,32 --> 0:10:24,86
blocks from disk, not from memory,
not from OS cache, these even

208
0:10:24,86 --> 0:10:27,32
few blocks become seconds.

209
0:10:28,26 --> 0:10:33,84
And yeah, I think without wait
event analysis it will be just

210
0:10:33,84 --> 0:10:34,62
guess game.

211
0:10:34,66 --> 0:10:37,86
But this just in a couple of days
I found the problem.

212
0:10:38,4 --> 0:10:39,58
Michael: A couple of quick questions.

213
0:10:40,2 --> 0:10:46,72
1 is around, like you can get I/O
timings in explain analyze output.

214
0:10:46,72 --> 0:10:49,9
Obviously it's a bit tricky if
they're always getting cancelled

215
0:10:50,06 --> 0:10:53,36
I don't know how you got the explain
analyze for the queries

216
0:10:53,36 --> 0:10:57,2
that were timing out actually how
did you do that

217
0:10:57,2 --> 0:11:0,04
Dmitry: I just increased the time
out for some portion of them

218
0:11:0,04 --> 0:11:1,78
to make this finish in a few seconds.

221
0:11:3,54004 --> 0:11:4,84
Nikolay: It's about 0, right?

222
0:11:6,96 --> 0:11:7,88
Michael: Did you have I/O

223
0:11:7,88 --> 0:11:9,22
Timings on the server?

224
0:11:9,86 --> 0:11:11,04
Dmitry: Yes, I do.

225
0:11:11,04 --> 0:11:16,96
But when you have 1k calls a minute
of this type and just very

226
0:11:16,96 --> 0:11:22,86
few and it fails you cannot track
it it just so it's 1 of my

227
0:11:22,86 --> 0:11:28,16
favorite topics that averages it's
every time so you have to

228
0:11:28,2 --> 0:11:33,72
have to have P99 and better more
nines to see the actual picture

229
0:11:33,96 --> 0:11:35,34
of the senior system?

230
0:11:35,66 --> 0:11:36,38
Nikolay: Just to push back,

231
0:11:36,38 --> 0:11:38,0
Michael: I think this is a really
interesting topic.

232
0:11:38,0 --> 0:11:41,82
I think actually in this 1 specific
case auto-explain might have

233
0:11:41,82 --> 0:11:43,18
been okay, like catching the...

234
0:11:43,18 --> 0:11:46,62
That's where it can be really good
in terms of catching the outlier

235
0:11:46,64 --> 0:11:47,9
queries that go beyond a set.

236
0:11:47,9 --> 0:11:51,14
I think as long as you've got the
I/O timings on, in this 1 case,

237
0:11:51,14 --> 0:11:55,24
we might have seen, oh, I/O timings
are the issue for these slow

238
0:11:55,24 --> 0:11:55,74
queries.

239
0:11:55,76 --> 0:11:58,32
But I'm sure there are other examples
where the wait events would

240
0:11:58,32 --> 0:11:59,62
have shown something more interesting.

241
0:11:59,96 --> 0:12:4,44
Nikolay: But wait event will analysis,
or not, AutoExplain will

242
0:12:4,44 --> 0:12:7,7
show you the plan, will show you
timing if you enable it, will

243
0:12:7,7 --> 0:12:9,68
show you buffer numbers if you
enable it.

244
0:12:9,68 --> 0:12:10,18
Good.

245
0:12:10,68 --> 0:12:12,6
But it won't show you WaitEventProfile.

246
0:12:14,24 --> 0:12:15,84
Although now I think, why not?

247
0:12:15,84 --> 0:12:17,42
It's a good idea, probably.

248
0:12:17,64 --> 0:12:22,12
This is maybe, yeah, even maybe
better than for manual explain

249
0:12:22,42 --> 0:12:23,9
to have it in auto explain.

250
0:12:24,66 --> 0:12:27,24
Michael: I think you're right,
but I think, I was talking about

251
0:12:27,34 --> 0:12:28,48
track I/O timing.

252
0:12:28,48 --> 0:12:30,54
You know the parameters of track
I/O timing?

253
0:12:31,6 --> 0:12:33,06
Nikolay: Yeah, I/O timing, great.

254
0:12:33,06 --> 0:12:36,3
But I/O timing is working, first
of all, it's working at higher

255
0:12:36,3 --> 0:12:36,8
level.

256
0:12:37,2 --> 0:12:43,5
But what if it would be not I/O timing,
but IPC, or like with local

257
0:12:43,5 --> 0:12:46,88
or log or something, like full
picture would be great to have,

258
0:12:46,88 --> 0:12:47,36
right?

259
0:12:47,36 --> 0:12:51,1
Also wait event, we talk like this
is a wait event type level,

260
0:12:51,1 --> 0:12:55,84
we have how many like 7, 9 wait
event types, but how many wait

261
0:12:55,84 --> 0:12:56,34
events?

262
0:12:56,38 --> 0:12:56,88
Hundreds.

263
0:12:56,94 --> 0:13:0,54
So it's very precise understanding
what the system was doing.

264
0:13:1,38 --> 0:13:5,08
So I think, just imagine for auto-explain
to have a wait event

265
0:13:5,08 --> 0:13:6,44
profile logged optionally.

266
0:13:7,44 --> 0:13:10,18
I think it's a good idea for those
who want to hack Postgres

267
0:13:10,32 --> 0:13:11,1
right now.

268
0:13:11,76 --> 0:13:12,54
Michael: Yeah, me too.

269
0:13:12,54 --> 0:13:16,62
And I think it probably transitions
onto like, why don't we have

270
0:13:16,62 --> 0:13:16,88
this?

271
0:13:16,88 --> 0:13:18,22
What's, what are the downsides?

272
0:13:18,4 --> 0:13:19,84
What are the, what's the overhead?

273
0:13:19,84 --> 0:13:22,32
What are the tricky parts of this?

274
0:13:22,72 --> 0:13:24,02
Dmitry: And we will go there.

275
0:13:24,14 --> 0:13:28,0
Yeah, because it's definitely a
thing that I cannot take out

276
0:13:28,0 --> 0:13:29,84
of my mind for weeks already.

277
0:13:30,26 --> 0:13:34,24
And so this last case with this
single backend problem, I reflected

278
0:13:34,24 --> 0:13:37,42
this experience, I spent a couple
of days on it, and I thought,

279
0:13:37,42 --> 0:13:41,84
so what tooling can help me with
it to next time to finish this

280
0:13:41,84 --> 0:13:46,88
investigation in hours and better
probably even enable dev people

281
0:13:46,88 --> 0:13:48,46
to do it instead of DBAs.

282
0:13:48,9 --> 0:13:53,04
And the Oracle has a very simple
answer for this type of problems.

283
0:13:53,08 --> 0:13:55,9
It's the 10046 event.

284
0:13:56,52 --> 0:13:57,36
It's a tracing.

285
0:13:57,36 --> 0:14:0,86
When you enable it on a certain
level, it writes everything in

286
0:14:0,86 --> 0:14:1,5
the file.

287
0:14:1,5 --> 0:14:6,86
Every single syscall, every single
tuple, I mean the raw joint,

288
0:14:6,86 --> 0:14:10,22
everything I mean very detailed
like real tracing.

289
0:14:10,6 --> 0:14:17,44
And I decided to create the pg_10046
extension that will do it in

290
0:14:17,44 --> 0:14:17,94
Postgres.

291
0:14:18,54 --> 0:14:20,74
And it was the prototype was really
good.

292
0:14:20,74 --> 0:14:22,4
So I really proud of it.

293
0:14:22,44 --> 0:14:25,38
But for wait events, Oracle also
traced the wait events.

294
0:14:25,68 --> 0:14:29,82
And I did the same, but I had to
sample it because I didn't find

295
0:14:29,82 --> 0:14:33,18
by that time any tracing approach
for wait events in Postgres.

296
0:14:33,48 --> 0:14:37,76
I know when I started posting on
LinkedIn this, Jeremy Schneider

297
0:14:37,9 --> 0:14:38,8
came and commented.

298
0:14:38,8 --> 0:14:42,88
So yeah, while it's really nice,
you cannot call it 146 because

299
0:14:42,88 --> 0:14:44,2
wait events are not tracing.

300
0:14:44,44 --> 0:14:48,04
Very true, But there is no way
in Postgres to do it.

301
0:14:48,12 --> 0:14:49,3
Nikolay: Yeah, yeah, 1 second,
1 second.

302
0:14:49,3 --> 0:14:53,3
I just wanted to send a big hello
if Jeremy Schneider listens

303
0:14:53,3 --> 0:14:53,98
to this.

304
0:14:54,52 --> 0:14:58,04
And I hope 1 day we will have him
on this podcast.

305
0:14:58,66 --> 0:15:2,98
And Jeremy Schneider is important
because he was making it popular,

306
0:15:3,4 --> 0:15:5,82
blog posting about ASH a lot.

307
0:15:6,18 --> 0:15:10,2
And he was in the RDS team when
they also started to do this

308
0:15:10,2 --> 0:15:12,1
like performance insights and so
on.

309
0:15:12,1 --> 0:15:15,24
So it's great that you connected
over LinkedIn with him.

310
0:15:15,24 --> 0:15:18,22
Michael: I think was also involved
in the very good wait event

311
0:15:18,34 --> 0:15:21,28
documentation that RDS and Aurora
have.

312
0:15:21,28 --> 0:15:25,52
Nikolay: Oh yes, we discussed this
with Dmitry offline a lot.

313
0:15:25,52 --> 0:15:26,02
Yeah.

314
0:15:28,66 --> 0:15:32,16
Dmitry: Yes, I mean, it's really
a lot of kudos to them for this

315
0:15:32,16 --> 0:15:32,66
work.

316
0:15:33,4 --> 0:15:33,76
Okay.

317
0:15:33,76 --> 0:15:37,6
And, and again, I was brainstorming
with all LLMs that I had

318
0:15:37,6 --> 0:15:38,46
by that moment.

319
0:15:38,46 --> 0:15:40,12
And I started complaining.

320
0:15:40,44 --> 0:15:44,34
Sometimes I use, I talk to them
like to real people and I was

321
0:15:44,34 --> 0:15:44,82
complaining.

322
0:15:44,82 --> 0:15:49,58
So yeah, I had a really nice extension,
but lack of real tracing.

323
0:15:50,28 --> 0:15:51,5
It's a big caveat.

324
0:15:52,68 --> 0:15:54,98
And Claude said to me, yeah, but
you can trace.

325
0:15:55,32 --> 0:15:56,92
And I said, no way.

326
0:15:57,18 --> 0:15:57,68
How?

327
0:15:58,28 --> 0:16:2,2
And he explained to me details,
how I can really trace the weight

328
0:16:2,2 --> 0:16:2,7
events.

329
0:16:3,58 --> 0:16:7,5
And for 2 days, I challenged this
idea a lot for reason.

330
0:16:7,8 --> 0:16:11,42
It could not be me the first who
found this, not me, okay, the

331
0:16:11,42 --> 0:16:14,76
Claude found, but I'm not the first
guy in the Postgres world

332
0:16:14,76 --> 0:16:16,06
who used this.

333
0:16:16,06 --> 0:16:20,6
Either this just does not work
or it was basically the only idea

334
0:16:20,6 --> 0:16:24,56
so it just does not work because
otherwise someone should find

335
0:16:24,56 --> 0:16:25,28
it before.

336
0:16:25,8 --> 0:16:29,92
Anyway 2 days of testing this idea
showed me that it basically

337
0:16:29,92 --> 0:16:33,38
works and I start prototyping the
tool.

338
0:16:34,54 --> 0:16:40,02
It's still in a very immature state,
but it's already showing

339
0:16:40,02 --> 0:16:45,6
nice pictures and already can help
to find some interesting,

340
0:16:45,76 --> 0:16:46,96
how to say, correlations.

341
0:16:47,66 --> 0:16:51,72
For example, I found that, you
know, that most of extensions

342
0:16:51,94 --> 0:16:54,98
now still use extension wait event.

343
0:16:55,44 --> 0:16:59,54
And when extension does something,
you really cannot distinguish

344
0:16:59,68 --> 0:17:3,66
it from doing a real job or it's
just a wait loop.

345
0:17:3,94 --> 0:17:7,86
When I use pg_wait_sampling, for
example, to cross-check the numbers

346
0:17:7,9 --> 0:17:11,58
that I get from my tool and from
pg_wait_sampling, I understood

347
0:17:11,58 --> 0:17:16,36
that the background of pg_wait_sampling,
just Even if it does

348
0:17:16,36 --> 0:17:19,64
nothing, because it works in the
background and there is no job

349
0:17:19,64 --> 0:17:23,34
for it, it's still in a waiting
state, in there.

350
0:17:24,64 --> 0:17:31,64
And so, I think since PG17, you
can have custom wait events for

351
0:17:31,64 --> 0:17:32,14
extension.

352
0:17:32,66 --> 0:17:37,36
And I really hope if someone listens,
just please use the custom

353
0:17:37,36 --> 0:17:40,74
wait events in your extensions,
that it will really help to understand

354
0:17:40,96 --> 0:17:45,78
is your extension busy with doing
some valuable work or it's

355
0:17:45,78 --> 0:17:46,96
just spinning loop.

356
0:17:47,22 --> 0:17:47,62
Nikolay: Right.

357
0:17:47,62 --> 0:17:52,74
This is why we, in my pg_ash also,
listening to Dmitry, I also

358
0:17:52,8 --> 0:17:54,64
spent some time analyzing colors.

359
0:17:55,04 --> 0:17:57,74
So green is what's usually called
CPU.

360
0:17:57,92 --> 0:18:3,42
And this is why in pg_ash and in
our monitoring tool, CPU has

361
0:18:3,42 --> 0:18:4,16
an asterisk.

362
0:18:4,82 --> 0:18:8,56
So CPU star means that it's CPU
or maybe not.

363
0:18:8,56 --> 0:18:11,1
And we also discussed it a few
times on our podcast.

364
0:18:11,74 --> 0:18:14,44
And yeah, so this is exactly why.

365
0:18:14,44 --> 0:18:16,02
So some extensions doing something.

366
0:18:16,02 --> 0:18:16,52
Yeah.

367
0:18:17,1 --> 0:18:20,84
Michael: I was just thinking whether
pg_ash would show up in pg_ash

368
0:18:21,06 --> 0:18:22,44
with its own custom wait events.

369
0:18:22,44 --> 0:18:24,86
But then I remembered it's not
really an extension.

370
0:18:24,96 --> 0:18:25,78
So it can't.

371
0:18:26,0 --> 0:18:26,5
Exactly.

372
0:18:27,8 --> 0:18:28,14
Sorry.

373
0:18:28,14 --> 0:18:28,48
Yeah.

374
0:18:28,48 --> 0:18:29,18
Nikolay: True Postgres.

375
0:18:30,06 --> 0:18:33,38
Dmitry: So that's basically the
story how this came to life.

376
0:18:34,22 --> 0:18:36,76
So what are we to show it?

377
0:18:37,66 --> 0:18:41,04
Nikolay: We cannot show it on podcast,
unfortunately, but just

378
0:18:41,04 --> 0:18:44,64
to recap, like you complained to
LLM that something is impossible

379
0:18:45,18 --> 0:18:47,06
And LLM said, let's do it.

380
0:18:47,64 --> 0:18:47,86
Dmitry: Yeah.

381
0:18:47,86 --> 0:18:49,18
And this is how it was.

382
0:18:49,6 --> 0:18:50,44
Nikolay: This is crazy.

383
0:18:50,92 --> 0:18:53,98
It's like, it's, it means that
it's good to sometimes complain.

384
0:18:54,24 --> 0:18:56,58
It would be good to have, unfortunately
we cannot.

385
0:18:56,58 --> 0:18:59,7
And then just, maybe you just don't
know how and it's possible.

386
0:18:59,7 --> 0:18:59,96
It's great.

387
0:18:59,96 --> 0:19:0,32
Dmitry: Yeah.

388
0:19:0,32 --> 0:19:3,88
Brainstorm with the LLM, I think
it's 1 of the best features.

389
0:19:3,88 --> 0:19:4,38
Yes.

390
0:19:5,08 --> 0:19:6,94
Nikolay: Similarly, our monitoring.

391
0:19:7,06 --> 0:19:9,8
I remember I was talking to you
and you said, oh, it's really

392
0:19:9,8 --> 0:19:14,62
hard or maybe impossible to show
the beginning of query in query

393
0:19:14,62 --> 0:19:16,02
analysis in Grafana.

394
0:19:17,0 --> 0:19:17,78
And that's it.

395
0:19:17,78 --> 0:19:19,56
Dmitry: We mean query, query text.

396
0:19:19,56 --> 0:19:19,78
Nikolay: Yeah.

397
0:19:19,78 --> 0:19:23,88
We, we, we see chart, we see query
IDs, but it would be good

398
0:19:23,88 --> 0:19:25,34
to see query itself.

399
0:19:25,58 --> 0:19:27,74
Is it select or something or in
source?

400
0:19:27,74 --> 0:19:31,82
So I just went and did it with
AI And it's there right now.

401
0:19:32,22 --> 0:19:35,36
Because we had limiting belief
like it's not possible.

402
0:19:35,46 --> 0:19:36,22
It's interesting.

403
0:19:36,46 --> 0:19:38,44
So yeah, AI helps here.

404
0:19:38,48 --> 0:19:41,36
Sometimes it doesn't help, but
here definitely helps to explore

405
0:19:42,18 --> 0:19:45,28
new options and yeah, create something.

406
0:19:45,28 --> 0:19:45,78
Dmitry: Yeah.

407
0:19:46,5 --> 0:19:51,5
The new idea of validation that
it's also 1 of fantastic features.

408
0:19:51,66 --> 0:19:56,52
You can really fast, I mean, check
the idea if it basically working

409
0:19:56,52 --> 0:19:57,1
or not.

410
0:19:57,1 --> 0:20:2,12
Just of course, bring the mature
software will take time.

411
0:20:2,12 --> 0:20:7,24
So, I mean, an LLM cannot do it
in 1 night, but prototyping the

412
0:20:7,54 --> 0:20:8,94
idea, cross-check.

413
0:20:9,02 --> 0:20:10,16
So it's, yes.

414
0:20:10,24 --> 0:20:12,54
Nikolay: So this new tool is tracing.

415
0:20:12,64 --> 0:20:17,56
So it's true, like it won't miss
any wait event or it still have

416
0:20:17,56 --> 0:20:21,74
some sampling or because when you
showed me the pictures which

417
0:20:21,74 --> 0:20:24,96
look amazing, I still think you
need to post those pictures to

418
0:20:24,96 --> 0:20:28,12
add those pictures to read me because
this is like super impressive.

419
0:20:28,62 --> 0:20:30,48
And it was microsecond precision.

420
0:20:30,48 --> 0:20:33,34
I was like, my mind was blown.

421
0:20:33,34 --> 0:20:34,6
So it's, it's really crazy.

422
0:20:34,6 --> 0:20:39,28
But then we started talking and
Dmitry actually came to our hacking

423
0:20:39,28 --> 0:20:43,12
sessions, which happened on Wednesdays
online on YouTube.

424
0:20:43,84 --> 0:20:49,08
So a couple of times we sat and
thought about how to do something

425
0:20:49,08 --> 0:20:52,08
and that something was about changing
Postgres, right?

426
0:20:52,74 --> 0:20:56,02
So why is it needed to change Postgres
for this tool?

427
0:20:57,18 --> 0:21:0,42
Dmitry: And here we, no, for this
tool, we do not need to change

428
0:21:0,42 --> 0:21:0,92
Postgres.

429
0:21:1,0 --> 0:21:4,9
But the thing is this tool has
overhead.

430
0:21:5,74 --> 0:21:7,08
Nikolay: Observer effect, right?

431
0:21:8,2 --> 0:21:11,24
Dmitry: Yes, in more or less, I
would say, if you can call it

432
0:21:11,24 --> 0:21:16,32
regular load, not pathological,
let's call it unacceptable way,

433
0:21:16,6 --> 0:21:19,08
level like 10% something plus minus.

434
0:21:19,54 --> 0:21:23,36
So you pay overhead for every wait
event transition, so when

435
0:21:23,36 --> 0:21:24,88
you get from 1 to another.

436
0:21:24,96 --> 0:21:29,28
And if you get more transitions
per second, so you pay more overhead.

437
0:21:29,66 --> 0:21:35,12
And The maximum that I got was
220K transitions per second.

438
0:21:35,22 --> 0:21:40,66
And in this case, yeah, 220, 000
transitions.

439
0:21:41,68 --> 0:21:42,18
Yeah.

440
0:21:42,26 --> 0:21:46,46
And so in this case, my overhead
was basically 30% of the query

441
0:21:46,46 --> 0:21:46,96
duration.

442
0:21:47,1 --> 0:21:47,6
So.

443
0:21:48,22 --> 0:21:52,0
Nikolay: Was it with very tiny
buffer pool, shared buffers, tiny

444
0:21:52,0 --> 0:21:52,54
shared buffers?

445
0:21:52,54 --> 0:21:53,04
Dmitry: Yes.

446
0:21:53,14 --> 0:21:56,98
When it read, that's why it needs
to go to the OS to get the

447
0:21:56,98 --> 0:21:59,94
block, but block is in OS cache.

448
0:22:0,06 --> 0:22:1,78
So that's why it's really fast.

449
0:22:2,04 --> 0:22:4,7
But you need to almost for every
block you need to go.

450
0:22:4,7 --> 0:22:5,2
Yes.

451
0:22:5,46 --> 0:22:8,9
And for even for evicting, so you
need to be pinning, unpinning,

452
0:22:9,02 --> 0:22:10,34
so all this kind of stuff.

453
0:22:10,34 --> 0:22:13,7
So it goes, I mean, in this case,
I was able to generate this

454
0:22:13,7 --> 0:22:14,94
amount of transitions.

455
0:22:15,48 --> 0:22:20,14
And while it's a kind of a, how
to say, not edge case, but kinder,

456
0:22:20,14 --> 0:22:20,92
very synthetic.

457
0:22:21,04 --> 0:22:26,26
But anyway, so it says that the
overhead, so I mean, you cannot

458
0:22:26,58 --> 0:22:27,42
avoid it.

459
0:22:27,98 --> 0:22:31,98
And when the Jeremy Schneider raised
this concern about it's

460
0:22:31,98 --> 0:22:36,54
not tracing, He also said that
the patch for progress can be

461
0:22:36,54 --> 0:22:37,32
very simple.

462
0:22:37,5 --> 0:22:41,74
You just add 2 probes in this function
that's used for set and

463
0:22:41,74 --> 0:22:44,38
unset wait events and basically
that's it.

464
0:22:45,24 --> 0:22:46,1285
Nikolay: And then you created this...

465
0:22:46,1285 --> 0:22:46,5857
Dmitry: And then you can

466
0:22:46,5857 --> 0:22:47,2
Nikolay: use eBPF?

467
0:22:47,98 --> 0:22:48,48
Yes.

468
0:22:48,62 --> 0:22:49,22
Yeah, yeah.

469
0:22:50,14 --> 0:22:51,84
Dmitry: And you created this patch
for...

470
0:22:51,9 --> 0:22:55,12
Nikolay: I wanted to say that even
if, like you said, for regular

471
0:22:55,12 --> 0:22:59,36
workload, it's not 30, like 10%
overhead observer effect, it

472
0:22:59,36 --> 0:23:3,34
still sounds super useful to me
to use it in lab environment.

473
0:23:3,48 --> 0:23:8,0
So if we reproduce some problem
and study it, not in production,

474
0:23:8,0 --> 0:23:10,22
but on some clone or something,
right?

475
0:23:10,44 --> 0:23:15,06
It's like I'm ready to pay 10%,
20%, maybe even 30% because it

476
0:23:15,06 --> 0:23:18,52
gives me an exact understanding
of everything that happened,

477
0:23:18,52 --> 0:23:19,02
right?

478
0:23:19,02 --> 0:23:21,9
But of course it would be good
to have a very low observer effect

479
0:23:21,9 --> 0:23:23,42
and have it in production right
away.

480
0:23:23,42 --> 0:23:27,54
Dmitry: To be honest, I personally
would pay even 20% in production,

481
0:23:28,36 --> 0:23:31,96
just will instrument me to find
the problem really fast.

482
0:23:31,96 --> 0:23:38,08
Because once I spent, I don't know,
2 or 3 days finding where

483
0:23:38,08 --> 0:23:42,52
the problem is because there was
some changing in the security

484
0:23:42,52 --> 0:23:46,32
configuration of the server and
basically everything became very

485
0:23:46,32 --> 0:23:46,82
slow.

486
0:23:46,98 --> 0:23:50,76
And again, so I spent a lot writing
custom tooling, custom scripts

487
0:23:50,76 --> 0:23:53,3
to find out and go to the problem.

488
0:23:53,48 --> 0:23:57,48
But if I had really good instrumentation,
like we now are discussing,

489
0:23:57,54 --> 0:24:0,64
so it would took a couple of hours
to find the problem.

490
0:24:0,82 --> 0:24:5,5
And I, as the tunnel producer said
in some of the comments, also,

491
0:24:5,5 --> 0:24:10,94
I mean, he was triggered by these
pictures, that the observability

492
0:24:11,32 --> 0:24:12,04
is investment.

493
0:24:12,18 --> 0:24:13,4
It's not for free.

494
0:24:13,78 --> 0:24:17,56
And for example, in Oracle world,
you just pay it, you just don't

495
0:24:17,56 --> 0:24:18,26
know it.

496
0:24:18,58 --> 0:24:24,3
Because you cannot have the Oracle
without the instrumenting.

497
0:24:24,4 --> 0:24:27,5
So I think they instrumented kernel
in version 7.

498
0:24:27,5 --> 0:24:30,18
Nikolay: And you cannot strip it
out and test it without it.

499
0:24:30,18 --> 0:24:35,66
AntennaPolar is just worth mentioning,
is a very noticeable expert

500
0:24:35,66 --> 0:24:36,94
in the Oracle world.

501
0:24:37,08 --> 0:24:39,66
It's great that also Paths connected
here.

502
0:24:39,96 --> 0:24:40,76
Dmitry: Yeah, well...

503
0:24:40,76 --> 0:24:46,34
And that's why I think the wait
event analysis should be in the

504
0:24:46,34 --> 0:24:49,1
capabilities for that, should be
in the Postgres core.

505
0:24:49,3 --> 0:24:50,54
And 2 ways of doing it.

506
0:24:50,54 --> 0:24:52,78
A small patch that you did with
this...

507
0:24:52,84 --> 0:24:53,0
Did

508
0:24:53,0 --> 0:24:53,52
Nikolay: some patch?

509
0:24:53,52 --> 0:24:54,48
I already forgot.

510
0:24:54,64 --> 0:24:55,14
Dmitry: Yes.

511
0:24:55,52 --> 0:24:56,26
Yeah, yeah.

512
0:24:57,04 --> 0:25:2,52
But I wanted to go further and
build the patch that will bring

513
0:25:2,8 --> 0:25:7,64
Oracle level of wait event analysis,
bring this system time

514
0:25:7,64 --> 0:25:10,72
model, the tracing on the backend
level.

515
0:25:10,72 --> 0:25:14,96
So without this, and at the beginning
I was skeptical and I thought

516
0:25:14,96 --> 0:25:19,06
that overhead would be kind of
similar to this because why it

517
0:25:19,06 --> 0:25:20,28
should be really less.

518
0:25:20,28 --> 0:25:21,98
But in reality, way less.

519
0:25:22,2 --> 0:25:27,4
I have this patch in my GitHub
and so last couple of weeks I

520
0:25:27,4 --> 0:25:30,92
was iterating it, making it better
and better and I hope it will

521
0:25:30,92 --> 0:25:35,84
be ready to propose to a community
just today.

522
0:25:35,98 --> 0:25:41,12
But today I was analyzing, there
was a commit in the master that

523
0:25:41,12 --> 0:25:42,84
breaks a lot.

524
0:25:43,34 --> 0:25:47,12
Yes, they changed some memory management
and basically breaks

525
0:25:47,96 --> 0:25:51,24
some parts in my code and I need
to rework some.

526
0:25:51,46 --> 0:25:54,06
Nikolay: Yeah and it's like now
it's the heavy work of preparing

527
0:25:54,06 --> 0:25:58,74
Postgres 19 and maybe like slightly
later it will be less like

528
0:25:58,86 --> 0:26:2,18
super active in terms of code changes
I guess.

529
0:26:2,18 --> 0:26:5,54
I wanted to mention not only 1
limiting belief was like, OK,

530
0:26:5,54 --> 0:26:6,42
it's not possible.

531
0:26:6,78 --> 0:26:10,2
Now you think, OK, observer effect
is too high.

532
0:26:10,2 --> 0:26:11,82
And obviously, it's not so high.

533
0:26:11,82 --> 0:26:15,52
And I remember the upgrade and
post-resume in PagerBouncer, I

534
0:26:15,52 --> 0:26:19,7
had so big belief it won't work,
but we see now how it works

535
0:26:19,7 --> 0:26:22,96
beautifully under huge loads and
huge clusters.

536
0:26:23,32 --> 0:26:25,34
So we just go and check, right?

537
0:26:25,38 --> 0:26:28,06
Now experimentation is cheap with
AI.

538
0:26:28,44 --> 0:26:31,76
It's great to check instead of
thinking it's not possible or

539
0:26:31,76 --> 0:26:32,26
hard.

540
0:26:32,64 --> 0:26:33,24
It's great.

541
0:26:33,24 --> 0:26:35,9
Like it's super inspiring to hear
what you say.

542
0:26:36,96 --> 0:26:37,36
Dmitry: Yeah.

543
0:26:37,36 --> 0:26:42,62
And back to the Tuli, I still think
it's very applicable in case

544
0:26:42,62 --> 0:26:47,06
you can, you, I don't know if the
patch, my patch or similar

545
0:26:47,12 --> 0:26:50,78
patch with a similar idea would
be committed any day upstream.

546
0:26:51,2 --> 0:26:55,18
Or you cannot afford new versions,
so you will stick with some

547
0:26:55,18 --> 0:26:58,16
vanilla Postgres without these
new capabilities.

548
0:26:58,94 --> 0:27:1,52
Nice thing that it's fully independent
from Postgres.

549
0:27:1,64 --> 0:27:4,98
It runs like a sidecar, so you
can switch on and off.

550
0:27:5,14 --> 0:27:9,16
You do not need to recompile Postgres,
you don't need to change

551
0:27:9,16 --> 0:27:10,02
anything in Postgres.

552
0:27:10,02 --> 0:27:11,02
It just runs.

553
0:27:12,42 --> 0:27:13,68
You can start to next to it.

554
0:27:13,94 --> 0:27:17,52
Yes, you need to self-host Postgres,
you need to have access

555
0:27:17,52 --> 0:27:18,08
to the box.

556
0:27:18,08 --> 0:27:18,9
Nikolay: Root access.

557
0:27:19,4 --> 0:27:22,66
Dmitry: Not root, but with elevated
access rights for running

558
0:27:22,66 --> 0:27:23,8
eBPF, basically.

559
0:27:24,92 --> 0:27:28,1
And so that's a nice thing about
the tracing.

560
0:27:28,26 --> 0:27:32,06
As soon as it's pure tracing, it's
not sampling at any moment,

561
0:27:32,3 --> 0:27:36,9
It opens doors for very interesting
things that are not even

562
0:27:36,9 --> 0:27:38,7
implemented in Oracle world.

563
0:27:38,94 --> 0:27:44,16
And here we can beat Oracle in
progress because it's tracing.

564
0:27:44,24 --> 0:27:48,72
It means that we have a full history
of transitions from 1 state

565
0:27:48,72 --> 0:27:51,42
to another state to the next state
and so on.

566
0:27:51,78 --> 0:27:57,04
And you can reconstruct all performance
problems or clashes or

567
0:27:57,04 --> 0:28:2,06
bursts in your system, not only
in time but also find the dependencies,

568
0:28:2,72 --> 0:28:3,96
who started the problem.

569
0:28:3,96 --> 0:28:8,68
Because even with a wait event
analysis, with a sampling approach,

570
0:28:8,68 --> 0:28:13,24
for example, you cannot distinguish
between you had 10 short

571
0:28:13,32 --> 0:28:15,46
I/O waits or 1 long.

572
0:28:15,58 --> 0:28:20,44
With the tracing, you can do it
and you can find the session

573
0:28:20,54 --> 0:28:21,84
who started the problem.

574
0:28:22,1 --> 0:28:26,04
Because in the regular way, it's
really hard to distinguish the

575
0:28:26,04 --> 0:28:29,44
session suffered from the problem
or it caused the problem.

576
0:28:30,1 --> 0:28:34,06
So with this, I believe, with the
tracing, you can find the root

577
0:28:34,06 --> 0:28:37,4
of the problem and all the consequences
of it.

578
0:28:37,86 --> 0:28:43,68
And with all these transitions,
you can see it as the servers

579
0:28:43,78 --> 0:28:47,92
and can analyze this from the queuing
theory perspective.

580
0:28:48,08 --> 0:28:53,68
You can get the already really
mature mathematician approach

581
0:28:53,68 --> 0:28:55,78
and everything is already there.

582
0:28:56,12 --> 0:29:1,46
You can analyze it, how much you
can serve in a given period

583
0:29:1,46 --> 0:29:2,22
of the time.

584
0:29:2,22 --> 0:29:6,3
And you can find the real bottleneck,
for example, with a regular

585
0:29:6,38 --> 0:29:9,56
wait event analysis you can see
that a lot of I/Os, for example,

586
0:29:9,56 --> 0:29:10,82
that I/Os are bottlenecks.

587
0:29:11,06 --> 0:29:17,18
But in reality, if you see from
the tracing that by I/O always

588
0:29:17,62 --> 0:29:20,36
gets the LWLock, for example,
for any reason.

589
0:29:20,5 --> 0:29:24,96
Even if you would be able to solve
the problem with I/O, giving,

590
0:29:24,96 --> 0:29:29,08
for example, find the faster disks,
the I/O would be shorter,

591
0:29:29,08 --> 0:29:32,02
but anyway, you would be locked
by LV locks.

592
0:29:32,08 --> 0:29:35,14
So the bottleneck would be just
moved to the next stage.

593
0:29:35,74 --> 0:29:36,24
And.

594
0:29:36,56 --> 0:29:39,52
Nikolay: This is what makes benchmarking
so hard.

595
0:29:39,52 --> 0:29:39,76
Yes.

596
0:29:39,76 --> 0:29:42,72
And what you're saying, as I hear,
I don't know all the details,

597
0:29:42,72 --> 0:29:46,72
but what I hear is there is a math,
mathematics, like apparatus

598
0:29:46,78 --> 0:29:50,02
basically, which could help here
and analyze bottlenecks much

599
0:29:50,02 --> 0:29:53,16
better and understand real bottleneck
reliably.

600
0:29:53,3 --> 0:29:54,22
That sounds amazing.

601
0:29:54,38 --> 0:29:55,22
I want this.

602
0:29:57,04 --> 0:29:58,38
Dmitry: So it's not at all.

603
0:29:59,16 --> 0:29:59,72
So not yet.

604
0:29:59,72 --> 0:30:2,96
I have more ideas that's semi-implemented.

605
0:30:3,44 --> 0:30:7,4
So I'm just playing with it because
collect data, it's not the...

606
0:30:7,54 --> 0:30:10,4
Even analyze the data, it's not
the last step.

607
0:30:10,4 --> 0:30:15,04
The last step is present data to
the human to make it consumable

608
0:30:15,3 --> 0:30:18,7
from human to understand this data,
to make the action.

609
0:30:19,44 --> 0:30:21,6
So this is the process analysis.

610
0:30:22,04 --> 0:30:27,84
There is a, again, already people
spent a lot of time, really

611
0:30:27,84 --> 0:30:31,4
smart people thinking and they
already have the really good approach

612
0:30:31,4 --> 0:30:36,82
how to analyze the graphs and when
you move data from 1 state,

613
0:30:36,82 --> 0:30:40,18
for example, tickets, when you
move from 1 state ticket to the

614
0:30:40,18 --> 0:30:45,8
open in progress, I don't know,
test completed and same with

615
0:30:45,8 --> 0:30:50,88
the, I don't know, the logistic
when you need to find the bottlenecks

616
0:30:50,9 --> 0:30:51,76
on your graph.

617
0:30:52,2 --> 0:30:57,1
And you can, with this math, you
can find the patterns that the

618
0:30:57,1 --> 0:31:1,82
most frequent path is that, and
the bottleneck is this specific

619
0:31:1,96 --> 0:31:2,46
state.

620
0:31:2,54 --> 0:31:6,58
It means that the, I don't know,
every, most of your backends

621
0:31:6,62 --> 0:31:8,98
goes through the buffer pin, for
example.

622
0:31:9,14 --> 0:31:11,92
And buffer pin basically the limiting
factor.

623
0:31:12,44 --> 0:31:16,82
You do not need to even look at
the dashboard with your eyes.

624
0:31:17,22 --> 0:31:21,16
System, not LLM, simple code can
do it for you.

625
0:31:21,42 --> 0:31:24,96
We analyze the backends, traces,
yes, everything goes through

626
0:31:24,96 --> 0:31:26,18
the buffer pin.

627
0:31:26,54 --> 0:31:30,2
And so we analyze that the buffer
pin and the system can make

628
0:31:30,2 --> 0:31:34,52
100k buffer pins a second, but
your system demands 200.

629
0:31:34,74 --> 0:31:36,72
So basically you need to solve
this problem here.

630
0:31:36,72 --> 0:31:38,0
So the problem is here.

631
0:31:38,0 --> 0:31:39,9
It's a very deterministic approach.

632
0:31:40,02 --> 0:31:42,14
It can give the report really easy.

633
0:31:42,26 --> 0:31:43,68
You do not need hallucinations.

634
0:31:44,16 --> 0:31:46,86
You don't need to look at your
dashboards for that.

635
0:31:47,46 --> 0:31:51,92
And so I think it opened doors
for really interesting stuff.

636
0:31:52,36 --> 0:31:56,18
And 1 last, I think, idea that
I have and tried to implement

637
0:31:56,18 --> 0:31:56,68
already.

638
0:31:57,12 --> 0:31:58,96
System can find the deviations.

639
0:31:59,44 --> 0:32:4,4
For example, now for Query ID,
the common wait event profile

640
0:32:4,4 --> 0:32:8,16
is, I don't know, spent 1 millisecond
in CPU, 1 millisecond in

641
0:32:8,16 --> 0:32:10,74
I/O, and after that, sometime in
the logs.

642
0:32:11,12 --> 0:32:15,96
But instead of 40 milliseconds,
it took 50 milliseconds.

643
0:32:16,3 --> 0:32:20,34
And it's because it's introduced
a new wait event in between.

644
0:32:20,6 --> 0:32:25,36
So again, it's very easy to, I
think, to write the code to make

645
0:32:25,36 --> 0:32:27,82
this analysis in a semi-automatic
way.

646
0:32:27,84 --> 0:32:33,2
So you just can, like in Oracle,
you open the 1 hour AWR report,

647
0:32:33,22 --> 0:32:34,9
but in the bottom you will have...

648
0:32:34,9 --> 0:32:38,86
So I made analysis for you, so
the problem is here, the query

649
0:32:38,86 --> 0:32:42,74
with the query id, change the wait
event profile from that to

650
0:32:42,74 --> 0:32:45,78
that, and you have a problem with
this, I don't know, disk or

651
0:32:45,78 --> 0:32:47,26
file or something like that.

652
0:32:47,86 --> 0:32:53,58
So it's a kind of a project, but
I think it's doable nowadays.

653
0:32:54,36 --> 0:32:58,38
Michael: Going back quickly, you
mentioned let's say we're self-managing

654
0:32:58,94 --> 0:33:0,26
using Postgres today.

655
0:33:1,36 --> 0:33:4,3
Presumably this tool already would
work for us.

656
0:33:4,3 --> 0:33:8,3
So I'm wondering what the changes
in core would be that you want

657
0:33:8,3 --> 0:33:8,72
to make.

658
0:33:8,72 --> 0:33:10,32
What added benefit would that have?

659
0:33:10,32 --> 0:33:13,28
Or is it mostly about getting it
to work on managed service providers

660
0:33:13,28 --> 0:33:14,34
or something else?

661
0:33:14,82 --> 0:33:18,82
Dmitry: From 1 hand, this tool
I think would enable a lot of

662
0:33:18,82 --> 0:33:22,04
debates to make the perfect wait
event analysis.

663
0:33:24,0 --> 0:33:27,88
But moving these capabilities to
the Postgres core will reduce

664
0:33:27,88 --> 0:33:29,92
the overhead, from 1 hand.

665
0:33:30,18 --> 0:33:33,66
Second hand, you will have it in
vanilla everywhere.

666
0:33:33,82 --> 0:33:36,48
So you would not need to bring
any tool.

667
0:33:36,48 --> 0:33:39,52
You would not need to have access
to the box.

668
0:33:39,52 --> 0:33:42,34
You do not, because not all Postgres
DBAs have it, right?

669
0:33:42,34 --> 0:33:45,2
Nikolay: You have interface, maybe
SQL interface or something.

670
0:33:45,62 --> 0:33:46,12
Dmitry: Yeah.

671
0:33:46,24 --> 0:33:51,58
So it's definitely going to be
available through the SQL views.

672
0:33:51,58 --> 0:33:52,08
Yes.

673
0:33:53,46 --> 0:33:56,88
Nikolay: But the question, we haven't
started any discussions

674
0:33:58,08 --> 0:33:59,06
in hackers yet.

675
0:33:59,06 --> 0:33:59,54
Right.

676
0:33:59,54 --> 0:34:0,04
Yes.

677
0:34:0,18 --> 0:34:2,36
So this is the interesting point.

678
0:34:2,36 --> 0:34:4,38
If when, what will they say?

679
0:34:4,54 --> 0:34:5,04
Because.

680
0:34:6,66 --> 0:34:7,16
Dmitry: Yeah.

681
0:34:7,2 --> 0:34:12,1
And why I still, how to say, want
to make this patch at least

682
0:34:12,1 --> 0:34:16,38
from the first look really solid,
because I expect a lot of pushback

683
0:34:16,8 --> 0:34:19,4
because it's a kind of a consensus
for some reason.

684
0:34:19,4 --> 0:34:24,04
When I talk to on any conf on any
place to the production DBAs

685
0:34:24,38 --> 0:34:28,94
everybody says yes we need it no
dubs but when you talk to the

686
0:34:28,94 --> 0:34:34,04
people who has some weight in the
community who can really promote

687
0:34:34,04 --> 0:34:38,68
something, they, how to say it,
I would say they spend less with

688
0:34:38,68 --> 0:34:41,86
a real production issue, less time
with the real production issues

689
0:34:42,04 --> 0:34:46,5
and that's why probably they pushing
back for any changes in

690
0:34:46,5 --> 0:34:50,38
core that can introduce the performance
degradation, even if

691
0:34:50,38 --> 0:34:54,64
it brings a lot of new, I don't
know, tooling for DBAs.

692
0:34:55,08 --> 0:34:57,42
Because it really depends on your
perspective.

693
0:34:57,7 --> 0:35:1,44
I look at the Postgres as the production
DBA, that's why I think

694
0:35:1,44 --> 0:35:5,24
I would pay 20% overhead so I don't
care just give me a tool.

695
0:35:5,38 --> 0:35:6,02
It's already

696
0:35:6,02 --> 0:35:8,5
Nikolay: paid, so you don't need
to go to them.

697
0:35:8,94 --> 0:35:12,84
As you said you're already working
with this like 10-20% or something

698
0:35:13,04 --> 0:35:13,54
overhead.

699
0:35:14,38 --> 0:35:16,08
Yeah but I guess...

700
0:35:16,08 --> 0:35:20,14
Michael: Quick question on the
tool as it is, it's on the GitHub

701
0:35:20,14 --> 0:35:23,3
repo, it says version 0.8 is the
last 1 I saw.

702
0:35:23,36 --> 0:35:26,26
Are you working towards, what does
1.0 look like?

703
0:35:26,26 --> 0:35:27,8
Is it a reliability thing?

704
0:35:27,8 --> 0:35:29,7
Is it like a more tests thing?

705
0:35:29,7 --> 0:35:32,62
What's missing that you don't want
to call it 1.0 yet?

706
0:35:33,62 --> 0:35:39,72
Dmitry: Yes, I still in some tests
it gets out of memory so seems

707
0:35:39,72 --> 0:35:44,64
to there is a I mean like so yes
I need the the more tests increase

708
0:35:44,64 --> 0:35:50,14
the quality of the code and I want
to get to run it on real box,

709
0:35:50,14 --> 0:35:54,52
not virtual machine from some cloud
provider on real box to make,

710
0:35:54,52 --> 0:35:57,8
you know, to say to people, so
it's if not production ready,

711
0:35:57,8 --> 0:36:1,22
but at least it's safe to run somewhere
on the test environment

712
0:36:1,22 --> 0:36:3,84
because nowadays I still cannot
say it for sure.

713
0:36:4,16 --> 0:36:8,36
But again, I thought I was really
close to the patch to make

714
0:36:8,36 --> 0:36:10,76
this ready for community to start
a conversation.

715
0:36:10,76 --> 0:36:13,62
I know that it's a really long
journey and I wanted to start

716
0:36:13,62 --> 0:36:14,06
this.

717
0:36:14,06 --> 0:36:17,38
And as soon as I had a feeling
that I'm really close to it.

718
0:36:17,4 --> 0:36:21,1
I invested all my time last couple
of weeks in the patch and

719
0:36:21,1 --> 0:36:23,32
I didn't commit anything to this
tool.

720
0:36:23,32 --> 0:36:26,52
That's, I mean, kind of a post,
but I will get back to it for

721
0:36:26,52 --> 0:36:27,02
sure.

722
0:36:27,54 --> 0:36:28,7842
But yes, the quality of the question.

723
0:36:28,7842 --> 0:36:29,28
A couple of

724
0:36:29,28 --> 0:36:32,72
Nikolay: questions For those who
are interested in trying out

725
0:36:32,72 --> 0:36:38,72
earlier, first of all, what are
best use cases for it in its

726
0:36:38,72 --> 0:36:40,62
current state, not in future state?

727
0:36:40,96 --> 0:36:43,16
And second question is how to start
quickly.

728
0:36:43,46 --> 0:36:45,16
Just clone repo and that's it.

729
0:36:45,72 --> 0:36:50,32
Dmitry: Yeah, I hope at least I
tried to make the readme up to

730
0:36:50,32 --> 0:36:54,14
date and it should be sufficient
just to go through the readme

731
0:36:54,14 --> 0:36:56,4
to compile it and just run it.

732
0:36:56,88 --> 0:37:1,88
I tailored it for my use case,
I mean for my day-to-day life

733
0:37:1,88 --> 0:37:6,9
and I hope that it's a good example
and people should be able

734
0:37:6,9 --> 0:37:9,44
to use it just right after the
cloning.

735
0:37:9,86 --> 0:37:12,78
Nikolay: I obviously see, for example,
the next big benchmark

736
0:37:12,86 --> 0:37:18,54
actually probably should be worth
using it to see how it helps

737
0:37:18,54 --> 0:37:21,8
to understand what's happening
with that benchmark.

738
0:37:21,82 --> 0:37:24,52
But maybe what are the other cases,
like some troubleshooting

739
0:37:24,64 --> 0:37:28,22
of complex situation in production
and try to reproduce it on

740
0:37:28,66 --> 0:37:30,36
a clone or something else?

741
0:37:30,88 --> 0:37:34,74
Dmitry: I think if you, for example,
you have a problem and fortunately

742
0:37:34,86 --> 0:37:38,48
enough you can reproduce it, but
you just don't know in some

743
0:37:38,48 --> 0:37:41,64
isolated environment, you just
don't know what happens during

744
0:37:41,64 --> 0:37:45,6
the problem, you can run the tool
and it would be just look into

745
0:37:45,6 --> 0:37:46,8
the problem with microscope.

746
0:37:46,8 --> 0:37:49,78
It will track everything, it will
show everything to you.

747
0:37:50,08 --> 0:37:54,14
So I think at this moment it's
good enough for that type of usage,

748
0:37:54,32 --> 0:37:57,42
investigating some problem in isolated
environment.

749
0:37:57,66 --> 0:38:3,64
But if you're brave enough, you
can try it on some close to some

750
0:38:3,66 --> 0:38:6,0
load in production because you
just can kill it.

751
0:38:6,0 --> 0:38:6,5
Just

752
0:38:6,58 --> 0:38:8,6
Nikolay: brave enough or desperate
enough.

753
0:38:8,6 --> 0:38:11,82
Sometimes you have a problem you
cannot reproduce and let's go

754
0:38:11,82 --> 0:38:13,22
to production if it's self-managed.

755
0:38:13,66 --> 0:38:17,62
I, in this case, someone goes and
needs it in production because

756
0:38:17,62 --> 0:38:21,38
otherwise it's not like possible
to understand what's happening.

757
0:38:21,38 --> 0:38:24,96
Do you recommend to attach to only
once backend or to analyze

758
0:38:24,96 --> 0:38:25,58
all of them?

759
0:38:25,58 --> 0:38:27,44
Like how's it better to use this
tool?

760
0:38:28,62 --> 0:38:32,64
Dmitry: I built it with the trace
everything, including the auxiliary

761
0:38:32,64 --> 0:38:36,66
processes, this postgres processes,
because sometimes that's

762
0:38:36,66 --> 0:38:37,36
the problem.

763
0:38:37,9 --> 0:38:41,4702
And I build this tool with this
in mind, so just let's say everything

764
0:38:41,4702 --> 0:38:42,54
and have everything.

765
0:38:44,6802 --> 0:38:45,1802
But

766
0:38:47,32 --> 0:38:51,18
Nikolay: It's possible to narrow
to only 1 session, only 1 backend,

767
0:38:51,18 --> 0:38:51,86
is it possible?

768
0:38:51,86 --> 0:38:52,66
Possible as well,

769
0:38:52,66 --> 0:38:53,16
Dmitry: right?

770
0:38:53,42 --> 0:38:53,46
Nikolay: Yes.

771
0:38:53,46 --> 0:38:53,96
Good.

772
0:38:54,78 --> 0:38:59,34
So if like, it's just less risk
is lower if you decide analyze

773
0:38:59,34 --> 0:39:0,7
only 1 backend, right?

774
0:39:0,96 --> 0:39:1,34
Then...

775
0:39:1,34 --> 0:39:2,82
Dmitry: Yeah, theoretically, yes.

776
0:39:3,9 --> 0:39:6,14
Surface should be smaller, yes.

777
0:39:6,98 --> 0:39:7,94
Nikolay: Yeah, that's great.

778
0:39:7,94 --> 0:39:13,48
Yeah, I think I'm definitely will
plan to use it in some next

779
0:39:13,48 --> 0:39:15,0
benchmarks I will be having.

780
0:39:15,22 --> 0:39:17,06
I had some benchmarks last Friday.

781
0:39:17,66 --> 0:39:20,14
I just realized I should involve
this tool, but I'm going to

782
0:39:20,14 --> 0:39:21,18
revisit those benchmarks.

783
0:39:21,18 --> 0:39:25,56
They are fully scripted, so I guess
I will just try and see what

784
0:39:25,56 --> 0:39:26,5
it will say.

785
0:39:26,82 --> 0:39:29,0
It's about this queuing Postgres tool.

786
0:39:30,06 --> 0:39:32,54
I will definitely connect to you
about that.

787
0:39:33,84 --> 0:39:36,3
Anyway, I'm excited to see this
work.

788
0:39:36,9 --> 0:39:40,8
It's a very unexpected for me angle
of active session history

789
0:39:40,8 --> 0:39:46,82
analysis, which actually dissolves
1 of the biggest concerns

790
0:39:46,92 --> 0:39:49,74
about ASH methodology, which is
sampling.

791
0:39:51,06 --> 0:39:57,24
Producer statements are precise,
unless query ID is evicted or

792
0:39:57,6 --> 0:40:0,48
unless we talk about the part which
is like cancelled statements,

793
0:40:0,48 --> 0:40:2,0
which statements don't see.

794
0:40:2,46 --> 0:40:6,04
But they are precise, it's just
cumulative metrics counters incrementing,

795
0:40:6,22 --> 0:40:7,4
like tracking all.

796
0:40:7,96 --> 0:40:12,7
I really liked producer statements
when they were created because

797
0:40:12,7 --> 0:40:17,02
before that we had only
pre-pgBadger, we had pgFouine, it's

798
0:40:17,02 --> 0:40:21,06
a French name, and it was PHP script
and it was based on sampling

799
0:40:21,06 --> 0:40:26,1
like everything related to logging
is painful and sampling is

800
0:40:26,1 --> 0:40:26,42
painful.

801
0:40:26,42 --> 0:40:31,12
So okay we have now we now have
exact precise instrument tool

802
0:40:31,12 --> 0:40:32,52
to work with.

803
0:40:32,7 --> 0:40:36,26
But then ASH, ASH is impressive,
great approach, but it's sampling

804
0:40:36,3 --> 0:40:36,78
based.

805
0:40:36,78 --> 0:40:39,56
Now you say ASH can be precise.

806
0:40:40,36 --> 0:40:42,62
And this is like new horizon or
opening for me.

807
0:40:42,62 --> 0:40:43,64
I'm super excited.

808
0:40:44,16 --> 0:40:45,8
Thank you for making this work.

809
0:40:45,8 --> 0:40:46,58
It's great.

810
0:40:47,48 --> 0:40:51,4
Dmitry: And when I working on this
tool and working on the Python

811
0:40:51,4 --> 0:40:55,46
for progress, I understood that
there are some, how to say gaps

812
0:40:55,68 --> 0:40:58,1
in the attributing time to the
queries.

813
0:40:58,62 --> 0:41:1,64
That's not really, how to say straightforward
to understand.

814
0:41:1,64 --> 0:41:5,56
For example, the client reads the
wait event that we see really

815
0:41:5,56 --> 0:41:10,64
often, but is it really database
time or it's still client time?

816
0:41:10,64 --> 0:41:15,32
It's not that simple and easy,
but even if you go deeper, so

817
0:41:15,32 --> 0:41:18,3
there are, for example, you ended
the query.

818
0:41:18,3 --> 0:41:22,9
I mean, you open transaction, begin,
you made some changes, the

819
0:41:22,9 --> 0:41:28,54
last update finished, and you issue
commit or end.

820
0:41:29,06 --> 0:41:33,58
And really, you need to attribute
the time and waits to end,

821
0:41:33,58 --> 0:41:34,24
to commit.

822
0:41:34,24 --> 0:41:35,86
I think it's defaulted behavior.

823
0:41:35,86 --> 0:41:39,28
But also, even after commit, there
are some work that Postgres

824
0:41:39,28 --> 0:41:40,98
does, some cleaning up.

825
0:41:41,4 --> 0:41:45,56
And from pg_stat_statements' perspective,
it's already not there.

826
0:41:45,92 --> 0:41:51,7
And some part of the work is kind
of unattributed, and it goes

827
0:41:51,88 --> 0:41:52,62
to nowhere.

828
0:41:52,66 --> 0:41:56,24
It's not really a big amount of
work, but still, playing with

829
0:41:56,24 --> 0:42:0,66
this precise tool will, if you
are curious enough, so will get

830
0:42:0,66 --> 0:42:3,56
you to the next level of understanding
how Postgres actually

831
0:42:3,56 --> 0:42:4,78
works to the internals.

832
0:42:4,92 --> 0:42:5,72
Really interesting.

833
0:42:5,72 --> 0:42:8,94
I really like for that because
I never thought about it until

834
0:42:8,94 --> 0:42:10,52
I started working with it.

835
0:42:10,52 --> 0:42:13,86
Nikolay: And it's true that not
only you can understand the like

836
0:42:13,86 --> 0:42:17,56
exact sequence of wait events for
this particular load, but also

837
0:42:17,56 --> 0:42:20,96
you can map it to source code,
right?

838
0:42:21,5 --> 0:42:25,8
Dmitry: Of course, nowadays LLM
can explain it to you, so it's

839
0:42:25,8 --> 0:42:28,98
not a foreign language anymore,
so you can speak to it, you can

840
0:42:28,98 --> 0:42:30,06
really easy to understand.

841
0:42:30,06 --> 0:42:33,9
Nikolay: Which opens doors for
more optimization of Postgres

842
0:42:33,9 --> 0:42:34,4
itself?

843
0:42:35,5 --> 0:42:36,78
Dmitry: I hope so, yes.

844
0:42:38,16 --> 0:42:43,04
Nikolay: Like usually with GDB
or with perf, now with this tool

845
0:42:43,04 --> 0:42:44,14
also it's possible.

846
0:42:44,24 --> 0:42:46,84
If you have some pathological workload
you will reproduce it

847
0:42:46,84 --> 0:42:48,02
in a synthetic environment.

848
0:42:48,14 --> 0:42:50,04
Let's go, That's it, yeah, that's
great.

849
0:42:50,82 --> 0:42:52,76
Michael, you wanted to add something,
right?

850
0:42:53,48 --> 0:42:56,38
Michael: Only when you were talking
about unexplained overhead,

851
0:42:56,52 --> 0:43:0,72
it often shows up in explain analyze
when you look at the difference

852
0:43:0,72 --> 0:43:4,9
between the execution time at the
end of the query plan and the

853
0:43:4,92 --> 0:43:11,12
actual total time of the like the
top level operation you almost

854
0:43:11,12 --> 0:43:15,18
always see a small discrepancy
there as well and not accounted

855
0:43:15,18 --> 0:43:18,48
for anywhere which is yes the same
thing you're talking about

856
0:43:18,48 --> 0:43:19,1
I think.

857
0:43:19,7 --> 0:43:23,2
Dmitry: Yeah a few percent there
and there and you lost 10 bucks.

858
0:43:24,92 --> 0:43:27,98
Michael: Yeah well yeah I'd like
to echo what Nik's saying it's

859
0:43:27,98 --> 0:43:30,44
really interesting work that you're
doing and thanks for sharing

860
0:43:30,44 --> 0:43:34,18
and also I think you you published
the tool under the Postgres

861
0:43:34,2 --> 0:43:34,84
license which is

862
0:43:34,84 --> 0:43:35,78
Dmitry: really cool.

863
0:43:36,04 --> 0:43:36,78
Nice 1.

864
0:43:37,86 --> 0:43:41,4
Yeah I personally believe in it
so if you develop for Postgres

865
0:43:41,4 --> 0:43:42,84
just then share it.

866
0:43:44,06 --> 0:43:49,5
Nikolay: And what book on Queue Theory
you are reading like for quite

867
0:43:49,5 --> 0:43:50,9
a long time as I know?

868
0:43:51,14 --> 0:43:54,0
Dmitry: Yeah so it's a quite old
1 so let me...

869
0:43:54,0 --> 0:43:56,26
Nikolay: Because it connects me
to my current work, like this

870
0:43:56,26 --> 0:43:57,54
tool I just released.

871
0:43:58,78 --> 0:44:1,1
And I guess I need to read it as
well.

872
0:44:1,8 --> 0:44:4,66
Dmitry: I will send it so you can
put it to the description.

873
0:44:6,78 --> 0:44:10,38
Nikolay: Okay, good luck with the
tool, definitely, I hope it

874
0:44:10,96 --> 0:44:11,82
will be popular.

875
0:44:12,38 --> 0:44:17,04
And I hope your patches will be
welcomed in hackers mailing list.

876
0:44:17,04 --> 0:44:20,28
Dmitry: Yeah, we will see how it
goes.

877
0:44:20,28 --> 0:44:22,78
Nikolay: Great, thank you so much
for coming again.

878
0:44:23,44 --> 0:44:24,02
Michael: Thank you.