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]

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