Search

Top 60 Oracle Blogs

Recent comments

Home » Monthly archive

April 2011

Evidence

Submitted by Jonathan Lewis on Wed, 2011-04-20 18:12

Here’s a nice example on the OTN database forum of Dom Brooks looking at the evidence.

  • The query is slow – what does the trace say.
  • There’s “row source execution” line that says we get 71,288 rows before doing a hash un ique drops it to 3,429 rows.
  • There’s a statement (upper case, bind variables as :Bn) in the trace file that has been executed 71,288 times
  • A very large fraction of the trace file time is in the secondary statement
  • There’s a user-defined function call in the original select list, before a ‘select distinct’.

Conclusion: the code should probably do a “distinct” in an inline view before calling the function, reducing the number of calls to the function from 71,288 to 3,429.

Footnote: There may be other efficiency steps to consider – I’m always a little suspicious of a query that uses “distinct”: possibly it’s hiding an error in logic, possibly it should be rewritten with an existence subquery somewhere, but sometimes it really is the best strategy. There’s are some unusual statistics names coming from autotrace in the OP’s system – I wonder if he’s installed one of Tanel Poder’s special library hacks.

BLKS_GETS_PER_ACCESS Index Rebuild Criteria ? (Twisted Logic)

Submitted by Richard Foote on Wed, 2011-04-20 10:34

A recent question on the database OTN forum and a previous request by Charles Hooper that I cover some basic indexing concepts for newbie’s who might be confused by “dubious” information out there in internet land has prompted me to discuss the BLKS_GETS_PER_ACCESS metric, available in INDEX_STATS after an analyze validate structure operation.   The OTN [...]

New Oracle security papers and Oracle forensics tool

Submitted by pete on Wed, 2011-04-20 07:51

David has released four new papers on Oracle security topics a few days ago. Two of the papers seem to be from his ill fated book on Oracle Forensics as they are labelled " chapter 3 - How attackers break....[Read More]

Posted by Pete On 20/04/11 At 09:50 AM

500MB/s越えのSSD登場

Submitted by Ichiro Obata on Wed, 2011-04-20 00:21

OCZ Technology社製 SATAⅢ6Gbps対応 SSD Vertex3 シリーズ

写真の240GB版は6万5千円と、非常に高価。しかし、今まで使ってきたCrucial RealSSDでは到達できなかった1本で500MB/sを上回るSequential Readが可能となる。
コントローラはSandForce2281を使用。（http://www.anandtech.com/show/4159/ocz-vertex-3-pro-preview-the-first-sf2500-ssd/1から引用）

More CR

Submitted by Jonathan Lewis on Tue, 2011-04-19 18:32

Following on from yesterday’s post on consistent reads, I thought I’d make the point that the way you work can make an enormous difference to the amount of work you do. Here’s a silly little demo (in 10.2.0.3):

drop table t1 purge;
create table t1 (id number, n1 number);
insert into t1 values (1,0);
insert into t1 values (2,0);
commit;

execute dbms_stats.gather_table_stats(user,'t1')
execute snap_my_stats.start_snap

begin
	for i in 1..1000 loop
		update t1 set n1 = i where id = 1;
	end loop;
end;
/

execute snap_my_stats.end_snap

set doc off
doc

Output - 10.2.0.3 (some rows deleted)
Name                                                                     Value
----                                                                     -----
opened cursors cumulative                                                   11
user calls                                                                   6
recursive calls                                                          1,068
recursive cpu usage                                                          7
session logical reads                                                    4,041
CPU used when call started                                                   7
CPU used by this session                                                     7
DB time                                                                      6
db block gets                                                            1,030
db block gets from cache                                                 1,030
consistent gets                                                          3,011
consistent gets from cache                                               3,011
consistent gets - examination                                                4
db block changes                                                         2,015
change write time                                                            4
free buffer requested                                                    1,014
switch current to new buffer                                             1,000
calls to kcmgas                                                          1,014
calls to get snapshot scn: kcmgss                                        3,009
redo entries                                                               960
redo size                                                              295,160
undo change vector size                                                111,584
no work - consistent read gets                                           1,004
table scans (short tables)                                               1,001
table scan rows gotten                                                   2,002
table scan blocks gotten                                                 1,001
buffer is pinned count                                                   1,000
execute count                                                            1,009

#

I’ve created two rows in a table, then updated one of them 1,000 times – using a table scan to do the update. I haven’t yet committed my transaction. At this point I’m going to use a second session to run the same update loop on the second row in the table:

begin
	for i in 1..1000 loop
		update t1 set n1 = i where id = 2;
	end loop;
end;
/

Name                                                                     Value
----                                                                     -----
opened cursors cumulative                                                    8
user calls                                                                   6
recursive calls                                                          1,009
recursive cpu usage                                                        170
session logical reads                                                  965,999
CPU used when call started                                                 172
CPU used by this session                                                   172
DB time                                                                    173
db block gets                                                            1,030
db block gets from cache                                                 1,030
consistent gets                                                        964,969
consistent gets from cache                                             964,969
consistent gets - examination                                          961,965
db block changes                                                         3,016
consistent changes                                                   1,001,000
free buffer requested                                                    1,015
CR blocks created                                                        1,001
calls to kcmgas                                                          1,015
calls to get snapshot scn: kcmgss                                        3,008
redo entries                                                             1,936
redo size                                                              358,652
undo change vector size                                                111,608
data blocks consistent reads - undo records applied                  1,001,000
cleanouts and rollbacks - consistent read gets                           1,001
immediate (CR) block cleanout applications                               1,001
active txn count during cleanout                                         2,000
cleanout - number of ktugct calls                                        1,001
IMU CR rollbacks                                                        41,041
table scans (short tables)                                               1,001
table scan rows gotten                                                   2,002
table scan blocks gotten                                                 1,001
execute count                                                            1,006

Many of the statistics are (virtually) identical (e.g. “execute count”, “db block gets”, “free buffer requested”); some show an increase by 1,000 (often from zero) – largely because we have to worry 1,000 times about cleaning out the current block and creating a read-consistent version so that we can check if it can be updated.

But the most noticeable changes are in the “CPU time” and “consistent gets” because of the 1,000 times we have to apply 1,000 undo records to the block as we create the read-consistent version of the block. The CPU time has gone from 7 (hundredths of a second) to 172 because of (roughly) 1,000,000 “consistent gets – examination”. As I mentioned yesterday, this matches closely to “data blocks consistent reads – undo records applied” so we know why they are happening. Watch out in your batch jobs – if you have a lot of concurrent update activity going on a significant fraction of the workload may be the constant re-creation of CR clones.

However, there is another interesting detail to watch out for – what happens if I change the update execution path from a tablescan to an indexed access path:

create table t1 (id number, n1 number);
insert into t1 values (1,0);
insert into t1 values (2,0);
commit;

execute dbms_stats.gather_table_stats(user,'t1')
create index t1_i1 on t1(id);                            --  Make indexed access path available.

Then with an index hint in my update code, I get the following effects (having done the same update loop on row 1 in the first session, of course):


begin
	for i in 1..1000 loop
		update /*+ index(t1) */ t1 set n1 = i where id = 2;     -- indexed access path hinted
	end loop;
end;
/

Name                                                                     Value
----                                                                     -----
opened cursors cumulative                                                    7
user calls                                                                   6
recursive calls                                                          1,006
recursive cpu usage                                                         11
session logical reads                                                    2,036
CPU used when call started                                                  11
CPU used by this session                                                    11
DB time                                                                     11
db block gets                                                            1,030
db block gets from cache                                                 1,030
consistent gets                                                          1,006
consistent gets from cache                                               1,006
consistent gets - examination                                                6
db block changes                                                         2,015
free buffer requested                                                       14
shared hash latch upgrades - no wait                                     1,000
calls to kcmgas                                                             14
calls to get snapshot scn: kcmgss                                        1,004
redo entries                                                               960
redo size                                                              295,144
undo change vector size                                                111,608
index crx upgrade (positioned)                                           1,000
index scans kdiixs1                                                      1,000
execute count                                                            1,005

The difference is astonishing – where did all the ‘create CR copy’ activity go ?

I’ve pointed out before now that choosing a different execution plan for an update can have a big impact on performance – this is just another example demonstrating the point.

Two New Articles: UDEV and Database Triggers…

Submitted by oraclebase on Tue, 2011-04-19 11:15

I’ve recently put a couple of new articles about old subjects on the website. In both cases, the articles were initiated by forum questions, but the explanations became too painful in the format of a forum post so they graduated into articles…

  • UDEV SCSI Rules Configuration In Oracle Linux 5 : For those of you that like to follow my Virtual RAC guides, but don’t like using ASMLib, you can use this article and replace ASMLib with UDEV.
  • Database Triggers Overview : This is really a primer on database triggers. I’ve focussed mostly on simple DML triggers, since this is what the vast majority of trigger-related questions I’m asked relate to. Consider it the “minimum” you should know before you write a database trigger.

Cheers

Tim…




Realtime SQL Monitoring – Designed with Exadata in Mind

Submitted by Kerry Osborne on Tue, 2011-04-19 01:22

One of the best new features of 11g from a diagnostic standpoint is the Real Time SQL Monitoring capabilities. I did a post about it a couple of years ago here: Oracle 11g Real Time SQL Monitoring In that post I talked about a procedure (DBMS_SQLTUNE.REPORT_SQL_MONITOR) that provides a very nicely formatted explain plan type output which contains quite a bit of useful information. Well, it has recently come to my attention that the report contains a column that shows cell offloading. That’s pretty cool. Here’s a script to call that procedure, report_sql_monitor.sql, and an example (note the format is really wide so be sure and use the scroll bar at the bottom to see the columns on the right of the output):

#99cc00">?View Code NONE
SYS@SANDBOX1> @report_sql_monitor.sql
Enter value for sid: 
Enter value for sql_id: 2hzzka3071hkj
Enter value for sql_exec_id: 
 
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
SQL Text
------------------------------
select /*+ INDEX (SKEW2 SKEW2_COL1) */ avg(pk_col) from kso.skew2
 
Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  SYS (3:2673)
 SQL ID              :  2hzzka3071hkj
 SQL Execution ID    :  16777216
 Execution Started   :  03/13/2011 17:02:35
 First Refresh Time  :  03/13/2011 17:02:35
 Last Refresh Time   :  03/13/2011 17:02:48
 Duration            :  13s
 Module/Action       :  sqlplus@Kerry-Osbornes-MacBook-Pro-4.local (TNS /-
 Service             :  SANDBOX
 Program             :  sqlplus@Kerry-Osbornes-MacBook-Pro-4.local (TNS
 Fetch Calls         :  1
 
Global Stats
============================================================================================================================
| Elapsed |   Cpu   |    IO    | Application | Concurrency | Cluster  |  Other   | Fetch | Buffer | Read | Read  |  Cell   |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes | Offload |
============================================================================================================================
|      96 |      92 |     2.33 |        0.00 |        0.80 |     0.00 |     0.47 |     1 |   653K | 6136 |   5GB |  71.83% |
============================================================================================================================
 
Parallel Execution Details (DOP=8 , Servers Allocated=8)
===================================================================================================================================================================================
|      Name      | Type  | Server# | Elapsed |   Cpu   |    IO    | Application | Concurrency | Cluster  |  Other   | Buffer | Read | Read  |  Cell   |        Wait Events        |
|                |       |         | Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Waits(s) |  Gets  | Reqs | Bytes | Offload |        (sample #)         |
===================================================================================================================================================================================
| PX Coordinator | QC    |         |    0.83 |    0.03 |     0.00 |        0.00 |        0.80 |     0.00 |          |      7 |    3 | 24576 |    NaN% |                           |
| p000           | Set 1 |       1 |      12 |      11 |     0.29 |             |             |          |     0.07 |  81601 |  770 | 637MB |  71.83% | cell smart table scan (1) |
| p001           | Set 1 |       2 |      12 |      11 |     0.31 |             |             |          |     0.06 |  81601 |  775 | 637MB |  71.83% |                           |
| p002           | Set 1 |       3 |      12 |      12 |     0.32 |             |        0.00 |          |     0.06 |  81601 |  764 | 637MB |  71.83% | cell smart table scan (1) |
| p003           | Set 1 |       4 |      12 |      11 |     0.25 |             |             |          |     0.04 |  81601 |  768 | 637MB |  71.83% |                           |
| p004           | Set 1 |       5 |      12 |      12 |     0.30 |             |             |          |     0.06 |  81601 |  757 | 637MB |  71.83% | cell smart table scan (1) |
| p005           | Set 1 |       6 |      12 |      11 |     0.26 |             |             |          |     0.05 |  81601 |  755 | 637MB |  71.83% |                           |
| p006           | Set 1 |       7 |      12 |      12 |     0.28 |             |             |          |     0.07 |  81601 |  769 | 637MB |  71.83% |                           |
| p007           | Set 1 |       8 |      12 |      12 |     0.33 |             |             |          |     0.06 |  81560 |  775 | 637MB |  71.83% |                           |
===================================================================================================================================================================================
 
SQL Plan Monitoring Details (Plan Hash Value=2117817910)
==============================================================================================================================================================================
| Id |            Operation             |   Name   |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  |  Cell   | Activity |      Activity Detail      |
|    |                                  |          | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes | Offload |   (%)    |        (# samples)        |
==============================================================================================================================================================================
|  0 | SELECT STATEMENT                 |          |         |       |         1 |    +13 |     1 |        1 |      |       |         |          |                           |
|  1 |   SORT AGGREGATE                 |          |       1 |       |         1 |    +13 |     1 |        1 |      |       |         |          |                           |
|  2 |    PX COORDINATOR                |          |         |       |         1 |    +13 |     9 |        8 |      |       |         |          |                           |
|  3 |     PX SEND QC (RANDOM)          | :TQ10000 |       1 |       |         2 |    +12 |     8 |        8 |      |       |         |          |                           |
|  4 |      SORT AGGREGATE              |          |       1 |       |        13 |     +1 |     8 |        8 |      |       |         |    50.52 | Cpu (49)                  |
|  5 |       PX BLOCK ITERATOR          |          |    128M | 24700 |        13 |     +1 |     8 |     128M |      |       |         |    45.36 | Cpu (44)                  |
|  6 |        TABLE ACCESS STORAGE FULL | SKEW2    |    128M | 24700 |        13 |     +1 |   104 |     128M | 6133 |   5GB |  71.83% |     3.09 | cell smart table scan (3) |
==============================================================================================================================================================================

So as you can see, this is a parallel query. For parallel queries there is a separate section that shows what each slave process did. There are a couple of columns that are particularly interesting in this section. The Cell Offload column shows the percentage reduction in data transferred to the database tier that resulted from offloading. The Wait Events column shows what the slaves waited on. In the Plan Details section you can see that the plan included a full table scan and that it was offloaded. This section has columns that show the same basic information (although the column names are slightly different), but it’s organized by plan step. This is extremely useful on complex statements that have multiple steps which may be offloaded. This section also clearly shows which steps are taking the most time (Activity %).

Here’s a more complicated example. The statement in this example doesn’t have a lot of steps, but the output is very useful in understanding what is happening. Again, be sure to scroll over to the right to see the interesting bits.

#99cc00">?View Code NONE
SYS@SANDBOX1> @report_sql_monitor
Enter value for sid: 
Enter value for sql_id: fm7y4nqu4tbv3
Enter value for sql_exec_id: 
 
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
SQL Text
------------------------------
update kso.skew_hcc1 set col1 =col1*1
 
Global Information
------------------------------
 Status              :  DONE
 Instance ID         :  1
 Session             :  SYS (451:1843)
 SQL ID              :  fm7y4nqu4tbv3
 SQL Execution ID    :  16777216
 Execution Started   :  04/10/2011 17:41:24
 First Refresh Time  :  04/10/2011 17:41:24
 Last Refresh Time   :  04/10/2011 18:07:16
 Duration            :  1552s
 Module/Action       :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)/-
 Service             :  SYS$USERS
 Program             :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)
 
Global Stats
=========================================================================================================================================
| Elapsed | Queuing |   Cpu   |    IO    | Application | Concurrency | Cluster  | PL/SQL  |  Other   | Buffer | Read  | Read  |  Cell   |
| Time(s) | Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Time(s) | Waits(s) |  Gets  | Reqs  | Bytes | Offload |
=========================================================================================================================================
|    1583 |    0.00 |    1442 |      132 |        0.00 |        0.03 |     2.35 |    0.00 |     7.01 |   231M | 63553 | 784MB | -29.87% |
=========================================================================================================================================
 
Parallel Execution Details (DOP=32 , Servers Allocated=32)
====================================================================================================================================================================================================================
|      Name      | Type  | Server# | Elapsed | Queuing |   Cpu   |    IO    | Application | Concurrency | Cluster  | PL/SQL  |  Other   | Buffer | Read  | Read  |  Cell   |              Wait Events              |
|                |       |         | Time(s) | Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Time(s) | Waits(s) |  Gets  | Reqs  | Bytes | Offload |              (sample #)               |
====================================================================================================================================================================================================================
| PX Coordinator | QC    |         |    1551 |    0.00 |    1425 |      117 |        0.00 |        0.03 |     2.23 |    0.00 |     6.69 |   231M | 58878 | 460MB |    NaN% | gc current grant 2-way (1)            |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | log buffer space (5)                  |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | log file switch completion (3)        |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | enq: FB - contention (2)              |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | cell single block physical read (122) |
| p000           | Set 1 |       1 |    0.93 |         |    0.53 |     0.39 |             |             |     0.00 |         |          |   1682 |   120 |  10MB | -72.41% | cell smart table scan (2)             |
| p001           | Set 1 |       2 |    0.98 |         |    0.51 |     0.48 |             |             |          |         |          |   1389 |   107 |  10MB | -72.41% | cell single block physical read (1)   |
| p002           | Set 1 |       3 |    0.97 |         |    0.57 |     0.41 |             |             |     0.00 |         |          |   2954 |   181 |  10MB | -66.67% |                                       |
| p003           | Set 1 |       4 |    0.91 |         |    0.51 |     0.40 |             |             |     0.00 |         |          |   1412 |   119 |  10MB | -72.41% |                                       |
| p004           | Set 1 |       5 |    0.92 |         |    0.52 |     0.40 |             |             |     0.00 |         |          |   1415 |   121 |  10MB | -69.49% | cell single block physical read (1)   |
|                |       |         |         |         |         |          |             |             |          |         |          |        |       |       |         | cell smart table scan (1)             |
| p005           | Set 1 |       6 |    1.31 |         |    0.54 |     0.77 |             |             |     0.00 |         |          |   7985 |   389 |  12MB | -58.73% | cell single block physical read (2)   |
| p006           | Set 1 |       7 |    0.98 |         |    0.48 |     0.50 |             |             |     0.00 |         |          |   2653 |   123 |  10MB | -72.41% |                                       |
| p007           | Set 1 |       8 |    0.96 |         |    0.49 |     0.46 |             |             |     0.00 |         |          |   2926 |   175 |  10MB | -69.49% |                                       |
| p008           | Set 1 |       9 |    0.84 |         |    0.53 |     0.30 |             |             |     0.00 |         |          |   1380 |    98 |  10MB | -75.44% | cell smart table scan (1)             |
| p009           | Set 1 |      10 |    0.81 |         |    0.48 |     0.33 |             |             |     0.00 |         |          |   1389 |   108 |  10MB | -72.41% |                                       |
| p010           | Set 1 |      11 |    1.32 |         |    0.54 |     0.46 |             |             |     0.00 |         |     0.32 |   2283 |    90 |  10MB | -75.44% | cell smart table scan (1)             |
| p011           | Set 1 |      12 |    1.13 |         |    0.44 |     0.68 |             |             |     0.00 |         |          |   1382 |    92 |  10MB | -75.44% | cell smart table scan (1)             |
| p012           | Set 1 |      13 |    1.12 |         |    0.58 |     0.54 |             |             |     0.00 |         |          |   5818 |   238 |  11MB | -66.67% |                                       |
| p013           | Set 1 |      14 |    0.92 |         |    0.55 |     0.37 |             |             |     0.00 |         |          |   1408 |   114 |  10MB | -72.41% |                                       |
| p014           | Set 1 |      15 |    1.12 |         |    0.53 |     0.59 |             |             |     0.00 |         |          |   3604 |   217 |  11MB | -66.67% |                                       |
| p015           | Set 1 |      16 |    0.98 |         |    0.53 |     0.45 |             |             |     0.00 |         |          |   1973 |   110 |  10MB | -75.44% |                                       |
| p016           | Set 1 |      17 |    0.97 |         |    0.51 |     0.46 |             |             |     0.00 |         |          |   1407 |   106 |  10MB | -72.41% | cell single block physical read (2)   |
| p017           | Set 1 |      18 |    0.95 |         |    0.50 |     0.45 |             |             |     0.00 |         |          |   5017 |   210 |  11MB | -69.49% |                                       |
| p018           | Set 1 |      19 |    1.08 |         |    0.52 |     0.56 |             |        0.00 |     0.00 |         |          |   2305 |   156 |  10MB | -69.49% |                                       |
| p019           | Set 1 |      20 |    0.92 |         |    0.49 |     0.42 |             |             |          |         |          |   1366 |    87 |  10MB | -75.44% |                                       |
| p020           | Set 1 |      21 |    0.89 |         |    0.55 |     0.33 |             |             |     0.00 |         |          |   2804 |   107 |  10MB | -72.41% |                                       |
| p021           | Set 1 |      22 |    0.89 |         |    0.53 |     0.35 |             |             |     0.00 |         |          |   1392 |   110 |  10MB | -72.41% | cell smart table scan (1)             |
| p022           | Set 1 |      23 |    0.94 |         |    0.53 |     0.40 |             |             |     0.00 |         |          |   1384 |    97 |  10MB | -72.41% |                                       |
| p023           | Set 1 |      24 |    0.93 |         |    0.52 |     0.41 |             |             |     0.00 |         |          |   9753 |   177 |  10MB | -66.67% |                                       |
| p024           | Set 1 |      25 |    1.07 |         |    0.53 |     0.53 |             |             |     0.00 |         |          |   7194 |   275 |  11MB | -66.67% |                                       |
| p025           | Set 1 |      26 |    1.15 |         |    0.54 |     0.53 |             |             |     0.08 |         |          |   2394 |    96 |  10MB | -75.44% |                                       |
| p026           | Set 1 |      27 |    1.13 |         |    0.54 |     0.59 |             |             |     0.00 |         |          |   5178 |   224 |  11MB | -63.93% | cell smart table scan (1)             |
| p027           | Set 1 |      28 |    0.94 |         |    0.48 |     0.45 |             |             |     0.00 |         |          |   3969 |   151 |  10MB | -69.49% |                                       |
| p028           | Set 1 |      29 |    0.99 |         |    0.54 |     0.45 |             |             |     0.00 |         |          |   1387 |    97 |  10MB | -75.44% | cell smart table scan (1)             |
| p029           | Set 1 |      30 |    0.80 |         |    0.54 |     0.26 |             |             |     0.00 |         |          |   1375 |    90 |  10MB | -75.44% |                                       |
| p030           | Set 1 |      31 |    1.10 |         |    0.62 |     0.48 |             |             |     0.00 |         |          |   2958 |   184 |  10MB | -69.49% | cell smart table scan (1)             |
| p031           | Set 1 |      32 |    1.03 |         |    0.52 |     0.51 |             |             |     0.00 |         |          |   1389 |   106 |  10MB | -69.49% | cell smart table scan (1)             |
====================================================================================================================================================================================================================
 
SQL Plan Monitoring Details (Plan Hash Value=3842559352)
==========================================================================================================================================================================================
| Id |            Operation            |   Name    |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read  | Read  |  Cell   | Activity |            Activity Detail            |
|    |                                 |           | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs  | Bytes | Offload |   (%)    |              (# samples)              |
==========================================================================================================================================================================================
|  0 | UPDATE STATEMENT                |           |         |      |           |        |     1 |          |       |       |         |          |                                       |
|  1 |   UPDATE                        | SKEW_HCC1 |         |      |      1552 |     +1 |     1 |        0 | 58650 | 458MB |         |    94.61 | gc current grant 2-way (1)            |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | log buffer space (5)                  |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | log file switch completion (3)        |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | Cpu (1359)                            |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | enq: FB - contention (2)              |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | cell single block physical read (122) |
|  2 |    PX COORDINATOR               |           |         |      |      1551 |     +2 |    33 |      32M |       |       |         |     3.68 | Cpu (58)                              |
|  3 |     PX SEND QC (RANDOM)         | :TQ10000  |     32M |  375 |      1551 |     +2 |    32 |      32M |       |       |         |     0.38 | Cpu (6)                               |
|  4 |      PX BLOCK ITERATOR          |           |     32M |  375 |      1551 |     +2 |    32 |      32M |       |       |         |          |                                       |
|  5 |       TABLE ACCESS STORAGE FULL | SKEW_HCC1 |     32M |  375 |      1551 |     +2 |   417 |      32M |  4675 | 324MB | -69.49% |     1.33 | Cpu (4)                               |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | cell single block physical read (6)   |
|    |                                 |           |         |      |           |        |       |          |       |       |         |          | cell smart table scan (11)            |
==========================================================================================================================================================================================
 
 
1 row selected.

In this example, we have an update statement that took a while, even though it was using Smart Scans. So what gives? When we looked at the output from SQL Monitor it was clear that it wasn’t spending all it’s time looking for the records to update, but rather on the update itself. As you might have guessed from the name of the table, this statement was attempting to update every row in a table that had been compressed using HCC (not something you would normally want to do). This caused a lot of extra work, migrating the rows to OLTP compressed blocks. So that’s what’s going on under the covers. The point of the example is that the report quickly focuses our attention on the area that needs investigation.

By the way, SQL Monitoring is supposed to kick in automatically for long running statements (over 5 seconds by default) and for parallel statements. Occasionally though we would like to see the SQL Monitoring Report on a statement that is not being monitored for some reason. Fortunately, there is a hint (MONITOR) that can be used to force SQL Monitoring. In situations where we don’t have access to the code, like a packaged app for example, we can apply the hint via a SQL Profile. I created a little script called fm.sql to do just that. And no fm doesn’t stand a radio frequency range, and no it doesn’t stand for some kind of magic, and no it’s not the name of a Steely Dan song (well it is, but that’s not why I called it that). It stands for “force monitoring”. Here’s an example:

#99cc00">?View Code NONE
 
 
*******************
Force Monitoring via a SQL Profile
*******************
 
 
SYS@SANDBOX1> select count(*) from kso.little_skew a;
 
  COUNT(*)
----------
   1100098
 
1 row selected.
 
SYS@SANDBOX1> @fsx
Enter value for sql_text: select count(*) from kso.little_skew a
Enter value for sql_id: 
 
SQL_ID         CHILD  PLAN_HASH  EXECS  AVG_ETIME AVG_PX OFFLOAD IO_SAVED_% SQL_TEXT
------------- ------ ---------- ------ ---------- ------ ------- ---------- ----------------------------------------------------------------------
8xrg1nunxn181      0 3498336203      1        .02      0 No             .00 select count(*) from kso.little_skew a
 
1 row selected.
 
SYS@SANDBOX1> @report_sql_monitor
Enter value for sid: 
Enter value for sql_id: 8xrg1nunxn181
Enter value for sql_exec_id: 
 
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
1 row selected.
 
SYS@SANDBOX1> -- It's a short duration non-PX statement so it wasn't monitored
SYS@SANDBOX1> -- let's force monitoring via a profile (we'll create the profile with fm.sql)
SYS@SANDBOX1> 
SYS@SANDBOX1> @fm
Enter value for sql_id: 8xrg1nunxn181
 
Profile PROFILE_8xrg1nunxn181_MONIOTR created.
 
SYS@SANDBOX1> select count(*) from kso.little_skew a;
 
  COUNT(*)
----------
   1100098
 
1 row selected.
 
SYS@SANDBOX1> @fsx
Enter value for sql_text: select count(*) from kso.little_skew a
Enter value for sql_id: 
 
SQL_ID         CHILD  PLAN_HASH  EXECS  AVG_ETIME AVG_PX OFFLOAD IO_SAVED_% SQL_TEXT
------------- ------ ---------- ------ ---------- ------ ------- ---------- ----------------------------------------------------------------------
8xrg1nunxn181      0 3498336203      1        .02      0 No             .00 select count(*) from kso.little_skew a
8xrg1nunxn181      1 3498336203      1        .02      0 No             .00 select count(*) from kso.little_skew a
 
2 rows selected.
 
SYS@SANDBOX1> @dplan
Enter value for sql_id: 8xrg1nunxn181
Enter value for child_no: 1
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  8xrg1nunxn181, child number 1
-------------------------------------
select count(*) from kso.little_skew a
 
Plan hash value: 3498336203
 
----------------------------------------------------------------------------------
| Id  | Operation                  | Name        | Rows  | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |             |       |  1546 (100)|          |
|   1 |  SORT AGGREGATE            |             |     1 |            |          |
|   2 |   TABLE ACCESS STORAGE FULL| LITTLE_SKEW |  1100K|  1546   (1)| 00:00:19 |
----------------------------------------------------------------------------------
 
Note
-----
   - SQL profile PROFILE_8xrg1nunxn181_MONITOR used for this statement
 
 
18 rows selected.
 
SYS@SANDBOX1> @report_sql_monitor
Enter value for sid: 
Enter value for sql_id: 8xrg1nunxn181
Enter value for sql_exec_id: 
 
REPORT
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
SQL Text
------------------------------
select count(*) from kso.little_skew a
 
Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  SYS (451:1845)
 SQL ID              :  8xrg1nunxn181
 SQL Execution ID    :  16777217
 Execution Started   :  04/10/2011 19:08:17
 First Refresh Time  :  04/10/2011 19:08:17
 Last Refresh Time   :  04/10/2011 19:08:17
 Duration            :  .020997s
 Module/Action       :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)/-
 Service             :  SYS$USERS
 Program             :  sqlplus@enkdb01.enkitec.com (TNS V1-V3)
 Fetch Calls         :  1
 
Global Stats
======================================
| Elapsed |   Cpu   | Fetch | Buffer |
| Time(s) | Time(s) | Calls |  Gets  |
======================================
|    0.02 |    0.02 |     1 |   5612 |
======================================
 
SQL Plan Monitoring Details (Plan Hash Value=3498336203)
=========================================================================================================================================
| Id |          Operation           |    Name     |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
|    |                              |             | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
=========================================================================================================================================
|  0 | SELECT STATEMENT             |             |         |      |         1 |     +0 |     1 |        1 |          |                 |
|  1 |   SORT AGGREGATE             |             |       1 |      |         1 |     +0 |     1 |        1 |          |                 |
|  2 |    TABLE ACCESS STORAGE FULL | LITTLE_SKEW |      1M | 1546 |         1 |     +0 |     1 |       1M |          |                 |
=========================================================================================================================================

So there you have it. A quick and dirty way to enable Real Time SQL Monitoring on a production statement that wasn’t being monitored by default.

I have really been using this capability a lot lately. Being able to see which steps in a complex plan are offloaded and what wait events are affecting which steps is very useful. The “Activity %” column which shows which steps the statement spent all it’s time on is also pretty helpful. It’s a tool that has moved very close to the top of my bag.

P.S. Greg Rahn has been a proponent of this report for some time and has been blogging about it for several years. Here’s one from Jan of 2008: Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR

Pop-Up Blockers

Submitted by Niall Litchfield on Mon, 2011-04-18 13:01

I’m not a fan of pop-up ads at all. This is quite a common position on the web and first led to the development of add-ins to popular browsers to prevent these being displayed and then to the browsers themselves blocking pop-ups. Something quite odd seems to have happened with Internet Explorer 9 however, when [...]

Consistent Reads

Submitted by Jonathan Lewis on Mon, 2011-04-18 11:08

Here’s a quick demo to make a point about consistent reads (prompted by a question on the Oracle-L mailing list):

SQL> drop table t1;

Table dropped.

SQL> create table t1 (n1 number);

Table created.

SQL> insert into t1  values(0);

1 row created.

SQL> begin
  2  for i in 1..1000 loop
  3  update t1 set n1 = i;
  4  end loop;
  5  end;
  6  /

PL/SQL procedure successfully completed.

Note that I haven’t issued a commit in this session, and all I’ve got is a single row in the table (and because it’s my usual demo setup of locally managed tablespaces with uniform extents of 1MB using freelist management I know that that one row is in the first available block of the table).

How much work is a second session going to do to scan that table ?

SQL> alter system flush buffer_cache;
SQL> execute snap_my_stats.start_snap
SQL> select * from t1;
SQL> set serveroutput on size 1000000 format wrapped
SQL> execute snap_my_stats.end_snap
---------------------------------
Session stats - 18-Apr 11:33:01
Interval:-  2 seconds
---------------------------------
Name                                                                     Value
----                                                                     -----
session logical reads                                                      967
consistent gets                                                            967
consistent gets from cache                                                 967
consistent gets - examination                                              964
consistent changes                                                       1,001
CR blocks created                                                            1
data blocks consistent reads - undo records applied                      1,001
IMU CR rollbacks                                                            41

The snap_my_stats package is similar in concept to Tom Kyte’s “runstats” or Tanel Poder’s “snapper” program to capture changes in values in the dynamic performance views over short time periods. In this case I’ve deleted all but a few of the larger changes, and a couple of small changes.

The figure that stands out (probably) is the “session logical reads” – we’ve done 967 logical I/Os to scan a tables of just one block. The reason for this is that we’ve created a read-consistent copy of that one block (“CR blocks created” = 1), and it has taken a lot of work to create that copy. We’ve had to apply 1,001 undo records (“data blocks consistent reads – undo records applied” = 1001).

Most of those undo records come from individual accesses (which are of the cheaper “consistent gets – examination” type that only need a single get on the “cache buffers chains” latch) to undo blocks, following the “UBA (undo block address)” pointer in the relevant ITL entry of the table block, but since this is a 10g database the last few undo records come out of the “In-memory Undo” of the other session. Basically the cloning operation is something like this:

  1. Get current block
  2. Notice uncommitted transaction
  3. Clone current block – then ignore current block
  4. Get Undo block indicated by uncommitted ITL and apply undo change vector
  5. Repeat step four – 1,000 times
  6. Block is now clear of all uncommitted transactions
  7. There are no committed transactions with a commit SCN later than the start of query
  8. Display contents of block

It is an interesting point that as the first session created undo records it would pin and fill undo blocks – so would only do a few current gets (one for each block) on the undo blocks it was using. As another process reverses out the changes in a CR clone it has to get and release each undo block every time it wants a single undo record … applying undo records introduces far more latch and buffer activity that the original generation of the undo.

Footnote

It’s worth knowing that there are three statistics relating to applying undo records:

transaction tables consistent reads - undo records applied        Estimating "old" commit SCNs during delayed block cleanout
data blocks consistent reads - undo records applied               Creating CR clones
rollback changes - undo records applied                           The result of a real "rollback;"

See this posting on comp.databases.oracle.server for a rough description of transaction table consistent reads; and this elderly posting highlighting a benefit of knowing about rollback changes.

Footnote 2

The second step in the list of actions is: “Notice uncommitted transaction”. It’s probably worth pointing out that another part of the ITL entry holds the transaction id (“xid”) which implicitly identifies the undo segment and transaction table slot in that segment that has been used to hold  the transaction state. The current contents of that slot allow Oracle to determine whether or not (and when, if necessary) the transaction was committed.

Chrysopylae, Part 2

Submitted by ddelmoli on Sun, 2011-04-17 17:59

Part 2 of my review of the Oracle GoldenGate 11g Implementer’s Guide begins with Chapter 5, Configuration Options.

The Configuration options chapter deals with more advanced options like batching, compression, encryption, triggering events, loop and conflict detection and DDL replication.

Batching and how SQL statements are cached to support batching, along with error handling and fallback processing are thoroughly explained.

Compression is also covered in some detail, with information about how GoldenGate cannot replicate data from Oracle compressed tables (including the EHCC compression from Exadata database machines).

In-flight (message) encryption and at-rest (trail) encryption is covered as well.

Event triggering is covered at a basic level, but gives a good insight as to what is possible – including the ability to have GoldenGate fire off a shell script in response to a particular set of values being detected in the capture process.

The discussion of bi-directional replication begins with a thorough list of items to be considered, including loops, conflict detection and resolution, sequences and triggers.

Conflict resolution options are slightly limited, and aren’t clearly defined – for example, applying a net difference instead of the after image is only useful in a subset of mathematical operations on numerical columns.  And there is no mention of prioritization by site (by which some sites updates always take precedence).  In truth, conflict resolution procedures can get pretty complicated, and I’m surprised there isn’t more information about them in this section or a referral to a later section (For example, Chapter 7 on Advanced Configuration).

The section on sequences is equally lacking in options, starting with a rather unclear statement about not supporting the replication of sequence values – what is really meant is that sequences themselves are not synchronized across multiple databases.  And the recommendation to use odd / even strategies is also rather simplistic – missing out on multi-master scenarios.  One can always reserve lower digits to enable more than 2 sites, and technically one can set up sequences to allow for an infinite number of sites as well…

Trigger handling advice is also rather simplistic – leading to more questions than answers as it talks about disabling triggers during the application of replicated data – there isn’t a mention of how that will affect an active / active system where local transactions are occurring.

There is a good discussion on DDL replication, with the information that the RECYCLEBIN must be disabled.

Chapter 6 – Configuring GoldenGate for HA

This chapter talks about GoldenGate in RAC environments, including the need for shared filesystems, and configuring GoldenGate with VIPs and with clusterware.  Sample scripts and commands are included – overall this chapter stays on point.

Chapter 7 – Advanced Configuration

In reality I’d call this chapter Configuration Details, but it does a very nice job of going through details around how to map objects in a replication configuration, as well as exploring the ability for GoldenGate to detect errors and execute SQL and/or stored procedures in response to those conditions.

Basic transformation is also covered.

Chapter 8 – Managing Oracle GoldenGate

This chapter covers basic command level security and spends a lot of time on the command interpreter GGSCI.  Also nice is a set of scripts and instructions to take performance output and format it for graphing in Excel.

Chapter 9 – Performance Tuning

The performance tuning chapter focuses on how to parallelize replication traffic and thoroughly exploit all system resources to increase throughput.  It also make mention of the 11.1 release of GoldenGate.  Details about tuning DBFS are also included. 

Like a lot of Performance Tuning advice, this section is more about throughput than performance optimization – in that vein it succeeds in covering ways to push more data more quickly.

Chapter 10 – Troubleshooting GoldenGate

The troubleshooting chapter begins with a good section on tracking down why replication may not be working – getting statistics on every process to see if they think they are capturing or sending data.  There is also good information on the CHECKPARAMS command which can be used to validate configuration files and the author also covers potential issues with the command.

The author covers the looking at checkpoints and networks as well.

There is a good section on creating exception handlers to capture and diagnose duplicate and missing record errors, including capture of before and after images.

Finally the chapter goes into detail on the LOGDUMP utility which can be used to examine trail files for error conditions.

Summary

Overall I found the book to be a good companion to the GoldenGate manuals and training materials.  It’s obvious that the author has a lot of configuration and operational experience with GoldenGate.  I found the book weak on design and planning for replication environments, so if you’re new to replication I’d suggest adding another book to your library above and beyond this one.