Is plan_hash_value a final say?

I was reviewing a performance issue with a client recently. Problem is that increased global cache waits causing application slowdown affecting few critical business functions. Using one of my script gc_traffic.sql > and graphing the results with Excel spreadsheet, it is established that there is a marked increase in GC traffic today compared to week earlier. Similar jobs runs every day and so comparing two week days is sufficient to show the GC traffic increase. Graph is between total blocks and AWR snap time in 30 minutes interval. [Click the picture below to review the graph clearly.]

Identifying the object creating this increased GC traffic is essential to identify root cause. We were able to quickly determine that this increase in GC traffic was localized around few SQL statements using ADDM and AWR reports. We decided to focus on one SQL with an obvious increase in elapsed time compared to prior week. So, first question asked, is there a change in the plan? plan_hash_value was reviewed and quickly determined that there is no change in the plan_hash_value.

RMOUG Training Days 2009

I had a privilege of presenting two papers in RMOUG Training days 2009 for the past couple of days. It is always been a valuable conference to attend considering quality of presentations. This proved to be true and was an excellent conference this year too.

During my presentation, I promised that I will upload recent copy of my papers and presentations in my blog and here they are:

1. Performance features 11g ppt
2. Performance features 11g paper
3. Battle of the nodes RAC performance myths presentation
4. Battle of the nodes RAC performance myths paper

I also met many awesome presenters such as mogens nørgaard , Stephen Haisley, Jeff Needham, Gaja , Cary Millsapp , Daniel Fink , Danial Morgan , Joze Senegacnik , Carol Dacko, Dan Norris, Tanel , Jeremiah Wilton, Kevin Closson to name a few. Apologies, if I missed anybody, many valuable presentations and highly knowledgeable presenters attended this conference.

I attended few presentations:
A valuable presentation by Jeremiah Wilton, on breaking Oracle. Especially, when he created ORA-600 errors with “Ouch” and other funny remarks as arguments, whole room went in to laughter. This presentation can be downloaded from his blog .

Tanel had an interesting presentation about ‘How execution plan works?”. He explained, internally, how various row sources are simply calls to various function calls etc. Very valuable presentation indeed. Tanel said that he will upload his presentations to his blog soon.

Joze, from wonderful Slovenia, gave a presentation about SQL Plan Management. This is a very important new feature and will be extremely useful for plan stability.

Of course, I had few interesting offline and thought provoking discussions with many others. Stephen Haisley shared some new features about streams and it will be great to see that one day. I had a length conversation with Kevin Closson about NUMA, CPU cache line and his days with NUMA engineering and development (in sequent).

How to find objects creating nologging changes?

In an Oracle-l thread, a question was raised: How to find objects creating nologging changes?

What is a ‘nologging’ change?

Redo logging mechanism plays critical role in media recovery. Media recovery relies on archivelog files generated to roll forward the database. Standby database or dataguard recovery also relies on archivelog files. It is possible to do DML changes with minimal logging, aka nologging changes or direct mode inserts. For example, insert /*+ append */ can be used to populate the rows in to a table without generating much redo. This can invalidate standby database and might trigger rebuilding some or all parts of the standby database.

Nologging changes generates minimal redo, since the blocks are pre-formatted and written to disk directly. A redo record is generated invalidating a range of affected blocks. This invalidation redo record size is far smaller, for e.g. hundreds of blocks can be invalidated using just a single redo record. Of course, recovery is severely affected as the changes performed with nologging operations can NOT be reapplied / recovered.

Internals of nologging changes

Since nologging is all about redo records, dumping redo log file or archivelog file is a concrete way to see what happens under the hood. Let’s consider an example to explain internals of nologging changes.

We will create a table, insert rows, and review redo records closely.

  create table t4 ( a number) nologging tablespace users;
  REM switch log file so that we wil have smaller log files to dump.
  alter system switch logfile;
  REM Direct mode or nologging inserts
  insert /*+ append */ into t4 select object_id from dba_objects;
  commit;
  alter system switch logfile;

Prior online redo log file contains nologging changes from table t4 above. We could dump that log file in its entirety, but we will dump just a layer specific to direct mode changes alone to limit trace file size. Layer 19 is for nologging changes. Following script will dump last online redo log file for layer 19.

 set serveroutput on size 1000000
 declare
   v_sqltext varchar2(255);
 begin
   -- Find name of latest but one log file.
   select 'alter system dump logfile '||chr(39)||
                member||chr(39) || ' layer 19 '
   into v_sqltext
   from
   v$log  lg, v$logfile lgfile
   where lg.group# = lgfile.group# and
   lg.sequence# =
       (select sequence#-1 from v$log where status='CURRENT' )
   and rownum <2;
   dbms_output.put_line ('Executing :'||v_sqltext);
   --Execute above SQL to dump log file and print it to see.
   execute immediate v_sqltext;
  end;
/

alter system dump logfile 'D:\ORACLE\ORADATA\ORCL11G\REDO02.LOG' layer 19

Above command generated a trace file in user_dump_dest directory and few redo records from that trace file printed below:

...
REDO RECORD - Thread:1 RBA: 0x0000b0.0000000f.00d4 LEN: 0x0034 VLD: 0x01
SCN: 0x0000.00486397 SUBSCN:  1 09/03/2008 10:54:38
CHANGE #1 INVLD AFN:4 DBA:0x01038824 BLKS:0x0001 OBJ:72852 SCN:0x0000.00486397 SEQ:  1 OP:19.2
Direct Loader invalidate block range redo entry

REDO RECORD - Thread:1 RBA: 0x0000b0.00000014.0118 LEN: 0x0034 VLD: 0x01
SCN: 0x0000.0048639a SUBSCN:  1 09/03/2008 10:54:38
CHANGE #1 INVLD AFN:4 DBA:0x01038832 BLKS:0x0001 OBJ:72852 SCN:0x0000.0048639a SEQ:  1 OP:19.2
Direct Loader invalidate block range redo entry
...

Explanation of redo records

Let’s review following two lines.

CHANGE #1 INVLD AFN:4 DBA:0x01038832 BLKS:0x0001 OBJ:72852 SCN:0x0000.0048639a SEQ:  1 OP:19.2
Direct Loader invalidate block range redo entry

OP:19.2 indicates that layer is 19 for this change vector and 2 is the opcode. This vector also specifies that BLKS=1 and DBA as 1038832. Essentially this change vector says “Invalidate range of blocks starting at block DBA 0x01038832 for 1 block”. This could be for a range of blocks too.

For nologging changes a block range invalidation redo generated, block formatted, populated with rows and written directly to disk. But, standby database and media recovery rely on redo records to replay these changes. When recovery code encounters above direct loader invalidate redo record, it throws a warning to alert log and simply mark that range of blocks as invalid. Any attempt to access those blocks will throw ORA-1578 block corruption error.

Just to reiterate, standby and media recovery are affected by nologging changes. But, Current database is still fine and there is no corruption in primary database. If we backup the primary database again or rebuild that tablespace in standby database, we avoid corruption. Point is that, if there is a business need to have nologging changes, consider taking a backup immediately after nologging changes. Of course, if there is a standby database involved, then that tablespace need to be re-copied from production.

Back to our problem

We need to find the object causing nologging changes. Field OBJ:72852 shows object_id in decimal. We can query dba_objects to find object_name.

select owner, object_name from dba_objects where
object_id=72852 or data_object_id=72852
SQL> /
OWNER                          OBJECT_NAM
------------------------------ ----------
CBQT                           T4

In essence, procedure to find object_name causing nologging generation is:

1. Find archivelog containing nologging changes. If timestamp is known, then v$archived_log can be queried to find archivelog file name.

2. Dump archivelog file for layer 19: alter system dump logfile ‘filename’ layer 19;

3. Locate redo record with opcode 19.2.

4. Query dba_objects for that object_id.More information about redo internals can be found in redo internals doc

Hotsos 2008 is over

I have been a regular presenter in hotsos performance intensive conference, three years in a row. This year my presentation was about cost based subquery transformation. Optimizer has become far smarter in 11g, and subqueries are transformed and cost calculated using physical optimizer. Enough about that.

As usual, I met many of my friends, Mark Bobak, Alex Gorbachev, Robyn Sands, Joze Sengachnik, Kyle Hailey, Jared Still, Wolfgang B, Carol Decko, Stephen Knecht, Christian Antognini and so on. We had a wonderful time on Monday in Bob’s steak house, good time on Wednesday in downtown dallas.

Now, I can’t wait for next HOTSOS!

At last, my blog is up.

This has been one of my long pending wishes to have a blog and update it regularly.

I am an Oracle Database Administrator and I specialize in Oracle database internals and performance tuning. My emphasis currently in Real Application Clusters and E-Business Suite.

Hopefully, I will keep this blog updated and love to hear your comments.

I have also written couple of articles, presented few and will upload them here soon.