Hunting The Slow Result Set Query

An earlier article Beware The Slow Result Set Query described how SQL Anywhere's stored procedure profiler doesn't highlight, or even report, the time spent executing SELECT statements that return result sets from stored procedures.

SQL Anywhere's Database Tracing feature does a bit better than the procedure profiler, but it can be somewhat confusing. Here's a demonstration using the same procedure as before:

CREATE PROCEDURE p() BEGIN WAITFOR DELAY '00:00:01'; SELECT COUNT_BIG(*) FROM SYSTAB AS A CROSS JOIN SYSTABCOL AS B CROSS JOIN SYSUSER AS C; END; SELECT * FROM p();

Let's pretend!

You and I both know where the time is going in this trivial procedure, but let's pretend that's not the case... let's pretend this code is part of a giant application and we don't know where the time is going.

Here's what the Database Tracing shows after a test run:



The first line in the Summary list tells us what ISQL told us before, but the procedure profiler didn't: that SELECT * FROM p() takes a long time to run (Total Time 179,079 milliseconds).

Unlike the procedure profiler, however, the Database Tracing feature captures graphical plans for all the time-consuming queries. Here's the plan for SELECT * FROM p(); it shows that the procedure call is taking all the time (Runtime 179.08 seconds):



Clearly, it can't be the procedure call itself that's taking the time, it must be something the procedure is doing... and it's only doing two things, a WAITFOR statement and a SELECT COUNT_BIG(*).

The Database Tracing Summary list doesn't show the WAITFOR statement at all, even though the procedure profiler previously reported that it took over 1,000 milliseconds. But never mind, it doesn't really matter if Database Tracing doesn't capture WAITFOR delays, what about the SELECT COUNT_BIG(*)?

Yes, there it is, line 12 in the Summary list shows that the SELECT COUNT_BIG(*) was executed twice (huh? oh, never mind) for a total time of 74 milliseconds.

Now, if this was a real example, and line 12 was one of many hundreds or thousands of queries in the Database Tracing Summary list, it might go unnoticed... 74 milliseconds is nothing.

It's not nothing!

It turns out that "74 milliseconds" is a complete fiction; the graphical plan for the SELECT COUNT_BIG(*) tells a whole different story:



This plan tells the real story: the Node Statistics FirstRowRunTime is 177.99 seconds, and that's backed up by the Subtree Statistics Runtime of 177.99 seconds.

Nobody runs Database Tracing on trivial applications

Here's the point of this exercise: When you're having trouble finding out exactly where the time is going in a big application, look for time-consuming stored procedure result set queries. Look at the code, and drill down into the plans captured by Database Tracing, or go Old School with the GRAPHICAL_PLAN() function.

---