DB operations taking a long time - Compression Issue? (SGWT 6.0 eval 2016/12/15)

[pankaj.jain]

Hi,
We are adding several rows into Oracle DB under one user operation and below is the log and sever.properties.
We have two questions on this.
1. Why do we have so many commit statements in log. We have set sql.Oracle.autoJointTransactions to true.
Seems like all the insertions are going under same transaction but seeing many statements on commit is confusing.
Please confirm that it is indeed a single transaction.

2. At the end of the log on statement “2016-12-28 11:23:30,972 [55-5] INFO Compression - /mi/MarketIntelligence/sc/IDACall: 8221 -> 184 bytes” it is taking as high as 30-40 seconds before proceeding further.
Why is it taking that long? We suspect compression should not be that slow and it is doing something else behind the scenes.
How can we reduce this time? Also we see this long gap specially after insert operations.

server.properties

sql.Oracle.interface.credentialsInURL: false
sql.Oracle.driver.driverType: thin
sql.Oracle.driver.networkProtocol: tcp
sql.Oracle.useURL: true
sql.Oracle.driver: oracle.ucp.jdbc.PoolDataSourceFactory
sql.Oracle.driverName: oracle
sql.Oracle.autoJointTransactions: true
sql.Oracle.interface.type: driverManager
#Oracle Connection Pool Settings
sql.Oracle.pool.maxActive:20
sql.Oracle.pool.maxIdle:10
sql.Oracle.pool.maxWait:5000

Smartgwt.log

=== 2016-12-28 11:23:30,941 [55-5] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2016-12-28 11:23:30,941 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,943 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,943 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,943 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,943 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,944 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,944 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,944 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,944 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,944 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,945 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,945 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,945 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,945 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,945 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,946 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,946 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,946 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,946 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,946 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,947 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,947 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,947 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,947 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,947 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,948 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,948 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,948 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,948 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,949 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,949 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,949 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,949 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,949 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,950 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,950 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,950 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,951 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,951 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,952 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,952 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,952 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,953 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,953 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,953 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,953 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,953 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,954 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,954 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,954 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,954 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,954 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,955 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,955 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,955 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,955 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,955 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,956 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,956 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,956 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,965 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,965 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,966 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,966 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,966 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,966 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,967 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,967 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,967 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,967 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,967 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,968 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,968 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,968 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,968 [55-5] DEBUG SQLTransaction - Committing Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,968 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,968 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,969 [55-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-12-28 11:23:30,970 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  hashcode "1812403130"
=== 2016-12-28 11:23:30,970 [55-5] DEBUG SQLTransaction - Ending Oracle transaction "1812403130"
=== 2016-12-28 11:23:30,970 [55-5] DEBUG SQLConnectionManager - About to close connection with hashcode "1812403130"
=== 2016-12-28 11:23:30,970 [55-5] DEBUG PoolableSQLConnectionFactory - Executing pingTest 'select 1 from dual' on connection 1812403130
=== 2016-12-28 11:23:30,971 [55-5] DEBUG PoolableSQLConnectionFactory - Passivating connection '1812403130
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 87 of type 'history'
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,971 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
=== 2016-12-28 11:23:30,972 [55-5] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 87
=== 2016-12-28 11:23:30,972 [55-5] INFO  Compression - /mi/MarketIntelligence/sc/IDACall: 8221 -> 184 bytes
=== 2016-12-28 11:24:04,093 [55-6] DEBUG SQLDriver - [builtinApplication.cubeSave] SequenceMode is not JDBC_DRIVER, skipping search for generated values
=== 2016-12-28 11:24:04,094 [55-6] DEBUG SQLDataSource - [builtinApplication.cubeSave] add operation affected 16 rows
=== 2016-12-28 11:24:04,095 [55-6] DEBUG DSRequest - freeOnExecute is false for request of type add on DataSource cubeInsert - not freeing resources!

[Isomorphic]

1. Yes, it is a single transaction. You've done some damage to the default logging - first of all everything is being logged 3 times, second, at least in this log, all of the different logs about the actual inserts are either squelched or have been trimmed off. If those were still visible, it would be clear that all of the INSERTs are executed before the first commit. After all the operations were performed, it's possible we've got redundant calls to commit(), but this would be harmless when there were no intervening queries or updates (we'll check on this as a low priority thing).

2. That log from compression is the final log for the request. The next log is a new request (note the different thread id: "55-6" instead of "55-5". So there is no mysterious missing time here - the server was idle (not processing any requests).

[Blama]

Hi all,

pankaj.jain, the name of your setting is autoJoinTransactions (without the extra "t") see for example these docs.

Isomorphic: I also see the issue with the many unnecessary log entries (commits and the other three the OP posted in his logs) and wondered what these are about.
I'm not sure if this is only cluttering of log files or also an unnecessary DB roundtrip as I don't know how JDBC handles those commits if there is nothing to commit.

Best regards
Blama

[claudiobosticco]

I also see the issue with the many unnecessary log entries (commits and the other three the OP posted in his logs) and wondered what these are about.

same here

[Isomorphic]

It would be an extremely naive JDBC driver that actually performs a network operation when it clearly knows that no new operations have been performed. However, if anyone takes the trouble to verify this happens for a particular DB, let us know and it will increase the priority we give to checking on the redundant calls.

[pankaj.jain]

Blama, Wow! And to think of it, this has been there in our application since quite a few years now! Thanks for pointing it out, will fix it. Hope it won't lead to surprises!

Isomorphic, Thanks for the response. We will see where we can clean up the logs.

[Blama]

Hi pankaj.jain,

regarding your typo:
The system wide default is ANY_CHANGE w.r.t. this thread and the framework.properties file of my installation.
If you had set it to true, this would mean ALL according to these docs.

The difference between ANY_CHANGE and ALL will most likely not be noticeable in application behavior (but will be in the logs):
Docs excerpt:

• ANY_CHANGE: Bundle all requests into a transaction, including leading fetches, if there is any change operation in the queue. Since ANY_CHANGE is the default .properties setting, this is effectively the default behavior of an RPCManager where transaction policy has not been set.
• ALL: Bundle all requests into a transaction unconditionally.

Normally you would not need transactions if there is no change operation (=fetch-only) in the original queue - at least I can't think of one currently.

Isomorphic:
In the DataSource.autoJoinTransactions doc, in the sentence

If the setting is not defined at the DataSource-type level, we use the system global default, which is defined in server.properties as autoJoinTransactions.

, server.properties should be replaced by framework.properties, as it is set in this file.

Best regards
Blama

[Isomorphic]

Docs are already correct. framework.properties is an internal file, not meant to be modified. Any properties that you set should be set in server.properties, which will override the (again, unmodifiable) default settings that you can see in framework.properties.

[Blama]

Hi Isomorphic,

I got that, but only in combination with the information of this thread.
The (understanding) problem is to know what happens if there is nothing set in server.properties, like it is in my project or the BuiltInDs sample? Perhaps the sentence should read like this:

If the setting is not defined at the DataSource-type level, we use the system global default, which can be defined in server.properties as autoJoinTransactions and defaults to ANY_CHANGE

Best regards
Blama

[Isomorphic]

"is defined" in the current docs means this is where the developer would define it if they want to. Already accurate - it seems like you can only become confused on this point because you happen to be aware of the internal details of framework.properties.

[Blama]

Hi Isomorphic,

fine for me. I just had problems to find and reason the default in #7 (and I read all the docs before and knew that the default was described somewhere).
Perhaps you can add the 2nd part ("and defaults to ANY_CHANGE") which would have made it more easy for the OP to tell if his typo was relevant.
The only place where the default is mentioned otherwise is here.

Best regards
Blama