sql.rows() in Groovy is running slow

Question

I'm supporting a Grails web application which shows different visuals for client using AmCharts. On one of the tabs there are three charts which each return the top ten, so only ten rows, from the database based on different measures. It takes 4-5 or sometimes even more time to finish. The query runs on the DB in under 10 seconds.

The following service method is called to return results:

List fetchTopPages(params, Map querySettings, String orderClause) {
    if(!((params['country'] && params['country'].size() > 0) || (params['brand'] && params['brand'].size() > 0) || (params['url'] && params['url'].size() > 0))) {
        throw new RuntimeException('Filters country or brand or url not selected.')
    }
    Sql sql = new Sql(dataSource)
    sql.withStatement { stmt -> stmt.fetchSize = 100 }
    Map filterParams = acquisitionService.getDateFilters(params, querySettings)
    ParamUtils.addWhereArgs(params, filterParams)
    String query = "This is where the query is"

    ParamUtils.saveQueryInRequest(ParamUtils.prettyPrintQuery(query, filterParams))
    log.debug("engagement pageviews-by-source query: " + ParamUtils.prettyPrintQuery(query, filterParams))
    List rows = sql.rows(query, filterParams)
    rows

}

After some investigation it was clear that the List rows = sql.rows(query, filterParams) line is the one that takes up this load time.

Has anyone expreienced this issue before? Why is sql.rows() taking so long when it's only returning 10 rows worth of results, and the query is runnig super fast on the DB side?

Additional info:

DB: FSL1D

Running following command on DB side: java -jar ojdbc5.jar - getversion returns: "Oracle 11.2.0.3.0 JDBC 3.0 compiled with JDK5 on Thu_Jul_11_15:41:55_PDT_2013 Default Connection Properties Resource Wed Dec 16 08:18:32 EST 2015"

Groovy Version: 2.3.7 Grails Version: 2.4.41 JDK: 1.7.0

Answer 1

My set up with Groovy Version: 2.3.6 JVM: 1.8.0_11 and Oracle 12.1.0.2.0 using driver ojdbc7.jar

Note the activation of the 10046 trace before the run to allow diagnostics.

import oracle.jdbc.pool.OracleDataSource

def ods = new OracleDataSource();
ods.setURL('url')
ods.setUser('usr')
ods.setPassword('pwd')

def con = ods.getConnection()
def sql = new groovy.sql.Sql(con)
sql.withStatement { stmt -> stmt.fetchSize = 100 }
def SQL_QUERY = """select id, col1  from table1 order by id"""
def offset = 150
def maxRows = 20
// activate trace 10046
con.createStatement().execute "alter session set events '10046 trace name context forever, level 12'"

def t = System.currentTimeMillis()
def rows = sql.rows(SQL_QUERY, offset, maxRows)
println "time1 : ${System.currentTimeMillis()-t} with offset ${offset} and maxRows ${maxRows}"

The examination of the trace shows that the stament is parsed and executed, this means if there is ORDER BY clause, all data is sorted.

The fetch size is used correctly and no more than required records are fetched - here 170 = 150 + 20. With fetch size 100 this is done in two steps (note the r parameter - number of fetched rows).

FETCH #627590664:c=0,e=155,p=0,cr=5,cu=0,mis=0,r=100,dep=0,og=1,plh=1169613780,tim=3898349818398
FETCH #627590664:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=70,dep=0,og=1,plh=1169613780,tim=3898349851458

So basically the only problem I see that the "skipped" data are passed over the network to the client (to be ignored there).

This could produce with very high offset lot of overhead (and take more time that the same query running interactively producing the first page).

But the best way to identify your problem is simple the enable the 10046 trace and see what going on. I'm using the level 12 which means you get also information about the waits in the DB and bind variables.