Thread: Runtime variations during day

Runtime variations during day

From

Carlos Henrique Reimer

Date:

13 February 2013, 21:43:00

Hi,

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


_________________________________________________________________________________________________________________________________________________________________________________________

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)


__________________________________________________________________________________________________________________________________________________________________________________________________


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 . Another reason we
rejected this hypothesis is that even if you run the query two times, both
took almost the same time.

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.

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

Thank you in advance!

Reimer

Re: Runtime variations during day

From

Joek Hondius

Date:

13 February 2013, 22:50:13

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:
>
> Hi,
>
> I`m trying to figure out why a query runs in 755ms in the morning and
> 20054ms (26x) in the evening.
>
>
_________________________________________________________________________________________________________________________________________________________________________________________
>
> 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)
>
>
>
__________________________________________________________________________________________________________________________________________________________________________________________________
>
>
> 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 . Another reason we rejected this hypothesis is that even
> if you run the query two times, both took almost the same time.
>
> 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.
>
> How could we determine why this difference in the response time?
>
> Thank you in advance!
>
> Reimer
>

Re: Runtime variations during day

From

Kevin Grittner

Date:

14 February 2013, 00:35:58

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

Re: Runtime variations during day

From

Tom Lane

Date:

14 February 2013, 00:54:00

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

Re: Runtime variations during day

From

Kevin Grittner

Date:

14 February 2013, 01:17:48

Tom Lane <tgl@sss.pgh.pa.us> wrote:=0A=0A> I'm wondering about cache effect=
s, ie memory already contains=0A> desired pages in the morning (perhaps as =
a side-effect of queries=0A> run overnight) and not so much by the evening.=
=A0 If so it's not=0A> clear that additional VACUUM activity would make thi=
ngs better.=0A>=0A> But in any case it's hard to diagnose this without EXPL=
AIN=0A> ANALYZE output.=0A=0AHe did show EXPLAIN OUTPUT results, which show=
ed an index scan in=0Athe morning and a seqscan in the evening.=A0 He also =
mentioned that=0Ahe doubted cache effects amounted to much because the data=
base was=0A40GB and the machine has 64GB.=0A=0Ahttp://www.postgresql.org/me=
ssage-id/CAJnnue1x6YYqKbvDQkMTonK62GZSPH-edPR4U7+LOt66M3s_Sw@mail.gmail.com=
=0A=0A-- =0AKevin Grittner=0AEnterpriseDB: http://www.enterprisedb.com=0ATh=
e Enterprise PostgreSQL Company

Re: Runtime variations during day

From

Jeff Janes

Date:

14 February 2013, 01:21:39

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

Re: Runtime variations during day

From

Carlos Henrique Reimer

Date:

14 February 2013, 01:23:44

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

Re: Runtime variations during day

From

Alvaro Herrera

Date:

14 February 2013, 01:33:01

Carlos Henrique Reimer wrote:

> Another example that could help is this seqscan:
>=20
> explain analyze select sittrib8 from iparq.arript where sittrib8=3D33;
>=20
> In the evening:
> Fri Feb  8 14:00:01 BRST 2013
>=20
>                                                         QUERY
> PLAN
> -----------------------------------------------------------------------=
---------------------------------------------------
>  Seq Scan on arript  (cost=3D100000000.00..100469613.21 rows=3D1 width=3D=
2)
> (actual time=3D198047.253..198047.253 rows=3D0 loops=3D1)
>    Filter: (sittrib8 =3D 33)
>  Total runtime: 198047.303 ms
> (3 rows)
>=20
>=20
> In the morning:
> Fri Feb  8 10:51:01 BRST 2013
>                                                        QUERY
> PLAN
> -----------------------------------------------------------------------=
-------------------------------------------------
>  Seq Scan on arript  (cost=3D100000000.00..100469607.58 rows=3D1 width=3D=
2)
> (actual time=3D11982.597..11982.597 rows=3D0 loops=3D1)
>    Filter: (sittrib8 =3D 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.

--=20
=C1lvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

Re: Runtime variations during day

From

Kevin Grittner

Date:

14 February 2013, 01:34:43

Carlos Henrique Reimer <carlos.reimer@opendb.com.br> wrote:=0A=0A> Anyway i=
t does not seam related to statistics as the query plan=0A> is exactly the =
same for both scenarios, morning and evening:=0A=0A> Morning:=0A=0A>=A0=A0 =
Index Scan using pagpk_aux_mes, pagpk_aux_mes, pk_cadpag,=0A>=A0=A0=A0=A0 p=
k_cadpag, pk_cadpag, pagchavefunc00 on cadpag=0A=0A> Evening:=0A=0A>=A0=A0 =
Seq Scan on cadpag=0A=0AThose don't look exactly the same to me.=0A=0A> I'v=
e used this query just as an example but the general feeling=0A> is that ev=
erything takes more time to process in the evening.=0A> Evening is also the=
 period with more tasks in the the database.=0A=0AWell, if the resources ar=
e split among more processes, each process=0Awill take longer to run.=A0 No=
 surprise there.=A0 Of course, there=0Acould be some interaction -- queries=
 which do more work because=0Astatistics are out of date could contribute t=
o the slowdown of=0Aeverything else.=0A=0A-- =0AKevin Grittner=0AEnterprise=
DB: http://www.enterprisedb.com=0AThe Enterprise PostgreSQL Company

Re: Runtime variations during day

From

Fabrízio de Royes Mello

Date:

14 February 2013, 01:51:28

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
>> Blog sobre TI: http://fabriziomello.blogspot.com
>> Perfil Linkedin: http://br.linkedin.com/in/fabriziomello
>> Twitter: http://twitter.com/fabriziomello

Re: Runtime variations during day

From

Tom Lane

Date:

14 February 2013, 01:53:25

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

Re: Runtime variations during day

From

Carlos Henrique Reimer

Date:

14 February 2013, 02:16:38

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

Re: Runtime variations during day

From

Jeff Janes

Date:

14 February 2013, 02:34:20

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

Re: Runtime variations during day

From

Vick Khera

Date:

14 February 2013, 16:31:24

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.

Re: Runtime variations during day

From

Jeff Janes

Date:

14 February 2013, 20:03:26

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