Announcement

**Isomorphic** · 27 Apr 2018, 16:56

There's not a change in this area that would explain this. In fact, there really almost nothing going on between those two logs except the activity of the JDBC Driver itself.

Using a profiler could give an idea of where the time is spent. Or watching the network to see when the query is fired and when it returns.

**Blama** · 2 May 2018, 06:10

Hi Isomorphic,

thanks a lot, this is what I assumed.

Does this also look OK? Two seconds spent before JDBC IMHO.

Code:

=== 2018-05-02 16:07:09,619 [c-70] DEBUG LMSIDACall - session exists: 81694B63397625E986088C2F95482790
=== 2018-05-02 16:07:09,619 [c-70] DEBUG LMSIDACall - remote user: Administrator
=== 2018-05-02 16:07:09,637 [c-70] DEBUG RPCManager - Processing 1 requests.
=== 2018-05-02 16:07:09,637 [c-70] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    criteria:{
        operator:"equals",
        fieldName:"AVAILABLE",
        value:true,
        _constructor:"AdvancedCriteria"
    },
    operationConfig:{
        dataSource:"T_COUNTRY",
        repo:null,
        operationType:"fetch",
        textMatchStyle:"substring"
    },
    sortBy:[
        "NAME_TRANSLATED"
    ],
    componentId:"isc_PickListMenu_4",
    appID:"builtinApplication",
    operation:"fetchDropdowndataCountry",
    oldValues:{
        operator:"equals",
        fieldName:"AVAILABLE",
        value:true,
        _constructor:"AdvancedCriteria"
    }
}
=== 2018-05-02 16:07:09,637 [c-70] INFO  LMSIDACall - Performing 1 operation(s)
=== 2018-05-02 16:07:09,637 [c-70] DEBUG AppBase - [builtinApplication.fetchDropdowndataCountry] No userTypes defined, allowing anyone access to all operations for this application
=== 2018-05-02 16:07:09,637 [c-70] DEBUG AppBase - [builtinApplication.fetchDropdowndataCountry] No public zero-argument method named '_fetchDropdowndataCountry' found, performing generic datasource operation
[B]=== 2018-05-02 16:07:09,637 [c-70] INFO  SQLDataSource - [builtinApplication.fetchDropdowndataCountry] Performing fetch operation with
        criteria: {_constructor:"AdvancedCriteria",criteria:[{fieldName:"TENANT_ID",value:36,operator:"equals"},{fieldName:"AVAILABLE",value:true,operator:"equals"}],operator:"and"}   values: {_constructor:"AdvancedCriteria",criteria:[{fieldName:"TENANT_ID",value:36,operator:"equals"},{fieldName:"AVAILABLE",value:true,operator:"equals"}],operator:"and"}
=== 2018-05-02 16:07:11,225 [c-70] INFO  SQLDataSource - [builtinApplication.fetchDropdowndataCountry] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause ORDER BY $defaultOrderClause[/B]
=== 2018-05-02 16:07:11,237 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 785 from Finalizer
=== 2018-05-02 16:07:11,257 [c-70] INFO  SQLDataSource - [builtinApplication.fetchDropdowndataCountry] 177: Executing SQL query on 'Oracle': SELECT T_COUNTRY.ID, T_COUNTRY.AVAILABLE, T_COUNTRY.ISO_3166_1_ALPHA_2, translation.gettranslation(T_COUNTRY.TENANT_ID, 'T_COUNTRY', T_COUNTRY.ID, 'NAME', 'de') AS NAME_TRANSLATED FROM T_COUNTRY WHERE ((T_COUNTRY.TENANT_ID = 36 AND T_COUNTRY.TENANT_ID IS NOT NULL) AND (T_COUNTRY.AVAILABLE = 'Y' AND T_COUNTRY.AVAILABLE IS NOT NULL)) ORDER BY NAME_TRANSLATED
=== 2018-05-02 16:07:11,258 [c-70] DEBUG SQLTransaction - [builtinApplication.fetchDropdowndataCountry] Started new Oracle transaction "1851297959"
=== 2018-05-02 16:07:11,258 [c-70] DEBUG SQLDataSource - [builtinApplication.fetchDropdowndataCountry] Setting DSRequest as being part of a transaction
=== 2018-05-02 16:07:11,258 [c-70] INFO  SQLDriver - [builtinApplication.fetchDropdowndataCountry] Executing SQL query on 'Oracle' using connection '1851297959': SELECT T_COUNTRY.ID, T_COUNTRY.AVAILABLE, T_COUNTRY.ISO_3166_1_ALPHA_2, translation.gettranslation(T_COUNTRY.TENANT_ID, 'T_COUNTRY', T_COUNTRY.ID, 'NAME', 'de') AS NAME_TRANSLATED FROM T_COUNTRY WHERE ((T_COUNTRY.TENANT_ID = 36 AND T_COUNTRY.TENANT_ID IS NOT NULL) AND (T_COUNTRY.AVAILABLE = 'Y' AND T_COUNTRY.AVAILABLE IS NOT NULL)) ORDER BY NAME_TRANSLATED
=== 2018-05-02 16:07:11,273 [c-70] INFO  DSResponse - DSResponse: List with 3 items
=== 2018-05-02 16:07:11,273 [c-70] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2018-05-02 16:07:11,274 [c-70] DEBUG SQLTransaction - Committing Oracle transaction "1851297959"
=== 2018-05-02 16:07:11,274 [c-70] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2018-05-02 16:07:11,275 [c-70] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  hashcode "1851297959"
=== 2018-05-02 16:07:11,275 [c-70] DEBUG SQLTransaction - Ending Oracle transaction "1851297959"
=== 2018-05-02 16:07:11,276 [c-70] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 177
=== 2018-05-02 16:07:11,276 [c-70] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 177
=== 2018-05-02 16:07:11,276 [c-70] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 177
=== 2018-05-02 16:07:11,276 [c-70] INFO  Compression - /growmatica/lms/sc/IDACall: 420 -> 266 bytes
=== 2018-05-02 16:07:11,317 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1506 from Finalizer
=== 2018-05-02 16:07:11,317 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1501 from Finalizer
=== 2018-05-02 16:07:11,317 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1484 from Finalizer
=== 2018-05-02 16:07:11,317 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1483 from Finalizer
=== 2018-05-02 16:07:11,317 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1433 from Finalizer
=== 2018-05-02 16:07:11,317 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 364 from Finalizer
=== 2018-05-02 16:07:11,349 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1519 from Finalizer
=== 2018-05-02 16:07:11,408 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1678 from Finalizer
=== 2018-05-02 16:07:11,408 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1636 from Finalizer
=== 2018-05-02 16:07:11,515 [izer] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1907 from Finalizer

Thank you & Best regards
Blama

**Blama** · 2 May 2018, 06:33

It's getting more weird:

Code:

=== 2018-05-02 16:20:01,853 [c-58] DEBUG LMSIDACall - session exists: 81694B63397625E986088C2F95482790
=== 2018-05-02 16:20:01,853 [c-58] DEBUG LMSIDACall - remote user: Administrator
=== 2018-05-02 16:20:01,854 [c-58] DEBUG RPCManager - Processing 1 requests.
=== 2018-05-02 16:20:01,854 [c-58] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
        RESELLER_ID:814,
        COUNTRY_ID:8302,
        COUNTRY_NAME_TRANSLATED:"Rum�nien"
    },
    operationConfig:{
        dataSource:"T_RESELLER_SALESAREA",
        repo:null,
        operationType:"add",
        textMatchStyle:"exact"
    },
    componentId:"isc_AddEditPartnerSalesarea_1_0",
    appID:"builtinApplication",
    operation:"T_RESELLER_SALESAREA_add",
    oldValues:{
        RESELLER_ID:814,
        COUNTRY_ID:8302,
        COUNTRY_NAME_TRANSLATED:"Rum�nien"
    },
    criteria:{
    }
}
=== 2018-05-02 16:20:01,854 [c-58] INFO  LMSIDACall - Performing 1 operation(s)
=== 2018-05-02 16:20:01,854 [c-58] DEBUG AppBase - [builtinApplication.T_RESELLER_SALESAREA_add] No userTypes defined, allowing anyone access to all operations for this application
=== 2018-05-02 16:20:01,854 [c-58] DEBUG AppBase - [builtinApplication.T_RESELLER_SALESAREA_add] No public zero-argument method named '_T_RESELLER_SALESAREA_add' found, performing generic datasource operation
=== 2018-05-02 16:20:01,854 [c-58] INFO  SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add] Performing add operation with
        criteria: {RESELLER_ID:814,COUNTRY_ID:8302,COUNTRY_NAME_TRANSLATED:"Rum�nien",CREATED_BY:"36",CREATED_AT:new Date(1525270801854),MODIFIED_BY:"36",MODIFIED_AT:new Date(1525270801854)}  values: {RESELLER_ID:814,COUNTRY_ID:8302,COUNTRY_NAME_TRANSLATED:"Rum�nien",CREATED_BY:"36",CREATED_AT:new Date(1525270801854),MODIFIED_BY:"36",MODIFIED_AT:new Date(1525270801854),TENANT_ID:36}
=== 2018-05-02 16:20:01,855 [c-58] INFO  SQLValuesClause - [builtinApplication.T_RESELLER_SALESAREA_add] Ignored data for non-existent or included columns: [COUNTRY_NAME_TRANSLATED]
=== 2018-05-02 16:20:01,855 [c-58] DEBUG SQLValuesClause - [builtinApplication.T_RESELLER_SALESAREA_add] Sequences: {ID=__default}
=== 2018-05-02 16:20:01,855 [c-58] DEBUG SQLTransaction - [builtinApplication.T_RESELLER_SALESAREA_add] Started new Oracle transaction "1851297959"
=== 2018-05-02 16:20:01,855 [c-58] DEBUG SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add] Setting DSRequest as being part of a transaction
[B]=== 2018-05-02 16:20:01,855 [c-58] INFO  SQLDriver - [builtinApplication.T_RESELLER_SALESAREA_add] Executing SQL query on 'Oracle' using connection '1851297959': INSERT INTO T_RESELLER_SALESAREA (COUNTRY_ID, CREATED_AT, CREATED_BY, MODIFIED_AT, MODIFIED_BY, RESELLER_ID, TENANT_ID, ID) VALUES (8302, TO_DATE('2018-05-02 16:20:01','YYYY-MM-DD HH24:MI:SS'), '36', TO_DATE('2018-05-02 16:20:01','YYYY-MM-DD HH24:MI:SS'), '36', 814, 36, T_RESELLER_SALESAREA_ID.NextVal)
=== 2018-05-02 16:20:26,559 [c-58] DEBUG SQLDriver - [builtinApplication.T_RESELLER_SALESAREA_add] SequenceMode is not JDBC_DRIVER, skipping search for generated values[/B]
=== 2018-05-02 16:20:26,559 [c-58] DEBUG SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add] add operation affected 1 rows
=== 2018-05-02 16:20:26,559 [c-58] DEBUG SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add] Setting DSRequest as being part of a transaction
=== 2018-05-02 16:20:26,559 [c-58] INFO  SQLDriver - [builtinApplication.T_RESELLER_SALESAREA_add] Executing SQL query on 'Oracle' using connection '1851297959': SELECT T_RESELLER_SALESAREA_ID.CurrVal FROM DUAL
=== 2018-05-02 16:20:26,560 [c-58] INFO  SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add] primaryKeys: {ID=727}
=== 2018-05-02 16:20:26,560 [c-58] INFO  SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add] Oracle getLastRow(): using default operationBinding
=== 2018-05-02 16:20:26,560 [c-58] DEBUG AppBase - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2018-05-02 16:20:26,560 [c-58] DEBUG AppBase - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2018-05-02 16:20:26,560 [c-58] INFO  SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] Performing fetch operation with
        criteria: {TENANT_ID:36,ID:"727"}       values: {TENANT_ID:36,ID:"727"}
=== 2018-05-02 16:20:26,561 [c-58] INFO  SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause$defaultAnsiJoinClause WHERE $defaultWhereClause
=== 2018-05-02 16:20:26,561 [c-58] DEBUG SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] JDBC driver windowed select rows 0->-1, result size 1. Query: SELECT T_RESELLER_SALESAREA.ID, T_RESELLER_SALESAREA.TENANT_ID, T_RESELLER_SALESAREA.CREATED_BY, T_RESELLER_SALESAREA.CREATED_AT, T_RESELLER_SALESAREA.MODIFIED_BY, T_RESELLER_SALESAREA.MODIFIED_AT, T_RESELLER_SALESAREA.RESELLER_ID, T_RESELLER_SALESAREA.COUNTRY_ID, T_RESELLER_SALESAREA.ADMINAREA, T_RESELLER_SALESAREA.ZIPCODE_FROM, T_RESELLER_SALESAREA.ZIPCODE_TO, T_RESELLER_SALESAREA.ZIPCODE_REGEX, T_RESELLER_SALESAREA.PRODUCT_ID, T_RESELLER.NAME AS RESELLERNAME, translation.gettranslation(T_COUNTRY.TENANT_ID, 'T_COUNTRY', T_COUNTRY.ID, 'NAME', 'de') AS COUNTRY_NAME_TRANSLATED, T_PRODUCT.NAME AS PRODUCTNAME FROM T_RESELLER_SALESAREA JOIN T_RESELLER ON T_RESELLER_SALESAREA.RESELLER_ID = T_RESELLER.ID JOIN T_COUNTRY ON T_RESELLER_SALESAREA.COUNTRY_ID = T_COUNTRY.ID LEFT OUTER JOIN T_PRODUCT ON T_RESELLER_SALESAREA.PRODUCT_ID = T_PRODUCT.ID WHERE (T_RESELLER_SALESAREA.TENANT_ID=36 AND T_RESELLER_SALESAREA.ID=727)
=== 2018-05-02 16:20:26,561 [c-58] DEBUG SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] Setting DSRequest as being part of a transaction
=== 2018-05-02 16:20:27,582 [c-58] DEBUG SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] Using paging strategy 'jdbcScroll' - scrolling to absolute position 1
=== 2018-05-02 16:20:27,582 [c-58] DEBUG SQLDataSource - [builtinApplication.T_RESELLER_SALESAREA_add, builtinApplication.null] Scrolling / positioning took 0ms
=== 2018-05-02 16:20:27,582 [c-58] INFO  DSResponse - [builtinApplication.T_RESELLER_SALESAREA_add] DSResponse: List with 1 items
=== 2018-05-02 16:20:27,582 [c-58] INFO  DSResponse - DSResponse: List with 1 items
=== 2018-05-02 16:20:27,582 [c-58] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2018-05-02 16:20:27,582 [c-58] DEBUG SQLTransaction - Committing Oracle transaction "1851297959"
=== 2018-05-02 16:20:27,583 [c-58] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  hashcode "1851297959"
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLTransaction - Ending Oracle transaction "1851297959"
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 2601
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1128
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1128
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 572
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 572
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 2602
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 2602
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 2601
=== 2018-05-02 16:20:27,583 [c-58] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 2601
=== 2018-05-02 16:20:27,584 [c-58] INFO  Compression - /growmatica/lms/sc/IDACall: 394 -> 296 bytes

The INSERT you can see is very very easy. Might this be related to anything else that comes into your mind?

The general setup of my application is as follows:

1 application, WARd per customer. Same client code for all customers, almost same server code for all customers. Only relevant difference is the different DB connection in server.properties.
About 20 instances of this WAR (~50 MB) deployed.
Very low load
At 0 sec of every minute (e.g. 16:25:00, 16:26:00) CRON-job WGET to a URL in order to send mails. Those are hit sequentially from one CRON Job, so no high load here. They all together finish normally in <5sec.
No changes to server.properties w.r.t. to pooling. Might this be an issue?

This is the relevant part of server.properties:

Code:

sql.defaultDatabase: Oracle
sql.useAnsiJoins: true

sql.Oracle.database.type: oracle
sql.Oracle.autoJoinTransactions: true
sql.Oracle.database.supportsSQLLimit: false

sql.Oracle.interface.credentialsInURL: true
sql.Oracle.interface.type: dataSource

sql.Oracle.driver: oracle.jdbc.pool.OracleDataSource
sql.Oracle.driver.serverName: localhost
sql.Oracle.driver.portNumber: 1521
sql.Oracle.driver.databaseName: DB11G
sql.Oracle.driver.user: xxx
sql.Oracle.driver.password: xxx

sql.Oracle.driver.driverType: thin
sql.Oracle.driver.networkProtocol: tcp
sql.Oracle.driver.context:

Best regards
Blama

**Isomorphic** · 2 May 2018, 13:02

This is very odd. The first log almost suggests SQL templating but the second is clearly after that. And there continue to be no recent changes that have anything to do with these areas.

The only thing that comes to mind is JVM JIT compilation - perhaps you made a configuration change or switched JVM recently.

And again we would recommend profiling to dig deeper.

Announcement

Very strange performance issue, but important for me

Comment

Comment

Comment

Comment