ADD executes unnecessary rowcount-query / serverside default logging

Blama

Registered Developer

Join Date: Sep 2009
Posts: 6817

ADD executes unnecessary rowcount-query / serverside default logging

20 Jan 2016, 06:28

Hi Isomorphic,

please see this server log you get when you add an entry to supplyItem in current BuiltInDS (v10.1p_2016-01-20):

Code:

=== 2016-01-20 15:09:33,056 [5-32] INFO  RequestContext - URL: '/builtinds/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.3; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0': Moz (Gecko) with Accept-Encoding header
=== 2016-01-20 15:09:33,058 [5-32] DEBUG IDACall - Header Name:Value pair: Cookie:isc_cState=ready; JSESSIONID=47yn5j8vs21l1muvdysweds2x; GLog=%7B%0A%20%20%20%20trackRPC%3Afalse%0A%7D
=== 2016-01-20 15:09:33,058 [5-32] DEBUG IDACall - Header Name:Value pair: DNT:1
=== 2016-01-20 15:09:33,058 [5-32] DEBUG IDACall - Header Name:Value pair: Host:127.0.0.1:8888
=== 2016-01-20 15:09:33,058 [5-32] DEBUG IDACall - Header Name:Value pair: Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2016-01-20 15:09:33,058 [5-32] DEBUG IDACall - Header Name:Value pair: Content-Length:1284
=== 2016-01-20 15:09:33,058 [5-32] DEBUG IDACall - Header Name:Value pair: Content-Type:application/x-www-form-urlencoded; charset=UTF-8
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - Header Name:Value pair: Accept-Language:de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - Header Name:Value pair: Pragma:no-cache
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - Header Name:Value pair: Connection:keep-alive
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - Header Name:Value pair: Referer:http://127.0.0.1:8888/BuiltInDS.html?gwt.codesvr=127.0.0.1:9997
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - Header Name:Value pair: User-Agent:Mozilla/5.0 (Windows NT 6.3; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - Header Name:Value pair: Cache-Control:no-cache
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - Header Name:Value pair: Accept-Encoding:gzip, deflate
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - session exists: 47yn5j8vs21l1muvdysweds2x
=== 2016-01-20 15:09:33,059 [5-32] DEBUG IDACall - remote user: null
=== 2016-01-20 15:09:33,081 [5-32] DEBUG XML - Parsed XML from (in memory stream): 11ms
=== 2016-01-20 15:09:33,082 [5-32] DEBUG ISCKeyedObjectPool - Borrowing object for 'transaction'
=== 2016-01-20 15:09:33,083 [5-32] DEBUG PoolableDataSourceFactory - Tried to create DataSource  of type 'transaction' but null was returned
=== 2016-01-20 15:09:33,084 [5-32] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'transaction' in the pooling flow
=== 2016-01-20 15:09:33,084 [5-32] DEBUG ISCKeyedObjectPool - Borrowing object for 'Object'
=== 2016-01-20 15:09:33,084 [5-32] DEBUG PoolableDataSourceFactory - Created DataSource 22 of type 'Object' and assigned it to thread qtp549073875-32
=== 2016-01-20 15:09:33,084 [5-32] DEBUG PoolableDataSourceFactory - Created DataSource 22 of type 'Object' in the pooling flow
=== 2016-01-20 15:09:33,084 [5-32] DEBUG PoolableDataSourceFactory - Activated DataSource 22 of type 'Object'
=== 2016-01-20 15:09:33,086 [5-32] DEBUG ISCKeyedObjectPool - Borrowing object for 'List'
=== 2016-01-20 15:09:33,089 [5-32] DEBUG PoolableDataSourceFactory - Created DataSource 23 of type 'List' and assigned it to thread qtp549073875-32
=== 2016-01-20 15:09:33,090 [5-32] DEBUG PoolableDataSourceFactory - Created DataSource 23 of type 'List' in the pooling flow
=== 2016-01-20 15:09:33,090 [5-32] DEBUG PoolableDataSourceFactory - Activated DataSource 23 of type 'List'
=== 2016-01-20 15:09:33,091 [5-32] DEBUG ISCKeyedObjectPool - Borrowing object for 'elem'
=== 2016-01-20 15:09:33,092 [5-32] DEBUG PoolableDataSourceFactory - Tried to create DataSource  of type 'elem' but null was returned
=== 2016-01-20 15:09:33,092 [5-32] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'elem' in the pooling flow
=== 2016-01-20 15:09:33,095 [5-32] DEBUG RPCManager - Processing 1 requests.
=== 2016-01-20 15:09:33,095 [5-32] DEBUG ISCKeyedObjectPool - Borrowing object for 'supplyItem'
=== 2016-01-20 15:09:33,095 [5-32] DEBUG PoolableDataSourceFactory - Activated DataSource 10 of type 'supplyItem'
=== 2016-01-20 15:09:33,097 [5-32] DEBUG DSRequest - Caching instance 10 of DS 'supplyItem' from DSRequest.getDataSource()
=== 2016-01-20 15:09:33,097 [5-32] DEBUG DSRequest - Caching instance 10 of DS supplyItem
=== 2016-01-20 15:09:33,098 [5-32] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
        nextShipment:new Date(1453244400000),
        itemName:"asd",
        SKU:"123",
        description:null,
        category:"asd",
        units:null,
        unitCost:123,
        inStock:null
    },
    operationConfig:{
        dataSource:"supplyItem",
        repo:null,
        operationType:"add",
        textMatchStyle:"exact"
    },
    componentId:"isc_DynamicForm_0",
    appID:"builtinApplication",
    operation:"supplyItem_add",
    oldValues:{
    },
    criteria:{
    }
}
=== 2016-01-20 15:09:33,099 [5-32] INFO  IDACall - Performing 1 operation(s)
=== 2016-01-20 15:09:33,103 [5-32] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2016-01-20 15:09:33,103 [5-32] DEBUG DeclarativeSecurity - DataSource supplyItem is not in the pre-checked list, processing...
=== 2016-01-20 15:09:33,104 [5-32] DEBUG AppBase - [builtinApplication.supplyItem_add] No userTypes defined, allowing anyone access to all operations for this application
=== 2016-01-20 15:09:33,105 [5-32] DEBUG AppBase - [builtinApplication.supplyItem_add] No public zero-argument method named '_supplyItem_add' found, performing generic datasource operation
=== 2016-01-20 15:09:33,107 [5-32] INFO  SQLDataSource - [builtinApplication.supplyItem_add] Performing add operation with
    criteria: {nextShipment:new Date(1453244400000),itemName:"asd",SKU:"123",description:null,category:"asd",units:null,unitCost:123,inStock:null}    values: {nextShipment:new Date(1453244400000),itemName:"asd",SKU:"123",description:null,category:"asd",units:null,unitCost:123.0,inStock:null}
=== 2016-01-20 15:09:33,111 [5-32] DEBUG SQLValuesClause - [builtinApplication.supplyItem_add] Sequences: {itemID=__default}
=== 2016-01-20 15:09:33,119 [5-32] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] DriverManager fetching connection for HSQLDB via jdbc url jdbc:hsqldb:hsql://localhost/isomorphic
=== 2016-01-20 15:09:33,120 [5-32] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] Passing JDBC URL only to getConnection
=== 2016-01-20 15:09:33,221 [5-32] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] makeObject() created an unpooled Connection '2093659823'
=== 2016-01-20 15:09:33,221 [5-32] DEBUG SQLConnectionManager - [builtinApplication.supplyItem_add] Borrowed connection '2093659823'
=== 2016-01-20 15:09:33,223 [5-32] DEBUG SQLTransaction - [builtinApplication.supplyItem_add] Started new HSQLDB transaction "2093659823"
=== 2016-01-20 15:09:33,223 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add] Setting DSRequest as being part of a transaction
=== 2016-01-20 15:09:33,223 [5-32] INFO  SQLDriver - [builtinApplication.supplyItem_add] Executing SQL query on 'HSQLDB' using connection '2093659823': INSERT INTO supplyItem (SKU, category, description, inStock, itemName, nextShipment, unitCost, units, itemID) VALUES ('123', 'asd', NULL, NULL, 'asd', '2016-01-20', 123.0, NULL, null)
=== 2016-01-20 15:09:33,238 [5-32] DEBUG SQLDriver - [builtinApplication.supplyItem_add] SequenceMode is not JDBC_DRIVER, skipping search for generated values
=== 2016-01-20 15:09:33,239 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add] add operation affected 1 rows
=== 2016-01-20 15:09:33,241 [5-32] DEBUG HSQLDBDriver - [builtinApplication.supplyItem_add] fetchLastRow data - primaryKeysPresent: {}sequencesNotPresent: [itemID]
=== 2016-01-20 15:09:33,241 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add] Setting DSRequest as being part of a transaction
=== 2016-01-20 15:09:33,241 [5-32] INFO  SQLDriver - [builtinApplication.supplyItem_add] Executing SQL query on 'HSQLDB' using connection '2093659823': CALL IDENTITY()
=== 2016-01-20 15:09:33,243 [5-32] INFO  SQLDataSource - [builtinApplication.supplyItem_add] primaryKeys: {itemID=3960}
=== 2016-01-20 15:09:33,244 [5-32] DEBUG DeclarativeSecurity - [builtinApplication.supplyItem_add] Processing security checks for DataSource null, field null
=== 2016-01-20 15:09:33,244 [5-32] DEBUG DeclarativeSecurity - [builtinApplication.supplyItem_add] DataSource supplyItem is not in the pre-checked list, processing...
=== 2016-01-20 15:09:33,245 [5-32] DEBUG AppBase - [builtinApplication.supplyItem_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2016-01-20 15:09:33,245 [5-32] DEBUG AppBase - [builtinApplication.supplyItem_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2016-01-20 15:09:33,246 [5-32] INFO  SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] Performing fetch operation with
    criteria: {itemID:3960}    values: {itemID:3960}
[B]=== 2016-01-20 15:09:33,248 [5-32] INFO  SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2016-01-20 15:09:33,249 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] Executing row count query: SELECT COUNT(*) FROM $defaultTableClause WHERE $defaultWhereClause
=== 2016-01-20 15:09:33,250 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] Eval'd row count query: SELECT COUNT(*) FROM supplyItem WHERE (supplyItem.itemID=3960)
=== 2016-01-20 15:09:33,250 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] Setting DSRequest as being part of a transaction
=== 2016-01-20 15:09:33,250 [5-32] INFO  SQLDriver - [builtinApplication.supplyItem_add, builtinApplication.null] Executing SQL query on 'HSQLDB' using connection '2093659823': SELECT COUNT(*) FROM supplyItem WHERE (supplyItem.itemID=3960)
=== 2016-01-20 15:09:33,253 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] Using SQL Limit query
=== 2016-01-20 15:09:33,253 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] SQL windowed select rows 0->-1, result size 1. Query: SELECT LIMIT 0 1  supplyItem.itemID, supplyItem.itemName, supplyItem.SKU, supplyItem.description, supplyItem.category, supplyItem.units, supplyItem.unitCost, supplyItem.inStock, supplyItem.nextShipment FROM supplyItem WHERE (supplyItem.itemID=3960)
=== 2016-01-20 15:09:33,254 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] SQL windowed select rows 0->-1, result size 1. Query: SELECT LIMIT 0 1  supplyItem.itemID, supplyItem.itemName, supplyItem.SKU, supplyItem.description, supplyItem.category, supplyItem.units, supplyItem.unitCost, supplyItem.inStock, supplyItem.nextShipment FROM supplyItem WHERE (supplyItem.itemID=3960)
=== 2016-01-20 15:09:33,254 [5-32] DEBUG SQLDataSource - [builtinApplication.supplyItem_add, builtinApplication.null] Setting DSRequest as being part of a transaction
=== 2016-01-20 15:09:33,257 [5-32] INFO  DSResponse - [builtinApplication.supplyItem_add] DSResponse: List with 1 items
=== 2016-01-20 15:09:33,258 [5-32] DEBUG DSRequest - [builtinApplication.supplyItem_add] freeOnExecute is false for request of type fetch on DataSource supplyItem - not freeing resources!
=== 2016-01-20 15:09:33,258 [5-32] INFO  DSResponse - DSResponse: List with 1 items[/B]
=== 2016-01-20 15:09:33,258 [5-32] DEBUG DSRequest - freeOnExecute is false for request of type add on DataSource supplyItem - not freeing resources!
=== 2016-01-20 15:09:33,258 [5-32] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2016-01-20 15:09:33,259 [5-32] DEBUG SQLTransaction - Committing HSQLDB transaction "2093659823"
=== 2016-01-20 15:09:33,260 [5-32] DEBUG SQLTransaction - Committing HSQLDB transaction "2093659823"
=== 2016-01-20 15:09:33,260 [5-32] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2016-01-20 15:09:33,262 [5-32] DEBUG SQLTransaction - getConnection() looked for transactional connection for HSQLDB:  hashcode "2093659823"
=== 2016-01-20 15:09:33,262 [5-32] DEBUG SQLTransaction - Ending HSQLDB transaction "2093659823"
=== 2016-01-20 15:09:33,263 [5-32] DEBUG SQLConnectionManager - About to close JDBCConnection with hashcode "2093659823"
=== 2016-01-20 15:09:33,264 [5-32] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 10
=== 2016-01-20 15:09:33,264 [5-32] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 10
=== 2016-01-20 15:09:33,264 [5-32] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 10
=== 2016-01-20 15:09:33,264 [5-32] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 10 of type 'supplyItem'
=== 2016-01-20 15:09:33,264 [5-32] DEBUG DSRequest - Ignoring freeResources call because this is not a primary request!
=== 2016-01-20 15:09:33,264 [5-32] DEBUG DSRequest - Ignoring freeQueueResources call because this is not a primary request!
=== 2016-01-20 15:09:33,265 [5-32] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2016-01-20 15:09:33,265 [5-32] DEBUG DSRequest - Ignoring freeQueueResources call because they have already been freed
=== 2016-01-20 15:09:33,265 [5-32] INFO  Compression - /builtinds/sc/IDACall: 267 -> 221 bytes

As you can see the rowCount-query is executed for every add. As an ADD can only affect one row, this seems pointless.
Even though be query itself should be fast as normally the PK is indexed, this puts unnecessary load on the database.
Just using the real cacheSync-query should be enough as default action after ADD, if I'm not missing something here.

Regarding the logged data:
In my application I'd like to set the log-level for SQLDataSource to INFO as DEBUG is not needed in most cases. But I'd like to see all SQLs that are sent to the DB like they are sent.
As you can see, for the INSERT and the COUNT(*), there are INFO-logs with the actual statement. This is not the case for the data-SELECT, where there is twice the same row as DEBUG (timestamp 2016-01-20 15:09:33,253). Could you make one of those logs to be of INFO-severity?
Also the last bold line reads
"INFO DSResponse - DSResponse: List with 1 items". Shouldn't this be
"INFO DSResponse - [builtinApplication.supplyItem_add] DSResponse: List with 1 items", too, like a bit above?

Best regards
Blama

Tags: None

Isomorphic

Administrator

Join Date: May 2006

Posts: 54650
#2

20 Jan 2016, 18:02

We'll check out whether there are special reasons why we would need a row count for cache sync requests. That indeed looks like a simple optimization.

As far as the logging: selects issued as part of cache sync are intentionally logged at DEBUG level, as they are internal details and not even required in all DBs. If you are executing a DSRequest with operationType "fetch", the SQL is logged at INFO level, consistent will all other operations.

About the "builtinApplication.supplyItem_add" tag - this prefix is added to logs from the DataSource subsystem on down. The log you're looking at comes from the RPC subsystem, after the DataSource operation has completed and as we head into serialization code. So the absence of tag here is expected.
Comment
Isomorphic

Administrator

Join Date: May 2006

Posts: 54650
#3

21 Jan 2016, 23:39

We removed row count query from cache sync request, it was indeed unnecessary. This is available in nightly builds since Jan 22.
Comment
Blama

Registered Developer

Join Date: Sep 2009

Posts: 6817
#4

9 Apr 2016, 15:03

Hi Isomorphic,

the query is indeed not there anymore.

Thank you for the change,
Blama
Comment

Previous template Next

Announcement

ADD executes unnecessary rowcount-query / serverside default logging

Comment

Comment

Comment