Re: Many DataFileRead - IO waits

On Thu, Feb 27, 2020 at 11:33 AM Ben Snaidero <bensnaidero(at)geotab(dot)com>
wrote:

> I have the following query that was on average running in ~2ms suddenly
> jump up to on average ~25ms.
>

What are you averaging over? The plan you show us is slow enough that if
you were averaging over the last 1000 executions, that one execution could
skew the entire average just by itself. When individual execution times
can vary over 4 powers of 10, I don't think averages are a very good way of
analyzing things.

> This query is called millions of time per day and there were cases of the
> query taking 20-30 seconds. Below is the explain analyze of one such
> example.
> When seeing this issue, the server was under some CPU pressure but even
> with that, I would not think it should get as slow as shown below as we are
> using SSDs and none of the windows disk counters (IOPS, queue length) show
> any value that would be of concern.
>

What is the average and expected random read latency on your SSDs? Have
you benchmarked them (outside of the database system) to see if they are
performing as expected?

> Rows Removed by Filter: 91686
> Buffers: shared hit=12102 read=13259 written=111
>

Do the faster executions have fewer rows removed by the filter (and fewer
buffers read), or are they just faster despite having about the same values?

> We took a perfview during the issue and below is the call stack from a
> process running this query, two call paths are shown.
>

I've never used perfview. But if I try to naively interpret it similar to
gdb backtrace, it doesn't make much sense to me. InitBufTable is only
called by "postmaster" while starting the database, how could it be part of
call paths during regular operations? Are these views of the slow-running
back end itself, or of some other postgresql process which was idle at the
time the snapshot was taken?

Cheers,

Jeff

>