Runtime variations during day

Some issues are just funny.
Maybe lots of inserts deletes during the day?
Vacuum/analyze timing may have an impact on the planner?
Try again morning evening with vac/ana commands before the query.

Op 13-2-2013 19:42, Carlos Henrique Reimer schreef:

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> wrote:

I`m trying to figure out why a query runs in 755ms in the morning
and 20054ms (26x) in the evening.

I would make autovacuum settings much more aggressive, or schedule
periodic VACUUM and/or ANALYZE runs during the day.

database size is 40GB and memory 64GB

If you haven't already done so, I would use settings something like
this in postgresql.conf:

effective_cache_size = 32GB
seq_page_cost = 0.1
random_page_cost = 0.1
cpu_tuple_cost = 0.03

--
Kevin Grittner
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Kevin Grittner <kgrittn@ymail.com> writes:

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> wrote:

I`m trying to figure out why a query runs in 755ms in the morning
and 20054ms (26x) in the evening.

I would make autovacuum settings much more aggressive, or schedule
periodic VACUUM and/or ANALYZE runs during the day.

I'm wondering about cache effects, ie memory already contains desired
pages in the morning (perhaps as a side-effect of queries run overnight)
and not so much by the evening. If so it's not clear that additional
VACUUM activity would make things better.

But in any case it's hard to diagnose this without EXPLAIN ANALYZE
output.

regards, tom lane

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Tom Lane <tgl@sss.pgh.pa.us> wrote:

I'm wondering about cache effects, ie memory already contains
desired pages in the morning (perhaps as a side-effect of queries
run overnight) and not so much by the evening.  If so it's not
clear that additional VACUUM activity would make things better.

But in any case it's hard to diagnose this without EXPLAIN
ANALYZE output.

He did show EXPLAIN OUTPUT results, which showed an index scan in
the morning and a seqscan in the evening.  He also mentioned that
he doubted cache effects amounted to much because the database was
40GB and the machine has 64GB.

/messages/by-id/CAJnnue1x6YYqKbvDQkMTonK62GZSPH-edPR4U7+LOt66M3s_Sw@mail.gmail.com

--
Kevin Grittner
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

On Wed, Feb 13, 2013 at 10:42 AM, Carlos Henrique Reimer
<carlos.reimer@opendb.com.br> wrote:

Hi,

I`m trying to figure out why a query runs in 755ms in the morning and
20054ms (26x) in the evening.

Morning:

Sort (cost=151845.90..152304.21 rows=183322 width=62) (actual
time=706.676..728.080 rows=32828 loops=1)

( index scan plan )

Evening:

Sort (cost=321670.51..322111.45 rows=176377 width=62) (actual
time=20010.616..20031.887 rows=32840 loops=1)

(sequential scan)

So it believes the evening plan (seq scan) to be twice as slow as the
morning plan (index scan), but uses it anyway. So it must think the
morning plan would be even slower than that yet if it were run in the
evening.

Do you change your database's cost settings between morning and
evening (for example, in preparation for night-time batch processing)?

It would interesting see what it thinks of the index plan at the time
which it is choosing the sequential scan plan.
In the evening, can you rerun the query to get the sequential plan,
then "set enable_seqscan=off" and run it again to get the index plan
under the same conditions?

We initially suspected the reason could be that in the morning all data is
in memory and in the evening not all is in memory but as database size is
40GB and memory 64GB I would eliminate this hypothesis .

I wouldn't eliminate it for that reason. Just because you have 64GB
doesn't mean the kernel is willing to use all of it for file caching,
we've seen complaints that some kernels under some settings are not
adept at using that much memory. The reason to eliminate that theory
is that you get two different execution plans. PostgreSQL must think
something is different in order to change plan, and empirical degree
of cachedness is not something PostgreSQL is cognizant of, so it must
be something else that is different.

Another reason we
rejected this hypothesis is that even if you run the query two times, both
took almost the same time.

That doesn't mean much for the sequential scan plans. PostgreSQL has
a "ring buffer" mechanism that prevents sequential scans from shoving
everything else out of the cache. If the OS has some mechanism with a
similar goal in mind for the part of the cache it controls, then
sequential plans might not become well cached even after several
repeated executions.

Another possibility is a CPU bottleneck but as there is no indication of
this condition in the performance data collected by sar, top, vmstat we
assume the problem has another origin.

Could you show us some of that info? sar averages over ten minutes,
so a 20 second query probably isn't going to show up in it, unless you
repeat it endlessly.

How could we determine why this difference in the response time?

You could run "explain (analyze,buffers)", and also turn on track_io_timing,

Cheers,

Jeff

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Hi,

Anyway it does not seam related to statistics as the query plan is exactly
the same for both scenarios, morning and evening:

Will include the EXPLAIN ANALYZE again here:
_______________________________________________________________________________________________

Morning:
pgipm=# explain analyze SELECT XMAX, ANO, MES, CODFUNC, SEQFUNC, TIPOPGTO,
CODPD, HRSPD, VLRPD, MESANO, TIPOCALCFERIAS, VLRBASE FROM fparq.cadpag
where (ANO >'2013') or (ANO ='2013' and MES >'01') or (ANO ='2013' and
MES ='01' and CODFUNC >'0000029602') or (ANO ='2013' and MES ='01' and
CODFUNC ='0000029602' and SEQFUNC >'02') or (ANO ='2013' and MES ='01'
and CODFUNC ='0000029602' and SEQFUNC ='02' and TIPOPGTO > (' ')) or
(ANO ='2013' and MES ='01' and CODFUNC ='0000029602' and SEQFUNC ='02'
and TIPOPGTO = (' ') and CODPD >'000') order by ANO ASC, MES ASC,
CODFUNC ASC, SEQFUNC ASC, TIPOPGTO ASC, CODPD ASC;

QUERY PLAN

------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------------
Sort (cost=151845.90..152304.21 rows=183322 width=62) (actual
time=706.676..728.080 rows=32828 loops=1)
Sort Key: ano, mes, codfunc, seqfunc, tipopgto, codpd
-> Index Scan using pagpk_aux_mes, pagpk_aux_mes, pk_cadpag, pk_cadpag,
pk_cadpag, pagchavefunc00 on cadpag (cost=0.00..131521.88 rows=183322
width=62) (actual time=0.664..614.080 rows=32828 loops=1)
Index Cond: ((ano > 2013::smallint) OR ((ano = 2013::smallint) AND
(mes > 1::smallint)) OR ((ano = 2013::smallint) AND (mes = 1::smallint) AND
(codfunc > 29602::bigint)) OR ((ano = 2013::smallint) AND (mes =
1::smallint) AND (codfunc = 29602::bigint) AND (seqfunc > 2::smallint)) OR
((ano = 2013::smallint) AND (mes = 1::smallint) AND (codfunc =
29602::bigint) AND (seqfunc = 2::smallint) AND ((tipopgto)::text > '
'::text)) OR ((codfunc = 29602::bigint) AND (seqfunc = 2::smallint) AND
((tipopgto)::text = ' '::text) AND (codpd > 0::smallint) AND (ano =
2013::smallint) AND (mes = 1::smallint)))
Filter: ((ano > 2013::smallint) OR ((ano = 2013::smallint) AND
(mes > 1::smallint)) OR ((ano = 2013::smallint) AND (mes = 1::smallint) AND
(codfunc > 29602::bigint)) OR ((ano = 2013::smallint) AND (mes =
1::smallint) AND (codfunc = 29602::bigint) AND (seqfunc > 2::smallint)) OR
((ano = 2013::smallint) AND (mes = 1::smallint) AND (codfunc =
29602::bigint) AND (seqfunc = 2::smallint) AND ((tipopgto)::text > '
'::text)) OR ((ano = 2013::smallint) AND (mes = 1::smallint) AND (codfunc =
29602::bigint) AND (seqfunc = 2::smallint) AND ((tipopgto)::text = '
'::text) AND (codpd > 0::smallint)))
Total runtime: 755.878 ms
(6 rows)
__________________________________________________________________________________________________________________________________________________________________________________________________

Evening:

explain analyze SELECT XMAX, ANO, MES, CODFUNC, SEQFUNC, TIPOPGTO, CODPD,
HRSPD, VLRPD, MESANO, TIPOCALCFERIAS, VLRBASE FROM fparq.cadpag where
(ANO >'2013') or (ANO ='2013' and MES >'01') or (ANO ='2013' and MES
='01' and CODFUNC >'0000029602') or (ANO ='2013' and MES ='01' and
CODFUNC ='0000029602' and SEQFUNC >'02') or (ANO ='2013' and MES ='01'
and CODFUNC ='0000029602' and SEQFUNC ='02' and TIPOPGTO > (' ')) or
(ANO ='2013' and MES ='01' and CODFUNC ='0000029602' and SEQFUNC ='02'
and TIPOPGTO = (' ') and CODPD >'000') order by ANO ASC, MES ASC,
CODFUNC ASC, SEQFUNC ASC, TIPOPGTO ASC, CODPD ASC;

pgipm=# explain analyze SELECT XMAX, ANO, MES, CODFUNC, SEQFUNC, TIPOPGTO,
CODPD, HRSPD, VLRPD, MESANO, TIPOCALCFERIAS, VLRBASE FROM fparq.cadpag
where (ANO >'2013') or (ANO ='2013' and MES >'01') or (ANO ='2013' and
MES ='01' and CODFUNC >'0000029602') or (ANO ='2013' and MES ='01' and
CODFUNC ='0000029602' and SEQFUNC >'02') or (ANO ='2013' and MES ='01'
and CODFUNC ='0000029602' and SEQFUNC ='02' and TIPOPGTO > (' ')) or
(ANO ='2013' and MES ='01' and CODFUNC ='0000029602' and SEQFUNC ='02'
and TIPOPGTO = (' ') and CODPD >'000') order by ANO ASC, MES ASC,
CODFUNC ASC, SEQFUNC ASC, TIPOPGTO ASC, CODPD ASC;

QUERY
PLAN

------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
------------------------------------------------------------
--------------------------------------------------------------
Sort (cost=321670.51..322111.45 rows=176377 width=62) (actual
time=20010.616..20031.887 rows=32840 loops=1)
Sort Key: ano, mes, codfunc, seqfunc, tipopgto, codpd
-> Seq Scan on cadpag (cost=0.00..302166.75 rows=176377 width=62)
(actual time=18415.380..19915.294 rows=32840 loops=1)
Filter: ((ano > 2013::smallint) OR ((ano = 2013::smallint) AND
(mes > 1::smallint)) OR ((ano = 2013::smallint) AND (mes = 1::smallint) AND
(codfunc > 29602::bigint)) OR ((ano = 2013::smallint) AND (mes =
1::smallint) AND (codfunc = 29602::bigint) AND (seqfunc > 2::smallint)) OR
((ano = 2013::smallint) AND (mes = 1::smallint) AND (codfunc =
29602::bigint) AND (seqfunc = 2::smallint) AND ((tipopgto)::text > '
'::text)) OR ((ano = 2013::smallint) AND (mes = 1::smallint) AND (codfunc =
29602::bigint) AND (seqfunc = 2::smallint) AND ((tipopgto)::text = '
'::text) AND (codpd > 0::smallint)))
Total runtime: 20054.851 ms
(5 rows)

__________________________________________________________________________________________________________________________________________________________________________________________________

I've used this query just as an example but the general feeling is that
everything takes more time to process in the evening. Evening is also the
period with more tasks in the the database.

Another example that could help is this seqscan:

explain analyze select sittrib8 from iparq.arript where sittrib8=33;

In the evening:
Fri Feb 8 14:00:01 BRST 2013

QUERY
PLAN
--------------------------------------------------------------------------------------------------------------------------
Seq Scan on arript (cost=100000000.00..100469613.21 rows=1 width=2)
(actual time=198047.253..198047.253 rows=0 loops=1)
Filter: (sittrib8 = 33)
Total runtime: 198047.303 ms
(3 rows)

In the morning:
Fri Feb 8 10:51:01 BRST 2013
QUERY
PLAN
------------------------------------------------------------------------------------------------------------------------
Seq Scan on arript (cost=100000000.00..100469607.58 rows=1 width=2)
(actual time=11982.597..11982.597 rows=0 loops=1)
Filter: (sittrib8 = 33)
Total runtime: 11982.654 ms
(3 rows)

Thank you!

On Wed, Feb 13, 2013 at 7:53 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Kevin Grittner <kgrittn@ymail.com> writes:

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> wrote:

I`m trying to figure out why a query runs in 755ms in the morning
and 20054ms (26x) in the evening.

I would make autovacuum settings much more aggressive, or schedule
periodic VACUUM and/or ANALYZE runs during the day.

I'm wondering about cache effects, ie memory already contains desired
pages in the morning (perhaps as a side-effect of queries run overnight)
and not so much by the evening. If so it's not clear that additional
VACUUM activity would make things better.

But in any case it's hard to diagnose this without EXPLAIN ANALYZE
output.

regards, tom lane

--
Reimer
47-3347-1724 47-9183-0547 msn: carlos.reimer@opendb.com.br

Carlos Henrique Reimer wrote:

Another example that could help is this seqscan:

explain analyze select sittrib8 from iparq.arript where sittrib8=33;

In the evening:
Fri Feb 8 14:00:01 BRST 2013

QUERY
PLAN
--------------------------------------------------------------------------------------------------------------------------
Seq Scan on arript (cost=100000000.00..100469613.21 rows=1 width=2)
(actual time=198047.253..198047.253 rows=0 loops=1)
Filter: (sittrib8 = 33)
Total runtime: 198047.303 ms
(3 rows)

In the morning:
Fri Feb 8 10:51:01 BRST 2013
QUERY
PLAN
------------------------------------------------------------------------------------------------------------------------
Seq Scan on arript (cost=100000000.00..100469607.58 rows=1 width=2)
(actual time=11982.597..11982.597 rows=0 loops=1)
Filter: (sittrib8 = 33)
Total runtime: 11982.654 ms
(3 rows)

When I have seen things such as this, it's because the disks are busier
during the slow hours. Since there's not much activity in the morning,
the disks are idle and can scan the pages much more quickly.

--
Álvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> wrote:

Anyway it does not seam related to statistics as the query plan
is exactly the same for both scenarios, morning and evening:

Morning:

   Index Scan using pagpk_aux_mes, pagpk_aux_mes, pk_cadpag,
     pk_cadpag, pk_cadpag, pagchavefunc00 on cadpag

Evening:

   Seq Scan on cadpag

Those don't look exactly the same to me.

I've used this query just as an example but the general feeling
is that everything takes more time to process in the evening.
Evening is also the period with more tasks in the the database.

Well, if the resources are split among more processes, each process
will take longer to run.  No surprise there.  Of course, there
could be some interaction -- queries which do more work because
statistics are out of date could contribute to the slowdown of
everything else.

--
Kevin Grittner
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

On Wed, Feb 13, 2013 at 8:23 PM, Carlos Henrique Reimer <
carlos.reimer@opendb.com.br> wrote:

I've used this query just as an example but the general feeling is that
everything takes more time to process in the evening. Evening is also the
period with more tasks in the the database.

What do you mean with "more tasks in the database" ? What kind of tasks run
on your database overnight?

Best regards,

--
Fabrízio de Royes Mello
Consultoria/Coaching PostgreSQL

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> writes:

Will include the EXPLAIN ANALYZE again here:

-> Index Scan using pagpk_aux_mes, pagpk_aux_mes, pk_cadpag, pk_cadpag,
pk_cadpag, pagchavefunc00 on cadpag (cost=0.00..131521.88 rows=183322
width=62) (actual time=0.664..614.080 rows=32828 loops=1)

BTW, I just noticed this multiple-index annotation, which means that
either you're not using a community version of Postgres or else it's
8.0 or older (8.1 replaced that plan type with bitmap index scans).
In the latter case you'd be well advised to think about updating to
something that hasn't been out of support for more than two years.
In any case you're unlikely to get helpful advice when you fail to
mention that you're using a dinosaur release.

regards, tom lane

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Sorry for the confusion, the plans from morning and evening are really
different for sure.

Let me ensure with my team that postgresql configuration is not changed
between morning and evening and will recollect the data tomorrow.

On Wed, Feb 13, 2013 at 8:34 PM, Kevin Grittner <kgrittn@ymail.com> wrote:

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> wrote:

Anyway it does not seam related to statistics as the query plan
is exactly the same for both scenarios, morning and evening:

Morning:

Index Scan using pagpk_aux_mes, pagpk_aux_mes, pk_cadpag,
pk_cadpag, pk_cadpag, pagchavefunc00 on cadpag

Evening:

Seq Scan on cadpag

Those don't look exactly the same to me.

I've used this query just as an example but the general feeling
is that everything takes more time to process in the evening.
Evening is also the period with more tasks in the the database.

Well, if the resources are split among more processes, each process
will take longer to run. No surprise there. Of course, there
could be some interaction -- queries which do more work because
statistics are out of date could contribute to the slowdown of
everything else.

--
Kevin Grittner
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

--
Reimer
47-3347-1724 47-9183-0547 msn: carlos.reimer@opendb.com.br

On Wed, Feb 13, 2013 at 2:53 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> writes:

Will include the EXPLAIN ANALYZE again here:

-> Index Scan using pagpk_aux_mes, pagpk_aux_mes, pk_cadpag, pk_cadpag,
pk_cadpag, pagchavefunc00 on cadpag (cost=0.00..131521.88 rows=183322
width=62) (actual time=0.664..614.080 rows=32828 loops=1)

BTW, I just noticed this multiple-index annotation, which means that
either you're not using a community version of Postgres or else it's
8.0 or older (8.1 replaced that plan type with bitmap index scans).

I was curious about that string, never haven seen anything like it before.

That also explains why disable_cost is 1e8 rather than 1e10 (commit
b24c02ff2c2a6) in the later query/explains he posted.

Cheers,

Jeff

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

On Wed, Feb 13, 2013 at 4:35 PM, Kevin Grittner <kgrittn@ymail.com> wrote:

seq_page_cost = 0.1
random_page_cost = 0.1

Is there any gain in setting these to the same low value, as it would to
leave them both at 4? I thought they are just relative numbers to each
other. And unless you're on SSD, these numbers seem way too low, and
probably shouldn't be the same.

On Thu, Feb 14, 2013 at 5:31 AM, Vick Khera <vivek@khera.org> wrote:

On Wed, Feb 13, 2013 at 4:35 PM, Kevin Grittner <kgrittn@ymail.com> wrote:

seq_page_cost = 0.1
random_page_cost = 0.1

Is there any gain in setting these to the same low value, as it would to
leave them both at 4? I thought they are just relative numbers to each
other.

They are also relative to all the cpu cost parameters as well to each other.

And unless you're on SSD, these numbers seem way too low, and
probably shouldn't be the same.

He said all his data is in RAM. If that is truly the case, these
parameters are basically just more CPU-like parameters--representing
the cost of reading from main memory into on-CPU cache, for example.

Cheers,

Jeff

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general