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:
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
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 |
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: 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.
(24 Jan '12, 08:23)
Justin Willey
Replies hidden
2
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.
(24 Jan '12, 11:25)
Tyson Lewis
Thanks - I'll give that a go
(24 Jan '12, 12:07)
Justin Willey
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...
(24 Jan '12, 14:57)
Volker Barth
Replies hidden
|
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. 2
"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"?
(26 Jan '12, 09:45)
Breck Carter
Replies hidden
1
...what's the current value of the brandnew BUZZWORD_LEVEL option...?
(26 Jan '12, 09:47)
Volker Barth
1
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
(26 Jan '12, 09:54)
Justin Willey
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 "futschikato" - both meaning
Some may claim that's a very fitting association with a cloud-based database, others may not...
(27 Jan '12, 08:08)
Volker Barth
|
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. 1
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.
(27 Jan '12, 08:42)
Breck Carter
Replies hidden
1
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
(27 Jan '12, 13:14)
Tyson Lewis
|
...Is DESPERATION_LEVEL another coming knob? If so, what's the default, and can I set it on a per-user base?
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!
Are you sure Database Tracing doesn't capture queries executed inside stored procedures?
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)
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
@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 :)
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.
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.