Getting plans for statements inside a function or procedure

[VolkerBarth]

I have been profiling a number of functions and procedures and this has highlighted a big difference (in the wrong direction, unfortunately) in performance of some individual statements within a number of functions after moving from v10.0.1 to 12.0.1.

Some of these statements are not straight selects or updates, but are in the form of a Watcom IF connstruct eg:

if VacID is not null and(exists(select 1 from Progress where Progress.VacancyID = VacID and Progress.PersonID = persid and Progress.status = '.')
or exists(select 1 from Progress where Progress.VacancyID = VacID and Progress.PersonID = persid and Progress.noreemploy = 1)) then
return 'V' end if;

This is just one of half a dozen similarly constructed statements in the function.

The application profiling / tracing viewer treats everything between the initial BEGIN and the final END as a single statement, so no plan is available. Obviously I could rewrite the statement as something like

select if VacID is not null and(exists(select 1 from Progress where Progress.VacancyID = VacID and Progress.PersonID = persid and Progress.status = '.')
or exists(select 1 from Progress where Progress.VacancyID = VacID and Progress.PersonID = persid and Progress.noreemploy = 1)) then 1 else 0 endif

then run that from isql and get a plan, but the query isn't quite the same and the context is quite different.

Is there some way of getting the plans for such statements as the are actually executed, in the context of the function / procedure?

---

UPDATE

Screen shot showing how the whole procedure is treated as a single statement, with no plan tab

[VolkerBarth]

...Is DESPERATION_LEVEL another coming knob? If so, what's the default, and can I set it on a per-user base?

[justin_willey]

Yup that's the one - I'll just have to wait until 2014 - probably about the time one of the queries is going to finish!

[Breck_Carter]

Are you sure Database Tracing doesn't capture queries executed inside stored procedures?

[justin_willey]

Part of the problem is that I don't really know how the IF statement is actually executed by the engine, ie is it recast as a SELECT, if so how etc? GRAPHICAL_PLAN() only takes SELECT, UPDATE and DELETE.

I presume the thing to do would be to fetch the plan for the statement, in re-written form, BEFORE doing it for real, so that the plan isn't changed by running the actual statement?

I rather like the LOG_EXPENSIVE_QUERY () idea - especially the way you would be able to have it in place at danger points and only invoke it when DESPERATION_LEVEL > (TOLERANCE_THRESHOLD - CAFFINE_QUOTIENT)

[justin_willey]

When I look at the detailed results you see the whole contents ie from BEGIN to END in the query column. Then when you click on that you see the contents in the query window with the overall timing but unlike a single statement there's no tab for the plan. I also looked to see if the individual statements are separately logged as well, but even after removing the filters I can't see them.

That doesn't mean I'm not missing something though!

---

I'll post some screen shots when I get a moment

[Breck_Carter]

@All: The "Comment Text Removed" isn't the work of some nefarious censor, it's the result of me deleting my own comments without realizing replies had already been posted. Oh, well... whatever you imagine the missing comments to be is probably more interesting than the (now forgotten) reality 🙂

[Breck_Carter]

FWIW... I usually start with the stored procedure profiler to find which statements are actually slow, before digging deeper. Sometimes, it is all I use, if the flaw is obvious once the statement is highlighted... and it's a LOT easier to use than database tracing.

[justin_willey]

Indeed, if only the tracing was as easy to use as the procedure profiling - turn on, look at results! That's how I got started down this route, then found I had to try to dig out the individual statements to why it had changed so much.

[Former Member]

There is some functionality to obtain these plans, Breck walks through it fairly well here:

LogExpensiveQueries: A Little Bit Of Jasper In 9.0.2

---

Edit: You won't be able to diagnose exactly as in 9.0.2. In later versions, you'll be able to specify plan logging with -zr ALL or -zr ...+PLAN and direct the output with -zo

---

Of course, you can always wrap a query in a GRAPHICAL_PLAN call to get the necessary plan details from within the stored procedure or function:

(i.e.)

CALL xp_write_file('my_plan.saplan', // write plan to a file
    GRAPHICAL_PLAN('SELECT * FROM my_table',2) // 2 for detailed statistics
);

Documentation for GRAPHICAL_PLAN is at:

GRAPHICAL_PLAN function

[justin_willey]

Thanks Tyson, I've been able to get plans for individual queries like the one in your example OK, but the problem comes with functions and procedures.

What seems to happen there is that the whole procedure is treated as a unit, you can get statistics on how long it took to run and so on, and in the profile of the function you can get execution times of the individual statements that make up the procedure, but not plans for those statements.

[Former Member]

This can be used to get the graphical plan from within a stored procedure. Although, if the statement is executed multiple times, you may want to insert the graphical plan into a temporary table before writing to disk.

But, with the LogExpensiveQueries feature, you should be able to get by without modifying the stored procedure or function. You can specify a minimum cost for queries as well as RememberLastPlan and the database server will output the plans accordingly.

[justin_willey]

Thanks - I'll give that a go

[VolkerBarth]

FWIW, how does that 9.0.2 feature "LogExpensiveQueries" apply to current versions?

With 10.0.1.4181 and 12.0.1.3389, both dbsrvX -zx and sa_server_option( 'LogExpensiveQueries', '1000'); are rejected as unknown options...

[Former Member]

Good point! I've updated my answer.