Thread: Many DataFileRead - IO waits

How big is ix_tabledata_intid_timestampdate_intotherid3_intotherid2 on disk? If you create another index with same fields, how much space does it take? Real question- are you vacuuming aggressively enough for your workload? Your index name seems to indicate that intotherid3 would be the third key, and yet the planner chose not to scan that deep and instead filtered after it found the relevant tuples based on intid and timestampdate. That seems peculiar to me.

The documentation discourages multi-column indexes because they have limited application unless the same fields are always used. Personally, I don't love reviewing the stats of indexscans or how many tuples were fetched and having to guess how deeply the index was scanned for the various queries involved.

I'd wonder if an index on only intid_timestampdate would be both much smaller and also have a more right-leaning pattern of information being added and accessed in terms of keeping frequently needing blocks in shared buffers.

As a side note, that planning time seems high to me for such a simple query. Have you increased default_statistics_target significantly perhaps?

If no updates or deletes are happening on the table, it would be best practice to set up a scheduled manual vacuum analyze to ensure statistics and the visibility map is updated. Other than creating the index on the first two columns only, I'm out of ideas. Hopefully someone running Postgres at large scale on Windows will chime in.

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

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.

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

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

Hello,
I'm not able to use your perfs diagrams,
but it seems to me that not using 3rd column of that index (int_otherid2)
generates an IO problem.

Could you give us the result of

explain (analyze,buffers) SELECT
tabledata.uuid_id,tabledata.int_id,tabledata.timestamp_date,tabledata.int_otherid,tabledata.float_value,tabledata.int_otherid2,tabledata.int_otherid3,tabledata.int_rowver
FROM tabledata
WHERE timestamp_date <= '2020-02-24 03:05:00.013'::timestamp without time
zone
ND int_otherid3 = '3ad2b707-a068-42e8-b0f2-6c8570953760'
AND tabledata.int_id=8149
ORDER BY timestamp_date DESC
LIMIT 1

and this for each value of int_otherid3 ?
and tell us if you are able to change the sql ?

Thanks
Regards
PAscal

On Thu, Feb 27, 2020 at 11:33 AM Ben Snaidero <bensnaidero@geotab.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