1

I have a performance issue with a function and I would like to understand why. I am not used to read EXPLAIN results, so I am asking for your advise.

I have created a function that returns id based on search criterion:

scientific.selectChannels(_measurelabel := '{O3,SO2,NO2}', _siteid:='{41R001}', _networkid := '{RTU}')

It returns an array and takes less than 60ms to run:

'{120,122,125}'

When I perform this query, the answer is really slow:

WITH
D AS (
SELECT
    DISTINCT ON (ChannelId)
    ChannelId
   ,TimeValue
   ,FloatValue
FROM
    datastore.inline
WHERE
    -- ANY('{120,122,125}')
    channelId =  ANY(scientific.selectChannels(_measurelabel := '{O3,SO2,NO2}', _siteid:='{41R001}', _networkid := '{RTU}'))
    AND QualityCodeId = 6
    AND GranulityId = 1
    AND TimeValue >= date_trunc('day', now()::TIMESTAMP) AND TimeValue < date_trunc('day', now()::TIMESTAMP) + '1 day'::INTERVAL
ORDER BY
    ChannelId
   ,TimeValue DESC
)

SELECT
    D.*
   ,CM.ChannelUnitsId
   ,CM.MeasureLabel
   ,CM.SiteId
   ,CM.SiteLabel
FROM
    D JOIN scientific.channelMetadata AS CM ON (D.ChannelId = CM.ChannelId)

Query planer returns:

"Hash Join  (cost=12320.23..12331.54 rows=3 width=332) (actual time=9150.405..9150.463 rows=3 loops=1)"
"  Hash Cond: (s.channelid = d.channelid)"
"  CTE d"
"    ->  Unique  (cost=12191.27..12192.55 rows=1 width=20) (actual time=9146.634..9146.647 rows=3 loops=1)"
"          ->  Sort  (cost=12191.27..12191.91 rows=256 width=20) (actual time=9146.633..9146.644 rows=108 loops=1)"
"                Sort Key: inline.channelid, inline.timevalue DESC"
"                Sort Method: quicksort  Memory: 33kB"
"                ->  Bitmap Heap Scan on inline  (cost=197.79..12181.03 rows=256 width=20) (actual time=6729.253..9146.572 rows=108 loops=1)"
"                      Recheck Cond: ((timevalue >= date_trunc('day'::text, (now())::timestamp without time zone)) AND (timevalue < (date_trunc('day'::text, (now())::timestamp without time zone) + '1 day'::interval)))"
"                      Filter: ((qualitycodeid = 6) AND (granulityid = 1) AND (channelid = ANY (scientific.selectchannels('{41R001}'::text[], '{}'::text[], '{O3,SO2,NO2}'::text[], NULL::text[], '{RTU}'::text[], NULL::text[], NULL::text[], false))))"
"                      Rows Removed by Filter: 6132"
"                      Heap Blocks: exact=104"
"                      ->  Bitmap Index Scan on idx_inline_timevalue  (cost=0.00..197.73 rows=5729 width=0) (actual time=1.016..1.016 rows=6240 loops=1)"
"                            Index Cond: ((timevalue >= date_trunc('day'::text, (now())::timestamp without time zone)) AND (timevalue < (date_trunc('day'::text, (now())::timestamp without time zone) + '1 day'::interval)))"
"  ->  Sort  (cost=127.65..129.39 rows=694 width=450) (actual time=3.714..3.740 rows=694 loops=1)"
"        Sort Key: s.siteid, s.networkid, s.measureid, s.jokerid"
"        Sort Method: quicksort  Memory: 118kB"
"        CTE s"
"          ->  Hash Join  (cost=14.44..81.02 rows=694 width=182) (actual time=0.117..1.219 rows=694 loops=1)"
"                Hash Cond: ((c.unitsid)::text = (u.id)::text)"
"                ->  Hash Join  (cost=12.79..66.35 rows=694 width=150) (actual time=0.098..0.866 rows=694 loops=1)"
"                      Hash Cond: ((c.networkid)::text = (n.id)::text)"
"                      ->  Hash Join  (cost=11.43..55.45 rows=694 width=137) (actual time=0.088..0.644 rows=694 loops=1)"
"                            Hash Cond: ((c.siteid)::text = (s_1.id)::text)"
"                            ->  Hash Join  (cost=5.15..39.63 rows=694 width=122) (actual time=0.052..0.406 rows=694 loops=1)"
"                                  Hash Cond: ((c.measureid)::text = (m.id)::text)"
"                                  ->  Seq Scan on channel c  (cost=0.00..24.94 rows=694 width=97) (actual time=0.001..0.164 rows=694 loops=1)"
"                                  ->  Hash  (cost=3.40..3.40 rows=140 width=31) (actual time=0.047..0.047 rows=140 loops=1)"
"                                        Buckets: 1024  Batches: 1  Memory Usage: 16kB"
"                                        ->  Seq Scan on measure m  (cost=0.00..3.40 rows=140 width=31) (actual time=0.002..0.023 rows=140 loops=1)"
"                            ->  Hash  (cost=3.90..3.90 rows=190 width=22) (actual time=0.032..0.032 rows=101 loops=1)"
"                                  Buckets: 1024  Batches: 1  Memory Usage: 14kB"
"                                  ->  Seq Scan on site s_1  (cost=0.00..3.90 rows=190 width=22) (actual time=0.002..0.014 rows=101 loops=1)"
"                      ->  Hash  (cost=1.16..1.16 rows=16 width=17) (actual time=0.007..0.007 rows=18 loops=1)"
"                            Buckets: 1024  Batches: 1  Memory Usage: 9kB"
"                            ->  Seq Scan on network n  (cost=0.00..1.16 rows=16 width=17) (actual time=0.001..0.002 rows=18 loops=1)"
"                ->  Hash  (cost=1.29..1.29 rows=29 width=36) (actual time=0.013..0.013 rows=29 loops=1)"
"                      Buckets: 1024  Batches: 1  Memory Usage: 10kB"
"                      ->  Seq Scan on units u  (cost=0.00..1.29 rows=29 width=36) (actual time=0.003..0.009 rows=29 loops=1)"
"        ->  CTE Scan on s  (cost=0.00..13.88 rows=694 width=450) (actual time=0.119..1.839 rows=694 loops=1)"
"  ->  Hash  (cost=0.02..0.02 rows=1 width=20) (actual time=9146.650..9146.650 rows=3 loops=1)"
"        Buckets: 1024  Batches: 1  Memory Usage: 9kB"
"        ->  CTE Scan on d  (cost=0.00..0.02 rows=1 width=20) (actual time=9146.636..9146.649 rows=3 loops=1)"
"Planning time: 1.931 ms"
"Execution time: 9150.594 ms"

It takes about 10s fetching 3 rows. If I replace the function call by its hard-coded result '{120,122,125}', it takes less than 100ms. Query planer then returns:

"Hash Join  (cost=376.05..387.36 rows=3 width=332) (actual time=7.483..7.595 rows=3 loops=1)"
"  Hash Cond: (s.channelid = d.channelid)"
"  CTE d"
"    ->  Unique  (cost=247.94..248.37 rows=1 width=20) (actual time=0.172..0.194 rows=3 loops=1)"
"          ->  Sort  (cost=247.94..248.15 rows=87 width=20) (actual time=0.172..0.182 rows=108 loops=1)"
"                Sort Key: inline.channelid, inline.timevalue DESC"
"                Sort Method: quicksort  Memory: 33kB"
"                ->  Index Scan using uq_inline on inline  (cost=0.44..245.13 rows=87 width=20) (actual time=0.036..0.109 rows=108 loops=1)"
"                      Index Cond: ((qualitycodeid = 6) AND (channelid = ANY ('{120,122,125}'::integer[])) AND (granulityid = 1) AND (timevalue >= date_trunc('day'::text, (now())::timestamp without time zone)) AND (timevalue < (date_trunc('day'::text, (now( (...)"
"  ->  Sort  (cost=127.65..129.39 rows=694 width=450) (actual time=7.215..7.269 rows=694 loops=1)"
"        Sort Key: s.siteid, s.networkid, s.measureid, s.jokerid"
"        Sort Method: quicksort  Memory: 118kB"
"        CTE s"
"          ->  Hash Join  (cost=14.44..81.02 rows=694 width=182) (actual time=0.225..2.351 rows=694 loops=1)"
"                Hash Cond: ((c.unitsid)::text = (u.id)::text)"
"                ->  Hash Join  (cost=12.79..66.35 rows=694 width=150) (actual time=0.190..1.661 rows=694 loops=1)"
"                      Hash Cond: ((c.networkid)::text = (n.id)::text)"
"                      ->  Hash Join  (cost=11.43..55.45 rows=694 width=137) (actual time=0.173..1.279 rows=694 loops=1)"
"                            Hash Cond: ((c.siteid)::text = (s_1.id)::text)"
"                            ->  Hash Join  (cost=5.15..39.63 rows=694 width=122) (actual time=0.106..0.817 rows=694 loops=1)"
"                                  Hash Cond: ((c.measureid)::text = (m.id)::text)"
"                                  ->  Seq Scan on channel c  (cost=0.00..24.94 rows=694 width=97) (actual time=0.002..0.306 rows=694 loops=1)"
"                                  ->  Hash  (cost=3.40..3.40 rows=140 width=31) (actual time=0.096..0.096 rows=140 loops=1)"
"                                        Buckets: 1024  Batches: 1  Memory Usage: 16kB"
"                                        ->  Seq Scan on measure m  (cost=0.00..3.40 rows=140 width=31) (actual time=0.005..0.040 rows=140 loops=1)"
"                            ->  Hash  (cost=3.90..3.90 rows=190 width=22) (actual time=0.063..0.063 rows=101 loops=1)"
"                                  Buckets: 1024  Batches: 1  Memory Usage: 14kB"
"                                  ->  Seq Scan on site s_1  (cost=0.00..3.90 rows=190 width=22) (actual time=0.005..0.037 rows=101 loops=1)"
"                      ->  Hash  (cost=1.16..1.16 rows=16 width=17) (actual time=0.011..0.011 rows=18 loops=1)"
"                            Buckets: 1024  Batches: 1  Memory Usage: 9kB"
"                            ->  Seq Scan on network n  (cost=0.00..1.16 rows=16 width=17) (actual time=0.002..0.003 rows=18 loops=1)"
"                ->  Hash  (cost=1.29..1.29 rows=29 width=36) (actual time=0.027..0.027 rows=29 loops=1)"
"                      Buckets: 1024  Batches: 1  Memory Usage: 10kB"
"                      ->  Seq Scan on units u  (cost=0.00..1.29 rows=29 width=36) (actual time=0.007..0.016 rows=29 loops=1)"
"        ->  CTE Scan on s  (cost=0.00..13.88 rows=694 width=450) (actual time=0.228..3.590 rows=694 loops=1)"
"  ->  Hash  (cost=0.02..0.02 rows=1 width=20) (actual time=0.202..0.202 rows=3 loops=1)"
"        Buckets: 1024  Batches: 1  Memory Usage: 9kB"
"        ->  CTE Scan on d  (cost=0.00..0.02 rows=1 width=20) (actual time=0.175..0.199 rows=3 loops=1)"
"Planning time: 1.676 ms"
"Execution time: 7.734 ms"

Could someone explain why my function is hanging the process? Function is defined as follow:

CREATE OR REPLACE FUNCTION scientific.selectChannels(
    _siteid TEXT[] = '{%}',
    _measureid TEXT[] = '{}',
    _measurelabel TEXT[] = '{%}',
    _jokerid TEXT[] = NULL,
    _networkid TEXT[] = NULL,
    _sitetype TEXT[] = NULL,
    _tags TEXT[] = NULL,
    _inactive BOOLEAN = FALSE
)
RETURNS INTEGER[] AS
$selectChannels$

SELECT
array(
SELECT
    CM.ChannelId
FROM
    scientific.ChannelMetadata AS CM
WHERE
    (CM.SiteId ILIKE ANY(_siteid))
    AND ((CM.MeasureId ILIKE ANY(_measureid)) OR (CM.MeasureLabel LIKE ANY(_measurelabel)))
    AND ((CM.JokerId ILIKE ANY(_jokerid)) OR (_jokerid IS NULL))
    AND (CM.NetworkId ILIKE ANY(_networkid) OR (_networkid IS NULL))
    AND ((CM.SiteType ILIKE ANY(_sitetype)) OR (_sitetype IS NULL) OR (CM.SiteType IS NULL))
    AND ((array_lowercase(_tags) && array_lowercase(CM.Tags)) OR (_tags IS NULL) OR (CM.Tags IS NULL))
    AND (_inactive OR CM.ActiveFlag)
ORDER BY
    -- Do not alter this ORDER BY clause (Python API relies on this invariant: channels are ordered by id):
    CM.ChannelId
);

$selectChannels$
LANGUAGE SQL;

Where channelMetada is a VIEW merging 5 tables.

I can see that in the first run rows removed (I don't know how to interpret this message), but it may be part of the answer. The only things I think, is that instead of being computed once, my function is called several times and become the bottle neck of my query. I don't know how to solve this issue.

Questions are:

  • Is my function called more than once?
  • Must I change my function signature?
  • What am I doing wrong with this query?

Update

If I extract the array and recreate it in the query, performances are better from far. Why my function signature slow down the process?

[...]
channelId = ANY(array(SELECT scientific.selectChannels(_measurelabel := '{O3,SO2,NO2}', _siteid:='{41R001}', _networkid := '{RTU}')))
[...]
Improve this question

1 Answer 1

Reset to default
4

Is my function called more than once?

Yes it is.

It is called for each of the 108 rows that are returned by the CTE. Actually you are lucky that the condition on the TimeValue column can be resolved by an index, otherwise your function would have been called once for each of the 6240 rows in the table inline, not just the 108 that are selected by the other part of the where condition.

As your function does not depend on any of the values that are retrieved from the table, you might be able to improve this by putting the result into yet another CTE:

WITH func_result (channels) AS (
   select scientific.selectChannels(_measurelabel := '{O3,SO2,NO2}', _siteid:='{41R001}', _networkid := '{RTU}')
), D AS (
  SELECT DISTINCT ON (ChannelId) ChannelId ,TimeValue, FloatValue
  FROM datastore.inline
  WHERE 
    channelId = ANY( (select channels from func_result)::int[] ) 
    AND QualityCodeId = 6
    AND GranulityId = 1
    AND TimeValue >= date_trunc('day', now()::TIMESTAMP) AND TimeValue < date_trunc('day', now()::TIMESTAMP) + '1 day'::INTERVAL
  ORDER BY ChannelId, TimeValue DESC
)
SELECT
    D.*
   ,CM.ChannelUnitsId
   ,CM.MeasureLabel
   ,CM.SiteId
   ,CM.SiteLabel
FROM
    D JOIN scientific.channelMetadata AS CM ON (D.ChannelId = CM.ChannelId)

Instead of 

FROM datastore.inline
WHERE channelId = ANY( (select channels from func_result)::int[] )

you could also use:

FROM datastore.inline
   JOIN func_result f on channelid = any(f.channels)
WHERE QualityCodeId = 6
  AND GranulityId = 1
  AND TimeValue ...

This should result in the function being called only once.

Theoretically you could trick Postgres in calling the function only once by defining it as immutable. But that would be a blatant lie (and a really dirty trick) as the function does do database lookups and functions that do that should never be defined as immutable.

Improve this answer
Sign up to request clarification or add additional context in comments.

Comments

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.