3.0.2284 and TimescaleDB view 'idata'

Started by jermudgeon, October 02, 2019, 01:54:47 AM

Previous topic - Next topic

jermudgeon

Upgraded to 3.0.2284 and ran database upgrade script. DCIs migrated successfully.

Database performance seems much worse:

2019.10.01 14:46:11.901 *E* [db.driver          ] SQL query failed (Query = "SELECT idata_value,idata_timestamp FROM idata WHERE item_id=233275 ORDER BY idata_timestamp DESC LIMIT 1"): Internal error (call to PQsendQuery failed)
2019.10.01 14:46:11.901 *E* [db.driver          ] SQL query failed (Query = "SELECT idata_value,idata_timestamp FROM idata WHERE item_id=233276 ORDER BY idata_timestamp DESC LIMIT 1"): Internal error (call to PQsendQuery failed)

Graphs load slowly, etc.

Running 'explain select' on the above failed queries result in:

Limit  (cost=2080.96..2082.61 rows=1 width=14) (actual time=19.277..20.802 rows=1 loops=1)
  ->  Merge Append  (cost=2080.96..31743.08 rows=18037 width=14) (actual time=19.128..19.128 rows=1 loops=1)
        Sort Key: _hyper_7_5752_chunk.idata_timestamp DESC
        ->  Index Scan Backward using "5752_5752_idata_sc_default_pkey" on _hyper_7_5752_chunk  (cost=0.29..13.67 rows=11 width=8) (actual time=0.012..0.012 rows=0 loops=1)
              Index Cond: (item_id = 233258)
        ->  Index Scan Backward using "5755_5755_idata_sc_default_pkey" on _hyper_7_5755_chunk  (cost=0.29..13.67 rows=11 width=8) (actual time=0.004..0.004 rows=0 loops=1)
              Index Cond: (item_id = 233258)

and continuing on with index scan backward.

Note that running similar queries on the individual hypertables that make up the idata view are VERY fast.

Victor Kirhenshtein

Hi,

could you please post full explains for same queries run on idata and on idata_sc_default?

Best regards,
Victor

jermudgeon

Here are full EXPLAIN queries.


jermudgeon

FWIW, this may be related to what appears to be a DOS re: the database itself in netxms:

2019.10.02 13:06:24.280 *D* [db.cpool           ] Database connection pool exhausted (call from dcitem.cpp:1
511)                                                                                                        2019.10.02 13:06:24.280 *D* [db.cpool           ] Database connection pool exhausted (call from devdb.cpp:30


Pool minimum is 20.

jermudgeon

And while we're at it, there are some bogus queries in the query log:
2019-10-02 13:07:00.206 AKDT [28100] netxms@netxmsts ERROR:  cannot insert into view "tdata"
2019-10-02 13:07:00.206 AKDT [28100] netxms@netxmsts DETAIL:  Views containing UNION, INTERSECT, or EXCEPT are not automatically updatable.
2019-10-02 13:07:00.206 AKDT [28100] netxms@netxmsts HINT:  To enable inserting into the view, provide an INSTEAD OF INSERT trigger or an unconditional ON INSERT DO INSTEAD rule.
2019-10-02 13:07:00.206 AKDT [28100] netxms@netxmsts STATEMENT:  INSERT INTO tdata (item_id,tdata_timestamp,tdata_value) VALUES ($1,$2,$3)
2019-10-02 13:07:25.950 AKDT [28102] netxms@netxmsts ERROR:  cannot insert into view "tdata"
2019-10-02 13:07:25.950 AKDT [28102] netxms@netxmsts DETAIL:  Views containing UNION, INTERSECT, or EXCEPT are not automatically updatable.
2019-10-02 13:07:25.950 AKDT [28102] netxms@netxmsts HINT:  To enable inserting into the view, provide an INSTEAD OF INSERT trigger or an unconditional ON INSERT DO INSTEAD rule.
2019-10-02 13:07:25.950 AKDT [28102] netxms@netxmsts STATEMENT:  INSERT INTO tdata (item_id,tdata_timestamp,tdata_value) VALUES ($1,$2,$3)

jermudgeon

I believe I've tracked the pool exhaustion down. It's DCIs that are querying idata, which we've already shown is slow. I can disable them temporarily, but they are ultimately essential.

netxms@netxmsts STATEMENT:  SELECT max(idata_value::double precision) FROM idata WHERE item_id=$1 AND idata_timestamp BETWEEN $2 AND $3 AND idata_value~E'^\\d+(\\.\\d+)*$'
2019-10-02 13:13:24.901 AKDT [28860] netxms@netxmsts ERROR:  out of shared memory
2019-10-02 13:13:24.901 AKDT [28860] netxms@netxmsts HINT:  You might need to increase max_locks_per_transaction.
2019-10-02 13:13:25.043 AKDT [28099] netxms@netxmsts LOG:  duration: 10728.421 ms  bind <unnamed>: SELECT max(idata_value::double precision) FROM idata WHERE item_id=$1 AND idata_timestamp BETWEEN $2 AND $3 AND idata_value~E'^\\d+(\\.\\d+)*$'
2019-10-02 13:13:25.043 AKDT [28099] netxms@netxmsts DETAIL:  parameters: $1 = '219502', $2 = '1570049993', $3 = '1570050293'
2019-10-02 13:13:26.104 AKDT [28108] netxms@netxmsts LOG:  duration: 10927.128 ms  bind <unnamed>: SELECT min(idata_value::double precision) FROM idata WHERE item_id=$1 AND idata_timestamp BETWEEN $2 AND $3 AND idata_value~E'^\\d+(\\.\\d+)*$'
2019-10-02 13:13:26.104 AKDT [28108] netxms@netxmsts DETAIL:  parameters: $1 = '219506', $2 = '1570049993', $3 = '1570050293'
2019-10-02 13:14:31.489 AKDT [28107] netxms@netxmsts LOG:  duration: 144850.468 ms  statement: SELECT idata_value,idata_timestamp FROM idata WHERE item_id=222029 ORDER BY idata_timestamp DESC LIMIT 1