Archive

Archive for the ‘performance’ Category

Performance live discussion on twitter, 12pm PST Tue April 15

April 14th, 2014

Followup:

 The tweets from the datachat are available at

http://www.confio.com/logicalread/oracle-db-performance-80-percent-hardware-dc01/

in chronological order.

 


Confio software is hosting a live discussion on twitter tomorrow Tuesday April 15 at 12pm PST on the subject of Oracle performance.

I’ll be online answering performance questions and have invited many other friends to participate. Some friends who’ve said they’ll be there are

Participation and tracking of the discussion can accomplished by either posting with and  following along with the #datachat  hashtag.

Get on TweetDeck or your favorite Twitter tool, search #datachat, add a column and you’ll see our chat appear. Always include #datachat in your tweet so you’ll be part of the conversation.

For an example of a previous #datachat check out Confio’s hosting of  Pete Finnigan on  the subject of security.

 

8109445607_150e8a5310_z

photo by elod beregszaszi

performance

Oracle SQL*Net Wait Events

March 24th, 2014

 

Introduction

Unfortunately, what Oracle calls “Network Waits” most often have little to do with Network but and almost exclusively to do with the time it takes to pack messages for the network before they are sent.
Client = you, the tool, sqlplus, application
Not the client, the other side = the shadow process is communicating to the client

Of the three waits, only “more data” is possibly related to network issues and that’s not even clear, the other two are simply the time it takes to pack a message before sending it.

SQL*Net message to client – time to pack a message (no network time included) possibly tune SDU
SQL*Net more data from client – possible network issues, possibly tune SDU
SQL*Net more data to client – time to pack a message (no network time included) possibly tune SDU

 

 The same events exist, but where the client is the shadow process and another database plays the roll of shadow process:

 

SQL*Net message to dblink 
SQL*Net more data from dblink – possible network issues, possibly tune SDU
SQL*Net more data to dblink 

 

SQL*Net Wait Events

 

SQL*Net message from client

Idle Event
Waiting for work from Client
Includes network transmission times for messages coming from shadow

Typically indicative of Client “think time” or “processing time”
Example from Egor Starostin,  http://oracledba.ru
From a 10046 trace
    =====================
   PARSING IN CURSOR #1 len=43 dep=0 uid=0 oct=3 lid=0 tim=1304096237
    hv=2707617103 ad=’89a03e18′
    select * from all_objects where rownum < 20
    END OF STMT
    PARSE #1:c=0,e=143,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1304096209
    EXEC #1:c=0,e=744,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1304097036
    WAIT #1: nam=’SQL*Net message to client’ ela= 3 driver id=1650815232
    #bytes=1 p3=0 obj#=-1 tim=1304097096
    FETCH #1:c=10000,e=6903,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=1304104057
1->WAIT #1: nam=’SQL*Net message from client‘ ela= 721 driver
    id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1304104865        # [non-idle]
    WAIT #1: nam=’SQL*Net message to client’ ela= 1 driver id=1650815232
    #bytes=1 p3=0 obj#=-1 tim=1304105319
    FETCH #1:c=0,e=627,p=0,cr=21,cu=0,mis=0,r=15,dep=0,og=1,tim=1304105524
2->WAIT #1: nam=’SQL*Net message from client‘ ela= 253 driver
    id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1304105818        # [non-idle]
    WAIT #1: nam=’SQL*Net message to client’ ela= 1 driver id=1650815232
    #bytes=1 p3=0 obj#=-1 tim=1304105867
    FETCH #1:c=0,e=63,p=0,cr=6,cu=0,mis=0,r=3,dep=0,og=1,tim=1304105900
3->WAIT #1: nam=’SQL*Net message from client‘ ela= 1960753 driver
    id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1306066946 # [idle]
    =====================
    PARSING IN CURSOR #1 len=21 dep=0 uid=0 oct=3 lid=0 tim=1306069444
    hv=2200891488 ad=’89913b50′
    select user from dual
    END OF STMT
    PARSE #1:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1306069440
    …
The first two “SQL*Net message from client’ are in the middle of cursor processing and are considered non-idle waits.
The third “SQL*Net message from client” is between cursors and considered an idle event, ie we are waiting for the next command from the client.

 

SQL*Net message to client

Time it takes to pack a message to be sent to the client
Doesn’t include network timing
see Tanel Poder’s analysis of SQL*Net message to client

 

SQL*Net more data to client

Same as SQL*Net message to client except this is for data that spans SDU packets.

Wait represents the time it takes to pack data.
Doesn’t include network timing

 

SQL*Net more data from client

The only SQL*Net wait that can indicate a possible NETWORK problem
Client is sending data to shadow that spans packets (think large data inserts, possibly large code blocks, large SQL statements)
Shadow waits for next packet.
Can indicate network latency.
Can indicate a problem with the client tool
Here is an example with ASHMON where the application server died mid-stream on inserts. The shadow processes were left waiting for completion of the message. You can see the regular load on the database on the left, then just past the middle the load crashes, and all that’s left is waits on “SQL*Net more data from client”

Possibly set SDU=32768 as well as setting RECV_BUF_SIZE and SEND_BUF_SIZE to 65536.

 

SQL*Net break/reset to client

Error in sql statement

Control C
Usually highlights and error in application
Example:
       CREATE TABLE T1 (C1 NUMBER);
       ALTER TABLE T1 ADD
            (CONSTRAINT T1_CHECK1 CHECK (C1 IN ('J','N')));
       ALTER SESSION SET EVENTS
            '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
       INSERT INTO T1 VALUES (1);
Trace File
       PARSING IN CURSOR #2 len=25 dep=0 uid=0 oct=2 lid=0 tim=5009300581224 hv=981683409 ad='8e6a7c10'
       INSERT INTO T1 VALUES (1)
       END OF STMT
       PARSE #2:c=0,e=2770,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=5009300581220
       BINDS #2:
       EXEC #2:c=0,e=128,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=5009300581418
       ERROR #2:err=1722 tim=512952379
       WAIT #2: nam='SQL*Net break/reset to client' ela= 31 driver id=1650815232 break?=1 p3=0 obj#=-1 tim=5009300581549
       WAIT #2: nam='SQL*Net break/reset to client' ela= 92 driver id=1650815232 break?=0 p3=0 obj#=-1 tim=5009300581662
Unfortunately Oracle doesn’t give much information about debugging unless you are trace. If you don’t trace, the SQL won’t be captured because from Oracle’s point of view the problem statement isn’t an acceptable SQL statement so there is no SQL ID to track down.

 

DBLINK SQL*Net Waits

These waits are the same as
SQL*Net message to dblink

SQL*Net more data from dblink
SQL*Net more data to dblink
SQL*Net break/reset to dblink

 

Analysis and Tuning

There isn’t much to do on the Oracle side for tuning. You can try optimizing the SDU and SEND_BUF_SIZE and RECV_BUF_SIZE.
For actually getting information on network speeds you will have to use something like
  • ping
  • tnsping
  • network sniffer

 

SDU

The default SDU can be set in the sqlnet. ora
If it’s not set, the default is 2048
The max is 32768
The default,or the value in sqlnet.ora, can be overridden in the tnsnames. ora and the listener.ora. The client and server negotiate the size aggreeing on the smaller of the two settings.
(TDU – Transmission Data Unit – see note 44694.1 The TDU parameter has been deprecated in the Oracle Net v8.0 and beyond and is ignored. It is only mentioned here for backward compatibility.)
tnsnames.ora
      V10G = (DESCRIPTION =
      (SDU=32768)
      (ADDRESS = (PROTOCOL = TCP)(HOST = fuji)(PORT = 1522))
      (CONNECT_DATA =
      (SERVER = DEDICATED) (SERVICE_NAME = v10g)
) )
listener.ora
       SID_LIST_LISTENER =
       (SID_LIST =
       (SID_DESC =
       (SDU=32768)
       (SID_NAME = v10g)
       (ORACLE_HOME = /export/home/oracle10)
))

Tracing

sqlnet.ora

       trace_level_client=16
       trace_directory_client=/tmp
       trace_file_client=client.trc
       trace_unique_client = true
       trace_level_server=16
       trace_directory_server=/tmp
       trace_file_server=server.trc

client.trc

       client_3582.trc:[12-JAN-2008 11:37:39:237] nsconneg: vsn=313, gbl=0xa01, sdu=32768, tdu=32767

more from Jonathan Lewis at http://www.jlcomp.demon.co.uk/sdu.html

 

RECV_BUF_SIZE and SEND_BUF_SIZE

The recommended size for these buffers (from Oracle’s docs) is at least
Network bandwidth * roundtrip = buffer min size
For example if the network bandwidth is 100mbs and the round trip time (from ping) is 5ms then
           100,000,000 bits   1 byte   5 seconds
           ---------------- x ------ x --------- = 62,500 bytes
            1 second          8 bits     1000
tnsnames.ora
           V10G = (DESCRIPTION =
           (SEND_BUF_SIZE=65536)
           (RECV_BUF_SIZE=65536)
           (ADDRESS = (PROTOCOL = TCP)(HOST = fuji)(PORT = 1522))
           (CONNECT_DATA =
           (SERVER = DEDICATED) (SERVICE_NAME = v10g)
           ) )
 
listener.ora
           SID_LIST_LISTENER =
           (SID_LIST =
           (SID_DESC =
           (SEND_BUF_SIZE=65536)
           (RECV_BUF_SIZE=65536)
           (SID_NAME = v10g)
           (ORACLE_HOME = /export/home/oracle10)
           ))
 
sqlnet.ora
          RECV_BUF_SIZE=65536
          SEND_BUF_SIZE=65536

 

performance, wait events

Oracle : buffer busy wait

March 21st, 2014

 

Oracle 10 and 11

Buffer Busy Waits usually happen on Oracle 10 and 11 mainly because of insert contention into tables or Indexes.  There are a few other rare cases of contention on old style RBS segments, file headers blocks and freelists.
Before Oracle 10 and 11 there was one other major reason which was readers waiting for readers, ie one user does a phyiscal IO of a block into memory and a second user want to read that block. The second user waits until the IO is finished by the first user. Starting in 10g this wait has been given the name “read by other session“.  Before Oracle 10g this was also a “buffer busy wait”.
The easiest way to analyse the bottleneck and find a solution is to use ASH (active session History) available in Oracle 10g with the diagnostics pack license or using Simulated ASH for free or using a product like DB Optimizer.
Data block class, which can be found in ASH,  is the most important piece of information in analysing buffer busy waits. If we know the block class we can determine what kind of bottleneck:
 If CLASS=
    1. data block
      • IF OTYPE =
      • INDEX , then the insert index leaf block is probably hot, solutions are
        • Hash partition the index
        • Use reverse key index
      • TABLE, then insert block is hot,solutions
        • Use free lists
        • Put Object in ASSM tablespace
    2. Segment header – If “segment header” occurs at the same time as CLASS= “data block” on the same object and the object is of OTYPE= “TABLE”  then this is just a confirmation that the TABLE needs to use free lists or  ASSM.
    3. File Header Block – Most likely extent allocation problems, look at extent size on tablespace and increase the extent size to there are few extent allocations and less contention on the File Header Block.
    4. free lists – Add free list groups to the object
    5. undo header – Not enough UNDO segments, if using old RBS then switch to AUM
    6. undo block – Hot spot in UNDO, application issue
How do we find the block class? With a quick query on the ASH data like:

select
       o.object_name obj,
       o.object_type otype,
       ash.SQL_ID,
       w.class
from v$active_session_history ash,
     ( select rownum class#, class from v$waitstat ) w,
      all_objects o
where event='buffer busy waits'
   and w.class#(+)=ash.p3
   and o.object_id (+)= ash.CURRENT_OBJ#
Order by sample_time;
For Example

 

OBJ    OTYPE  SQL_ID        CLASS
------ ------ ------------- ------------------
TOTO1  TABLE  8gz51m9hg5yuf data block
TOTO1  TABLE  8gz51m9hg5yuf data block
TOTO1  TABLE  8gz51m9hg5yuf segment header
TOTO1  TABLE  8gz51m9hg5yuf data block
If we find that CLASS=datablock, then we will want more information to diagnose, such as the object type “OTYPE” , object name and what kind of tablespace the object is stored in. The following query provides that information:

set linesize 120

col block_type for a20
col objn for a25
col otype for a15
col filen for 9999
col blockn for 9999999
col obj for a20
col tbs for a10
select
       bbw.cnt,
       bbw.obj,
       bbw.otype,
       bbw.sql_id,
       bbw.block_type,
       nvl(tbs.name,to_char(bbw.p1)) TBS,
       tbs_defs.assm ASSM
from (
    select
       count(*) cnt,
       nvl(object_name,CURRENT_OBJ#) obj,
       o.object_type otype,
       ash.SQL_ID sql_id,
       nvl(w.class,'usn '||to_char(ceil((ash.p3-18)/2))||' '||
                    decode(mod(ash.p3,2),
                         1,'header',
                         0,'block')) block_type,
       --nvl(w.class,to_char(ash.p3)) block_type,
       ash.p1 p1
    from v$active_session_history ash,
        ( select rownum class#, class from v$waitstat ) w,
        all_objects o
    where event='buffer busy waits'
      and w.class#(+)=ash.p3
      and o.object_id (+)= ash.CURRENT_OBJ#
      and ash.session_state='WAITING'
      and ash.sample_time > sysdate - &minutes/(60*24)
      --and w.class# > 18
   group by o.object_name, ash.current_obj#, o.object_type,
         ash.sql_id, w.class, ash.p3, ash.p1
  ) bbw,
    (select   file_id, 
       tablespace_name name
  from dba_data_files
   ) tbs,
    (select
 tablespace_name    NAME,
        extent_management  LOCAL,
        allocation_type    EXTENTS,
        segment_space_management ASSM,
        initial_extent
     from dba_tablespaces 
   ) tbs_defs
  where tbs.file_id(+) = bbw.p1
    and tbs.name=tbs_defs.name
Order by bbw.cnt
/
and the output looks like

  CNT OBJ     OTYPE   SQL_ID        BLOCK_TYPE       TBS        ASSM

----- ------- ------- ------------- ---------------- ---------- ------
    3 TOTO1   TABLE   8gz51m9hg5yuf segment header   NO_ASSM    MANUAL
   59 TOTO1   TABLE   8gz51m9hg5yuf data block       NO_ASSM    MANUAL
Oracle 7, 8 and 9

Before Oracle 10, buffer busy waits also happened because IO blocking another user wanting to do the same IO. On Oracle 9, the main reasons for buffer busy waits are

1)       IO read contention (only Oracle 9i and below)

2)       Insert Block Contention on Tables or Indexes
3)       Rollback Segment Contention

On  7.0  – 8.1.5 see http://sites.google.com/site/embtdbo/oracle-buffer-busy-wait/oracle-buffer-busy-wait-7-8-1-5

On version 8 and 9, the p3 value has a different meaning. Instead  of meaning the block type (which is the best thing to know) it means the kind of buffer busy wait. There are only two values that matter to us, values in

100 range = read waits (basically just an IO wait)

Reader blocking Reader, ie one reader is reading a block in and another person wants to read this block and waits on a buffer busy wait p3=130.

200 range = write contetion (same as in 10g)

Writers blocking other writers for example while doing inserts either because of no free lists on the table or because everyone is inserting into the same index block.

If you have set up ASH style collection with S-ASH or have a product like DB Optimizer you can run a query like:

select

       count(*) cnt,
       o.object_name obj,
       o.object_type otype,
       ash.CURRENT_OBJ#,
       ash.SQL_ID,
       decode(substr(ash.p3,1,1),1,'read',2,'write',p3) p3
from v$active_session_history ash,
      all_objects o
where event='buffer busy waits'
   and o.object_id (+)= ash.CURRENT_OBJ#
group by o.object_name, o.object_type, ash.sql_id, ash.p3,ash.CURRENT_OBJ#
order by cnt
/
And see what kind of buffer busy waits there are and what the objects are:

 CNT OBJ     OTYPE   CURRENT_OBJ#     SQL_ID P3

--- ------- ------- ------------ ---------- ------
  1                           -1 1375352856 read
  2                           -1  996767823 read
  2                           -1 2855119862 write
 17                           -1 1375352856 write
 89 TOTO1   TABLE         296030 1212617343 write
109                       296022 1212617343 write

Often the Current_obj# is -1 so we can’t figure out what the object is . There is an alternative method

col block_type for a18

col objn for a25
col otype for a15
col event for a15
col blockn for 999999
col segment_name for a20
col partition_name for a15
col owner for a15
set timing on
/*
drop table myextents;
l
create table myextents as select * from dba_extents;
l
*/
select
       count(*),
       ext.owner,
       ext.segment_name,
       ext.partition_name,
      ext.segment_type,
        decode(substr(ash.p3,1,1),1,'read',2,'write',p3) p3
       --ash.p1,
       --ash.p2
from v$active_session_history ash,
     myextents ext
where
       event = 'buffer busy waits'
   and ( current_obj# = -1 or current_obj#=0  or current_obj# is null )
   --and sample_time > sysdate - &minutes/(60*24)
   --and session_state='WAITING'
   and  ext.file_id(+)=ash.p1 and
        ash.p2 between  ext.block_id and ext.block_id + ext.blocks
group by
       ext.owner,
       ext.segment_name,
       ext.partition_name,
       ext.segment_type,
       p3
       --ash.p1,
       --ash.p2,
       --ash.sql_id
Order by count(*)
/
Because querying DBA_EXTENTS  is a slow operation, I made a copy of DBA_EXTENTS which will be faster to query.

CNT OWNER  SEGMENT_NAME   PARTITION_NAME  SEGMENT_TYPE  P3

--- ------ -------------- --------------- ------------- --------
  1 SYS    _SYSSMU2$                      TYPE2 UNDO    read
  1 SYS    _SYSSMU3$                      TYPE2 UNDO    write
This second option of getting the object from P1 and P2 (file and block) should probably be done only with the users consent, because we would have to create a copy of the dba_extent table which might take a long time if it’s big.
No ASH ?

If you don’t have ASH data you will have to do some guess work.
Block Class (block type)

The first step in finding out the source of buffer busy waits is looking at

     V$waitstats
This will tell us what kind of datablocks we have contention on.
File with contention

You can also get an idea of what file contains the object with the buffer busy waits by looking at:

    X$KCBFWAIT
Object with contention

Starting in version 9i there is the table

    v$segstat
That will list the objects with buffer busy waits.
If you are on version 7 or 8 good luck finding the object without setting up ASH style data collection.
Why do buffer busy waits happen?

To put it most succinctly, buffer busy waits happen because two users want to change a block at the same time. Two users can change the same block, or even same row “at the same time” ie without committing, but that’s different from the actual operation of modifying the block. The modification on the block in RAM, or computer memory, can only be done by one process at at time in order to avoid memory corruptions. Different users can modify different blocks at the same time but only one user or process can modify a the same block at a time.
In order to really understand what’s going on we have to take a look at how Oracle manages memory and block access and modifications.
Here is the layout of
Above is a diagram shows some of the essential parts of Oracle in regards to performance tuning.
In the machine memory are
  •     Oracle’s SGA, or System Global Area, a memory that is shared between Oracle users
  •     LGWR – log writer process
  •     DBWR – database writer process
  •     User1,2,3 … – user processes, in this case “shadow processes”

On the machine file system are

  • Redo log files
  • Data files
The SGA is composed of (among other things)
  • Log Buffer
  • Library Cache
  • Buffer Cache
What’s important for understanding buffer busy waits is how the buffer cache is managed. Here is view of the buffer cache with more components:
In order to access a block, a user (shadow process) has to get a latch (cache buffer chains latch) which protects buckets or linked lists of buffer headers. Once the header desired if found the latch is released. The buffer headers point to the actual data block in memory. Before modifying a block in memory a user has to lock the buffer header. The buffer header is locked any time a modification is made whether it is reading a block into memory or modifying a block that is already in memory. Usually the header is locked only for a brief amount of time but when there is a lot of concurrent access the buffer header can become a bottleneck.
BBW when readling data – read by other session

A buffer busy can happen on oracle 7,8 and 9 when one user is reading a block into memory and a second user wants to read that block. Instead of the second user trying to read that block into memory as well, they just wait for the first user to finish. Starting in Oracle 10, this kind of wait was renames “read by other session”

BBW on insert
If multiple concurrent users are inserting into a table that doesn’t have free lists or is not in an ASSM tablespace then all users will end up inserting into the same block, the first one on the free list and this block will become the hot block
by adding free lists or moving the table to an ASSM tablespace we will alleviate the bottleneck.
Multiple free lists:
The other option is ASSM or Automatic Segment Space Management which is set at the tablespace level.
In this case free block information is kept in Level 1 BMB (or bitmapped blocks). These Level 1 BMBs are chosen by a hash on the users process ID thus distributing the inserts across the table.
The inserts would look something like this (somewhat exaggerated drawing)
the ASSM BMB blocks take up more space in the table , about 1 extra block for every 16 data blocks and there is overhead first looking in the header/level 3 BMB block then going to the Level 2  then level 1 and finally to the datablock but all in all ASSM is worth reduced costs of management verses free lists.
Identifying and creating ASSM tablespaces
Which tablespaces are ASSM or not?

select

        tablespace_name,
        extent_management  LOCAL,
        allocation_type    EXTENTS,
        segment_space_management ASSM,
        initial_extent
from dba_tablespaces

TABLESPACE_NAME LOCAL      EXTENTS   ASSM

--------------- ---------- --------- ------
SYSTEM          LOCAL      SYSTEM    MANUAL
UNDOTBS1        LOCAL      SYSTEM    MANUAL
SYSAUX          LOCAL      SYSTEM    AUTO
TEMP            LOCAL      UNIFORM   MANUAL
USERS           LOCAL      SYSTEM    AUTO
EXAMPLE         LOCAL      SYSTEM    AUTO
DATA            LOCAL      SYSTEM    MANUAL
creating an ASSM tablespace:

create tablespace data2 

datafile '/d3/kyle/data2_01.dbf' 
size 200M
segment space management auto;

BBW on index (because of insert)

If users are inserting data that has a rising key value, especially a monotonically rising value, then all the new inserts will have to update the leading edge leaf block of the index and with high concurrent inserts this can cause buffer busy waits.
Solutions
Hash partition the index
Reverse Key Index

BBW on old style RBS

IF block class > 18 it’s an old style RBS segment

Select  CURRENT_OBJ#||' '||o.object_name objn,

          o.object_type otype,
          CURRENT_FILE# filen,
          CURRENT_BLOCK# blockn,
          ash.SQL_ID,
          w.class ||' '||to_char(ash.p3) block_type
from v$active_session_history ash,
      (select rownum class#, class from v$waitstat ) w,
       all_objects o
where event='buffer busy waits'
    and w.class#(+)=ash.p3
    and o.object_id (+)= ash.CURRENT_OBJ#
Order by sample_time;    

OBJN        OTYPE  FILEN  BLOCKN SQL_ID        BLOCK_TYPE

----------- ------ ------ ------ ------------- ------------
54962 TOTO1 TABLE     16   45012 8gz51m9hg5yuf data block 
54962 TOTO1 TABLE     16     161 8gz51m9hg5yuf segment header
0                     14       9 8gz51m9hg5yuf  87
0                     14       9 8gz51m9hg5yuf  87

IF the block is of class > 18, the there will be no object name, so we have to look it up ourselves to be sure:

select  segment_name,  

            segment_type
from     dba_extents 
where
     &P2  between 
    block_id and block_id + blocks – 1
     and 
     file_id = &P1 ;

Plug in 14 for P1 the file # and 9 for P2 the block number:

SEGMENT_NAME   SEGMENT_TYPE

-------------- --------------
R2             ROLLBACK
solution
move to new AUM or Automatic Undo Mangement
alter system set undo_management=auto  scope=spfile;
BBW on a file header
The ASH data has two different fields that indicate the file # and block # when the wait is a buffer busy wait.
For a buffer busy wait
    File # = p1  *and* File # = current_file#
    Block # = P2  *and* Block # = current_block#
if  p1 != current_file#  or p2 != current_block# then use p1 and p2. They are more reliable.
for example

Time   P1  P2 OBJN OTYPE FN BLOCKN BLOCK_TYPE

----- --- --- ---- ----- -- ------ -----------------
11:44 202   2 -1          0      0 file header block
11:44 202   2 TOTO TABLE  1  60218 file header block
11:44 202   2 TOTO TABLE  1  60218 file header block
11:44 202   2 TOTO TABLE  1  60218 file header block
11:44 202   2 TOTO TABLE  1  60218 file header block
Notice P1 != BLOCKN (BLOCKN is CURRENT_BLOCK#)  and P2 != FN (FN is CURRENT_FILE#)
The real file # is P1 =202 and block # is P2 which is 2
In my database I only had 10 files, so what is this file# 202?!
Solution
If you are getting buffer busy waits on the file header block for a tempfile (datafile in a temporary tablespace) then try increasing the “next extent” size in the temporary tablespace.
This wait can happen when lots of extents are being allocated in the temporary tablespace.
What Would ADDM do?
Interstingly enough the ADDM page doesn’t show the new load that has recently come on the system but the analysis is there.  I clicked on the next to bottom line in the page, “Read and write contention on database blocks was consuming significant database time.
Here are the outputs for the different scenarios.
 inserts into a table contention
 inserts into a table with contention on index
 
 
RBS contention
 
File Header Contention

 

performance, wait events

Metrics vs Statistics

September 4th, 2013



Here are  the tuning metrics tables (SQL  stats are not in “metric” tables per say)

(*DBA_HIST_…_HISTORY views are sort of confusing. AFAI remember they were storing alert history, but apparently they are used for adaptive thresholds – an area for future investigation)

MH900182646

I’ve noticed a number of people posting queries using DBA_HIST_SYSSTAT instead of DBA_HIST_SYSMETRIC_SUMMARY which leads me to believe that there is some confusion or lack of information on the metric tables.

Oracle 10g introduced metric tables which compute deltas and rates of statistics thus hugely simplifying the ability to answer simple questions like “what is the I/O rate on my databases right now.” This question, before 10g, was surprisingly tedious to answer. To answer the question one would have to query v$sysstat  for example:

Select value from v$sysstat where name=’physical reads’;

but querying v$sysstat just once fails to answer the question but instead answers the question “How much I/O has been done since the database was started”. To answer the original question one would have to query v$sysstat twice and take the delta between the two values:

  • Take value at time A
  • Take value at time B
  • Delta = (B-A)
  • and/or get Rate = (B-A)/elapsed time

Getting these deltas and rates could be a pesky task especially working with a customer over the phone. Then 10g Oracle introduced metric tables which answer the questions in one single query using

V$SYSMETRIC

such as

Select  VALUE , METRIC_UNIT,INTSIZE_CSEC
from v$sysmetric
where metric_name='Physical Reads Per Sec';
VALUE METRIC_UNIT           INTSIZE_CSEC
---------- ----------------- ------------
654.6736 Reads Per Second          5959
134.9835 Reads Per Second          1515

Notice that the query returns 2 rows. The first row is the the last minute (ie 59.59 seconds) and the second row is the last 15 seconds (ie 15.15 seconds). Oracle collects both the deltas and rates for 60 second and 15 second intervals.

Oracle has the average, maximum, minimum for the values for the last hour in

V$SYSMETRIC_SUMMARY

that one can query like:

select MAXVAL,MINVAL,AVERAGE,STANDARD_DEVIATION
from V$SYSMETRIC_SUMMARY
where metric_name='Physical Reads Per Sec';

MAXVAL     MINVAL    AVERAGE      STANDARD_DEVIATION
---------- ---------- ---------- ------------------
3.71784232          0 .076930034         .478529283

Also for the last hour Oracle stores the 60 second intervals and for the last 3 minutes the 15 second intervals in

V$SYSMETRIC_HISTORY

 

Then for the last week by default, Oracle saves the values for each hour including the maximum, minimum, average, stddev etc in

 

DBA_HIST_SYSMETRIC_SUMMARY

 

Issues

One issue with using

  • V$SYSMETRIC – last 15 and 60 seconds
  • V$SYSMETRIC_SUMMARY – values  last hour (last snapshot)  like avg, max, min etc
  • V$SYSMETRIC_HISTORY – last hour for 1 minute, last 3 mintes for 15 second deltas
  • DBA_HIST_SYSMETRIC_SUMMARY – hour summaries for last week.

is becoming familiar with the statistics names which are different from v$sysstat. We can look at

V$METRICNAME

For the group_names (statistic definitions)

For trending data over multiple days, the view DBA_HIST_SYSMETRIC_SUMMARY can be used.  The view has a history of all theSystem Metrics Long Duration statistics.  If you store multiple databases in the same AWR repository you can check the statistics available to a particular DBID with the view DBA_HIST_METRIC_NAME.

 

 

Easy query

 

The view DBA_HIST_SYSMETRIC_SUMMARY  can be queried easily for trending metrics, such as the simple query for bytes read by the database per second:

select   dbid, to_char( begin_time ,'YYYY/MM/DD HH24:MI'),
         round(average)
from     dba_hist_sysmetric_summary
where    metric_name= 'Physical Read Total Bytes Per Sec' /* and DBID=[dbid if share repository] */
order by begin_time;

Tougher Query

 

Compare the above query  to the same query on DBA_HIST_SYSSTAT (note there are a lot of stats in v$sysstat)

with stats as (
           select sn.dbid,
                  st.stat_name,
                  to_char(cast(begin_interval_time as date ), 'YYYY/MM/DD HH24:MI') btime,
                  -- Lag (st.value) OVER( PARTITION BY st.stat_name,st.dbid ORDER BY sn.snap_id)
                  Lag (st.value) OVER( PARTITION BY st.stat_name,st.dbid,st.startup_time ORDER BY sn.snap_id)
                               value_beg,
                  st.value     value_end,
                  (cast(end_interval_time as date) - cast(begin_interval_time as date )) * (24*60*60) delta
           from
                  DBA_HIST_SYSSTAT  st,
                  DBA_HIST_SNAPSHOT sn
           where
                    sn.snap_id=st.snap_id and
                    sn.dbid=st.dbid and
                    (st.stat_name= 'physical read total bytes')
           order by begin_interval_time
     )
   select
          dbid, btime,
          round((value_end-value_beg)/delta) rate_per_sec
   from stats
   where (value_end-value_beg) > 0
;

Its a bit disconcerting to note that the above two queries don’t return the exact same data on my laptop. If it was roughly the same that would be fine, and in general the stats are the similar but there are cases where they differ dramatically.  I don’t see anything obvious in the way the queries are written.  Possibly has to do with database bounces or the way the database is affected by the laptop’s sleep and hibernate modes. Will have to look into this farther.

One trick to make the data easy to load into Excel is to use the html output format and spool to a file with an “.html” extension

SET markup HTML on
spool output.html

 

Other info

 

List of DBA_HIST views

https://sites.google.com/site/oraclemonitor/awr-views

 

Power Struggle Between a Man and a Woman

Oracle, performance , , ,

Wait Metrics vs Wait Events

September 3rd, 2013



Here is a quick table comparison of  different types of metrics views

metric_tables

The first line of the table is the classic wait event and statistic views. The following lines are the metric views.  The metric views were introduced in Oracle 10g.

Why Metrics are good

Metric views compute deltas and rates  which hugely simplifying the ability to answer simple questions like “what is the I/O rate on my databases right now?” This question, before 10g, was surprisingly tedious to answer. To answer the question one would have to query v$sysstat  for example:

Select value from v$sysstat where name=’physical reads’;

but querying v$sysstat just once fails to answer the question but instead answers the question “How much I/O has been done since the database was started?” To answer the original question one would have to query v$sysstat twice and take the delta between the two values:

  • Take value at time A
  • Take value at time B
  • Delta = (B-A)
  • and/or get Rate = (B-A)/elapsed time

Getting these deltas and rates could be a pesky task especially working with a customer over the phone. Then 10g Oracle introduced metric tables which answer the questions in one single query .

Using Metrics with Waits

Time business concept.

The metric views  apply to wait events as well as  statistics. In a future posting we will go over statistics. In this posting we will go over wait events.  The number of views available to analyze wait events can be confusing. The point of this post is to clarify what the different views available are and how they can be used.

The wait event views are   (at system level)

  • V$SYSTEM_EVENT – wait events cumulative since startup
  • V$EVENTMETRIC – wait event deltas last 60 seconds
  • DBA_HIST_SYSTEM_EVENT – wait events by snapshot (hour) for last week, cumulative since startup

The wait events are rolled up in to groups called wait classes. For wait class we have the following views:

  • V$SYSTEM_WAIT_CLASS – cumulative since start up
  • V$WAITCLASSMETRIC – last 60 seconds deltas
  • V$WAITCLASSMETRIC_HISTORY – 60 seconds deltas for last hour

Note: DBA_HIST_WAITCLASSMETRIC_HISTORY is used for alerts and or baselines not everyday values.

Use Wait Event Metrics for Latency

I use wait event metrics for I/O latencies.

It may be surprising that I don’t mention using waits to identify bottlenecks and load on the system. For bottlenecks and load on the system the data in V$ACTIVE_SESSION_HISTORY (ASH) is probably better for a few reasons. One the data in ASH is mult-dimesional so it can be grouped by SQL and Session Also CPU information is derivable from ASH. CPU information is not in the event/waitclass views but is in ASH along with the waits.

The second part, the  latencies, specifically I/O latencies,  are only available in the wait event and waitclass views (and the filestat views on a per file basis)

User I/O latency with WAIT CLASS

One  use  of wait  metrics is determining the average read I/O  for all the various kinds of read I/O and read sizes:

select 10*time_waited/nullif(wait_count,0) avg_io_ms -- convert centi-seconds to milliseconds
from   v$waitclassmetric  m
       where wait_class_id= 1740759767 --  User I/O
/
 AVG_IO_MS
----------
     8.916

One issue with V$WAITCLASSMETRIC is that the field WAIT_CLASS name is not in the view, so we either have to use the WAIT_CLASS_ID (the hash of the name)  as above or join to V$SYSTEM_WAIT_CLASS as below

select
        10*m.time_waited/nullif(m.wait_count,0) avgms -- convert centisecs to ms
from   v$waitclassmetric  m,
       v$system_wait_class n
where m.wait_class_id=n.wait_class_id
  and n.wait_class='User I/O'
/
 AVG_IO_MS
----------
     8.916

Another issue is that the documentation for 11gR2 says that the TIME_WAITED is microseconds but in my tests it’s actually centisecs

 desc V$SYSTEM_WAIT_CLASS
Name                                        Type
-----------------------------------------  ----------------------------
WAIT_CLASS_ID                                NUMBER
WAIT_CLASS#                                  NUMBER
WAIT_CLASS                                   VARCHAR2(64)
TOTAL_WAITS                                  NUMBER
TIME_WAITED                                  NUMBER  - centi-seconds

You can get a list of all the WAIT_CLASS names in the view V$SYSTEM_WAIT_CLASS.  

 select wait_class_id , wait_class from V$SYSTEM_WAIT_CLASS ;

WAIT_CLASS_ID WAIT_CLASS
------------- ----------------------------------------------------------------
   1893977003 Other
   4217450380 Application
   3290255840 Configuration
   4166625743 Administrative
   3875070507 Concurrency
   3386400367 Commit
   2723168908 Idle
   2000153315 Network
   1740759767 User I/O
   4108307767 System I/O

Latencies for specific I/O  Wait Events

For specific I/O latencies there are two choices – v$eventmetric and v$system_event. With v$system_event it requires  running multiple queries and taking the deltas but the deltas are are already calculated in v$eventmetric. Here is an example of getting I/O latencies from v$eventmetric

Latencies in the past minute

col name for a25
select m.intsize_csec,
       n.name ,
       round(m.time_waited,3) time_waited,
       m.wait_count,
       round(10*m.time_waited/nullif(m.wait_count,0),3) avgms
from v$eventmetric m,
     v$event_name n
where m.event_id=n.event_id
  and n.name in (
                  'db file sequential read',
                  'db file scattered read',
                  'direct path read',
                  'direct path read temp',
                  'direct path write',
                  'direct path write temp',
                  'log file sync',
                  'log file parallel write'
)
/
INTSIZE_CSEC NAME                      TIME_WAITED WAIT_COUNT      AVGMS
------------ ------------------------- ----------- ---------- ----------
        6017 log file parallel write         2.538          4      6.345
        6017 log file sync                   2.329          1     23.287
        6017 db file sequential read             0          0
        6017 db file scattered read              0          0
        6017 direct path read                    0          0
        6017 direct path read temp               0          0
        6017 direct path write                   0          0
        6017 direct path write temp              0          0

Latencies averaged over each hour for specific I/O Wait Events

select
       btime,
       round((time_ms_end-time_ms_beg)/nullif(count_end-count_beg,0),3) avg_ms
from (
select
       to_char(s.BEGIN_INTERVAL_TIME,'DD-MON-YY HH24:MI')  btime,
       total_waits count_end,
       time_waited_micro/1000 time_ms_end,
       Lag (e.time_waited_micro/1000)
              OVER( PARTITION BY e.event_name ORDER BY s.snap_id) time_ms_beg,
       Lag (e.total_waits)
              OVER( PARTITION BY e.event_name ORDER BY s.snap_id) count_beg
from
       DBA_HIST_SYSTEM_EVENT e,
       DBA_HIST_SNAPSHOT s
where
         s.snap_id=e.snap_id
   and e.event_name like '%&1%'
order by begin_interval_time
)
order by btime
/
BTIME               AVG_MS
--------------- ----------
20-JUL-11 06:00      5.854
20-JUL-11 07:00      4.116
20-JUL-11 08:00     21.158
20-JUL-11 09:02      5.591
20-JUL-11 10:00      4.116
20-JUL-11 11:00      6.248
20-JUL-11 12:00     23.634
20-JUL-11 13:00     22.529
20-JUL-11 14:00      21.62
20-JUL-11 15:00     18.038
20-JUL-11 16:00     23.127

What are the sizes of the I/O requests?

One issue with looking at I/O latencies is determining the I/O sizes.  It would be awesome if there was a view with I/O counts, sizes and latencies in one place. ASH does have this information  but ASH data is weighted to the longer latencies and sizes and not the average. The average sizes have to be gotten from system statistics. The I/O sizes for ‘db file sequential read’ are single block reads so are single value that can be determined , but the other read events can vary in size. To get a general idea of I/O sizes one could just average across all I/O using the system statistics

Average I/O Size (across all I/O waits)

select
          sum(decode(metric_name,'Physical Reads Per Sec',value,0))*max(intsize_csec)/100  blocks_read,
          nullif(sum(decode(metric_name,'Physical Read IO Requests Per Sec',value,0)),0)*max(intsize_csec)/100  reads,
            sum(decode(metric_name,'Physical Reads Per Sec',value,0))/
          nullif(sum(decode(metric_name,'Physical Read IO Requests Per Sec',value,0)),0) avg_blocks_read
from v$sysmetric
where group_id = 2  -- 60 second deltas only (not the 15 second deltas);

BLOCKS_READ      READS AVG_BLOCKS_READ
----------- ---------- ---------------
       4798       4798               1

 

Load and Bottlenecks

The good thing about wait classes is that they simplify dealing with 1000s of wait events and group them into just a few wait classes. We can get a quick view of load on the system with

select n.wait_class, round(m.time_waited/m.INTSIZE_CSEC,3) AAS
from   v$waitclassmetric  m,
       v$system_wait_class n
where m.wait_class_id=n.wait_class_id
and n.wait_class != 'Idle'
;
WAIT_CLASS             AAS
--------------- ----------
Other                    0
Application              0
Configuration            0
Administrative           0
Concurrency              0
Commit                   0
Network                  0
User I/O              .149
System I/O            .002

but the big drawback with wait event and/or wait class views is that they lack information on CPU load. CPU load can be found in the system statistics but it’s just easier to do it all in one query using v$active_session_history. Here is a query using ASH to calculate AAS load on the database over the last 60 seconds:

select
            round(count(*)/secs.var,3)     AAS,
            decode(session_state,'ON CPU','CPU',wait_class)  wait_class
       from v$active_session_history ash,
            (select 60 var from dual)  secs
       where
            SAMPLE_TIME > sysdate - (secs.var/(24*60*60)) and
            SESSION_TYPE = 'FOREGROUND'
       group by decode(session_state,'ON CPU','CPU',wait_class) , secs.var
/
      AAS WAIT_CLASS
---------- ---------------
      .016 Concurrency
      .001 Network
         0 Other
      .083 Configuration
      .001 Administrative
      .034 CPU
         0 System I/O
      .001 Commit
      .054 Application
         0 User I/O

Though with v$sysmetric it’s pretty easy to join to v$waitclassmetric

  select n.wait_class, round(m.time_waited/m.INTSIZE_CSEC,3) AAS
   from   v$waitclassmetric  m,
          v$system_wait_class n
   where m.wait_class_id=n.wait_class_id
   and n.wait_class != 'Idle'
  union
   select  'CPU', round(value/100,3) AAS from v$sysmetric where metric_name='CPU Usage Per Sec' and group_id=2 ;
WAIT_CLASS                                                              AAS
---------------------------------------------------------------- ----------
Administrative                                                            0
Application                                                            .009
CPU                                                                   1.696
Commit                                                                    0
Concurrency                                                            .001
Configuration                                                             0
Network                                                                .002
Other                                                                     0
System I/O                                                                0
User I/O                                                                  0

and adding v$sysmetric into the query allows me to do something I’ve always wanted which is to include the OS CPU in AAS

 select n.wait_class, round(m.time_waited/m.INTSIZE_CSEC,3) AAS
   from   v$waitclassmetric  m,
          v$system_wait_class n
   where m.wait_class_id=n.wait_class_id
   and n.wait_class != 'Idle'
  union
   select  'CPU', round(value/100,3) AAS from v$sysmetric where metric_name='CPU Usage Per Sec' and group_id=2
  union
   select 'CPU_OS', round((prcnt.busy*parameter.cpu_count)/100,3) - aas.cpu
  from
  ( select value busy from v$sysmetric where metric_name='Host CPU Utilization (%)' and group_id=2 ) prcnt,
  ( select value cpu_count from v$parameter where name='cpu_count' )  parameter,
  ( select  'CPU', round(value/100,3) cpu from v$sysmetric where metric_name='CPU Usage Per Sec' and group_id=2) aas
;
WAIT_CLASS                                                              AAS
---------------------------------------------------------------- ----------
Administrative                                                            0
Application                                                               0
CPU                                                                    .009
CPU_OS                                                                 .024
Commit                                                                    0
Concurrency                                                               0
Configuration                                                             0
Network                                                                .002
Other                                                                     0
System I/O                                                                0
User I/O                                                                  0

One huge loss over using ASH is the loss of the information users waiting for CPU but not running on CPU.

For further reading see

  • oramon.sh – shell script to display I/O latency from v$system_event
  • Oracle CPU time – how to see Oracle’s usage and demand of CPU

 

09-45-55-583_950x510

 

Oracle, performance, wait events , ,

Enqueue – PK, FK or Bitmap Index problem?

August 30th, 2013



MP900302987If one is seeing waits for enq: TX – row lock contention  then there could be a lot of reasons. One distinguishing factor is the lock mode. If the lock mode is exclusive (mode 6) then it’s most likely a classic row lock where two sessions are trying to modify the same row. On the other hand if the lock mode is share (mode 4)  it’s typically going to be

  • Primary/Unique Key: inserting a unique key when  someone else has already inserted that key but not committed
  • Foreign Key: Inserting a foreign when then parent value has been inserted but not committed or deleted and not commited (not to be confused with locks due to un-indexed foreign key which cause a “enq: TM – contention”  wait not a TX wait)
  • Bitmap Index: bitmap index chunk contention

Now how to tell which of these is happening? Well here is a query on ASH (I’ve commented out some of the useful fields to limit the output)  that will generate output to help us distinguish between the 3 different cases

col object for A15
col otype for A10
select
       substr(event,0,20)    lock_name,
       --ash.session_id        waiter,
       --mod(ash.p1,16)        lmode,
       --ash.p2                p2,
       --ash.p3                p3,
       o.object_name           object,
       o.object_type           otype,
       CURRENT_FILE#           filen,
       CURRENT_BLOCK#          blockn,
       --ash.SQL_ID            waiting_sql,
       BLOCKING_SESSION        blocker
       --,ash.xid
from
         v$active_session_history ash,
         all_objects o
where
           event like 'enq: TX%'
   and   mod(ash.p1,16)=4
   and o.object_id (+)= ash.CURRENT_OBJ#
/

Here is the output from the 3 different cases

Unique Index

  OBJECT   OTYPE FILEN BLOCKN BLOCKER
  ------  ------ ----- ------ -------
      -1             0      0     158
      -1             0      0     158
      -1             0      0     158
      -1             0      0     158

Foreign Key

  OBJECT   OTYPE FILEN BLOCKN BLOCKER
  ------  ------ ----- ------ -------
   CHILD   TABLE     1  60954       1
   CHILD   TABLE     1  60954       1
   CHILD   TABLE     1  60954       1

Bitmap Index

  OBJECT   OTYPE FILEN BLOCKN BLOCKER
  ------  ------ ----- ------ -------
      I1   INDEX     0      0     144
      I1   INDEX     0      0     144
      I1   INDEX     0      0     144
      I1   INDEX     0      0     144

Each case has a different footprint.

  • Unique key index issue object of “-1″
  • Foreign key case has a blocker of “1″
  • Bitmap index case as filen and blockn “0″

These cases were run on 10.2.0.3 thus the “footprint” could change on other versions.

The above ASH query and many other useful ASH queries are maintained on GitHub at

https://github.com/khailey/ashmasters

MP900302924

Oracle, performance, wait events , ,

Oracle I/O latency monitoring

August 29th, 2013


stopwatchOne thing that I have found sorely missing in the performance pages of Enterprise Manager is latency values for various types of I/O. The performance page or top activity may show high I/O waits but it won’t indicated if the latency of I/O is unusually high or not. Thus I put together a shell script that shows latency for the main I/O waits

  • db file sequential read
  • db file scattered read
  • log file parallel write
  • direct path reads
  • direct path reads temp

Of course it would be nice to add a few others like direct path writes, direct path writes temp and log file sync but there is only so much room in the screen width.

oramon.sh

 

The script is called oramon.sh and is available on github at

https://github.com/khailey/oramon/blob/master/oramon.sh

Example:

$  oramon.sh
Usage: oramon.sh [username] [password] [host] [sid] <port=1521> <runtime=3600>

$ ./oramon.sh system sys 172.16.100.81 vsol
RUN_TIME=-1
COLLECT_LIST=
FAST_SAMPLE=iolatency
TARGET=172.16.100.81:vsol
DEBUG=0
Connected, starting collect at Wed Apr 18 18:41:13 UTC 2012
starting stats collecting

   single block       logfile write       multi block      direct read   direct read temp
   ms      IOP/s        ms    IOP/s       ms    IOP/s       ms    IOP/s       ms    IOP/s
   20.76    27.55    32.55      .71     3.50      .00      .00      .01      .00      .00
     .00      .20               .00               .00               .00               .00
   34.93   369.64   116.79     3.55               .00               .00               .00
   31.43   640.33    92.40     8.33               .00               .00               .00
   39.39   692.33   111.69     8.00               .00               .00               .00

The first line of output is the average since the database started up.
The subsequent lines are the averages since the last line which is 5 seconds by default.
One should be able to see immediately how much activity there is on the database and the latency for the basic types of database I/O.

Reads
Single block reads are the typical I/O from a database which would happen for example when reading a row in a table with indexes in place.
Multi block reads are common as well is which would happen when for example summing the values over all rows in a table.
Direct reads are less common but quite normal and happen almost exclusively for parallel query though may be used for other activities especially in newer version of Oracle such as 11.2. Direct reads are multiblock reads that by pass the Oracle buffer cache. The size varies from a datablock, such as 8k to 1MB.
Direct read temp happens when a sort has overflowed memory limits and been written to disk. Direct reads temp are multiblock reads that by pass the Oracle buffer cache. The size varies from a datablock, such as 8k to 1MB.

Writes
Logfile writes are the only writes that database users wait for in general. Actually users only wait when the commit, which then is a wait for a signal from the log writer that their particular redo data is on disk which could have already happened. Typically the user wait time is a bit slower than the logwrite time but in general it’s close, ie within a few milliseconds. The farther apart the user wait time is from the log write time the more likely there is a CPU, paging or other concurrency problem on the VDB host slowing down the users signalling and wake up time.

Rising profits

oramon.sql : Oracle Latency Query

If for some reason the shell script isn’t able to connect to the database, then the same data can be collected manually by running the SQL query in SQL*Plus by hand.
The following two SQL queries, oramon_setup.sql and oramon.sql are available on github at

https://github.com/khailey/oramon

If you want to see the latencies over periods shorter than 60s, then you have to collect the values of the cumulative counters at time A, then again at time B and take the difference. The following two queries, oramon.sql and oramon_setup.sql, are available on ftp site

Run oramon_setup.sql *once*
  column seq_ms for 9999.99
   column seq_ct for 9999.99
   column lfpw_ms for 9999.99
   column lfpw_ct for 9999.99
   column seq_ms for 9999.99
   column scat_ct for 9999.99
   column dpr_ms for 9999.99
   column dpr_ct for 9999.99
   column dprt_ms for 9999.99
   column dprt_ct for 9999.99
   column prevdprt_ct new_value prevdprt_ct_var
   column prevdprt_tm new_value prevdprt_tm_var
   column prevdpwt_ct new_value prevdpwt_ct_var
   column prevdpwt_tm new_value prevdpwt_tm_var
   column prevdpr_ct new_value prevdpr_ct_var
   column prevdpr_tm new_value prevdpr_tm_var
   column prevdpw_ct new_value prevdpw_ct_var
   column prevdpw_tm new_value prevdpw_tm_var
   column prevseq_ct new_value prevseq_ct_var
   column prevseq_tm new_value prevseq_tm_var
   column prevscat_ct new_value prevscat_ct_var
   column prevscat_tm new_value prevscat_tm_var
   column prevlfpw_ct new_value prevlfpw_ct_var
   column prevlfpw_tm new_value prevlfpw_tm_var
   column prevsec new_value prevsec_var
   select 0 prevsec from dual;
   select 0 prevseq_tm from dual;
   select 0 prevseq_ct from dual;
   select 0 prevscat_ct from dual;
   select 0 prevscat_tm from dual;
   select 0 prevlfpw_ct from dual;
   select 0 prevlfpw_tm from dual;
   select 0 prevdprt_ct from dual;
   select 0 prevdprt_tm from dual;
   select 0 prevdpwt_ct from dual;
   select 0 prevdpwt_tm from dual;
   select 0 prevdpr_ct from dual;
   select 0 prevdpr_tm from dual;
   select 0 prevdpw_ct from dual;
   select 0 prevdpw_tm from dual;
   column prevdprt_ct noprint
   column prevdprt_tm noprint
   column prevdpwt_ct noprint
   column prevdpwt_tm noprint
   column prevdpr_ct noprint
   column prevdpr_tm noprint
   column prevdpw_ct noprint
   column prevdpw_tm noprint
   column prevseq_ct noprint
   column prevseq_tm noprint
   column prevscat_ct noprint
   column prevscat_tm noprint
   column prevlfpw_ct noprint
   column prevlfpw_tm noprint
   column prevsec noprint

Run following query to see the current latency for

  • single block read
  • log file parallel write
  • multi-block read

oramon.sql

select
        round(seqtm/nullif(seqct,0),2) seq_ms,
        round(seqct/nullif(delta,0),2) seq_ct,
        round(lfpwtm/nullif(lfpwct,0),2) lfpw_ms,
        round(lfpwct/nullif(delta,0),2) lfpw_ct,
        round(scattm/nullif(scatct,0),2) scat_ms,
        round(scatct/nullif(delta,0),0) scat_ct,
        round(dprtm/nullif(dprct,0),2) dpr_ms,
        round(dprct/nullif(delta,0),2) dpr_ct,
        round(dprttm/nullif(dprtct,0),2) dprt_ms,
        round(dprtct/nullif(delta,0),2) dprt_ct,
        prevseq_ct, prevscat_ct, prevseq_tm, prevscat_tm, prevsec,prevlfpw_tm,prevlfpw_ct
        , prevdpr_ct, prevdpr_tm , prevdprt_ct, prevdprt_tm , prevdpw_ct, prevdpw_tm
        , prevdpwt_ct, prevdpwt_tm
from
(select
       sum(decode(event,'db file sequential read', round(time_waited_micro/1000) -  &prevseq_tm_var,0)) seqtm,
       sum(decode(event,'db file scattered read',  round(time_waited_micro/1000) - &prevscat_tm_var,0)) scattm,
       sum(decode(event,'log file parallel write',  round(time_waited_micro/1000) - &prevlfpw_tm_var,0)) lfpwtm,
       sum(decode(event,'db file sequential read', round(time_waited_micro/1000) ,0)) prevseq_tm,
       sum(decode(event,'db file scattered read',  round(time_waited_micro/1000) ,0)) prevscat_tm,
       sum(decode(event,'log file parallel write',  round(time_waited_micro/1000) ,0)) prevlfpw_tm,
       sum(decode(event,'db file sequential read', total_waits - &prevseq_ct_var,0)) seqct,
       sum(decode(event,'db file scattered read',  total_waits - &prevscat_ct_var,0)) scatct,
       sum(decode(event,'log file parallel write',  total_waits - &prevlfpw_ct_var,0)) lfpwct,
       sum(decode(event,'db file sequential read', total_waits ,0)) prevseq_ct,
       sum(decode(event,'db file scattered read',  total_waits ,0)) prevscat_ct,
       sum(decode(event,'log file parallel write',  total_waits ,0)) prevlfpw_ct,
       sum(decode(event,'direct path read',  round(time_waited_micro/1000) - &prevdpr_tm_var,0)) dprtm,
       sum(decode(event,'direct path read',  round(time_waited_micro/1000) ,0)) prevdpr_tm,
       sum(decode(event,'direct path read',  total_waits - &prevdpr_ct_var,0)) dprct,
       sum(decode(event,'direct path read',  total_waits ,0)) prevdpr_ct,
       sum(decode(event,'direct path write',  round(time_waited_micro/1000) - &prevdpw_tm_var,0)) dpwtm,
       sum(decode(event,'direct path write',  round(time_waited_micro/1000) ,0)) prevdpw_tm,
       sum(decode(event,'direct path write',  total_waits - &prevdpw_ct_var,0)) dpwct,
       sum(decode(event,'direct path write',  total_waits ,0)) prevdpw_ct,
       sum(decode(event,'direct path write temp',  round(time_waited_micro/1000) - &prevdpwt_tm_var,0)) dpwttm,
       sum(decode(event,'direct path write temp',  round(time_waited_micro/1000) ,0)) prevdpwt_tm,
       sum(decode(event,'direct path write temp',  total_waits - &prevdpwt_ct_var,0)) dpwtct,
       sum(decode(event,'direct path write temp',  total_waits ,0)) prevdpwt_ct,
       sum(decode(event,'direct path read temp',  round(time_waited_micro/1000) - &prevdprt_tm_var,0)) dprttm,
       sum(decode(event,'direct path read temp',  round(time_waited_micro/1000) ,0)) prevdprt_tm,
       sum(decode(event,'direct path read temp',  total_waits - &prevdprt_ct_var,0)) dprtct,
       sum(decode(event,'direct path read temp',  total_waits ,0)) prevdprt_ct,
       to_char(sysdate,'SSSSS')-&prevsec_var delta,
       to_char(sysdate,'SSSSS') prevsec
from
     v$system_event
where
     event in ('db file sequential read',
               'db file scattered read',
               'direct path read temp',
               'direct path write temp',
               'direct path read',
               'direct path write',
               'log file parallel write')
) ;

Output looks like

  SEQ_MS   SEQ_CT  LFPW_MS  LFPW_CT   SEQ_MS  SCAT_CT   DPR_MS   DPR_CT  DPRT_MS  DPRT_CT
-------- -------- -------- -------- -------- -------- -------- -------- -------- --------
  115.71   422.67    76.17    12.00               .00               .00               .00

The first execution of the query is I/O since database startup, so should most likely be ignored.
Subsequent executions are the I/O since the last execution

The columns are

  1. SEQ_MS: single block latency
  2. SEQ_CT: single block reads per second
  3. LFPW_MS: log file parallel write latency
  4. LFPW_CT: log file parallel write count per second
  5. SCAT_MS: multi-block latency
  6. SCAT_CT: multi-block reads per second
  7. DPR_MS: direct path read latency
  8. DPR_CT: direct path read count
  9. DPRT_MS: direct path read temp latency
  10. DPRT_CT: direct path read temp count
Instead of running the query by hand the script “oramon.sh” available at https://github.com/khailey/oramon/blob/master/oramon.sh (see top of page) will collect this info ever 5 seconds in a loop and output to standard out at the UNIX prompt

Simple but only once a minute

NOTE: the following is a simpler query but the data only updates once a minute
select
       n.name event,
       m.wait_count  cnt,
       10*m.time_waited ms,
       nvl(round(10*m.time_waited/nullif(m.wait_count,0),3) ,0) avg_ms
  from v$eventmetric m,
       v$event_name n
  where m.event_id=n.event_id
        and (
              wait_class_id= 1740759767 --  User I/O 
                   or
              wait_class_id= 4108307767 --  System I/O  
             )
        and m.wait_count > 0 ;

.

io, Oracle, performance, wait events , ,

CURSOR_SHARING : a picture is worth a 1000 words

August 28th, 2013


Anyone who has been around Oracle performance over the years knows the grief that hard parsing SQL queries can cause on highly concurrent applications. The number one reason for hard parsing has been applications that don’t use bind variables. Without bind variables queries that would otherwise be shared get recompiled because their text is different and Oracle treats them as different queries. Oracle addressed this issue with a parameter called cursor_sharing. The parameter cursor_sharing has three values

  1. exact – the default
  2. similar – replace literals with bind variables, if a histogram keep literal in place
  3. force – replace literals with bind variables and use existing plan if it exists

Here is what the load looks like going from the default, exact, to the value force on a load of the same query but a query that doesn’t use bind variables:

looks like a significant load savings – impressive!
Now many people tell me that they think there are bugs with “force” and that you should use “similar”. The value similar does a similar thing but if there are histograms on the column, then Oracle will attempt, in certain cases, to have different plans based on different values. Sounds cool huh? Well their are bugs. Here is the same load with similar:
If we look at the different child cursors for this statement we find that Oracle, instead of sharing the children creates a different one for each execution:
This bug still seems to exist on 11gR2 :
Here is the code for the examples I (run by 8 users on 10g and 12 users on 11g)
--alter session set cursor_sharing=exact;
--alter session set cursor_sharing=force;
--alter session set cursor_sharing=similar;
declare
 l_cursor integer default 0;
 stmt varchar2(400);
 ret number;
BEGIN
 select hparse.nextval into ret  from dual;
 dbms_random.seed(ret);
 FOR i IN 1..1000  LOOP
   l_cursor:=dbms_sql.open_cursor;
   stmt:='SELECT  count(*) FROM t1 where c1  < '|| 
     dbms_random.value()||' and c2  < '||dbms_random.value();
   execute immediate stmt into ret;
   dbms_sql.close_cursor(l_cursor);
 END LOOP;
END;
/
Table t1 has no histograms. In the case above it had one row, but results were similar with no rows:
create table t1 (c1 number, c2 number);
insert into t1 values (0,0);
commit;
The issue should be addressed in 11g with a combination of cursor_sharing and adaptive cursor sharing
Also see Charles Hooper’s blog post on this topic at

Oracle, performance, sql, wait events , , ,

Finding the slowest SQL execution of the same query

August 28th, 2013


When running the same query multiple times, several questions come to mind:

  • Does the query always execute in the same amount of  time?
  • If some executions are slower, what is the slowest execution time?
  • When did the slowest exectution happen?
  • What more can I find out about the slowest exectution?

All of this can be answered from data in Active Session History or ASH.   The following query finds the maximum, minimum and average execution times in seconds as well as the time of the slowest execution which is given by start time and end time of the  slowest exectuiton:

col av for 9999999
col mx for 9999999
col mn for 9999999

select
   sql_id,
   count(*),
   round(min(delta),0) mn,
   round(avg(delta),0) av,
   round(max(delta),0) mx,
   substr(max(times),12) max_run_time
from (
   select
        sql_id,
        sql_exec_id,
        max(delta) delta ,
        -- lpad sets a fixed width on delta so it can be
        -- stripped off above with substr
        -- delta in "times" is just for sorting not displaying
        lpad(round(max(delta),0),10) || ' ' ||
        to_char(min(start_time),'YY-MM-DD HH24:MI:SS')  || ' ' ||
        to_char(max(end_time),'YY-MM-DD HH24:MI:SS')  times
   from ( select
                                            sql_id,
                                            sql_exec_id,
              cast(sample_time as date)     end_time,
              cast(sql_exec_start as date)  start_time,
              ((cast(sample_time    as date)) -
               (cast(sql_exec_start as date))) * (3600*24) delta

           from
              dba_hist_active_sess_history
           where sql_exec_id is not null
        )
   group by sql_id,sql_exec_id

)
group by sql_id
having count(*) > 10
order by mx
/

SQL_ID          COUNT(*)       MN       AV       MX MAX_RUN_TIME
------------- ---------- -------- -------- -------- -----------------------------------
155vjqzjqp58f         27        0      115      786 11-04-11 07:39:47 11-04-11 07:41:20
7nf5917x3tq5x        113        0      129      791 11-04-11 01:03:19 11-03-02 04:16:09
asg774pz0kqga         11       11      225      799 11-04-14 12:20:10 11-03-02 12:18:58
1kf1jsykb1nk6        529        0      107      800 11-04-09 18:41:28 11-03-01 23:13:56
8rua4c9agcqkb        978        0       73      820 11-03-01 23:13:50 11-03-01 23:13:56
fdagtr1sdk8tn        313        0      242      841 11-04-08 21:30:31 11-04-08 21:30:38
7b5w34atn8q1h        124        0       25      898 11-03-07 20:53:17 11-03-07 20:53:23
9w7mbuv734tfy         11       30      509      954 11-04-14 09:00:55 11-03-02 04:27:33
88qxmg220db9s         23        4      357     1040 11-04-13 22:08:20 11-04-13 02:20:09
83ngzw213v0cs        302        1      207     1122 11-04-11 16:26:32 11-03-07 16:12:11
34cgtc9xkgxny         61      978     1163     1272 11-03-02 10:06:24 11-03-02 10:06:30
g5u58zpg0tuk8         97        1       62     1359 11-04-13 02:49:33 11-04-12 02:23:39
6tkqndn1tzf23         29        7      187     1370 11-04-13 06:56:43 11-03-02 06:56:54
g4wrnvdmf23b1         11       19      458     1397 11-04-14 12:22:28 11-03-02 12:21:19
bpkg6y9wvf717         31        0      189     1427 11-04-13 21:19:51 11-03-02 21:08:00
4d6m2q3ngjcv9        320        3      485     1701 11-04-10 18:00:54 11-03-01 23:10:55
882tp5sbq1tq5         17       39      367     1795 11-04-14 14:00:30 11-03-01 23:04:33
5k7vccwjr5ahd       2653        0       33     1963 11-04-12 09:06:08 11-03-01 23:10:15
44034jty9vnrg         19        2      188     1968 11-03-03 09:17:34 11-03-03 09:17:43
g9n69a23s3wxz         40        6      280     2009 11-04-08 13:47:23 11-03-03 09:37:38
ds8cz0fb8w147        161       13      274     2531 11-04-12 16:10:21 11-03-01 23:11:55
bzyny95313u12        114        0       47     2599 11-03-03 03:06:18 11-03-03 03:06:25
0fvrpk7476b7y         26        0      133     3068 11-03-07 07:57:56 11-03-07 07:58:00
1pjp66rxcj6tg         15       57      768     3106 11-04-09 17:25:21 11-03-07 08:58:26
8r5wuxk1dprhr         39       24      841     3510 11-04-14 14:00:47 11-03-02 09:54:37
0w5uu5kngyyty         21        0      442     3652 11-04-11 08:00:21 11-04-11 09:01:13
0hbv80w9ypy0n        161        0     1184     4089 11-04-12 22:26:09 11-03-02 04:36:15
71fwb4n6a92fv         49       30      677     4481 11-04-10 17:01:17 11-03-01 23:40:45
0bujgc94rg3fj        604        0       25     4929 11-04-08 10:53:34 11-04-08 12:15:43
64dqhdkkw63fd       1083        0        7     7147 11-03-07 04:01:01 11-03-07 06:00:08
990m08w8xav7s        591        0       52     7681 11-04-13 00:39:27 11-04-13 00:39:37
2n5369dsuvn5a         16      303     5727    10472 11-04-14 11:18:11 11-04-14 14:12:43
2spgk3k0f7quz        251        0      546    29607 11-04-12 12:11:47 11-04-12 12:11:48
36pd759xym9tc         12     1391    23862    37934 11-04-13 19:25:49 11-03-01 23:00:12
497wh6n7hu14f         49        0     5498    69438 11-04-12 19:01:17 11-04-13 12:03:54

We can add a histogram of execution spread to the query

col 1 for 99999
col 2 for 99999
col 3 for 9999
col 4 for 999
col 5 for 99
col av for 99999.9
col ct for 99999
col mn for 999
col av for 99999.9

with pivot_data as (
select
      sql_id,
      ct,
      mxdelta mx,
      mndelta mn,
      avdelta av,
      -- high_boundary is set to maxdelta + 1 so that
      -- nothing ends up in the overflow bucket
      -- otherwise the max value ends up in the overflow bucket
      width_bucket(delta,mndelta,mxdelta+1,5) as bucket  ,
      substr(times,12) max_run_time
from (
select
   sql_id,
   delta,
   count(*) OVER (PARTITION BY sql_id) ct,
   max(delta) OVER (PARTITION BY sql_id) mxdelta,
   min(delta) OVER (PARTITION BY sql_id) mndelta,
   avg(delta) OVER (PARTITION BY sql_id) avdelta,
   max(times) OVER (PARTITION BY sql_id) times
from (
   select
        sql_id,
        sql_exec_id,
        max(delta) delta ,
        -- lpad sets a fixed width on delta so it can be
        -- stripped off above with substr
        -- delta in "times" is just for sorting not displaying
        lpad(round(max(delta),0),10) || ' ' ||
        to_char(min(start_time),'YY-MM-DD HH24:MI:SS')  || ' ' ||
        to_char(max(end_time),'YY-MM-DD HH24:MI:SS')  times
   from ( select
                                            sql_id,
                                            sql_exec_id,
              cast(sample_time as date)     end_time,
              cast(sql_exec_start as date)  start_time,
              ((cast(sample_time    as date)) -
               (cast(sql_exec_start as date))) * (3600*24) delta
           from
              dba_hist_active_sess_history
           where sql_exec_id is not null
        )
   group by sql_id,sql_exec_id
)
)
where ct > &min_repeat_executions_filter
)
select * from pivot_data
PIVOT ( count(*) FOR bucket IN (1,2,3,4,5))
order by mx,av;
/
SQL_ID            CT         MX   MN       AV MAX_RUN_TIME                             1      2     3    4   5
------------- ------ ---------- ---- -------- ----------------------------------- ------ ------ ----- ---- ---
8rua4c9agcqkb    978        820    0     72.7 11-03-01 23:13:50 11-03-01 23:13:56    830    116    21    9   2
fdagtr1sdk8tn    313        841    0    241.8 11-04-08 21:30:31 11-04-08 21:30:38    194     45     0    0  74
7b5w34atn8q1h    124        898    0     24.8 11-03-07 20:53:17 11-03-07 20:53:23    122      0     0    0   2
83ngzw213v0cs    302       1122    1    207.5 11-04-11 16:26:32 11-03-07 16:12:11    200     68    21    6   7
g5u58zpg0tuk8     97       1359    1     62.1 11-04-13 02:49:33 11-04-12 02:23:39     92      3     1    0   1
4d6m2q3ngjcv9    320       1701    3    484.7 11-04-10 18:00:54 11-03-01 23:10:55     92    168    50    9   1
5k7vccwjr5ahd   2653       1963    0     33.4 11-04-12 09:06:08 11-03-01 23:10:15   2623     15     8    4   3
ds8cz0fb8w147    161       2531   13    273.8 11-04-12 16:10:21 11-03-01 23:11:55    136     18     5    1   1
bzyny95313u12    114       2599    0     46.5 11-03-03 03:06:18 11-03-03 03:06:25    113      0     0    0   1
0hbv80w9ypy0n    161       4089    0   1183.9 11-04-12 22:26:09 11-03-02 04:36:15     27    116     9    6   3
71fwb4n6a92fv     49       4481   30    676.9 11-04-10 17:01:17 11-03-01 23:40:45     38      6     2    2   1
0bujgc94rg3fj    604       4929    0     24.7 11-04-08 10:53:34 11-04-08 12:15:43    601      1     1    0   1
64dqhdkkw63fd   1083       7147    0      7.2 11-03-07 04:01:01 11-03-07 06:00:08   1082      0     0    0   1
990m08w8xav7s    591       7681    0     51.8 11-04-13 00:39:27 11-04-13 00:39:37    587      0     0    2   2
2spgk3k0f7quz    251      29607    0    546.1 11-04-12 12:11:47 11-04-12 12:11:48    247      2     0    0   2
497wh6n7hu14f     49      69438    0   5498.2 11-04-12 19:01:17 11-04-13 12:03:54     44      1     0    1   3

Finally add the SQL_EXEC_ID of the longest running execution. This SQL_EXEC_ID can then be used to go look at the events in ASH for that particular execution

col 1 for 99999
col 2 for 99999
col 3 for 9999
col 4 for 999
col 5 for 99
col av for 99999
col ct for 99999
col mn for 999
col av for 99999.9
col longest_sql_exec_id for A10

WITH pivot_data AS (
SELECT
      sql_id,
      ct,
      mxdelta mx,
      mndelta mn,
      round(avdelta) av,
      WIDTH_BUCKET(delta_in_seconds,mndelta,mxdelta+.1,5) AS bucket  ,
      SUBSTR(times,12) max_run_time,
      SUBSTR(longest_sql_exec_id, 12) longest_sql_exec_id
FROM (
SELECT
   sql_id,
   delta_in_seconds,
   COUNT(*) OVER (PARTITION BY sql_id) ct,
   MAX(delta_in_seconds) OVER (PARTITION BY sql_id) mxdelta,
   MIN(delta_in_seconds) OVER (PARTITION BY sql_id) mndelta,
   AVG(delta_in_seconds) OVER (PARTITION BY sql_id) avdelta,
   MAX(times) OVER (PARTITION BY sql_id) times,
   MAX(longest_sql_exec_id) OVER (PARTITION BY sql_id) longest_sql_exec_id
FROM (
   SELECT
        sql_id,
        sql_exec_id,
        MAX(delta_in_seconds) delta_in_seconds ,
        LPAD(ROUND(MAX(delta_in_seconds),0),10) || ' ' ||
        TO_CHAR(MIN(start_time),'YY-MM-DD HH24:MI:SS')  || ' ' ||
        TO_CHAR(MAX(end_time),'YY-MM-DD HH24:MI:SS')  times,
        LPAD(ROUND(MAX(delta_in_seconds),0),10) || ' ' ||
        TO_CHAR(MAX(sql_exec_id)) longest_sql_exec_id
   FROM ( SELECT
                                            sql_id,
                                            sql_exec_id,
              CAST(sample_time AS DATE)     end_time,
              CAST(sql_exec_start AS DATE)  start_time,
              ((CAST(sample_time    AS DATE)) -
               (CAST(sql_exec_start AS DATE))) * (3600*24) delta_in_seconds
           FROM
              dba_hist_active_sess_history
           WHERE sql_exec_id IS NOT NULL
        )
   GROUP BY sql_id,sql_exec_id
)
)
where ct > &min_repeat_executions_filter
 and  mxdelta > &min_elapsed_time
)
SELECT * FROM pivot_data
PIVOT ( COUNT(*) FOR bucket IN (1,2,3,4,5))
ORDER BY mx DESC,av DESC
;

SQL_ID            CT         MX   MN       AV MAX_RUN_TIME                        LONGEST_SQ      1      2     3    4   5
------------- ------ ---------- ---- -------- ----------------------------------- ---------- ------ ------ ----- ---- ---
2spgk3k0f7quz    251      29607    0    546.0 11-04-12 12:11:47 11-04-12 20:25:14 16781748      247      2     0    0   2
990m08w8xav7s    591       7681    0     52.0 11-04-13 00:39:27 11-04-13 02:47:28 16786685      587      0     0    2   2
64dqhdkkw63fd   1083       7147    0      7.0 11-03-07 04:01:01 11-03-07 06:00:08 16777218     1082      0     0    0   1
0bujgc94rg3fj    604       4929    0     25.0 11-04-08 10:53:34 11-04-08 12:15:43 16814628      601      1     1    0   1
0hbv80w9ypy0n    161       4089    0   1184.0 11-03-02 04:36:10 11-04-12 23:34:18 16777290       27    116     9    6   3
bzyny95313u12    114       2599    0     47.0 11-03-03 03:06:18 11-03-03 03:49:37 16781191      113      0     0    0   1
ds8cz0fb8w147    161       2531   13    274.0 11-03-01 23:11:48 11-04-12 16:10:37 16777285      136     18     5    1   1
5k7vccwjr5ahd   2653       1963    0     33.0 11-03-01 23:10:12 11-04-12 09:06:12 16778244     2623     15     8    4   3
4d6m2q3ngjcv9    320       1701    3    485.0 11-03-01 23:10:53 11-04-10 18:01:26 16777261       92    168    50    9   1
g5u58zpg0tuk8     97       1359    1     62.0 11-04-12 02:23:37 11-04-13 02:51:09 16777217       92      3     1    0   1
34cgtc9xkgxny     61       1272  978   1163.0 11-03-02 10:06:24 11-03-02 10:27:36 16777250        4      4    14   30   9
09-02-05-623_950x510

Oracle, performance, sql

Oracle CPU Time

August 27th, 2013


 

 

oracle_cpu_bertrand_drouvot.png

Image from 

UPDATE: thanks to a discussion in the comments it’s come to my attention that there should be some more clarification on values used and what the mean at the beginning of this post.

Ever wonder where CPU wait comes from in EM performance screens as seen above? well the following discussion will give you a SQL query to calculate CPU wait. In the above image we see both CPU and CPU Wait as two colors (light green and dark green) in EM as well as two values from the output of the SQL script (CPU_ORA and CPU_ORA_WAIT).

Oracle CPU statistics are measured from calls to the OS to see how much CPU is burned over a given elapsed time (i.e. certain quantity of code). The CPU values are cycles used and not time, thus it does not include time on the run queue waiting to get the CPU.

Oracle ASH, on the other hand, lists all Oracle sessions that want to run from Oracle’s perspective, i.e. they aren’t idle and they aren’t waiting for a non-idle wait event like I/O. Thus ASH includes time spent both running on CPU burning cycles and time spent waiting to get on the CPU.

Thus we can take the the amount of time “On CPU” from ASH and subtract the amount of CPU in Oracle statistics for CPU usage then the remainder is roughly time spent by Oracle sessions waiting to get onto the CPU.

The two challenges to getting the value of “Wait for CPU” are getting  CPU cycles burned and ASH time “ON CPU” into the same units and making sure that we are measuring both over the same interval.

Oracle already reports CPU in % used and in centi-seconds used.  I like to transform this into Average Active Sessions on CPU so I can compare it to my main way of showing ASH data which is Average Active Sessions on “ON CPU” which includes wait for CPU.

There are 3 kinds of CPU in the Oracle stats.

  1. Oracle CPU used
  2. System CPU used
  3. Oracle demand for CPU

Starting in 10g Oracle records both the CPU used by the instance as well as the load on the system in v$sysmetric. This is awesome as we can see how busy the system is and how much of the CPU Oracle is responsible for:

col metric_name for a25
col metric_unit for a25
select metric_name, value, metric_unit from v$sysmetric where metric_name like'%CPU%' and group_id=2;
METRIC_NAME                         VALUE METRIC_UNIT
------------------------------ ---------- ------------------------------
CPU Usage Per Sec              251.067016 CentiSeconds Per Second
CPU Usage Per Txn              5025.52477 CentiSeconds Per Txn
Host CPU Utilization (%)       11.6985845 % Busy/(Idle+Busy)
Database CPU Time Ratio        76.3291033 % Cpu/DB_Time

Now the question is how do we convert these to something useful? For me I put it into the equivalent of AAS and compare it to the core count:

   select 'CPU_ORA_CONSUMED'                                     CLASS,
                    round(value/100,3)                             AAS
             from v$sysmetric
             where metric_name='CPU Usage Per Sec'
               and group_id=2
          union
            select 'CPU_OS'                                        CLASS ,
                    round((prcnt.busy*parameter.cpu_count)/100,3)    sAAS
            from
              ( select value busy from v$sysmetric
                where metric_name='Host CPU Utilization (%)'
                 and group_id=2 ) prcnt,
             ( select value cpu_count
                 from v$parameter
                where name='cpu_count' )  parameter;

CLASS                  AAS
---------------- ----------
CPU_ORA_CONSUMED       .002
CPU_OS                 .022

An AAS of 1 is equivalent to 100% of a core, so, OS CPU is about 2% of a core and of that Oracle used 0.2% of a core.
Not a very active system, and we can look at an active system later, but what I wanted to point out is that this query is missing an important statistic: the demand for CPU by Oracle. We can only add that, AFAIK, by joining in ASH:

   select 'CPU_ORA_CONSUMED'                                     CLASS,
                    round(value/100,3)                             AAS
             from v$sysmetric
             where metric_name='CPU Usage Per Sec'
               and group_id=2
          union
            select 'CPU_OS'                                         CLASS ,
                    round((prcnt.busy*parameter.cpu_count)/100,3)     AAS
            from
              ( select value busy from v$sysmetric
                 where metric_name='Host CPU Utilization (%)'
                   and group_id=2 ) prcnt,
              ( select value cpu_count from v$parameter
                 where name='cpu_count' )  parameter
          union
             select
               'CPU_ORA_DEMAND'                                            CLASS,
               nvl(round( sum(decode(session_state,'ON CPU',1,0))/60,2),0) AAS
             from v$active_session_history ash
             where SAMPLE_TIME > sysdate - (60/(24*60*60));

CLASS                   AAS
---------------- ----------
CPU_ORA_CONSUMED       .001
CPU_ORA_DEMAND          .02
CPU_OS                 .019

So the demand for CPU was higher than the amount consumed. Now the demand for CPU is coming from ASH which is sampled so the accuracy is weak, but in larger sample sets or busier systems it’s pretty darn good. The demand alerts us to CPU starvation on a busy  system.

I like to wrap all this up into a query with all the wait classes to see the overall load on Oracle including CPU consumed by Oracle, CPU demanded by Oracle and CPU used at the OS level:

select
                 decode(n.wait_class,'User I/O','User I/O',
                                     'Commit','Commit',
                                     'Wait')                               CLASS,
                 sum(round(m.time_waited/m.INTSIZE_CSEC,3))                AAS
           from  v$waitclassmetric  m,
                 v$system_wait_class n
           where m.wait_class_id=n.wait_class_id
             and n.wait_class != 'Idle'
           group by  decode(n.wait_class,'User I/O','User I/O', 'Commit','Commit', 'Wait')
          union
             select 'CPU_ORA_CONSUMED'                                     CLASS,
                    round(value/100,3)                                     AAS
             from v$sysmetric
             where metric_name='CPU Usage Per Sec'
               and group_id=2
          union
            select 'CPU_OS'                                                CLASS ,
                    round((prcnt.busy*parameter.cpu_count)/100,3)          AAS
            from
              ( select value busy from v$sysmetric where metric_name='Host CPU Utilization (%)' and group_id=2 ) prcnt,
              ( select value cpu_count from v$parameter where name='cpu_count' )  parameter
          union
             select
               'CPU_ORA_DEMAND'                                            CLASS,
               nvl(round( sum(decode(session_state,'ON CPU',1,0))/60,2),0) AAS
             from v$active_session_history ash
             where SAMPLE_TIME > sysdate - (60/(24*60*60));

CLASS                   AAS
---------------- ----------
CPU_ORA_CONSUMED       .002
CPU_ORA_DEMAND          .03
CPU_OS                 .023
Commit                    0
User I/O                  0
Wait                      0

Ideally I’d want the CPU stats to be subsets of each other so that I could have a graphically stack-able set of statistics

now rolling it all together
with AASSTAT as (
           select
                 decode(n.wait_class,'User I/O','User I/O',
                                     'Commit','Commit',
                                     'Wait')                               CLASS,
                 sum(round(m.time_waited/m.INTSIZE_CSEC,3))                AAS
           from  v$waitclassmetric  m,
                 v$system_wait_class n
           where m.wait_class_id=n.wait_class_id
             and n.wait_class != 'Idle'
           group by  decode(n.wait_class,'User I/O','User I/O', 'Commit','Commit', 'Wait')
          union
             select 'CPU_ORA_CONSUMED'                                     CLASS,
                    round(value/100,3)                                     AAS
             from v$sysmetric
             where metric_name='CPU Usage Per Sec'
               and group_id=2
          union
            select 'CPU_OS'                                                CLASS ,
                    round((prcnt.busy*parameter.cpu_count)/100,3)          AAS
            from
              ( select value busy from v$sysmetric where metric_name='Host CPU Utilization (%)' and group_id=2 ) prcnt,
              ( select value cpu_count from v$parameter where name='cpu_count' )  parameter
          union
             select
               'CPU_ORA_DEMAND'                                            CLASS,
               nvl(round( sum(decode(session_state,'ON CPU',1,0))/60,2),0) AAS
             from v$active_session_history ash
             where SAMPLE_TIME > sysdate - (60/(24*60*60))
)
select
       ( decode(sign(CPU_OS-CPU_ORA_CONSUMED), -1, 0, (CPU_OS - CPU_ORA_CONSUMED )) +
       CPU_ORA_CONSUMED +
        decode(sign(CPU_ORA_DEMAND-CPU_ORA_CONSUMED), -1, 0, (CPU_ORA_DEMAND - CPU_ORA_CONSUMED ))) CPU_TOTAL,
       decode(sign(CPU_OS-CPU_ORA_CONSUMED), -1, 0, (CPU_OS - CPU_ORA_CONSUMED )) CPU_OS,
       CPU_ORA_CONSUMED CPU_ORA,
       decode(sign(CPU_ORA_DEMAND-CPU_ORA_CONSUMED), -1, 0, (CPU_ORA_DEMAND - CPU_ORA_CONSUMED )) CPU_ORA_WAIT,
       COMMIT,
       READIO,
       WAIT
from (
select
       sum(decode(CLASS,'CPU_ORA_CONSUMED',AAS,0)) CPU_ORA_CONSUMED,
       sum(decode(CLASS,'CPU_ORA_DEMAND'  ,AAS,0)) CPU_ORA_DEMAND,
       sum(decode(CLASS,'CPU_OS'          ,AAS,0)) CPU_OS,
       sum(decode(CLASS,'Commit'          ,AAS,0)) COMMIT,
       sum(decode(CLASS,'User I/O'        ,AAS,0)) READIO,
       sum(decode(CLASS,'Wait'            ,AAS,0)) WAIT
from AASSTAT)
/

    CPU_OS    CPU_ORA CPU_ORA_WAIT     COMMIT     READIO       WAIT
---------- ---------- ------------ ---------- ---------- ----------
       .02       .002            0          0          0          0

Now let’s run up some load on a machine and database.
Take two databases, run up the CPU demand on both and add some wait contention. The machine has 24 cores so there is a definitely a problem when the CPU_TOTAL goes over 24. I’m running 14 sessions each trying to burn a core on two different databases. The first few lines the test is ramping up

SQL> /

 CPU_TOTAL     CPU_OS    CPU_ORA CPU_ORA_WAIT     COMMIT     READIO       WAIT
---------- ---------- ---------- ------------ ---------- ---------- ----------
    14.887       .387     13.753         .747          0          0       .023

SQL> /

 CPU_TOTAL     CPU_OS    CPU_ORA CPU_ORA_WAIT     COMMIT     READIO       WAIT
---------- ---------- ---------- ------------ ---------- ---------- ----------
    21.989      7.469     12.909        1.611          0          0       .044

SQL> /

 CPU_TOTAL     CPU_OS    CPU_ORA CPU_ORA_WAIT     COMMIT     READIO       WAIT
---------- ---------- ---------- ------------ ---------- ---------- ----------
    26.595     12.125     11.841        2.629          0          0       .025

SQL> /

 CPU_TOTAL     CPU_OS    CPU_ORA CPU_ORA_WAIT     COMMIT     READIO       WAIT
---------- ---------- ---------- ------------ ---------- ---------- ----------
    27.045     12.125     11.841        3.079          0          0       .025

Historically CPU used by Oracle was derived from

v$sysstat.name=’CPU used by this session’

but this statistic had problems as the value was only updated every time a call ended. A call could be a 1 hour PL/SQL procedure which would thus report zero cpu usage in the stats until it finished and the CPU would spike off the scale.

ASH had always been the most stable way to gather CPU demand, though Oracle has made improvements in gathering CPU statistics. I believe that the time model gathers CPU every 5 seconds in 10g, and in 11g it’s possible that CPU stats are gathered every second

Here is a visual example of a machine that has server memory contention, massive amounts of paging. There is OS CPU being used, but hardly any CPU being used by Oracle which makes sense as it’s an idle database, but what is revealing is the massive amount of CPU wait by Oracle. Oracle only has a little bit of work to do to take care of an idle database but we can see that most of Oracle’s CPU time is wait for CPU time as when it wants to work, pages have to be read back in,

I have my doubts as to the clarity of the layout of the above graph. A possibly clearer graph would be simply adding a line representing available CPU and take out the OSCPU bars. In the above graph I’ve charted OSCPU usage as AAS, ie average active sessions, mixing AAS of the database with AAS at the OS level. I think a  possible clear representation would be to show the Core count line, and draw the OSCPU usage shown upside down from the # of core lines, thus the space from the bottom axis to where the OSCPU reaches down would be available CPU.

 UPDATE

Thanks to the eagle eyes of John Beresniewicz a small error was identified in the above script. The last script didn’t correlate the time windows of v$sysmetric with v$active_session history. They both reported the last minute of statistics but the last minute reported in v$sysmetric could be up to a minute behind those in v$active_session_history, so here is a version that tries to correlate to two time windows so they are in sync

with AASSTAT as (
           select
                 decode(n.wait_class,'User I/O','User I/O',
                                     'Commit','Commit',
                                     'Wait')                               CLASS,
                 sum(round(m.time_waited/m.INTSIZE_CSEC,3))                AAS,
                 BEGIN_TIME ,
                 END_TIME
           from  v$waitclassmetric  m,
                 v$system_wait_class n
           where m.wait_class_id=n.wait_class_id
             and n.wait_class != 'Idle'
           group by  decode(n.wait_class,'User I/O','User I/O', 'Commit','Commit', 'Wait'), BEGIN_TIME, END_TIME
          union
             select 'CPU_ORA_CONSUMED'                                     CLASS,
                    round(value/100,3)                                     AAS,
                 BEGIN_TIME ,
                 END_TIME
             from v$sysmetric
             where metric_name='CPU Usage Per Sec'
               and group_id=2
          union
            select 'CPU_OS'                                                CLASS ,
                    round((prcnt.busy*parameter.cpu_count)/100,3)          AAS,
                 BEGIN_TIME ,
                 END_TIME
            from
              ( select value busy, BEGIN_TIME,END_TIME from v$sysmetric where metric_name='Host CPU Utilization (%)' and group_id=2 ) prcnt,
              ( select value cpu_count from v$parameter where name='cpu_count' )  parameter
          union
             select
               'CPU_ORA_DEMAND'                                            CLASS,
               nvl(round( sum(decode(session_state,'ON CPU',1,0))/60,2),0) AAS,
               cast(min(SAMPLE_TIME) as date) BEGIN_TIME ,
               cast(max(SAMPLE_TIME) as date) END_TIME
             from v$active_session_history ash
              where SAMPLE_TIME >= (select BEGIN_TIME from v$sysmetric where metric_name='CPU Usage Per Sec' and group_id=2 )
               and SAMPLE_TIME < (select END_TIME from v$sysmetric where metric_name='CPU Usage Per Sec' and group_id=2 )
)
select
       to_char(BEGIN_TIME,'HH:MI:SS') BEGIN_TIME,
       to_char(END_TIME,'HH:MI:SS') END_TIME,
       CPU_OS CPU_TOTAL,
       decode(sign(CPU_OS-CPU_ORA_CONSUMED), -1, 0, (CPU_OS - CPU_ORA_CONSUMED )) CPU_OS,
       CPU_ORA_CONSUMED CPU_ORA,
       decode(sign(CPU_ORA_DEMAND-CPU_ORA_CONSUMED), -1, 0, (CPU_ORA_DEMAND - CPU_ORA_CONSUMED )) CPU_ORA_WAIT,
       COMMIT,
       READIO,
       WAIT 
       -- ,(  decode(sign(CPU_OS - CPU_ORA_CONSUMED), -1, 0, 
       --                (CPU_OS - CPU_ORA_CONSUMED))
       --    + CPU_ORA_CONSUMED +
       --  decode(sign(CPU_ORA_DEMAND - CPU_ORA_CONSUMED), -1, 0, 
       --             (CPU_ORA_DEMAND - CPU_ORA_CONSUMED ))) STACKED_CPU_TOTAL 
from ( 
        select 
                min(BEGIN_TIME) BEGIN_TIME,
                max(END_TIME) END_TIME, 
                sum(decode(CLASS,'CPU_ORA_CONSUMED',AAS,0)) CPU_ORA_CONSUMED, 
                sum(decode(CLASS,'CPU_ORA_DEMAND' ,AAS,0)) CPU_ORA_DEMAND, 
                sum(decode(CLASS,'CPU_OS' ,AAS,0)) CPU_OS, 
                sum(decode(CLASS,'Commit' ,AAS,0)) COMMIT, 
                sum(decode(CLASS,'User I/O' ,AAS,0)) READIO, 
                sum(decode(CLASS,'Wait' ,AAS,0)) WAIT 
         from AASSTAT) 
/

The output now looks like

BEGIN_TI END_TIME  CPU_TOTAL	 CPU_OS    CPU_ORA CPU_ORA_WAIT     COMMIT     READIO	    WAIT
-------- -------- ---------- ---------- ---------- ------------ ---------- ---------- ----------
07:23:35 07:24:35	.044	   .024       .002	   .018 	 0	    0	    .001

I’m still open that there might be some more tweaking to do, so your milage may vary. Test, Test, Test and only trust yourself!
As a reminder the code above is on Github as part of the ASH Masters project. Feel free to get a Github account, fork the code and make changes. If you find cool new code or errors in old code, let me know and we will merge it into the ASH Masters project

 

https://github.com/khailey/ashmasters/blob/master/cpu_consumed_verses_cpuwait.sql

Oracle, performance ,