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