Announcement

Collapse
No announcement yet.
X
  • Filter
  • Time
Clear All
new posts

    Very strange performance issue, but important for me

    Hi Isomorphic,

    could you think of some change between v11.1p_2018-04-11 and v11.1p_2018-04-23 (< 2 weeks difference) that somehow can affect server/database query performance?
    I have two instances of almost the same code that behaves well in the older version and bad in the newer version.
    Both use the same DB with different data, but both with very little data, so this *should* not be the reason (but of course it can).

    Before I start now diving into debugging a hard-to-impossible-to-debug-issue, I wanted to ask if you could think of any change that might have happened in (most likely) DB-related code recently.

    The issue is that between those two log timestamps VERY much time (30 sec) passes. The query is complicated, but under no circumstances it may make so long.
    Code:
    [B]=== 2018-04-27 15:10:37,864 [c-20] INFO  SQLDriver - [builtinApplication.fetchMyPickedLeads] Executing SQL query on 'Oracle' using connection '579961934': SELECT ....
    === 2018-04-27 15:11:07,669 [c-20] INFO  DSResponse - DSResponse: List with 1 items[/B]
    === 2018-04-27 15:11:07,669 [c-20] INFO  DSResponse - DSResponse: List with 1 items
    === 2018-04-27 15:11:07,669 [c-20] DEBUG DataSourceDMI - Freeing resources in DataSourceDMI...
    === 2018-04-27 15:11:07,669 [c-20] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
    === 2018-04-27 15:11:07,669 [c-20] DEBUG SQLTransaction - Committing Oracle transaction "579961934"
    === 2018-04-27 15:11:07,670 [c-20] DEBUG RPCManager - DMI response, dropExtraFields: false
    === 2018-04-27 15:11:07,670 [c-20] DEBUG DataSourceDMI - Freeing QueueResources in DataSourceDMI
    === 2018-04-27 15:11:07,670 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4196
    === 2018-04-27 15:11:07,670 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4196
    === 2018-04-27 15:11:07,670 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1746
    === 2018-04-27 15:11:07,670 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1746
    === 2018-04-27 15:11:07,670 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1309
    === 2018-04-27 15:11:07,670 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1309
    === 2018-04-27 15:11:07,670 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4210
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4210
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1743
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1743
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4207
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4207
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4212
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4212
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 955
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 955
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1731
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1731
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1519
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1519
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4211
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4211
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 328
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 328
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4194
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4194
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1689
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4155
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 4155
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1689
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1695
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1695
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1701
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1701
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1540
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1540
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1707
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1707
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1713
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1713
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1497
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1497
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1719
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1719
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1636
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1636
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1725
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1725
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1307
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1307
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1005
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1005
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  hashcode "579961934"
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLTransaction - Ending Oracle transaction "579961934"
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1552
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1552
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1552
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
    === 2018-04-27 15:11:07,671 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 837
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 837
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 837
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1306
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1306
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1306
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1304
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1304
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1304
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1275
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1275
    === 2018-04-27 15:11:07,672 [c-20] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1275
    === 2018-04-27 15:11:07,672 [c-20] INFO  Compression - /villeroy-boch/lms/sc/IDACall: 3560 -> 1418 bytes
    A fast "yeah I have an idea" or "no, there definitely did not change anything related to this area" would be enough for now.

    Thank you & Best regards
    Blama

    #2
    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.

    Comment


      #3
      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

      Comment


        #4
        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

        Comment


          #5
          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.

          Comment

          Working...
          X