ODBC tracing

In ACE/IIB/WMB there are a number of statistics, events and log files that the runtime can?generate that can help with monitoring, trouble shooting and tuning IIB/ACE deployments.

In our product we currently use a few of these:

• We use trace files to help us generate code coverage reports for ESQL, msgflow and mapping files that are being executed. For ACE and for WMB/IIB the commands are slightly different. But in both cases we can create test coverage using the trace file output.
• We use timing statistics to help determine which msgflows consume the most resources so that teams can track the usage by msgflow over time, which is enabled using the mqsichangeresourcestats command. Using this data we can generate graphs of flow resource usage and also we have rules to flag nodes and flows that use the most resources.

One of the tools that we have been using recently is not a statistic or trace that is specific to IIB.

We have been using the trace generated by the ODBC driver that can be enabled which generates trace logging file. We can use this file to understand the SQL that ACE/IIB is executing.

In our case, we are using a local Postgres DB, so we were using this resource:

https://knowledgebase.progress.com/articles/Article/3059

This has allowed us to understand the runtime of what IIB is sending through to the underlying SQL processor, so we can see which ESQL code creates which SQL queries.

For example, when we write code like this (Example A):

SET Environment.Variables.DBResult2[] = SELECT * FROM Database.suburb_search AS S WHERE S.id = 123456;        

We get the trace file (summary) below:

[53119.845]	ok: - 'T' - SELECT 3

[53121.791]PQsendQuery: 000000A6C80330A0 'RELEASE _EXEC_SVP_000000A6C83C2F40;SAVEPOINT _EXEC_SVP_000000A6C83C2F40'

[53121.799]	ok: - 'C' - RELEASE

[53121.804]	ok: - 'C' - SAVEPOINT

[53121.901]PQprepare: 000000A6C80330A0 'SELECT S.id, S.suburb_name, S.comments FROM suburb_search S WHERE (S.id)=(123456)' plan=_PLAN000000A6C837BD80 nParams=0

[53121.907]	ok: - 'C' -?

[53121.909]	PQdescribePrepared: 000000A6C80330A0 plan_name=_PLAN000000A6C837BD80

[53121.913]	ok: - 'C' -?

[53121.917]	nParams=0

[53121.924]	nFields: 3

[53121.928]	fieldname='id', adtid=23, adtsize=4, atttypmod=-1 (rel,att)=(965791,1)

[53121.932]	fieldname='suburb_name', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(965791,2)

[53121.937]	fieldname='comments', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(965791,3)

[53121.943]PQexecPrepared: 000000A6C80330A0 plan=_PLAN000000A6C837BD80 nParams=0

[53121.949]	nFields: 3

[53121.952]	fieldname='id', adtid=23, adtsize=4, atttypmod=-1 (rel,att)=(965791,1)

[53121.955]	fieldname='suburb_name', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(965791,2)

[53121.958]	fieldname='comments', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(965791,3)

[53121.962]	ok: - 'T' - SELECT 0

[53122.576]PQsendQuery: 000000A6C80330A0 'select n.nspname, c.relname, a.attname, a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull, c.relhasrules, c.relkind, c.oid, pg_get_expr(d.adbin, d.adrelid), case t.typtype when 'd' then t.typbasetype else 0 end, t.typtypmod, c.relhasoids, '', c.relhassubclass from (((pg_catalog.pg_class c inner join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid = 965791) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname, attnum'

[53122.605]	nFields: 18
        

But when we write the code like this (Example B):

DECLARE lookup INTEGER;

SET lookup = 123456;

SET Environment.Variables.DBResult2[] =SELECT * FROM Database.test_param_only AS S WHERE S.id =?lookup;
        

We get a prepared statement being generated:

[44644.133]	ok: - 'T' - SELECT 3

[44645.552]PQsendQuery: 000000A6BE7B8040 'RELEASE _EXEC_SVP_000000A6CA5F1F50;SAVEPOINT _EXEC_SVP_000000A6CA5F1F50'

[44645.557]	ok: - 'C' - RELEASE

[44645.559]	ok: - 'C' - SAVEPOINT

[44645.575]PQprepare: 000000A6BE7B8040 'SELECT S.id, S.param_name, S.param_comments FROM test_param_only S WHERE (S.id)=($1)' plan=_PLAN000000A6C24E7560 nParams=1

[44645.580]	ok: - 'C' -?

[44645.581]	PQdescribePrepared: 000000A6BE7B8040 plan_name=_PLAN000000A6C24E7560

[44645.584]	ok: - 'C' -?

[44645.587]	nParams=1 23

[44645.591]	nFields: 3

[44645.593]	fieldname='id', adtid=23, adtsize=4, atttypmod=-1 (rel,att)=(1401498,1)

[44645.597]	fieldname='param_name', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(1401498,2)

[44645.601]	fieldname='param_comments', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(1401498,3)

[44645.655]PQsendQuery

[44645.660]	ok: - 'C' - RELEASE

[44645.663]	ok: - 'C' - SAVEPOINT

[44645.684]PQexecPrepared: 000000A6BE7B8040 plan=_PLAN000000A6C24E7560 nParams=1

[44645.687]	t '123456' OID=0

[44645.693]	nFields: 3

[44645.695]	fieldname='id', adtid=23, adtsize=4, atttypmod=-1 (rel,att)=(1401498,1)

[44645.698]	fieldname='param_name', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(1401498,2)

[44645.701]	fieldname='param_comments', adtid=1043, adtsize=-1, atttypmod=50 (rel,att)=(1401498,3)

[44645.704]	ok: - 'T' - SELECT 0

[44646.217]PQsendQuery: 000000A6BE7B8040 'select n.nspname, c.relname, a.attname, a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull, c.relhasrules, c.relkind, c.oid, pg_get_expr(d.adbin, d.adrelid), case t.typtype when 'd' then t.typbasetype else 0 end, t.typtypmod, c.relhasoids, '', c.relhassubclass from (((pg_catalog.pg_class c inner join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid = 1401498) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname, attnum'

[44646.241]	nFields: 18
        

So what we see above is that when the argument is provided as variable parameter (Example B), then a more generic prepared statement is created. One that could handle multiple invocations and provide performance improvements. While in the first example SQL (Example A) call above, a reusable prepared statement was not being created.

So the second method to call an SQL SELECT (Example B) could perform better against the DB if there are more then one SQL being executed with a similar signature, while the first style of coding did not.

So to help identify where this could be applied to your code, we create a new rule:

R444 – SELECT uses constant value. Could use parameterized value to allow caching prepared statement (WMB)

More information on our products and on pricing can be found on our website:

https://bettercodingtools.com

You can also reach me via email at:

[email protected]

Or contact me via the contact page on our website:

www.bettercodingtools.com/contact

Regards

Richard