Beware The Slow Subquery

Here's a snippet from a very curious graphical plan for a large, slow 4-way UNION in a SQL Anywhere 16 stored procedure:



The selected DT (Derived Table) node represents the 3rd SELECT statement in the UNION, and the Subtree Statistics - PercentTotalCost of 66.979% shows that this SELECT is the slowest of the four.

So, why is it curious?

It's curious because the node immediately below the DT, the JNL Nested Loop Join node, shows a Node Statistics - PercentTotalCost of zero and a Subtree Statistics - PercentTotalCost of only 8%... where did the rest of the 66.979% go?

Did it disappear somewhere between the DT and the JNL?

In an effort to find where the time was going, the third SELECT was moved out of the UNION and executed separately. Here's an even-more-curious snippet from the graphical plan for that SELECT:



The DT node has now become the SELECT node, with 100% for the Subtree Statistics - PercentTotalCost.

However, the Work node immediately underneath the SELECT node shows zero for both the Node and Subtree Statistics - PercentTotalCost.

Now we're not just looking for most of the time, we're looking for ALL the time . . .

Where did it go?

It turns out there's more to this query than one giant SELECT FROM... there are a bunch of subqueries in the SELECT list, and one of them is consuming . . . wait for it . . . 98.88% of the time.

To see the subqueries in the SQL Anywhere Plan Viewer, you have to click on the dropdown list that says "Main Query" and look at the "SubQ" entries, in this case SubQ 4:



Back in the "Main Query" display, the SubQ 4 subquery appears as the third-last item in the SELECT list:

expr166[EXISTS(SubQ 4) : 50% Guess,1,0]

The subquery itself isn't so bad, it only took 0.19238% of the time (the Actual(Avg) column in the Node Statistics above)... it's the 514 separate executions, one for each row in the outer SELECT, that brought the total to 98.88% (the Actual(Total) column).

The solution wasn't so hard, either... one more CREATE INDEX, and the execution time for the stored procedure call dropped from 42 seconds to 3.4 seconds.

But the solution's not the point here... the point is, just because a SELECT contains a dozen tables in the FROM clause doesn't mean that's where the time is going.

And just because the Plan Viewer doesn't shout "Hey, look at this slow subquery!" doesn't mean you shouldn't dig down and look for yourself... especially when the Main Query display doesn't account for all the time being spent.

Note: The plans shown here were obtained using the technique shown in Capture Plans With GRAPHICAL_PLAN().