Monday, January 25, 2016

40 Days.....



OK folks about 40 days to the Hotsos Symposium!  If you haven’t registered this would be a great day to do it!  Lots of great speakers this year and I’m very excited to have Mr. Index, Richard Foote for our training day. 





See you there!!

Friday, January 8, 2016

You need to be using DBMS_APPLICATION_INFO

I’m honestly very surprised how often I meet Oracle professionals who are not familiar with this package.  It’s a great thing to help you in debugging and monitoring your application.   It does require a little bit of “work” to use, and it’s little, but the benefits are potentially huge.

Let say I’m the owner of a particular piece of code that is pretty critical to the business, if it performs badly then lots of folks get pretty upset.  And being a proactive kind of guy I’d like to be able to monitor its performance even when it’s not causing problems.   The best way to see how something is running is to do a 10046 trace, or more formally, extended SQL tracing.

But tracing something is hard, especially since I want to trace a “thing” not a “user”.   This has been rather difficult until rather recently since all tracing was (are really still is) base on a session. But with DBMS_MONITOR we can now turn on tracing based on these things called “Module” and “Action”.

But to do this we need to set module and action otherwise this is useless.   This is where a few lines of code can make the huge impact.   The process is very simple; it’s a process that we’ve all used in one fashion or another in programming.  We want to set a variable to a value but we need to retain what it was set to, this way we can then set it back to its original setting later.

Here is a simple block of code to illustrate the process.  All I need to do to take advantage of these setting is use a few calls from the package:
DBMS_APPLICATION_INFO.read_module
DBMS_APPLICATION_INFO.set_module
And maybe
DBMS_APPLICATION_INFO.set_action

In my example I’m not using the last one.  I would use that in a more complicated code block where I’d want to show I’m doing something different within the same main code block. 

Here is a simple block of code to illustrate the process.

01)         PROCEDURE get_emp_instr IS
02)           fnlist_stack  fnlist_tab;
03)           lnlist_stack  lnlist_tab;
04)           preModuleName VARCHAR2(32) := NULL;
05)           preActionName VARCHAR2(32) := NULL;  
06)         BEGIN
07)           DBMS_APPLICATION_INFO.read_module(module_name => preModuleName, action_name => preActionName);
08)           DBMS_APPLICATION_INFO.set_module(module_name => 'Human Resources', action_name => 'Get Employees');
09)           SELECT first_name, last_name BULK COLLECT INTO fnlist_stack, lnlist_stack FROM employees;
010)          DBMS_APPLICATION_INFO.set_module(module_name => preModuleName, action_name => preActionName);
011)        EXCEPTION
012)          WHEN OTHERS THEN
013)          DBMS_APPLICATION_INFO.set_module(module_name => preModuleName, action_name => preActionName);
014)          raise_application_error (-20042,'ERROR in get_emp_instr');
015)        END get_emp_instr;
016)        /

Lines 4 and 5 set up holding locations for the previous module and action names.   In Line 7 we capture the current setting of module and action and put them into the defined variables.  Line 8 then sets the module and action name to what you want it set to for this code block.  Then we would do whatever it is we would do in the block.  Also this is not intended to set action every other line or something quite that detailed.  The idea is that a module is a “large” unit of work and that an action is a “significant” amount of work in a sub unit under the module.  I have found that trying to set it too quickly and the kernel seems to ignore some of the settings, or they go so fast they the change gets “lost”.   (I didn’t see the changes in the trace file.)

Lines 10 and 13 both set the module and action back to the previous settings.   Line 10 is certainly needed, since it not reset, when the code goes back to the calling environment the old setting would be lost.  However line 13 you may or may not want to have.  If it’s a locally handled exception and all it good to go then yes set it back to what it was, but it’s really an error state you likely will not want to reset them so these values are still set to what they were when the error occurred.   A little thought is required about resetting the module and action in an exception handler.

So there it is. With about 5-6 lines of code this block is instrumented and as it is executed I can monitor its executions (these module and action names get populated into several V$ views and such). And I could even trace this by turning on trace like this:

EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE (service_name =>'HOTSOS', module_name =>'Human Resources', action_name => DBMS_MONITOR.ALL_ACTIONS, waits => TRUE, binds => TRUE);

Notice there is a system defined constant for all actions this way if I had a large code unit with the same module (for example a package) this would allow me to get any action used within the defined module.  Inside the trace file(s) I would see line like this:

*** MODULE NAME:(Human Resources) 2016-01-04 09:08:49.535
*** ACTION NAME:(get_emp) 2016-01-04 09:08:49.535

Of course you need to turn it off too so it would look like this (for every enable there is a disable):

EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE (service_name =>'HOTSOS', module_name =>'Human Resources', action_name => DBMS_MONITOR.ALL_ACTIONS);

A key point is that if you turn it on my module action you could end up with multiple trace files.  Because anyone running the named module/action combination will generate a trace, and trace files are still session generated.   So you can use trcsess to put them all together like this (this is an OS level utility, you run this at the OS command level):

trcsess output=hr_test.trc action="get_emp" module="Human Resources" *OP.trc

Pretty cool stuff eh? 

Oh and DBMS_APPLICAITON_INFO has been around since about 7.2 so don’t try this “it’s a new thing that’s why I don’ know about it” excuse.

Thursday, December 10, 2015

New version of the Hotsos SQL Test Harness: V5

Dateline – December 2015, Grapevine TX, Hotsos World Headquarters

The latest and greatest version of the Harness is now available for download from the Hotsos Education Downloads page.  

This version is functionally quite different from the old one.  The use of it remains the same, you provide a SQL script file name, a workspace and scenario name and the test harness will run the SQL file and provide key statistics on the run, including the Extended SQL Trace File (10046).

How it works is quite different and it does show some different and I believe more useful information then the old one.  In version past the output included the explain plan.  However this is becoming less useful with the new features like Cardinality Feedback in 11 and Adaptive Query Optimization in 12.  The new version of the Harness now shows the execution plan using DBMS_XPLAN.DISPLAY_CURSOR.  The format options are set to TYPICAL ALLSTATS LAST ALIAS which I believe give you key information about the run. 

You still get the PARSE line and all the STAT lines from the 10046 trace as part of the output.  Also it still takes a snap shot of the statistics before and after the run to show you the total work done by the query. 

But a really big change is that the Harness no longer requires the use of a username and password.  In the old version the tool had to log off and back on a few times as trace files were created.   The new version uses the DBMS_MONITOR.SESSION_TRACE_ENABLE and DISABLE to create the 10046 trace file so logging off and on is no longer required to get the full trace file.  The problem really was in the old style of creating trace file you might not get “everything” if you just turned off trace when you were done with the statement.  And a key part was the STAT lines didn’t always get written to the trace file when you just “turned it off”.  Now they do.

Also, the new Harness doesn’t create the 10053 trace anymore (CBO Enable optimizer trace).  This is the trace of a hard parse and for the most part it’s not used for performance optimization.  Yes it can be interesting to look at to see what the optimizer was “thinking” as it created a plan.  There will be a separate utility to create and load the 10053 trace added to the tool pack soon.   

Please let me know of any issue you have while using the Harness.   

A simple example of a run:

SQL> @dosql emp emp emp
+-+-+-+-+-+-+
Starting Test
+-+-+-+-+-+-+
Snapshot 1 collection OK.
Snapshot 2 collection OK.

+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
| Actual PARSE and STAT line data for emp:emp
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

PARSE #383679648:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1445457117,tim=343535899973

STAT #383679648 id=1 cnt=27 pid=0 pos=1 obj=116599 op='TABLE ACCESS FULL EMPLOYEES (cr=363 pr=0 pw=0 time=1331 us cost=73 size=83 card=1)'

+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
| Plan using DBMS_XPLAN.DISPLAY_CURSOR
| Format options: TYPICAL ALLSTATS LAST ALIAS
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  g76m74pycbct4, child number 0
-------------------------------------
select * from employees where first_name = 'David'

Plan hash value: 1445457117

----------------------------------------------------------------------------------------------------------
|Id |Operation         |Name      |Starts |E-Rows|E-Bytes|Cost (%CPU)|E-Time  |A-Rows|   A-Time  |Buffers|
----------------------------------------------------------------------------------------------------------
|  0|SELECT STATEMENT  |          |     1 |      |       |   73 (100)|        |    27|00:00:00.01|    363|
|* 1| TABLE ACCESS FULL|EMPLOYEES |     1 |     1|    83 |   73   (0)|00:00:01|    27|00:00:00.01|    363|
----------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$1 / EMPLOYEES@SEL$1

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("FIRST_NAME"='David')


+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
| Statistics Snapshot for emp:emp
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

Type  Statistic Name                                    Value
----- ---------------------------------------- --------------
Latch cache buffers chains                              1,040
      row cache objects                                    55
      shared pool                                          33

Stats buffer is pinned count                                0
      consistent gets                                     363
      consistent gets direct                                0
      db block changes                                      0
      db block gets                                         0
      execute count                                         6
      index fast full scans (full)                          0
      parse count (hard)                                    0
      parse count (total)                                   6
      physical reads                                        0
      physical writes                                       0
      redo size                                             0
      session logical reads                               363
      session pga memory                                    0
      session pga memory max                                0
      session uga memory                                    0
      session uga memory max                                0
      sorts (disk)                                          0
      sorts (memory)                                        0
      sorts (rows)                                          0
      table fetch by rowid                                  0
      table scan blocks gotten                            355
      table scans (long tables)                             0
      table scans (short tables)                            1

Time  elapsed time (centiseconds)                           3

+-+-+-+-+-+-+
Test Complete
+-+-+-+-+-+-+
SQL>

Happy Optimizing!