Search
Navigation
OakieTags
Who's online
Affiliations
April 2011
Evidence
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)
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
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登場
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
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…
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
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):
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.
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:
******************* 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
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
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:
- Get current block
- Notice uncommitted transaction
- Clone current block – then ignore current block
- Get Undo block indicated by uncommitted ITL and apply undo change vector
- Repeat step four – 1,000 times
- Block is now clear of all uncommitted transactions
- There are no committed transactions with a commit SCN later than the start of query
- 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
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.
.png){kind=small}
TweetsPopular content
Today's:
Monthly archive
- December 2003 (1)
- November 2003 (1)
- September 2003 (1)
- August 2003 (1)
- « first
- ‹ previous
- 1
- 2
- 3
- 4
Recent comments
1 year 7 weeks ago
1 year 16 weeks ago
1 year 18 weeks ago
1 year 21 weeks ago
1 year 23 weeks ago
1 year 33 weeks ago
1 year 35 weeks ago
1 year 36 weeks ago
1 year 36 weeks ago
1 year 38 weeks ago