2016-08-18 23:06 GMT+03:00 Jeff Janes <jeff.ja...@gmail.com>:
> It does account for them, but perhaps not perfectly. See "[PERFORM]
> index fragmentation on insert-only table with non-unique column" for
> some arguments on that which might be relevant to you.
>
Thanks for pointing this out, good stuff to know.
If you can come up with a data generator which creates data that
> others can use to reproduce this situation, we can then investigate it
> in more detail.
>
I do not think this has any value anymore. I have reconfigured the server:
- r_p_c returned to the default 4.0
- turned on track_io_timing
- reindexed all indexes on the table
- went with the suggestion from Jim about partial index on `due_date`,
although
delayed it a bit to get a better view on the situation
Running several explains in a row produces the following:
Index Scan using idx_loan_agreemnets_loan_id_cond_is_current_true on
loan_agreements la (cost=0.42..21469.40 rows=224331 width=13) (actual
time=0.040..2687.422 rows=216440 loops=1)
Filter: ('2016-08-11'::date > due_date)
Rows Removed by Filter: 21806
Buffers: shared hit=226670 read=692 dirtied=48
I/O Timings: read=9.854
Planning time: 1885.219 ms
Execution time: 2712.833 ms
Index Scan using idx_loan_agreemnets_loan_id_cond_is_current_true on
loan_agreements la (cost=0.42..21469.40 rows=224331 width=13) (actual
time=426.027..2273.617 rows=216440 loops=1)
Filter: ('2016-08-11'::date > due_date)
Rows Removed by Filter: 21806
Buffers: shared hit=227276
Planning time: 0.175 ms
Execution time: 2296.414 ms
Index Scan using idx_loan_agreemnets_loan_id_cond_is_current_true on
loan_agreements la (cost=0.42..21469.40 rows=224331 width=13) (actual
time=0.034..297.113 rows=216440 loops=1)
Filter: ('2016-08-11'::date > due_date)
Rows Removed by Filter: 21806
Buffers: shared hit=227276
Planning time: 0.173 ms
Execution time: 310.509 ms
Index Scan using idx_loan_agreemnets_loan_id_cond_is_current_true on
loan_agreements la (cost=0.42..21469.40 rows=224331 width=13) (actual
time=0.031..286.212 rows=216440 loops=1)
Filter: ('2016-08-11'::date > due_date)
Rows Removed by Filter: 21806
Buffers: shared hit=227276
Planning time: 0.163 ms
Execution time: 299.831 ms
This makes me think, that IO is not my issue here and, honestly, I have no
clue what can be behind this.
What I noticed — queries do experience this kind of hiccups from time to
time. CPU and IO monitoring shows no spikes at all, CPU is below 40% all
the time.
Currently I am trying to find out ways how to track down what's going on
here.
Still — thanks everyone for the feedback, it was valuable for me!
--
Victor Y. Yegorov
