Performance issue if linking ODBC datasource

[tomesc]

We access our database with a self-written resource-adapter/translator and are using the plsqlodbc driver (v9.6.5) for MS Access.

If we limit the metadata in the VDB it works fine so far, but if we provide a huge amount of tables and views (more than 1000 with many columns and indices) the linking of a single table in MS Access takes a long time, over 5 minutes in this case.

The log shows a long busy or hanging period (marked red):

15:40:53,108 INFO [org.teiid.COMMAND_LOG] (Worker3_QueryProcessorQueue230) +XGkYC3kBw59  START USER COMMAND:     startTime=2018-11-06 15:40:53.108       requestID=+XGkYC3kBw59.41       txID=null       sessionID=+XGkYC3kBw59  applicationName=ODBC    principal=user  vdbName=prodis  vdbVersion=1    sql=select pg_catalog.getOid(SYS.Columns.TableUID), cast(SYS.Columns.Position as short), cast((select p.value from SYS.Properties p where p.name = 'pg_type:oid' and p.uid = SYS.Columns.uid) as integer) from SYS.Columns where Name = ? and TableName = ? and SchemaName = ?

15:40:53,111 INFO [org.teiid.COMMAND_LOG] (Worker3_QueryProcessorQueue230) +XGkYC3kBw59  END USER COMMAND:       endTime=2018-11-06 15:40:53.111 requestID=+XGkYC3kBw59.41 txID=null sessionID=+XGkYC3kBw59 principal=user vdbName=prodis  vdbVersion=1    finalRowCount=1

15:40:53,124 INFO [org.teiid.COMMAND_LOG] (Worker3_QueryProcessorQueue231) +XGkYC3kBw59  END USER COMMAND:       endTime=2018-11-06 15:40:53.124 requestID=+XGkYC3kBw59.27 txID=null sessionID=+XGkYC3kBw59 principal=user vdbName=prodis  vdbVersion=1    finalRowCount=377

15:40:53,228 INFO [org.teiid.COMMAND_LOG] (NIO2) +XGkYC3kBw59    START USER COMMAND:     startTime=2018-11-06 15:40:53.228       requestID=+XGkYC3kBw59.42       txID=null       sessionID=+XGkYC3kBw59  applicationName=ODBC    principal=user  vdbName=prodis  vdbVersion=1    sql=select c.relname, i.indkey, i.indisunique, i.indisclustered, a.amname, c.relhasrules, n.nspname, c.oid, d.relhasoids, 0 from pg_catalog.pg_index i, pg_catalog.pg_class c, pg_catalog.pg_class d, pg_catalog.pg_am a, pg_catalog.pg_namespace n where d.relname = 'MYTABLE' and n.nspname = 'MYDB' and n.oid = d.relnamespace and d.oid = i.indrelid and i.indexrelid = c.oid and c.relam = a.oid order by i.indisprimary desc, i.indisunique, n.nspname, c.relname

15:47:38,024 INFO [org.teiid.COMMAND_LOG] (Worker4_QueryProcessorQueue431) +XGkYC3kBw59  START USER COMMAND:     startTime=2018-11-06 15:47:38.024       requestID=+XGkYC3kBw59.43       txID=null       sessionID=+XGkYC3kBw59  applicationName=ODBC    principal=user  vdbName=prodis  vdbVersion=1    sql=select pg_catalog.getOid(SYS.Columns.TableUID), cast(SYS.Columns.Position as short), cast((select p.value from SYS.Properties p where p.name = 'pg_type:oid' and p.uid = SYS.Columns.uid) as integer) from SYS.Columns where Name = ? and TableName = ? and SchemaName = ?

15:47:38,035 INFO [org.teiid.COMMAND_LOG] (Worker4_QueryProcessorQueue431) +XGkYC3kBw59  END USER COMMAND:       endTime=2018-11-06 15:47:38.035 requestID=+XGkYC3kBw59.43 txID=null sessionID=+XGkYC3kBw59 principal=user vdbName=prodis  vdbVersion=1    finalRowCount=1

If limited to few tables it is much faster:

16:44:53,209 INFO [org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue28) zPUVJ1g6Fx4M   END USER COMMAND:       endTime=2018-11-06 16:44:53.209 requestID=zPUVJ1g6Fx4M.27       txID=null       sessionID=zPUVJ1g6Fx4M  principal=user  vdbName=prodis  vdbVersion=1    finalRowCount=377

16:44:53,270 INFO [org.teiid.COMMAND_LOG] (NIO2) zPUVJ1g6Fx4M    START USER COMMAND:     startTime=2018-11-06 16:44:53.27        requestID=zPUVJ1g6Fx4M.42       txID=null       sessionID=zPUVJ1g6Fx4M  applicationName=ODBC    principal=user  vdbName=prodis  vdbVersion=1    sql=select c.relname, i.indkey, i.indisunique, i.indisclustered, a.amname, c.relhasrules, n.nspname, c.oid, d.relhasoids, 0 from pg_catalog.pg_index i, pg_catalog.pg_class c, pg_catalog.pg_class d, pg_catalog.pg_am a, pg_catalog.pg_namespace n where d.relname = 'MYTABLE' and n.nspname = 'MYDB' and n.oid = d.relnamespace and d.oid = i.indrelid and i.indexrelid = c.oid and c.relam = a.oid order by i.indisprimary desc, i.indisunique, n.nspname, c.relname

16:44:55,792 INFO [org.teiid.COMMAND_LOG] (Worker2_QueryProcessorQueue30) zPUVJ1g6Fx4M   START USER COMMAND:     startTime=2018-11-06 16:44:55.792       requestID=zPUVJ1g6Fx4M.43       txID=null       sessionID=zPUVJ1g6Fx4M  applicationName=ODBC    principal=user  vdbName=prodis  vdbVersion=1    sql=select pg_catalog.getOid(SYS.Columns.TableUID), cast(SYS.Columns.Position as short), cast((select p.value from SYS.Properties p where p.name = 'pg_type:oid' and p.uid = SYS.Columns.uid) as integer) from SYS.Columns where Name = ? and TableName = ? and SchemaName = ?

16:44:55,802 INFO [org.teiid.COMMAND_LOG] (Worker2_QueryProcessorQueue30) zPUVJ1g6Fx4M   END USER COMMAND:       endTime=2018-11-06 16:44:55.801 requestID=zPUVJ1g6Fx4M.43 txID=null sessionID=zPUVJ1g6Fx4M principal=user vdbName=prodis  vdbVersion=1    finalRowCount=1

How can we improve the performance? The statement above seems to read the indices, maybe the decrease of indices would help? Any advice?

Thank's in advance.

Thomas

(WILDFLY / TEIID 9.2.3)

[shawkins]

Could you provide a representative VDB / ddl of this scenario?  It also doesn't need to actually utilize a source.

You should also try this on a later version of Teiid.

I'll see if I can reproduce this locally as well.

[shawkins]

I see related behavior upstream - but only for the first query against pg_index.  In 10.1.1 as part of [TEIID-5236] Document and update GeoServer/PG JDBC compatibility - JBoss Issue Tracker that view is materialized.  For 2000 tables each with an index, I see an initial query time of around 20 seconds, and subsequent timings in the 10s of milliseconds after the view is materialized.  So in prior releases with a lot of tables there will be an issue.

It looks like it's a good idea to make that a managed materialization such that it will load automatically.  I'll also test with even higher table counts to see if the initial load needs optimized.

[tomesc]

Thanks Steven, so it seems that I should test it with a newer TEIID version.

FYI, our limited datamodel results in 315 records in table "pg_catalog.pg_index". The response time will increase unusually if the column "indkey" is read.

select count(*) from pg_catalog.pg_index i; (response time: 66ms)

select i.oid,/*i.indkey,*/i.indisunique,i.indisclustered from pg_catalog.pg_index i; (response time: 69ms)

select i.oid,i.indkey,i.indisunique,i.indisclustered from pg_catalog.pg_index i; (response time: 14s)

Thomas

[shawkins]

Thanks Tomas,

This has been captured as [TEIID-5533] Improve odbc index metadata query performance - JBoss Issue Tracker

There are few related issues I need to address, but locally I'm seeing that I get the initial load down significantly - for my testing scenario the initial time is going from 100s to 3s.

This work will be made available in 11.x as well.

[tomesc]

Many thanks Steven, so I will look forward to the improved version.

Thomas