Thinking Out Loud

December 29, 2012

Poor Performance Compression Bug

Filed under: 11g,performance — mdinh @ 5:25 am

I was really puzzled why performance for compressed tables was horrendous.

My knowledge of the environment enabled me to make a hypothesis on the cause for performance degradation-db_block_checking.

I agree with Martin Berger the finding was generally indirect and not sure how someone else would have been able to identify the issue.

Even Oracle Support suggested the only hint is increase CPU. However, there can be many factors affecting CPU, e.g. nested loop.

The database version is 11.2.0.3 running on Sparc Solaris 10 64bit

Setup:

FACT table COMPRESS FOR OLTP with DEFAULT PCTFREE, INITTRANS settings (53 cols NOT NULL)
PK (1 col)
AK (3 col)
IX (1 col)
33,179,386 rows

STAGING table with DEFAULT PCTFREE, INITTRANS settingsĀ (52 cols, 1 col NOT NULL, remaining NULL)
No index/constraints
911,861 rows

Pseudo Code:

MERGE INTO FACT f USING STAGING s ON (f.KEY=s.KEY)
WHEN MATCHED THEN UPDATE SET … 52 columns

SQL Script:

set timing on serveroutput on
spool testcomp.log

exec runstats_pkg.rs_start;
commit;

alter session force parallel dml parallel 8;
@/oracle/sqlt/input/sample/oltp_false.sql
alter session disable parallel dml;

exec runstats_pkg.rs_middle;
commit;

alter session force parallel dml parallel 8;
@/oracle/sqlt/input/sample/oltp_medium.sql
alter session disable parallel dml;

exec runstats_pkg.rs_stop(0,’WORKLOAD’);
exec runstats_pkg.rs_stop(1000000);

alter system set db_block_checking=FALSE;
spool off

SQL Execution Snipit:

SQL> alter system set db_block_checking=FALSE;
System altered.
Elapsed: 00:00:00.01

SQL> set echo off
911861 rows merged.
Elapsed: 00:01:52.30
Commit complete.

SQL> alter system set db_block_checking=MEDIUM;
System altered.
Elapsed: 00:00:00.01

SQL> set echo off
911861 rows merged.
Elapsed: 00:23:44.38
Commit complete.

Run1 ran in 11483 hsecs  - db_block_checking=FALSE
Run2 ran in 142483 hsecs - db_block_checking=MEDIUM
run 1 ran in 8.06% of the time

Name                                                Run1            Run2        Diff
STAT...physical reads direct                     517,192         517,208              16
STAT...physical reads                            522,167         517,224          -4,943
STAT...physical reads cache                        4,975              16          -4,959
STAT...Elapsed Time                               11,487         142,487         131,000
STAT...recursive cpu usage                        34,909         498,166         463,257
STAT...CPU used by this session                   35,572         498,920         463,348
STAT...redo size                             889,907,464     892,430,032       2,522,568
STAT...session logical reads                   3,480,123       6,557,752       3,077,629

Run1 latches total versus runs -- difference and pct
Run1            Run2            Diff       Pct
20,508,977      68,940,229      48,431,252     29.75%
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.08

Run1 ran in 11483 hsecs  - db_block_checking=FALSE
Run2 ran in 142491 hsecs - db_block_checking=MEDIUM
run 1 ran in 8.06% of the time

Name                                                Run1            Run2        Diff
STAT...session uga memory max                    130,976       1,293,104       1,162,128
STAT...in call idle wait time                    115,158       1,409,641       1,294,483
LATCH.simulator hash latch                       247,055       1,556,432       1,309,377
LATCH.object queue header operation              205,535       1,766,312       1,560,777
STAT...session pga memory                        851,968        -720,896      -1,572,864
LATCH.transaction allocation                     108,304       1,936,419       1,828,115
STAT...DB time                                   189,534       2,196,702       2,007,168
STAT...redo size                             889,907,464     892,433,832       2,526,368
LATCH.checkpoint queue latch                      90,178       2,757,576       2,667,398
STAT...session logical reads                   3,480,123       6,557,897       3,077,774
STAT...consistent gets                           838,019       3,926,800       3,088,781
STAT...consistent gets from cache                 20,153       3,109,037       3,088,884
STAT...consistent gets - examination              11,341       3,101,011       3,089,670
STAT...data blocks consistent reads -
       undo records applied                            0       3,091,383       3,091,383
STAT...Effective IO time                       8,124,867       4,359,804      -3,765,063
LATCH.DML lock allocation                        450,593       5,815,377       5,364,784
STAT...file io wait time                      51,133,453      44,027,178      -7,106,275
LATCH.cache buffers chains                    14,751,617      45,136,022      30,384,405
STAT...physical read bytes                 8,555,184,128   8,474,198,016     -80,986,112
STAT...physical read total bytes           8,555,184,128   8,474,198,016     -80,986,112
STAT...cell physical IO interconnect byt   8,555,184,128   8,474,198,016     -80,986,112
STAT...logical read bytes from cache      43,618,418,688  94,044,405,760  50,425,987,072

Run1 latches total versus runs -- difference and pct
Run1            Run2            Diff       Pct
41,017,954     137,883,083      96,865,129     29.75%

Run1 - blk_checking_false
Disk Reads 522,167
Buffer Gets 3,479,799  
98% CPU Wait 1:60 (mm:ss)

Run2 - blk_checking_medium
Disk Reads 517,116
Buffer Gets 6,547,223
90% CPU Wait 21:08 (mm:ss)

Test shows db_block_checking and compression are bad for performance due to a bug.

Unfortunately, from the all the metrics I have looked at, there’s is not a direct indication to the cause.

Open to ideas as what to look for or what analysis can be performed.

I have used XTRACT, XECUTE, COMPARE, TRCANLZR from SQLTXPLAIN (SQLT) 11.4.5.2

References:

Notes with explanations for OLTP compression, db_block_checking, db_lost_write_protect.

Best Practices for Corruption Detection, Prevention, and Automatic Repair – in a Data Guard Configuration [ID 1302539.1]
Master Note for OLTP Compression [ID 1223705.1]

Bug 12711341: EXTREME SLOWNESS WITH DB_ULTRA_SAFE ON COMPRESSED TABLES

Customer is not happy with the performance of DML after enabling COMPRESS option and turning DB_BLOCK_CHECKING = FULL.

Bug 8931846: DB_BLOCK_CHECKING CAUSES LARGE PERFORMANCE HIT WITH COMPRESSED TABLE

About these ads

Leave a Comment »

No comments yet.

RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme. Create a free website or blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 313 other followers

%d bloggers like this: