Database Operations with Slow Execution Phases

This page describes the recommended approach to database operations with slow execution phases, which is the case if:

The database is identified as the root cause for a slow interface (possibly using the Interface Performance and Debugging section as a guide)
You determined that the execute phase was the longest phase of your query execution operation
You optimized slow running queries in the database. Follow, Database Performance Best Practices if you need assistance in optimizing your database

Required Actors

Database Administrator
Network Administrator
Appian Administrator/Cloud Technical Support

Checklists

Database Administrator Checklist

Turn on Trace Database Logging (Ex: SQL Profiler in SQL Server)
Database trace logging should include request received time, response sent time and database locking information

Network Administrator Checklist

Turn debugging (i.e. tcpdump) for packets which are routed from Appian to the database

Appian Administrator Checklist

Set hibernate debugging to TRACE (log4j.logger.org.hibernate.SQL=DEBUG and log4j.logger.org.hibernate.type=TRACE) in appian_log4j.properties
Turn on expression trace logging.
Ensure that the network and database administrators activated network packet debugging and database debugging respectively

Analyzing the Log Files

Collect and collate the log files from Appian, the Database and the Network Administrator into a single table like the one below

Appian Example Log File

The difference between the last BasicBinder entry and the first BasicExtractor entry represent the round trip between Appian and the database.

2015-10-10 03:17:13,123 [Appian Work Item - 0 - ProcessExec01 : ExpressionGroupRequest] DEBUG org.hibernate.SQL - select top 1 this_.[customerid] as y0_ from [customer] this_ where (this_.[customerid]=?)
2015-10-10 03:17:13,321 [Appian Work Item - 0 - ProcessExec01 : ExpressionGroupRequest] TRACE org.hibernate.type.descriptor.sql.**BasicBinder** - binding parameter [1] as [INTEGER] - 12345
2015-10-10 03:17:57,123 [Appian Work Item - 0 - ProcessExec01 : ExpressionGroupRequest] TRACE org.hibernate.type.descriptor.sql.**BasicExtractor** - found [12345] as column [y0_]

You may need to run the trace logging during a time of low or no load if the amount of trace logging messages are unmanageable.

Example 1: Network Latency

Timing	Log Timestamp	Delta
Last BasicBinder statement	3:17:13
Router Receives Packet	3:17:13	0s Network Latency
Database Receives Query	3:17:33	20s Network Latency
Database Sends Response	3:17:35	2s Database Time
Router Receives Packet	3:17:35	0s Network Latency
First BasicExtractor Statement	3:17:57	22s Network Latency
Total Time	44s
Expression Trace Time	46s	2s Appian Overhead

Notice that a majority of the time is spent during transport of the request and the response back and forth between Appian and the database.

Contact the network administrator if a majority of the time is spent on the network

Example 2: Database Bottleneck

Timing	Log Timestamp	Delta
Last BasicBinder statement	3:17:13
Router Receives Packet	3:17:13	0s Network Latency
Database Receives Query	3:17:14	2s Network Latency
Database Sends Response	3:17:55	41s Database Time
Router Receives Packet	3:17:56	0s Network Latency
First BasicExtractor Statement	3:17:57	1s Network Latency
Total Time	44s
Expression Trace Time	46s	2s Appian Overhead

Notice that a majority of the time is spent on the database.

Contact the database administrator if a majority of the time is spent on the database Review the Database Performance Best Practices to improve the query execution times

Determine which area is responsible for the majority of the execution time.

Contact the Appian Cloud team if the majority of time is spent between Appian and the server hosting the VPN connection

Topics