Simple Performance Diagnostics in APEX

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.

Leave a Reply