Getting plans for statements inside a function or procedure

[justin_willey]

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]

I really don't understand, why only SA still don't has convenient mechanism for getting plans of any sql statements, without voodoo. Using Tracing/LogExpensiveQueries is not that thing that all wants today. For some statement 1min is very fast, for another -1ms - very slow. So how to use LogExpensiveQueries in that case? Please, just give us simple mechanism getting any plans without voodoo, like any other RDBMS has.

[Breck_Carter]

"A simple mechanism for getting plans without voodoo" is a good description of a much needed improvement... too bad it lacks management appeal.

Let's see... paradigm shift... adaptive server... unwired enterprise...

...got it! cloud computing!

How about "A simple mechanism for getting plans to improve cloud performance"?

[VolkerBarth]

...what's the current value of the brandnew BUZZWORD_LEVEL option...?

[justin_willey]

I'm sure it's essential for implementing IP6 🙂 or even better BIG DATA - the last one is even has the advantage of being true

[VolkerBarth]

And now is the time to give the slight pointer that in German (or my particular region), "Fuji" sounds similar to the colloquial "futsch" or its "italized" version "fut­schi­ka­to" - both meaning

lost, gone, broken

Some may claim that's a very fitting association with a cloud-based database, others may not...

[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.

[Former Member]

I see the[/an] issue now.

The database server is not tracing the value of the expression tested in the IF statement. It's hard to say exactly why this is, but it could be that the EXISTS keyword is usually treated as a predicate for a query which creates a subquery. Since the IF statement isn't quite a query, the EXISTS subquery is not easily tied to the IF statement.

But, there is in fact request logging for these statements (in my test using "dbsrv12 -zr ALL -zp -zo rll.log ...").

For example, the following code:

CREATE OR REPLACE PROCEDURE myProc() 
RESULT ( ret LONG VARCHAR )
BEGIN
    DECLARE ret LONG VARCHAR;
    IF EXISTS(SELECT * FROM SYS.SYSTAB WHERE table_id = 3408) THEN
        SET ret = '1';
    END IF;
    IF EXISTS(SELECT * FROM SYS.SYSTAB WHERE table_name = 'Robert') THEN
        SET ret = '2';
    END IF;
    IF EXISTS(SELECT * FROM SYS.SYSPROCEDURE WHERE proc_name = 'myProc') THEN
        SELECT COUNT(*) INTO ret FROM SYS.SYSPROCEDURE WHERE proc_name = 'myProc';
    END IF;
    SET ret = '0';
    SELECT ret;
END;

CALL myProc();

Produces the following plan information in the request log:

+1,P,1,[R][0]tab<ISYSTAB(IO)>
=,P,1,[R][1]tab<table_name(IO)>
+1,P,1,[R][1]b<procedure_name(IO)>
=,[,1,myProc,15,select COUNT() into ret from SYS.SYSPROCEDURE where proc_name = 'myProc'
+12,P,1,[R][1]GrByS[ b<procedure_name(IO)> ]

As you can see, the output is fairly obscure. Also, the SELECT COUNT(*)... plan is pretty clearly tied to its query. This output can get better if the query can be executed apart from the if statement (although not ideal) as in:

DECLARE test INTEGER;
SELECT 1 INTO test FROM SYS.DUMMY WHERE EXISTS(...); // or SELECT TOP 1 1 INTO test FROM ...
IF test = 1 THEN
    //it exists!
END IF;

Again, not ideal, but I hope this can provide some more ammo to tackle the problem.

[Breck_Carter]

Is that "request log" the result of request level logging? If so, it will only show requests coming into the server from the outside world; i.e., the CREATE PROCEDURE coming from dbisql, not the statements executed inside the procedure.

[Former Member]

That statement is somewhat correct... However, if you look at the fifth line for my request output, you'll notice that the query

=,[,1,myProc,15,select COUNT() into ret from SYS.SYSPROCEDURE where proc_name = 'myProc'

is the rewritten statement being executed by the stored procedure on line 15. (Although it's not actually line 15, I modified the procedure a couple of times in my test, but I digress...)

For a more recent execution I have:

+147,P,1,[R][0]tab<ISYSTAB(IO)>
+1,P,1,[R][1]tab<table_name(IO)>
+2,P,1,[R][1]b<procedure_name(IO)>
=,[,1,myProc,12,select COUNT() into ret from SYS.SYSPROCEDURE where proc_name = 'myProc'
+1,P,1,[R][1]GrByS[ b<procedure_name(IO)> ]
=,],1,myProc,12
=,[,1,myProc,14,set ret = '0'
=,],1,myProc,14
=,[,1,myProc,15,select ret
=,P,1,[S]DUMMY<seq>
=,],1,myProc,15