Recently I received a call that an APEX application was experiencing poor performance. They asked me to investigate what was happening on the database or in APEX itself.
First, I ask if they have any application logs that give some indication of where the problems might be. The answer came back no. There was no instrumentation or logging of their own in place to capture the activity; but we did have APEX debug enabled for some of the user actions.
So, I query the APEX dictionary for their application, user, and an approximate execution time when the users saw poor performance while debugging.
SELECT view_timestamp,
page_id,
elapsed_time,
page_view_type,
apex_session_id,
debug_page_view_id
FROM apex_workspace_activity_log
WHERE application_id = 100
AND apex_user = 'EXAMPLEUSER'
AND view_timestamp > TIMESTAMP '2018-10-02 15:00:00 -04:00'
AND view_timestamp < TIMESTAMP '2018-10-02 15:20:00 -04:00'
ORDER BY view_timestamp;
This yielded output as follows, with page 27 having nearly 9 seconds of time. Users reported other times where the page was even slower, however they were not running with DEBUG mode enabled then so this was the view I used for Step 1.
VIEW_TIMESTAMP PAGE_ID ELAPSED_TIME PAGE_VIEW_TYPE APEX_SESSION_ID DEBUG_PAGE_VIEW_ID 2018-10-02 15:11:48.691578 -04:00 20 3.121443 Rendering 307779930648678 801 2018-10-02 15:11:54.204761 -04:00 27 0.045717 Rendering 307779930648678 804 2018-10-02 15:11:54.651241 -04:00 27 0.03838 Ajax 307779930648678 807 2018-10-02 15:12:21.752888 -04:00 27 0.570659 Rendering 307779930648678 810 2018-10-02 15:12:22.267021 -04:00 27 0.031825 Ajax 307779930648678 813 2018-10-02 15:12:31.484343 -04:00 27 8.814905 Ajax 307779930648678 816
With this output, I then took the session id and debug view id into Step 2.
SELECT id,
message_timestamp,
elapsed_time,
execution_time,
message
FROM apex_debug_messages
WHERE application_id = 100
AND apex_user = 'EXAMPLEUSER'
AND session_id = 307779930648678
AND page_view_id = 816
ORDER BY message_timestamp;
APEX debugging is quite verbose, even at the default level 4, within those 8 seconds, over 11000 debug messages were recorded.
ID MESSAGE_TIMESTAMP ELAPSED_TIME EXECUTION_TIME MESSAGE
817021 2018-10-02 15:12:22.678806 -04:00 0.009403 0.00036 Session State: fetch from database (exact)
817022 2018-10-02 15:12:22.679166 -04:00 0.009761 0.000042 ... sentry+verification success
817023 2018-10-02 15:12:22.679208 -04:00 0.009802 0.000393 ...Session ID 307779930648678 can be used
...
{ 11000+ more rows }
...
828467 2018-10-02 15:12:31.483859 -04:00 8.814462 0.000292 Stop APEX Engine detected
828468 2018-10-02 15:12:31.484151 -04:00 8.814746 Final commit
Scanning through all of those messages wasn't going to be a very efficient diagnostic method, so I changed the ORDER BY to sort by execution time, with the slowest first.
SELECT id,
message_timestamp,
elapsed_time,
execution_time,
message
FROM apex_debug_messages
WHERE application_id = 100
AND apex_user = 'EXAMPLEUSER'
AND session_id = 307779930648678
AND page_view_id = 816
ORDER BY execution_time desc;
This immediately identified the main culprits.
ID MESSAGE_TIMESTAMP ELAPSED_TIME EXECUTION_TIME MESSAGE 828468 2018-10-02 15:12:31.484151 -04:00 8.814746 Final commit 825696 2018-10-02 15:12:26.932971 -04:00 4.263569 2.733338 SQL Statement prepared: ... found binds=1 817036 2018-10-02 15:12:22.683182 -04:00 0.013779 1.840666 SQL Statement prepared: ... found binds=2 821366 2018-10-02 15:12:25.143178 -04:00 2.473775 1.426806 SQL Statement prepared: ... found binds=2 ...
Thus 6 out of the total 8.8 seconds were spent in the application sql statements. The remainder of the time was primarily spent iterating over the result sets populating 3 series of chart data with several thousand data points.
In this case it appears APEX was executing their application quite quickly, the problem was their queries needed some work, possibly pruning the result sets down a little if the charting didn't really benefit from results of that granularity.
While a 9 second page was still considered slow, that performance was benefiting from caching by repeatedly running tests; thus further highlighting the need to focus on the queries.
What struck me most in this exercise was how quickly and easily it was to identify the problem areas. With just three queries, each of which only took a few seconds to run, the problem queries were clearly identified. Had it been a custom javascript function, or something in APEX itself, those too would have been similarly identified.
One of the hallmarks of a good architecture is how easy it is to diagnose. APEX gets an A+ here even before adding in any external instrumentation.