Improvements to SQL Logging in Payara Server 173

Originally published on 13 Oct 2017
Last updated on 13 Oct 2017

A crucial component in many web applications is the use of a database. The chances of using JDBC directly or indirectly to access a relational database (through JPA or other ORM frameworks) on these applications are quite high. A common problem when dealing with relational databases is dealing with SQL queries or statements that take too much time to resolve, thus causing your application to be considered slow in producing results to the user. It's usually better to detect these issues preemptively, before sub-par performance damages your application, and Payara Server has you covered!

You can configure whether or not Payara Server detects and logs all slow SQL queries or statements when they are being executed through a JDBC Connection Pool. An SQL query or statement is considered slow if its execution time exceeds a configured threshold in seconds or milliseconds. To illustrate this with an example, let's say that you are working on a crucial application where every query needs to be executed in less than one second. You can configure the server to log all queries that don't fulfill this criteria using this simple command:

asadmin set domain.resources.jdbc-connection-pool.SamplePool.slow-query-threshold-in-seconds=1

When the server detects queries that fail to run under a second, it will log the SQL queries or statements, its execution time and the stack trace to track where in the application's code the query or statement was executed:

[#|2017-10-02T12:30:11.181+0000|WARNING|Payara 4.1|javax.enterprise.resource.sqltrace.com.sun.gjc.util|_ThreadID=61;_ThreadName=http-listener-1(2);_TimeMillis=1454366369289;_LevelValue=900;|
SQL Query Exceeded Threshold Time: 1000(ms): Time Taken: 20000(ms)
Query was SELECT ID, DATEOFBIRTH, EMAIL, NAME, USERNAME FROM USERS;
 
java.lang.Exception: Stack Trace shows code path to SQL at fish.payara.jdbc.SlowSQLLogger.sqlTrace(SlowSQLLogger.java:123)
 at com.sun.gjc.util.SQLTraceDelegator.sqlTrace(SQLTraceDelegator.java:122) at com.sun.gjc.spi.jdbc40.ProfiledConnectionWrapper40$1.invoke(ProfiledConnectionWrapper40.java:448)
 at com.sun.proxy.$Proxy265.executeQuery(Unknown Source) at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeSelect(DatabaseAccessor.java:1009)
 at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:644)
 at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:560)
 at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2055)
 at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:570)
 at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:242)
 at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:228)
 at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:299)
 at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectAllRows(DatasourceCallQueryMechanism.java:694)
 at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRowsFromTable(ExpressionQueryMechanism.java:2740)
 at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectAllRows(ExpressionQueryMechanism.java:2693)
 at org.eclipse.persistence.queries.ReadAllQuery.executeObjectLevelReadQuery(ReadAllQuery.java:559)
 at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1175)
 at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:904)
 at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1134)
 at org.eclipse.persistence.queries.ReadAllQuery.execute(ReadAllQuery.java:460) at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1222)
 at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2896)
 at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1857)
 at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1839)
 at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1804)
 at org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:258)
 at org.eclipse.persistence.internal.jpa.QueryImpl.getResultList(QueryImpl.java:473)
 at fish.payara.blog.controller.DatabaseViewBean.getUsers(DatabaseViewBean.java:35)

JDBC Monitoring Improvements

As part of Payara Server 4.1.2.173 release, the following monitoring statistics for JDBC connection pools have been added to enhance the user experience for SQL fine tuning, in addition to the logging events mentioned earlier:

FreqUsedSqlQueries
A list of the top 10 most used SQL queries or statements run through a JDBC connection pool.
SlowSqlQueries
A list of the top 10 slowest SQL queries or statements run through a JDBC connection pool. This statistic can be collected even if the JDBC connection pool hasn't been configured to log slow SQL statements.

Remember that to see these statistics, you need to enable the monitoring of JDBC connection pools for the server to a HIGH level first:

asadmin set configs.config.server-config.monitoring-service.module-monitoring-levels.jdbc-connection-pool=HIGH

Once this is done, you can query these statistics using any of the means available (REST interface, JMX monitoring tools, etc.). The following is a sample to get the most frequently used SQL queries via the monitoring REST API. Running the following command:

curl http://localhost:4848/monitoring/domain/server/resources/postgresPool/frequsedsqlqueries

Will provide the following result:

{
    "message": "",
    "command": "Monitoring Data",
    "exit_code": "SUCCESS",
    "extraProperties": {
        "entity": {
            "frequsedsqlqueries": {
                "unit": "List",
                "current": "%%%EOL%%%SELECT RE1_ID, RE1NM, RE1_MOE_ID FROM RE1 WHERE (RE1_MOE_ID = ?) executions: 10%%%EOL%%%SELECT RE2_ID, RE2NM FROM RE2 WHERE (RE2_ID = ?) executions: 10%%%EOL%%%SELECT t2.PAE_ID, t2.PAENM, t0.COE_ID, t1.SMOE_ID, t1.MOEATR1, t0.MOEDESC, t1.MOEVAL1, t0.COENM, t0.MOE_PAE_ID, t1.MOE_RE2_ID FROM MOE t0, PAE t2, SMOE t1 WHERE (t2.PAENM LIKE ? AND ((t0.MOE_PAE_ID = t2.PAE_ID) AND (t1.SMOE_ID = t0.COE_ID))) executions: 1",
                "lastsampletime": 1507310156484,
                "name": "FreqUsedSqlQueries",
                "description": "Most frequently used sql queries",
                "starttime": 1507309462522
            }
        },
        "childResources": {}
    }
}

You will notice that the format of the statistic is a simple string value of the list of the SQL queries accompanied by the number of times each query has been executed. Every record is separated by the %%%%EOL%%%(end-of-line) separator string:

SELECT  RE1_ID, RE1NM,  RE1_MOE_ID  FROM    RE1 WHERE   (RE1_MOE_ID =   ?)  executions: 10
SELECT  RE2_ID, RE2NM   FROM    RE2 WHERE   (RE2_ID =   ?)  executions: 10
SELECT  t2.PAE_ID,  t2.PAENM,   t0.COE_ID,  t1.SMOE_ID, t1.MOEATR1, t0.MOEDESC, t1.MOEVAL1, t0.COENM,   t0.MOE_PAE_ID,  t1.MOE_RE2_ID   FROM    MOE t0, PAE t2, SMOE    t1  WHERE   (t2.PAENM   LIKE    ?   AND ((t0.MOE_PAE_ID =   t2.PAE_ID)  AND (t1.SMOE_ID =   t0.COE_ID)))    executions: 1

And for the slow SQL queries statistic, each query will be accompanied by its worst execution time:

SELECT  t2.PAE_ID,  t2.PAENM,   t0.COE_ID,  t1.SMOE_ID, t1.MOEATR1, t0.MOEDESC, t1.MOEVAL1, t0.COENM,   t0.MOE_PAE_ID,  t1.MOE_RE2_ID   FROM    MOE t0, PAE t2, SMOE    t1  WHERE   (t2.PAENM   LIKE    ?   AND ((t0.MOE_PAE_ID =   t2.PAE_ID)  AND (t1.SMOE_ID =   t0.COE_ID)))    -   Slowest Execution   Time:   11ms
SELECT  RE1_ID, RE1NM,  RE1_MOE_ID  FROM    RE1 WHERE   (RE1_MOE_ID =   ?)  -   Slowest Execution   Time:   0ms
SELECT  RE2_ID, RE2NM   FROM    RE2 WHERE   (RE2_ID =   ?)  -   Slowest Execution   Time:   0ms

Summary

Remember to use these statistics if you're having trouble with your JDBC connections! Since they will always be available when the server's monitoring is enabled, you can constantly check what are the most used SQL queries and cross-check them with the slowest ones to determine which queries and statements need to be fine-tuned immediately. In the future, we will include additional SQL related statistics that can direct users to detect performance issues for their applications.

If you have any suggestions, feel free to let us know!

Improvements to SQL Logging in Payara Server 173

JDBC Monitoring Improvements

Summary

Related Posts

Comments