At some point during the process of writing or maintaining an APEX application you will need to step into the world of debugging. APEX 5 has quite extensive debugging capabilities compared to its predecessors. This chapter will introduce you to the nuances of debugging in APEX.

Principles of Code Instrumentation

While it may seem odd to start a chapter on APEX debugging with a discussion about what makes good code instrumentation, it’s an important topic. In any development environment, the ability to quickly and easily see what your program is doing during execution is a critical component of debugging, especially when using a framework such as APEX where a large portion of the core code is beyond your capacity to change.

Proper code instrumentation has a set of precepts that should be followed. They include the following:

• Exists in every environment: Code instrumentation should be available in all environments, from development to production. Inserting instrumentation code in a development environment and then removing it before migrating to production not only takes away your ability to diagnose issues in production but also changes the core code, potentially introducing changes in functionality.
• Easy to enable and disable: The instrumentation should be easy for the programmer (and in certain cases, for the user) to enable and disable. Often code instrumentation is disabled by default and turned on only when there is a problem to diagnose.
• Always available: You should not need to recompile any code to turn on instrumentation. This is especially important in a production environment where on-the-fly code changes are often locked down tightly. Instead, instrumentation should be enabled by using a parameter or by adding a value to a table.
• Lightweight: The instrumentation should be “nonintrusive” in terms of the load it introduces to the process that it is measuring. The difference between timings when instrumentation is enabled and disabled should be minimal, if measurable at all.
• Integrated: Instrumentation should take advantage of any and all functionality that is built into its native environment, especially any functionality that will make problems easier to diagnose using other tools within the environment.

As you examine APEX 5’s debugging features in greater depth, you’ll see that APEX adheres to these precepts quite closely. I’ll also discuss how you can extend instrumentation into your own code to provide even more granular coverage than what APEX provides by itself.

Debugging Basics

To understand how debugging works, you need to take a quick tour of the core APEX engine. While this might seem like an unnecessary review for many people, it’s important because of the way APEX 5 manages and logs debug information.

Page Processing and Rendering

An APEX application is basically a group of pages that are linked together via buttons, hyperlinks, tabs, and so on. When a user navigates through the application, submits data, or requests to view an APEX page, there are two phases that the APEX engine goes through to provide the correct information to the user.

• ACCEPT (processing): This phase acts upon the request made by the user and, if appropriate, runs any defined validations, computations, processes, and branches. This includes setting session state and manipulating the underlying database tables.
• SHOW (rendering): This phase executes all appropriate code to render the page that was identified by the branch taken in the processing phase. Page rendering may also contain computations, processes, and branches, as well as the visual components that make up the page to be rendered.

The reason these phases are important to debugging is that APEX breaks down the logging of debug information into these same component parts. When the application server tier connects to the Oracle database that contains the APEX installation, it grabs a connection from the database connection pool and uses that to service the user’s APEX request. You can see this sequence in Figure 7-1.

The first phrase (ACCEPT) of servicing the user’s requests is to process the current page and the user’s input. Because the state of the connection from the pool cannot be guaranteed to match the requirements of the user’s APEX session, the first thing that APEX does is to alter the session, setting the desired NLS parameters and session settings. Figure 7-2 shows this portion of the processing.

Once the database session is in the proper state, APEX then begins checking to see whether the APEX session is still valid, checking to see whether the user has authorization to run the page, retrieving session state from the APEX data dictionary tables, setting session state that may have been altered by the user, and then running the page-processing components as defined in the metadata.

The last step of the processing is to decide which programmatic branch to take, which in turn decides which page will then be rendered and sent to the user. APEX always takes the first branch whose condition evaluates to true.

The second phase (SHOW) is to render the page identified by the branching section of the first phase. Because it is possible for page rendering to be called directly via a URL, this phase also walks through the process of altering the database session, retrieving the APEX session state from the metadata tables, and executing any required security checks. Figure 7-2 also shows the second phase of processing.

Once everything is set, APEX then walks through the process of rendering the page as defined in the APEX metadata and presenting that page to the user via the application server. Once the application server sees that the original request has been fully satisfied, it returns the Oracle database connection back to the connection pool to be reused.

The two phases can be mapped directly to the page editor, as shown in Figure 7-3. In the section on the left side of the page, the Rendering tab (1) equates to the SHOW phase, while the Processing tab (2) equates to the ACCEPT phase. Furthermore, each step is timed. Time is measured from the beginning of the current step to the beginning of the subsequent step. When debugging is turned on, these times are saved into the APEX dictionary along with the step detail.

The two-phase process of ACCEPT and SHOW iterates as the user navigates through and uses an APEX application. At some point, you may run into issues in development where you want to see exactly what is happening during the execution of either one, or both, of these phases. This is where APEX debugging comes in.

APEX debugging indicates to APEX that it should emit information about exactly what it’s doing during each of these phases. Unlike versions prior to 4.0, APEX does not emit the debug information into the page being processed or rendered but instead stores the full debug information in a set of tables in the APEX schema.

The newer approach is superior in that the debugging information persists beyond the lifetime of the rendered page so that you can view and analyze multiple runs of a single page, comparing and contrasting their debug output to see how changes you may have made might have affected the processing or performance.

Enabling Debug

Turning interactive debugging on is a straightforward process and can be done in one of two ways: via the Developer Toolbar or via the URL. The Developer Toolbar will be visible if you are running an application while you are also logged in to the application’s parent workspace as a developer. Figure 7-4 shows the Developer Toolbar and highlights the Debug button, which toggles Debug mode on and off.

You can also enable Debug mode by setting the DEBUG component of the APEX URL to either YES or LEVELn, where n is between 1 (most critical) and 9 (least critical). The following shows both the URL syntax and two examples of using the DEBUG component to enable Debug mode:

http://server/apex/f?p=App:Page:Session:Request:Debug:ClearCache:ItemNames:ItemValues

http://server/apex/f?p=100:1:23929384838429::YES:::
http://server/apex/f?p=100:1:23929384838429::LEVEL7:::

However, it is important to note that the ability to use either of these methods is controlled by an attribute in the application definition. Editing the application properties and navigating to the Properties region on the Definition tab will give you the ability to turn interactive debugging on or off. By default the attribute is set to disallow interactive debugging.

Even so, if you are running an application in development mode (that is to say, you are running the application while also logged in as a developer to the underlying workspace), debugging will always be available to you. While this may seem a bit odd, this fact will allow developers to interactively debug an application even if the application-level attribute is set to disallow debugging.

Figure 7-5 shows the Properties region and indicates the debugging attribute that should be changed to allow interactive debugging.

While it may be slightly confusing, once debugging is enabled via either the Developer Toolbar or the URL, the page will refresh, but you will notice nothing externally different about the page per se. Just remember that APEX stores the debug information in its data dictionary tables and does not emit it into the page being debugged.

There are two visual clues that will help you recognize when debug mode is active. If the Developer Toolbar is visible, the text of the debug button will now be changed to No Debug, as shown in Figure 7-6. Even if the Developer Toolbar isn’t visible, the URL will contain either YES or LEVELn in the debug position.

Debug Information

Once Debug mode is turned on and you have executed the steps you want to debug, such as running a report or submitting a page, you will then want to view the debug information that was captured during your session. There are a couple of different places where you can do this.

Developer Toolbar

It’s probably most common to want to view the debug information for the page you’re currently running immediately after turning debugging on. To do this, you again use the Developer Toolbar and click the View Debug button. A pop-up window will appear that lists all the page views for the page you are currently running. Figure 7-7 shows an example. The pop-up screen presents a high-level overview of all the views (or debug sessions) that have been captured for the current page. This is actually an interactive report with a filter set to show only views for the current page in the current application. You can alter the filters to show whatever combination you want.

From this screen you can click the View Identifier link to drill down into each view and see the detailed steps that APEX took to process and render the page. Figure 7-8 shows the detailed view for view ID 93320.

From the simple high-level view shown in Figure 7-7 you can actually see some interesting things. You can see the timeline of debug views that have been created for this page by looking at the Timestamp column, the action that was executed by looking at the Path Info column, the duration of each view by looking at the Seconds column, and the number of detailed debug entries for each view by looking at the Entries column.

Examining this particular example, you can see that one particular view (view ID 93320) took approximately around a second to complete while the others were less than one second.

Remember that there are two phases involved in processing a user request: ACCEPT and SHOW. The APEX debugging engine stores these two phases as separate “views” in the debug data. You can see from the overview report that the SHOW phases are all very fast, but the ACCEPT phases often take more time.

How much more time will depend upon how much “work” is being done in the processing of your page. The more work being done, the more likely it is that the page will take longer.

You can drill down into the individual views to see what the APEX engine was doing during each phase and identify the activities within the page that were taking the most time.

The details page shows the data in two formats. First is the histogram graph across the top of the page. In this histogram, the bars represent the duration of each step in relation to the single step with the largest duration. The second is the actual report that shows the details of what was executed during the phase execution.

Hovering over any of the bars in the histogram with your mouse (as shown in Figure 7-9) will show information about the step represented by that bar. Clicking that bar will scroll the screen so that the detail line represented by the bar will come into view in the window.

The detail report is, again, an interactive report allowing you to create filters and manipulate the data in many different ways. The first row of the report, when sorted by elapsed time or row, will identify the base information about the current view, including the phase and request. This will help you identify exactly what you are looking at. The subsequent lines show the individual steps taken to complete the phase being executed.

The detail report also has a column labeled Graph that mirrors the histogram that appears at the top of the page. This visual clue will help you scroll down the detail report and easily identify those steps that took the most time during the phase execution.

The actual detailed steps that appear will vary from page to page and also between the ACCEPT and SHOW phases. However, they will generally conform to the broad sections outlined earlier in Figure 7-2.

Navigation between the different detail views can be achieved via the navigation region at the top of the detail page, as presented in Figure 7-10. If you know the view ID, you can simply type it in the Page View Identifier field at the top of the detail view page and click the Set button. If you want to return to the high-level view page, click the Select Page View Identifier button.

Clicking the Reset button will return the current report to its default settings, resetting any filters you may have implemented.

Application Utilities

Another place to view debug information is via the application utilities. You can reach these by clicking the large Utilities icon on the main application edit page (as shown in Figure 7-11) or by clicking the small Utilities icon in the menu at the top of the Page Designer and then selecting Application Utilities (as shown in Figure 7-12).

Selecting either option will take you to the Application Utilities page. From here, select the Debug Messages option (as indicated in Figure 7-13).

You will be presented with a high-level report identical to the one you see when accessing the data from the Developer Toolbar. The difference is that the report initially shows all views for all pages in the current application. Using the interactive report capabilities, you can filter the debug views to display only the ones you’re interested in.

Drilling down will take you to the detail report, this time without the histogram across the top. Apart from this small change, all the data is the same as you would see via the Developer Toolbar.

Navigation in this version of the report is slightly different. Here you use the APEX breadcrumbs to navigate between the Debug and Debug Message Data pages to select the desired views, as shown in Figure 7-14.

Another change to the utilities-based Debug view is the addition of the Purge Debug Messages button. This button allows both workspace administrators and developers to purge underlying debug data for the currently selected application based on certain criteria. The available criteria are as follows:

• Purge all messages: This option will purge all data for the selected application that currently resides in the underlying debug tables.
• Purge messages by age: This option allows you to select a time frame for which to purge, from 1 day to 4 weeks.
• Purge current session messages: This option allows the purge of messages for the currently active user session.
• Purge by View Identifier: This option allows the purge of messages related to a specific view ID.

Benefits of Debug Mode

There are a few benefits to Debug mode that are worth mentioning because they help make debugging some of the more complex pieces of APEX a little easier. These benefits are particularly apparent when working with graphs and charts or when developing interactive reports.

Graphs and Charts

APEX 5 uses AnyChart 6 (www.anychart.com) as its main graphing and charting engine. While the APEX team has done a wonderful job of hiding the behind-the-scenes complexity of how charting works, sometimes you may need to dig into the details of how charts are being rendered.

As you learned in Chapter 3, everything you change on the Chart Attributes page of a given chart’s definition ends up creating an XML document that determines how the chart will be drawn. You can, if you want, edit the XML manually to make changes that are not available via the Chart Attribute options.

Although you can get a good feel for the XML that will be generated, you cannot guarantee what the XML will look like until runtime. To be able to view the full runtime XML, prior versions of APEX required you to use third-party, browser-based debugging tools. APEX, however, has made things much easier.

When Debug mode is on, each chart will contain a link that will allow you to view the XML that was generated to drive it. Figure 7-15 shows a bar chart with the Show XML link visible in the lower-left corner.

Clicking this link will display the full runtime XML that was generated to drive the chart. This is useful for debugging manual changes you may have made to chart XML or to view how the data has been emitted into the XML from the series queries you have defined. Figure 7-16 shows an example of the generated XML.

When debugging is enabled, APEX 5 also captures the AJAX callback to the database to generate the XML and inserts information about that call into the APEX_DEBUG_MESSAGES table. The Path Info setting for the corresponding Debug view will be set to show APXWGT, and the details will show information regarding the underlying series of the chart, as shown in Figure 7-17.

Interactive Reports

While interactive reports give an amazing amount of power to the end user, debugging them can be a bit challenging because APEX basically rewrites the query behind the scenes based on the user’s column selections, filters, and more. Enabling debugging on an Interactive Report page will emit the SQL that is generated for the current incarnation of the interactive report into the debug data.

Once an interactive report is rendered to the page, any changes made to the filters, sorting, column selection, and so on, are done via AJAX calls. If debugging is enabled, changes to the report will still be logged, but as an ajax plugin request for the page as opposed to a “show.” In fact, APEX now logs any AJAX call having to do with the interactive report, including ones as simple as retrieving a distinct list of values when clicking a column heading. While this may seem like overkill, it is extremely useful to know what’s going on as you click around the interactive report options.

Consider the three debug snippets shown in Figures 7-18, 7-19, and 7-20. All the snippets are from the same interactive report.

Figure 7-18 shows the detail debug data for an interactive report region prior to a user having made any changes to the report. The path info for this view would be SHOW. You can tell the following from the figure:

• Line 76 indicates the start of the region.
• Line 81 lists the columns that will be displayed.
• Line 83 shows the base SQL statement.
• Line 84 shows the value of the APXWS_MAX_ROW_CNT bind variable because it will be used in the SQL statement.

Figure 7-19 shows the AJAX plugin view that is associated with the user having clicked the Assigned To column in the report to get a distinct list of asignees. Here you can see the following:

• Line 25 indicates the request for a distinct list.
• Line 28 shows the SQL statement that is to be executed.
• Line 29 to 30 show the bind variables and their values.

  

  Figure 7-19. Debug data for the AJAX call to get the distinct list of asignees

Figure 7-20 shows the detailed debug data for the same Interactive Report region after a user has made changes to the report, as indicated in Figure 7-21. The changes indicate that you are filtering on the ASSIGNED_TO value.

• Line 27 lists the columns that will be displayed.
• Line 30 shows the base SQL statement.
• Line 32 shows the value of the APXWS_EXPR_1 bind variable because it will be used in the SQL statement.

With this debug data you have enough information to not only troubleshoot but also examine the potential performance of the query that was generated.

APEX Debugging API

Not only does APEX provide you with a method to interactively debug your application pages, it also provides a full API that allows you to instrument your own code and even turn on debugging programmatically. In this section, you’ll examine the APIs and see how they can be put to use in an application context.

APEX_DEBUG

The core debugging API exists in the form of the APEX_DEBUG package. This package is now well documented in the Oracle Application Express API reference. The following sections are brief descriptions of what’s available in the API and some usage notes. For full technical definitions, please refer to the official documentation. I’ll discuss their usage further in later sections.

CONSTANTS

The package provides a number of constants used throughout the package itself as well as being available for developers to use.

subtype t_log_level is pls_integer;
c_log_level_error        constant t_log_level := 1; -- critical error
c_log_level_warn         constant t_log_level := 2; -- less critical error
c_log_level_info         constant t_log_level := 4; -- default debug level
c_log_level_app_enter    constant t_log_level := 5; -- APP: message when Procs/Funcs entered
c_log_level_app_trace     constant t_log_level := 6; -- APP: other messages within Procs/Funcs
c_log_level_engine_enter  constant t_log_level := 8; -- APEX: message when Procs/Funcs entered
c_log_level_engine_trace  constant t_log_level := 9; -- APEX: other messages within Procs/Funcs

DISABLE Procedure

This procedure allows the developer to programmatically disable debugging in the context of the current phase of page processing.

Usage Notes

DISABLE will turn off debugging no matter how it was enabled.

Disabling debugging in the middle of a phase will cause the actions that follow to be omitted from the debug information.

The latest points in an APEX page where debugging can be programmatically disabled are as follows:

• Page rendering: Occurs after the footer, making sure that the sequence number of the process is the highest in the set
• Page processing: Occurs on submit, after computations and validations, making sure that the sequence number of the process is the highest in the set

ENABLE Procedure

This procedure allows the developer to programmatically enable debugging in the context of the current phase of page processing.

Usage Notes

Level 1 is the most critical.

Level 9 is the least critical.

Setting p_level to 3 would log any message at levels 1, 2, and 3.

Enabling debugging programmatically is not limited by the application-level setting that disallows interactive debugging. Therefore, even if the application is set to disallow interactive debugging, programmatic debugging will still work as expected.

The earliest points in an APEX page where debugging can be programmatically enabled are as follows:

• Page rendering: You can create a branch of type Function Returning a Page (Show Only) with a processing point of Before Header, making sure that the sequence number of the process is the lowest in the set. Set the function body to simply return the current page number and use the condition to create a PL/SQL function body to use APEX_DEBUG to turn debugging on to the correct level. If the condition function always returns false, the branch will never be taken, but debugging can still be turned on.
• Page processing: You can create a process of type PL/SQL Code with a processing point of After Submit, making sure that the sequence number of the process is the lowest in the set.

When debugging is programmatically enabled via the API, APEX will not emit the debug message that indicates the phase (that is, SHOW or ACCEPT). Therefore, it is good practice to use the LOG_MESSAGE procedure to output a message immediately after debug that will help you to identify the phase. For example, the following code snippet could be placed in an On Load page process to programmatically enable debugging and immediately emit a message indicating the phase:

apex_debug.enable (p_level => 7);
apex_debug.log_message(’S H O W --- Programmatically enabled’);

Once turned on programmatically, debugging will remain on until it is either turned off programmatically or via the Developer Toolbar, if available.

ENTER Procedure

This procedure logs messages only when debugging is set to the level defined by the constant c_log_level_app_enter or higher.

Usage Notes

ENTER allows you to log the name of a routine being called and up to ten of its arguments and their values. You can also use the p_value_max_length to truncate the values passed to a finite length.

This procedure is useful when you need to understand what’s being passed in to a procedure or function so you can debug what it will do with those particular values.

ERROR Procedure

This procedure logs messages only when debugging is set to the level defined by the constant c_log_level_error or higher.

Usage Notes

ERROR allows you to log errors into the DEBUG_MESSAGES table. This procedure will always log errors even if debugging is off.

The message passed to the ERROR procedure is reminiscent of the C language’s sprintf routine and therefore can contain up to 20 occurrences of %s. Those occurrences will be replaced with the values of p0 to p19. Values passed via the p<n> variables can be truncated to a maximum length using the p_max_length parameter.

INFO Procedure

This procedure logs messages only when debugging is set to the level defined by the constant c_log_level_info or higher.

Usage Notes

INFO allows you to log errors into the DEBUG_MESSAGES table.

The message passed to the INFO procedure is reminiscent of the C language’s sprintf routine and therefore can contain up to ten occurrences of %s. Those occurrences will be replaced with the values of p0 to p09. Values passed via the p<n> variables can be truncated to a maximum length using the p_max_length parameter.

LOG_DBMS_OUTPUT Procedure

This procedure uses dbms_output.get_lines to retrieve the current contents of the DBMS_OUTPUT buffer and write them to the DEBUG_MESSAGES table.

Usage Notes

Using this procedure, the messages emitted by legacy PL/SQL that contains calls to DBMS_OUTPUT can be captured and written to the debug log.

For these messages to be captured, debugging must be enabled.

LOG_MESSAGE Procedure

This procedure allows the developer to emit debug messages from within either APEX anonymous blocks or stored packages and procedures called from APEX.

Usage Notes

Level 1 is the most critical.

Level 9 is the least critical.

When using within stored PL/SQL program units that might be called outside of the context of APEX, always set P_ENABLED to FALSE. Failing to do so will result in an error because the APEX security group ID will not be set.

LOG_LONG_MESSAGE Procedure

This procedure allows the developer to emit debug messages larger than 4,000 characters from within either APEX anonymous blocks or stored packages and procedures called from APEX.

Usage Notes

Level 1 is the most critical.

Level 9 is the least critical.

Logging will be split into 4,000-byte chunks.

When using the LOG_LONG_MESSAGE procedure within stored PL/SQL program units that might be called outside of the context of APEX, always set P_ENABLED to FALSE. Failing to do so will result in an error because the APEX security group ID will not be set.

LOG_PAGE_SESSION_STATE Procedure

This procedure allows the developer to emit session state information into the debug messages table for a given page in the current application.

Usage Notes

Each item from the indicated page and its current value in session state will be emitted to the debug messages table.

MESSAGE Procedure

This procedure inserts a formatted debug message into the DEBUG_MESSAGES table.

Usage Notes

The message passed to the MESSAGE procedure is reminiscent of the C language’s sprintf routine and therefore can contain up to 20 occurrences of %s. Those occurrences will be replaced with the values of p0 to p19. Values passed via the p<n> variables can be truncated to a maximum length using the p_max_length parameter.

If p_force is set to true, the message will be logged even if debugging is turned off or if the current debug level is smaller than that set using the p_level parameter.

REMOVE_DEBUG_BY_AGE Procedure

This procedure allows the developer to programmatically remove all debug messages for a specific application where the message timestamp is prior to n days before today.

REMOVE_DEBUG_BY_APP Procedure

This procedure allows the developer to programmatically remove any debug messages associated with a specific application.

REMOVE_DEBUG_BY_VIEW Procedure

This procedure allows the developer to programmatically remove any debug messages for a specific application that are identified as belonging to a specific debug view.

REMOVE_SESSION_MESSAGES Procedure

This procedure allows the developer to programmatically remove any debug messages associated with a specific user session.

TOCHAR Function

This function converts a Boolean true or false value to its VARCHAR2 equivalent.

TRACE Procedure

This procedure logs messages only when debugging is set to the level defined by the constant c_log_level_trace or higher.

Usage Notes

TRACE allows you to log messages into the DEBUG_MESSAGES table.

The message passed to the TRACE procedure is reminiscent of the C language’s sprintf routine and therefore can contain up to ten occurrences of %s. Those occurrences will be replaced with the values of p0 to p10. Values passed via the p<n> variables can be truncated to a maximum length using the p_max_length parameter.

WARN Procedure

This procedure logs messages only when debugging is set to the level defined by the constant c_log_level_warn or higher.

Usage Notes

WARN allows you to log messages into the DEBUG_MESSAGES table.

The message passed to the WARN procedure is reminiscent of the C language’s sprintf routine and therefore can contain up to ten occurrences of %s. Those occurrences will be replaced with the values of p0 to p10. Values passed via the p<n> variables can be truncated to a maximum length using the p_max_length parameter.

Programmatic Debugging

As you can see, the APEX_DEBUG_MESSAGE API provides the facilities necessary to enable and disable Debug mode programmatically. And as mentioned in the preceding documentation, the ability to use programmatic debugging is not affected by the application-level setting. This means that even if you have a standard that dictates that applications are deployed into production with debugging disabled, you still have the ability to capture debug information.

Figure 7-22 shows the capture of debug information for a single page in an application that displays a simple report. The debug information was captured interactively by using the Developer Toolbar.

Figure 7-23 shows a branch created to gather debug information programmatically. The branch was created at the earliest possible point on the page. The branch does not in fact redirect to another page but instead simply enables debugging programmatically. Figure 7-24 shows the resulting debug data.

While it may be more natural to think that a page process might be the best place to turn on programmatic debugging, there is some method to the madness of choosing a branch instead. No matter what its sequence number, page processes always execute after branches and computations. Therefore, if you want to capture information about branches and computations in your debug output, you must turn Debug mode on before these items are processed by APEX.

The ability to create a branch of type Function Returning a Page (Show Only) at a process point of Before Header that actually does not branch anywhere is perfect for these purposes. As long as its sequence number is lower than any other branch, programmatic debugging will capture all logged messages for any branch, computation, or process that follows it.

When debugging is turned on via the API, even at the earliest point possible, APEX will have already completed some of the steps involved in rendering or processing the page.

If you compare the interactive data to the data that was gathered programmatically, you’ll notice there are a number of things that just don’t get captured in the programmatic version. This shouldn’t concern you too much because what is missing is directly related to core APEX code and not code for which you will likely be seeking to gather information.

However, one of the more important things that gets left out is the first line of debug information, which indicates the phase. This is easily remedied by following the ENABLE call with a call to LOG_MESSAGE, as shown earlier in Figure 7-23.

The same is true for the PROCESS phase as for the SHOW phase demonstrated earlier. When enabling debugging programmatically, there will be some things that get missed. In most circumstances, the missing data isn’t significant enough to be concerned about; however, if you want to make sure you get all the data relating to a page, you’re likely to want to enable debug as part of the page phase that is directly before the one you want to capture.

For example, if you want to capture all the details about page processing for a page, turn debugging on during that page’s SHOW phase. Alternatively, if you want to capture all information regarding a page’s SHOW phase, enable debugging as part of the processing phase of the page that branches to the page in question. If Debug mode is already enabled prior to reaching the desired phase, even if it was enabled programmatically, the entire phase’s information will be captured.

Instrumenting Your Own Code

While having access to the debug information APEX emits by default is helpful, there will inevitably be times when you’ll need deeper insight into what may be going on in the code that you have written.

The APEX Debugging API provides methods to expand the depth of information being gathered. This is especially useful when you’re trying to understand what is happening within PL/SQL that might be part of a branch, computation, or process.

Logging Custom Messages

The LOG_MESSAGE and LOG_LONG_MESSAGE procedures are quite simple in signature; however, they provide an amazing amount of flexibility and functionality when it comes to gathering information about what’s going on within your application.

The most straightforward use case would be one in which you might want to emit simple messages that mark the steps a piece of PL/SQL might be executing, such as marking the purpose of a simple code construct, like a loop, as in Listing 7-1.

BEGIN
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’START - INSERTING 10000 RECORDS...’);
--
FOR I IN 1..10000 LOOP
    INSERT INTO PERF_TEST (guid1, guid2, guid3, created_on)
    VALUES (SYS_GUID, SYS_GUID, SYS_GUID, SYSDATE);
END LOOP;
--
END;

Enabling Debug mode and running the page will produce the output shown in Figure 7-25.

However, to add real value, it behooves you to mark not only the beginning but also the end of each significant step, as in Listing 7-2.

BEGIN
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’START - INSERTING 10000 RECORDS...’);
--
FOR I IN 1..10000 LOOP
    INSERT INTO PERF_TEST (guid1, guid2, guid3, created_on)
    VALUES (SYS_GUID, SYS_GUID, SYS_GUID, SYSDATE);
END LOOP;
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>END - INSERTING 10000 RECORDS...’);
--
END;

Remember that execution timing is measured from the beginning of the current step to the beginning of the subsequent step. These step boundaries coincide with the point at which a debug message is logged. Therefore, surrounding a code block with calls to LOG_MESSAGE provides the extra benefit of capturing an accurate timing of all the code that ran between those two messages, as shown in Figure 7-26.

You have to be careful about your usage of the LOG_MESSAGE procedure, though. For instance, injecting a LOG_MESSAGE call in the middle of the loop would first create a huge number of log entries that you would be unlikely to want to wade through, and also it would potentially impact performance because you would be executing the full code path of the LOG_MESSAGE procedure 10,000 times.

That is where the p_level parameter comes in handy. Consider Listing 7-3. Here I’ve done exactly what I just warned against, but notice that the value for the level of the outer calls is at a higher level than that of the inner calls.

BEGIN
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’START - INSERTING 10000 RECORDS...’, P_LEVEL=>5);
--
FOR I IN 1..10000 LOOP
    --
    APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’START RECORD ’||I, P_LEVEL=>7);
    --
    INSERT INTO PERF_TEST (guid1, guid2, guid3, created_on)
    VALUES (SYS_GUID, SYS_GUID, SYS_GUID, SYSDATE);
    --
    APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’END RECORD ’||I, P_LEVEL=>7);
    --
END LOOP;
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’END - INSERTING 10000 RECORDS...’, P_LEVEL=>5);
--
END;

Now when you choose to enable debugging programmatically, you can use the p_level parameter to decide to what level of message you want to log. Calling ENABLE with p_level set to 5 would log only the messages outside the loop. However, enabling debugging with a message level of 7 would log both outside and inside the loop. Using this mechanism, you can manage the level at which messages are logged and what level of log message you want to capture.

Lastly, using the p_enabled parameter of LOG_MESSAGE allows you to dictate that a message is important enough to always be logged, whether or not debugging has been enabled. Listing 7-4 shows the same code but injects a LOG_MESSAGE call in the top of the block that will always be written to the APEX dictionary, regardless of the state of debugging.

BEGIN
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’THIS MESSAGE IS ALWAYS LOGGED...’, P_ENABLED=>TRUE, P_LEVEL=>3);
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’START - INSERTING 10000 RECORDS...’, P_LEVEL=>5);
--
FOR I IN 1..10000 LOOP
    --
    APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’START RECORD ’||I, P_LEVEL=>7);
    --
    INSERT INTO PERF_TEST (guid1, guid2, guid3, created_on)
    VALUES (SYS_GUID, SYS_GUID, SYS_GUID, SYSDATE);
    --
    APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’END RECORD ’||I, P_LEVEL=>7);
    --
END LOOP;
--
APEX_DEBUG.LOG_MESSAGE( P_MESSAGE =>’END - INSERTING 10000 RECORDS...’, P_LEVEL=>5);
--
END;

Logging Session State

There are many instances when trying to debug a page where it would be beneficial to know specifically what was in session state. The LOG_PAGE_SESSION_STATE procedure will provide you with exactly that information.

The API will emit information into the DEBUG logs, which shows the session state for each item on the designated page. Like the LOG_MESSAGE procedure, the LOG_PAGE_SESSION_STATE procedure lets you dictate what log level will be associated with the emitted log records and allows you to decide whether to override the debug setting and always log the session state.

You can call the LOG_PAGE_SESSION_STATE procedure without passing any parameters, and it will log the session state for the currently processing page at debug message level 4, but it will do so only if debugging is enabled.

Figure 7-27 shows an example of the output of debug information that contains session state information. The session state information is specifically contained in rows 34 through 38 in the report.

The data contains a row for each item that appears on the page, whether visible to the user or not, and contains the item name, length, and value. While it may seem odd that the items are rendered not in the order that they appear on the screen, but in alphabetical order by item name, this is because many of the new APEX themes are div based and it is not necessarily possible to identify where they appear on the page.

You can also emit more than just the current page’s session state, but to do this you will need to make an API call for each page you want to include. Figure 7-28 shows an example including session state for page 9 and page 7.

The Data Behind Debugging

As mentioned earlier, APEX debugging data is now kept in a set of data dictionary tables so that it can be examined and compared to other runs of the same page. In this section, you’ll look at the underlying tables and view, the lifetime of the data in them, and how the data differs when captured interactively as opposed to when captured programmatically.

Tables and View

Debug data is stored as metadata in the core APEX schema and is split across two tables: WWV_FLOW_DEBUG_MESSAGES and WWV_FLOW_DEBUG_MESSAGES2. The data is exposed to the developer via a single APEX data dictionary view: APEX_DEBUG_MESSAGES.

While it may seem odd that there are two underlying tables, APEX uses this two-table setup in a number of places to keep a finite duration of data around. The table into which data is actually inserted is switched, by default, every 14 days. When the switch occurs from one table to the other, APEX truncates the table that it’s switching to. This means that at a minimum it will have no data (in other words, no debug information has been gathered) or, depending upon how APEX is configured, up to 360 days’ worth of data. Figure 7-29 gives a visual depiction of this idea.

You may think that having a finite amount of data available to you at any one time might be too limiting, and I would have to agree with you. If you want to keep more than that amount of data, you’ll have to take matters into your own hands. Doing this is actually quite straightforward.

First, you’ll need to create a local version of the debug data table that you control. The simplest way to do this is as follows:

CREATE TABLE MY_DEBUG_MESSAGES
AS
SELECT * FROM APEX_DEBUG_MESSAGES
WHERE ’X’ = ’Y’

This will create the table without bringing any of the rows over. Then, you’ll want to copy only the rows from the APEX_DEBUG_MESSAGES view to your new table, but to make this something that can be run over and over, you’ll want to copy only the rows that don’t already exist in the table. Luckily, the PAGE_VIEW_ID column gives you something unique to compare against. The following SQL statement will copy only the information that does not already exist in the table:

INSERT INTO MY_DEBUG_MESSAGES
SELECT *
FROM APEX_DEBUG_MESSAGES
WHERE PAGE_VIEW_ID NOT IN
  (SELECT DISTINCT PAGE_VIEW_ID FROM MY_DEBUG_MESSAGES);

To automate this process, you can include the previous SQL statement in a stored procedure and set it up to run regularly as a database-scheduled job. And to make sure that you are always looking at the latest information, you can create a view that joins the data in your table with the data in the APEX view, as follows:

CREATE OR REPLACE VIEW MY_DEBUG_MESSAGES_V
AS
  SELECT *
  FROM my_debug_messages
UNION
  SELECT *
  FROM APEX_DEBUG_MESSAGESS
  WHERE page_view_id NOT IN
    (SELECT DISTINCT page_view_id FROM my_debug_messages);

Now you have everything you need to duplicate the screens and reports that APEX provides you as part of the debugging interface. In fact, you can actually replicate it 100 percent by simply examining the code behind the APEX pages.

Examining the Debug Data

Now that you know where the debug data is kept, let’s take a look at exactly what is being kept. Table 7-1 describes each column and the data it contains.

Most of the columns in the view are pretty self-explanatory, but the relationship between MESSAGE_TIMESTAMP, ELAPSED_TIME, and EXECUTION_TIME merits some discussion.

The MESSAGE_TIMESTAMP column is straightforward; it’s merely the accurate timestamp of when the debug message was entered into the underlying debug message tables. To get a clear picture of the order in which things happened during a page SHOW or ACCEPT, simply order the rows ascending by the MESSAGE_TIMESTAMP.

The EXECUTION_TIME is calculated as the difference between the current timestamp and the timestamp from the subsequent record. So, in essence, it shows how much time has elapsed between the two records being inserted. You can see this calculation in the definition of the APEX_DEBUG view. The view uses the LEAD and PARTITION functions to calculate the difference between the two timestamps.

ELAPSED_TIME is something different entirely. This column is supposed to show the elapsed time since the beginning of the page submission or the page view. While logic might dictate that you should be able to perform some arithmetic using the timestamp and the calculated execution time to arrive at the elapsed time, you’d be wrong to do so. APEX actually uses yet another mechanism (a function call in this case) to calculate the elapsed time since the beginning of this phase. Because the function call actually takes some time (even if it’s microseconds), the timing of the elapsed time is always just a little off from what you might expect. Don’t get hung up on this. They are usually within such a small tolerance that it’s fairly unmeasurable unless the task you are tracking is huge.

And in any account, what you really should be paying attention to is EXECUTION_TIME. If you want to find what you need to performance-tune within your page, pay attention to the thing with the largest execution time.

Using Debug Data for More Than Debugging

The fact that you have direct access to the data, and now know how to keep the data around for longer than the natural cycle that is built in to APEX, means that you can begin to use this data for more than just debugging. The overall information that is available makes this data perfect for performing longer-term analysis and performance tracking.

For instance, using programmatic debugging, you could choose to collect and keep performance information about your most important application pages. You may not want to keep information for every page view, but you could easily write logic that captures n percent of all page views. Then using the information contained in your long-term debug tables, you can track the performance over time. You could even begin to spot and map trends in performance, potentially identifying when a critical process might trend outside its window of acceptability.

Another potential use is to compare data before and after making a change to a page. If the main structure of the page hasn’t changed, but instead the driving query behind it has changed, then you would be able to easily write code to compare, line for line, whether the new version of the page ran faster or slower than a previously captured version.

If a page calls stored PL/SQL code that is also instrumented using the APEX debugging API, you then have insight into the performance trends of the business logic that you’ve written in PL/SQL.

The bottom line is that you have this data for whatever purposes you want, and the better instrumented your code, the more detail you have at your disposal.

Debugging Dynamic Actions

Because the Dynamic Actions framework is actually implemented as JavaScript that is processed in the browser, debugging dynamic actions is approached a bit differently. APEX still uses Debug mode to determine whether the Dynamic Actions framework should emit data, and you can still enable debugging in all the same ways that have been discussed. However, instead of inserting data into the underlying debug messages tables, the Dynamic Actions framework emits message to the browser’s JavaScript console.

The information that appears in the JavaScript console takes the following form:

Dynamic Action Fired: [Dynamic Action Name](Specific Action Fired)

Figure 7-30 shows an example of using Chrome’s debug console to view the debug information.

While this doesn’t give you any detail about what the dynamic action code is doing, it does give you a visual indicator that the dynamic action code is firing. For a bit more information, you can edit the Chrome console’s settings to include XMLHttpRequests, as shown in Figure 7-31.

After this is turned on, you’ll not only see the dynamic actions that fire but also the calls to WWV_FLOW.SHOW that indicate XMLHttpRequests (or AJAX calls), as shown in Figure 7-32.

In Chrome, to view information about the XMLHttpRequest, click the link that contains the reference to wwv_flow.show. This will take you to the Network tab and briefly highlight the related row.

Clicking the indicated row will expand the detail of the AJAX call and will expose the header, post, response, and so on, as shown in Figure 7-33. Because the dynamic actions are generated code based on what you declared within the APEX builder, the POST section will be only partially useful. You’ll be able to see what field initiated the transaction and what APP and PAGE were involved, but the other data will likely be unfamiliar and mean nothing to you. However, the data contained on the Response tab actually represents any data that was returned by the AJAX call and was used by the dynamic action.

If you really want to get into the details of what is happening during a dynamic action, you’ll need to get into the depths of JavaScript debugging, which is beyond the scope of this chapter. But ideally what has been presented will give you a method for at least knowing whether the defined dynamic actions are firing when expected and bringing back the data they should.

Like interactive reports, any AJAX callbacks to the database performed by a dynamic action will be captured in the APEX_DEBUG_MESSAGES table under the path info of ajax plugin. You’ll be able to see any session state that was set as part of the AJAX call as well as the execution of any SQL or PL/SQL, as shown in Figure 7-34.

Debugging Plugins

When it comes to plugins, things are similar to debugging most other things. Plugins that provide any type of visual content to a page will emit debug information into the APEX_DEBUG_MESSAGES table as part of the standard page’s SHOW view.

However, anywhere a plugin makes a callback to the database via AJAX, the debug detail will be inserted into a separate AJAX plugin view, much like interactive reports or dynamic actions.

Because plugins are often a mix of SQL, PL/SQL, and JavaScript, you may again have to break open the JavaScript console and debugging tools of your browser to get a full picture of what is going on.

Summary

I hope you’ve seen how useful APEX debugging can be when trying to troubleshoot your applications, and I hope I’ve given you some food for thought as to how debug data could potentially be used for performance analysis and trending. As APEX continues to develop as a product, I am sure that there will be more alterations and extensions to the APIs, allowing for more and more granular messages to be captured. Keep an eye on the APEX core documentation for new releases because many of these alterations and extensions often go unannounced and unnoticed.