Re: very slow execution of stored procedures

On 4/20/01, 2:31:29 PM, Vilson farias <vilson(dot)farias(at)digitro(dot)com(dot)br> wrote
regarding Re: [GENERAL] very slow execution of stored procedures:

> Richard,

> I've tried all your advices and still nothing.
> It's been very hard to me understand why this is happening. The only
> solution is to modify the stored procedure.

Debugging functions is not easy unfortunately. AFAIK in 7.0 the only way
to see what's going on is to turn the logging level up and rummage
through the logs after running the function.

>
--------------------------------------------------------------------------
--
> ----------------------------------------------------------

> bxs=# SET ENABLE_SEQSCAN = OFF;
> SET VARIABLE
> bxs=# SELECT finaliza_chamv2(1,65535,49644,'2001-04-17
11:50:55','2001-04-17
> 12:17:40', '0', 0, 0, 48, '', 0, 10, '2817107', 0, 261, 65535);
> finaliza_chamv2
> -----------------
> 0
> (1 row)

> Execution time = about 4s.

OK - so we haven't persuaded it to use the index.

>
--------------------------------------------------------------------------
--
> ----------------------------------------------------------

> This time I'm trying to remove timestamp conversions from where clause:

> CREATE FUNCTION finaliza_chamv2(INT4, INT4, INT4, CHAR(23), CHAR(23),
> CHAR(1),
> INT4, INT4, INT4, CHAR(23), INT4, INT4,
> CHAR(25),
> INT4, INT4, INT4) RETURNS int4 AS
> '
[comparing timestamps to char(23) and letting PG figure it out]
> '
> LANGUAGE 'plpgsql';

> Execution time : ?? (I was forced to abort after more than 1 minute
waiting
> and a lot of cpu was sucked while executing)

Sounds like PG is having trouble figuring out how to convert from
char(23) to timestamp.

> Note that execution time go back to 4seconds if I put the original stored
> procedure back.

> Here some info about my table and fast execution :

[psql query...]
> bxs-# WHERE cod_bxs = 1 AND
> bxs-# chave = 65535 AND
> bxs-# identificacao = 49644 AND
> bxs-# dt_inicial = TIMESTAMP('2001-04-17 12:12:00');
> NOTICE: QUERY PLAN:

> Index Scan using xpkcham_chamada on cham_chamada (cost=0.00..4.23 rows=1
> width=58)

OK - so here we are using the query.

> EXPLAIN

> bxs=# \d cham_chamada
> Table "cham_chamada"
> Attribute | Type | Modifier
> -----------------+-------------+----------
> cod_bxs | integer | not null
> chave | integer | not null
> identificacao | integer | not null
> dt_inicial | timestamp | not null
> indicadora | integer |
> cod_categoria | integer |
> identidadea | varchar(20) |
> dt_final | timestamp |
> juntor | integer |
> indicadorb | integer |
> identidadeb | varchar(20) |
> flg_chamada | char(1) |
> flg_liberacao | char(1) |
> temp_total | integer |
> ddd | smallint |
> cod_liberjuntor | integer |
> cod_resultcham | integer |
> cod_fds | integer |
> cifra_origem | integer |
> Indices: xie1cham_chamada,
> xie2cham_chamada,
> xpkcham_chamada

I take it xpkcham_chamada is a primary-key on the first 4 fields, which
would fit with the explain above.

> bxs=# SELECT COUNT(*) FROM cham_chamada;
> count
> --------
> 145978
> (1 row)

I guess it could take 4s to scan this many records versus using the
index, so that would be the difference.

>
--------------------------------------------------------------------------
--
> ----------------------------------------------------------
> I found a solution that uses index scan. I redone some parameters, check
out
> :

> CREATE FUNCTION finaliza_chamv2(INT4, INT4, INT4, TIMESTAMP, TIMESTAMP,
> CHAR(1),
> INT4, INT4, INT4, CHAR(23), INT4, INT4,
> CHAR(25),
> INT4, INT4, INT4) RETURNS int4 AS
[same function but passing timestamps in rather than converting them to
text]

> Now execution time is <1s. Ok, but I really would like to know what's
> happening to the older version.

Looks like the parser is getting confused by the timestamp(x)
conversions.

Because timestamp() is marked non-cachable, Postgres doesn't know it is
constant over the duration of the query and so scans every row in the
table re-calculating the timestamp each time.

When you use it in the fast psql query you call timestamp('constant')
which Postgres probably is clever enough to figure out as a constant.

In fact, if you used WHERE ... dt_inicial = timestamp('2001-04-17
12:12:00') in the function Postgres would probably figure it out.

There are two ways you could help Postgres to do the right thing:

1. Use another variable for the conversions:

...
DECLARE
...
ts_pdtinicial timestamp;
BEGIN
ts_pdtinicial := timestamp(pdtinicial);
...
WHERE
...
dt_inicial = ts_pdtinicial;
...

Hopefully this will simplify things for Postgres and it will decide it
can use the index.

2. Mark the timestamp() conversions as cachable
You need to find the entry in pg_proc which takes text and returns a
timestamp and update the proiscachable flag.
You'll need to be user postgres, I don't know if it will work and it
might break other things, so be careful.

HTH

- Richard Huxton