Friday, June 01, 2007

Application Express Debug Mode Timing on Post/Submit

A co-worker recently approached me with an Apex 2.2.1 problem. He had a report that was running extremely slowly. The report used a database link. He suspected the dblink was the problem.

We spent some time looking over it directly in sql*plus (always a good way to start) and confirmed that the query ran slowly accross the link. Next step, we ran the query directly in the source database--still slow. There were a lot of rows in the view (which was based upon two other views, which were both based upon views). Only one index, on the primary key. I recommended some specific indexes that would help his situation.

A week later he returned. Now the query ran great in sql*plus, but the report was still slow in Apex with certain query criteria. I ran the page, submitting different criteria and confirmed that with some criteria it ran very slowly. Turning on debug indicated that the query region was running fast. I suspected that the debug mode timing somehow did not include the time spent in the linked database (boy was I wrong).

After some hair pulling, I looked at the page that I was submitting (the page with the query criteria) and saw several validations on that page. Aha! Perhaps a validation was the culprit. The report was branched via a "Branch to Page or URL" branch, so debug mode was not showing anything that happened during the submit portion--only the render portion of the report page. I created a new branch with sequence=1. This branch was a Direct Branch (see image). By making it a direct branch I was able to see the time spent in the validation:

0.03: Branch point: BEFORE_VALIDATION
0.03: Perform validations:
0.03: ...PL/SQL "function body returning error text"...
317.62: ...

As you can see, the validation was taking over 5 minutes. Using the direct branch made all difference, allowing me to look at the submit processing. The validation also used the dblink, but did a select count(*) from that same view (with 50 million rows)--not using any indexes. Cleaning that up did the trick.

No comments: