Wednesday, May 30, 2012

Alter System Flush Shared_Pool and Alter System Flush Buffer_Cache

This example shows the effect of the alter system flush shared_pool and alter system flush buffer_cache commands. It was tested on Oracle 11.2. First create a table with some rows to count:
 
SQL> create table tab1
  2  as select * from dba_tables
  3  /
 
Table created.
 
SQL> begin
  2  for a in 1..5
  3  loop
  4  insert into tab1 select * from tab1;
  5  end loop;
  6  end;
  7  /
 
PL/SQL procedure successfully completed.
 
SQL>
 
The shared pool contains the library cache. This stores the parsing details and execution plans for SQL statements which have been run. You can remove these details by flushing the shared pool:
 
SQL> alter system flush shared_pool
  2  /
 
System altered.
 
SQL>
 
The buffer cache contains blocks which have been read from disk. You can flush the buffer cache as follows:
 
SQL> alter system flush buffer_cache
  2  /
 
System altered.
 
SQL>
 
Now you can get a baseline time (1.94 seconds) for parsing the SQL, creating an execution plan, getting the database blocks from disk and counting the rows:
 
SQL> set timing on
SQL> select count(*) from tab1
  2  /
 
  COUNT(*)
----------
     97920
 
Elapsed: 00:00:01.94
SQL>
 
Count the rows again. This time the SQL is already in the library cache so it does not need to be reparsed. The database blocks are still in the buffer cache from the previous SQL statement so there is no need to get them from disk either. As a result, this statement is much quicker (0.04 seconds):
 
SQL> select count(*) from tab1
  2  /
 
  COUNT(*)
----------
     97920
 
Elapsed: 00:00:00.04
SQL> set timing off
SQL>
 
Now flush the shared pool to remove the SQL from the library cache:
 
SQL> alter system flush shared_pool
  2  /
 
System altered.
 
SQL>
 
Run the SQL again. Having to reparse the SQL and recreate the execution plan adds a fraction of a second to the elapsed time:
 
SQL> set timing on
SQL> select count(*) from tab1
  2  /
 
  COUNT(*)
----------
     97920
 
Elapsed: 00:00:00.07
SQL> set timing off
SQL>
 
Flush the buffer cache to remove the database blocks:
 
SQL> alter system flush buffer_cache
  2  /
 
System altered.
 
SQL>
 
Count the rows in the table as before. Having to fetch the database blocks from disk again adds over a second to the elapsed time:
 
SQL> set timing on
SQL> select count(*) from tab1
  2  /
 
  COUNT(*)
----------
     97920
 
Elapsed: 00:00:01.49
SQL> set timing off
SQL>
 
Finally, flush both the shared pool AND the buffer cache:
 
SQL> alter system flush shared_pool
  2  /
 
System altered.
 
SQL> alter system flush buffer_cache
  2  /
 
System altered.
 
SQL>
 
Count the rows in the table for the last time. This involves reparsing the SQL, recreating the execution plan and fetching the database blocks. This time the elapsed time is roughly the same as the baseline time at the start:
 
SQL> set timing on
SQL> select count(*) from tab1
  2  /
 
  COUNT(*)
----------
     97920
 
Elapsed: 00:00:01.85
SQL> set timing off
SQL>

Monday, May 28, 2012

DBMS_STATS.SET_PARAM

The example below worked as shown in Oracle 10. First create a test table with an index:
 
SQL> create table andrews_table (col1 number)
  2  /
 
Table created.
 
SQL> create index andrews_index
  2  on andrews_table(col1)
  3  /
 
Index created.

SQL>

Next run dbms_stats.set_param and set cascade to false:
 
SQL> exec dbms_stats.set_param('cascade','false');
 
PL/SQL procedure successfully completed.

SQL>

Then, if you analyze the table using gather_table_stats:
 
SQL> exec dbms_stats.gather_table_stats -
> (ownname=>'oracle', tabname=>'andrews_table');
 
PL/SQL procedure successfully completed.

SQL>

The table is analyzed:
 
SQL> select nvl(to_char(last_analyzed),'NULL') analyzed
  2  from user_tables
  3  where table_name = 'ANDREWS_TABLE'
  4  /
 
ANALYZED
---------
15-MAY-12

SQL>

... but the index isn't:
 
SQL> select nvl(to_char(last_analyzed),'NULL') analyzed
  2  from user_indexes
  3  where index_name = 'ANDREWS_INDEX'
  4  /
 
ANALYZED
---------
NULL

SQL>

However, if you run dbms_stats.set_param and set cascade to true:

SQL> exec dbms_stats.set_param('cascade','true');
 
PL/SQL procedure successfully completed.

SQL>

When you analyze the table, the index is analyzed too:
 
SQL> exec dbms_stats.gather_table_stats -
> (ownname=>'oracle', tabname=>'andrews_table');
 
PL/SQL procedure successfully completed.
 
SQL> select nvl(to_char(last_analyzed),'NULL') analyzed
  2  from user_tables
  3  where table_name = 'ANDREWS_TABLE'
  4  /
 
ANALYZED
---------
15-MAY-12
 
SQL> select nvl(to_char(last_analyzed),'NULL') analyzed
  2  from user_indexes
  3  where index_name = 'ANDREWS_INDEX'
  4  /
 
ANALYZED
---------
15-MAY-12
 
SQL>
 
In Oracle 11, dbms_stats.set_param still runs but it has no effect. You can run
dbms_stats.set_param('cascade','false'); but the index might still be analyzed!

Friday, May 25, 2012

V$SYSTEM_EVENT

This was tested on Oracle 11.2. V$SYSTEM_EVENT shows what an instance has been waiting for since it was last started. You can see the top 10 events (by total time waited) as follows. The times are in hundredths of a second:

SQL> l
  1  select * from
  2  (select event, time_waited
  3   from v$system_event
  4   where wait_class != 'Idle'
  5   order by 2 desc)
  6* where rownum <= 10
SQL> /
 
EVENT                               TIME_WAITED
----------------------------------- -----------
control file sequential read             992637
db file sequential read                  569680
control file parallel write              543468
os thread startup                        515992
log file parallel write                  499896
db file parallel write                   426726
db file scattered read                   202302
log file sync                            159840
Disk file operations I/O                  45765
ADR block file read                       29553
 
10 rows selected.
 
SQL>
 
If you include Idle events, you see the wait events where the database wasn’t doing anything. The SQL*Net message from client event, for example, records how long the database spent waiting for its next instruction. This may not be what you want to see:

SQL> l
  1  select * from
  2  (select event, time_waited
  3   from v$system_event
  4   order by 2 desc)
  5* where rownum <= 10
SQL> /
 
EVENT                                    TIME_WAITED
---------------------------------------- -----------
rdbms ipc message                         1956293654
SQL*Net message from client                637129764
DIAG idle wait                             326433989
dispatcher timer                           163322456
shared server idle wait                    163320698
Streams AQ: qmn coordinator idle wait      163318553
Streams AQ: qmn slave idle wait            163315578
smon timer                                 163264804
pmon timer                                 163252749
Space Manager: slave idle wait             163171812
 
10 rows selected.
 
SQL>
 
The TIME_WAITED for SQL*Net message from client works out at almost 74 days. However, the database has been open for less than 20 days:
 
SQL> l
  1  select startup_time, sysdate
  2* from v$instance, dual
SQL> /
 
STARTUP_TIME SYSDATE
------------ ---------
04-MAY-12    23-MAY-12
 
SQL>
 
That’s because the TIME_WAITED values are the sum of all the TIME_WAITED values for all the sessions which have logged in since the database was opened.
 
If you combine these figures with the CPU time used, you start to get an idea of what your database has been doing:
 
SQL> l
  1  select a.name, b.value
  2  from v$statname a, v$sysstat b
  3  where a.statistic# = b.statistic#
  4* and a.name = 'CPU used by this session'
SQL> /
 
NAME                                     VALUE
----------------------------------- ----------
CPU used by this session               1854863
 
SQL>

V$EVENT_NAME

This was run in an Oracle 11.2 database. What is in V$EVENT_NAME?

SQL> desc v$event_name
Name                       Null?    Type
-------------------------- -------- ------------------
EVENT#                              NUMBER
EVENT_ID                            NUMBER
NAME                                VARCHAR2(64)
PARAMETER1                          VARCHAR2(64)
PARAMETER2                          VARCHAR2(64)
PARAMETER3                          VARCHAR2(64)
WAIT_CLASS_ID                       NUMBER
WAIT_CLASS#                         NUMBER
WAIT_CLASS                          VARCHAR2(64)
 
SQL>
 
Despite its name, this is not a dynamic view like V$SESSION, for example. It contains details of all the wait events being recorded by your database. In Oracle 11.2 there are over 1000 wait events:
 
SQL> select count(*) from v$event_name
  2  /
 
  COUNT(*)
----------
      1118
 
SQL>
 
Each event has a number and name. These can change between Oracle versions:
 
SQL> l
  1* select event#, name from v$event_name
SQL> /
 
    EVENT# NAME
---------- ----------------------------------------
         0 null event
         1 pmon timer
         2 logout restrictor
         3 VKTM Logical Idle Wait
         4 VKTM Init Wait for GSGA
         5 IORM Scheduler Slave Idle Wait
         6 Parameter File I/O
         7 rdbms ipc message
         8 remote db operation
         9 remote db file read
        10 remote db file write
        11 Disk file operations I/O
        12 Disk file I/O Calibration
        13 Disk file Mirror Read
        14 Disk file Mirror/Media Repair Write
        15 direct path sync
        16 Datapump dump file I/O
Etc.
 
Each event also has a hash value based on the name. This will not change between Oracle versions if the name remains the same. It is stored in the EVENT_ID column:
 
  1* select event_id, name from v$event_name
SQL> /
 
  EVENT_ID NAME
---------- ----------------------------------------
2516578839 null event
3539483025 pmon timer
3934444552 logout restrictor
939791390 VKTM Logical Idle Wait
1513856046 VKTM Init Wait for GSGA
1421578053 IORM Scheduler Slave Idle Wait
1179235204 Parameter File I/O
866018717 rdbms ipc message
3222461937 remote db operation
2171045634 remote db file read
538064841 remote db file write
166678035 Disk file operations I/O
2215689832 Disk file I/O Calibration
  13102552 Disk file Mirror Read
2577606720 Disk file Mirror/Media Repair Write
2093619153 direct path sync
4155572307 Datapump dump file I/O
etc
 
Each event has a WAIT_CLASS. This allows you to exclude Idle events, for example. Each WAIT_CLASS has a hash value based on its name. This is stored in the WAIT_CLASS_ID column:
 
SQL> l
  1  select wait_class, wait_class_id, count(*)
  2  from v$event_name
  3* group by wait_class, wait_class_id
SQL> /
 
WAIT_CLASS           WAIT_CLASS_ID   COUNT(*)
-------------------- ------------- ----------
Network                 2000153315         35
Configuration           3290255840         24
Queueing                 644977587          9
Other                   1893977003        719
Concurrency             3875070507         32
Idle                    2723168908         94
Scheduler               2396326234          7
User I/O                1740759767         45
System I/O              4108307767         30
Commit                  3386400367          2
Cluster                 3871361733         50
Administrative          4166625743         54
Application             4217450380         17
 
13 rows selected.
 
SQL>

Thursday, May 24, 2012

AVERAGE_WAIT

The AVERAGE_WAIT column in V$SYSTEM_EVENT records how long Oracle has had to wait (on average) for a given event. The value is in hundredths of a second:
 
SQL> l
  1  select event, average_wait
  2  from v$system_event
  3  where event in
  4  ('db file sequential read',
  5*  'db file scattered read')
SQL> /
 
EVENT                          AVERAGE_WAIT
------------------------------ ------------
db file sequential read                1.67
db file scattered read                 5.16
 
SQL>
 
The example above was run on an Oracle 11.2 test database running on Solaris with datafiles on a Celerra filer. The first line relates to single block reads and the second to multiblock reads. Here are the same values from an Oracle 11.2 production database, also running on Solaris but with datafiles on dedicated disks:
 
SQL> l
  1  select event, average_wait
  2  from v$system_event
  3  where event in
  4  ('db file sequential read',
  5*  'db file scattered read')
SQL> /
 
EVENT                          AVERAGE_WAIT
------------------------------ ------------
db file sequential read                  .2
db file scattered read                  .58
 
SQL>

Finally, here are the figures from an Oracle 10.2.0.1.0 database running on Windows XP SP3 on a PC I assembled myself:

SQL> l
  1  select event, average_wait
  2  from v$system_event
  3  where event in
  4  ('db file sequential read',
  5*  'db file scattered read')
SQL> /

EVENT                          AVERAGE_WAIT
------------------------------ ------------
db file sequential read                6,49
db file scattered read                 5,88

SQL>


 

Wednesday, May 23, 2012

CPU Usage

I tested this on Oracle 11.2. You need to be careful when looking at Oracle statistics on CPU usage. Here is an idle session (in red):

SQL> select distinct sid from v$mystat
  2  /
 
       SID
----------
         6
 
SQL>
 
Here is its CPU usage as seen from another session (in blue). The CPU used when call started and CPU used by this session figures are in hundredths of a second. The DB CPU figure is in microseconds:
 
SQL> select
  2  (select value from v$sesstat a, v$statname b
  3   where sid = 6
  4   and a.statistic# = b.statistic#
  5   and name = 'CPU used when call started') as CUWCS,
  6  (select value from v$sesstat a, v$statname b
  7   where sid = 6
  8   and a.statistic# = b.statistic#
  9   and name = 'CPU used by this session') as CUBTS,
10  (select value
11   from v$sess_time_model
12   where sid = 6
13   and stat_name = 'DB CPU') as "DB CPU"
14  from dual
15  /
 
     CUWCS      CUBTS     DB CPU
---------- ---------- ----------
     41669      41669  416810000
 
SQL>
 
The first session runs a query:
 
SQL> set timing on
SQL> select count(*) from dba_tables a, dba_tables b
  2  /
 
While this is going on, the second session monitors it every 30 seconds The  CPU used when call started figure stays the same while the SQL is running. This is reasonable. The CPU used by this session figure goes up a little then stays the same. It is not clear what this is measuring at all. The DB CPU figure appears to be updated regularly:
 
SQL> /
 
     CUWCS      CUBTS     DB CPU
---------- ---------- ----------
     41669      41752  441270000
 
SQL> /
 
     CUWCS      CUBTS     DB CPU
---------- ---------- ----------
     41669      41752  470980000
 
SQL> /
 
     CUWCS      CUBTS     DB CPU
---------- ---------- ----------
     41669      41752  494630000
 
SQL> /
 
     CUWCS      CUBTS     DB CPU
---------- ---------- ----------
     41669      41752  522780000
 
SQL>
 
The first session’s query finishes:
 
SQL> select count(*) from dba_tables a, dba_tables b
  2  /
 
  COUNT(*)
----------
   9369721
 
Elapsed: 00:02:25.93
SQL>
 
Then the figures in the second session match again:
 
SQL> /
 
     CUWCS      CUBTS     DB CPU
---------- ---------- ----------
     54891      54891  549030000
 
SQL>

ORA-02260

This was tested on Oracle 11.2. I saw ORA-02260 for the first time today and decided to investigate further. If you want to ensure that more than 1 column holds unique values, you can do this by creating unique indexes or modifying the columns to be unique. However, if you try to explicitly set up more than one primary key on a table, you get this error:
 
SQL> create table andrews_table
  2  (col1 number,
  3   col2 number,
  4   col3 number,
  5   col4 number,
  6   col5 number,
  7   col6 number)
  8  /
 
Table created.
 
SQL> create unique index andrews_index1
  2  on andrews_table(col1)
  3  /
 
Index created.
 
SQL> create unique index andrews_index2
  2  on andrews_table(col2)
  3  /
 
Index created.
 
SQL> alter table andrews_table
  2  modify (col3 unique)
  3  /
 
Table altered.
 
SQL> alter table andrews_table
  2  modify (col4 unique)
  3  /
 
Table altered.
 
SQL> alter table andrews_table
  2  add constraint pk1 primary key(col5)
  3  /
 
Table altered.
 
SQL> alter table andrews_table
  2  add constraint pk2 primary key(col6)
  3  /
add constraint pk2 primary key(col6)
                   *
ERROR at line 2:
ORA-02260: table can have only one primary key
 
SQL>

Tuesday, May 22, 2012

Skewed Indexes

This example looks at skewed indexes and was tested on Oracle 10.2.0.3.0. First create a very basic salary table. Start off with 1 column to store the gender:

SQL> create table salaries
  2  (gender varchar2(1))
  3  pctfree 50
  4  /
 
Table created.
 
SQL>

Insert 10000 rows in the table. Approximately 1% will have a gender of F (for female) and the rest will be M (for male):

SQL> begin
  2  for a in 1..10000 loop
  3  insert into salaries values
  4  (decode(ceil(dbms_random.value*100),1,'F','M'));
  5  end loop;
  6  end;
  7  /
 
PL/SQL procedure successfully completed.
 
SQL>

Check the distribution of values is as expected:

SQL> select gender, count(*) from salaries
  2  group by gender
  3  /
 
GENDER   COUNT(*)
------ ----------
M            9902
F              98
 
SQL>
 
Add a salary column to the table:

SQL> alter table salaries add
  2  (salary number)
  3  /
 
Table altered.
 
SQL>

Now input random salaries. Males have a salary between 1 and 20000. Females have a salary between 1 and 40000:

SQL> update salaries
  2  set salary = ceil(dbms_random.value*20000)
  3  where gender = 'M'
  4  /
 
9902 rows updated.
 
SQL> update salaries
  2  set salary = ceil(dbms_random.value*40000)
  3  where gender = 'F'
  4  /
 
98 rows updated.
 
SQL>

Create an index on the gender column. There are far more rows for males than there are for females so the data and the associated index are said to be skewed:

SQL> create index gender_index
  2  on salaries(gender)
  3  /
 
Index created.
 
SQL>
 
Now, without analyzing the data, work out the average salary for each gender. Oracle does some dynamic sampling. This tells it to do a full table scan for the males and an index lookup for the females, which is what you would expect with the data we have created:

SQL> set autotrace on
SQL> select avg(salary) from salaries
  2  where gender = 'M'
  3  /
 
AVG(SALARY)
-----------
  10030.627
 
Execution Plan
----------------------------------------------------------
Plan hash value: 793938830
 
-------------------------------------------------------------------------------
| Id  | Operation          | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |          |     1 |    15 |     9   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE    |          |     1 |    15 |            |          |
|*  2 |   TABLE ACCESS FULL| SALARIES |  9902 |   145K|     9   (0)| 00:00:01 |
-------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - filter("GENDER"='M')
 
Note
-----
   - dynamic sampling used for this statement
 
Statistics
----------------------------------------------------------
          9  recursive calls
          0  db block gets
         70  consistent gets
          5  physical reads
          0  redo size
        537  bytes sent via SQL*Net to client
        491  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed
 
SQL> select avg(salary) from salaries
  2  where gender = 'F'
  3  /
 
AVG(SALARY)
-----------
  18762.898
 
Execution Plan
----------------------------------------------------------
Plan hash value: 3244963775
 
---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |     1 |    15 |     2   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE              |              |     1 |    15 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| SALARIES     |    98 |  1470 |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | GENDER_INDEX |    98 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   3 - access("GENDER"='F')
 
Note
-----
   - dynamic sampling used for this statement

Statistics
----------------------------------------------------------
          7  recursive calls
          0  db block gets
         64  consistent gets
          0  physical reads
          0  redo size
        537  bytes sent via SQL*Net to client
        491  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed
 
SQL> set autotrace off
 
Now analyze the table. Note that this creates 4 entries in DBA_HISTOGRAMS. I assume Oracle uses these to record the spread of the data:
 
SQL> select count(*) from dba_histograms
  2  where owner = 'ORACLE'
  3  and table_name = 'SALARIES'
  4  /
 
  COUNT(*)
----------
         0
 
SQL> exec dbms_stats.gather_table_stats -
> (ownname=>'oracle', -
>  tabname=>'salaries', -
>  cascade=>true);
 
PL/SQL procedure successfully completed.
 
SQL> select count(*) from dba_histograms
  2  where owner = 'ORACLE'
  3  and table_name = 'SALARIES'
  4  /
 
  COUNT(*)
----------
         4
 
SQL>

Work out the average salary by gender again. Oracle does not have to do dynamic sampling this time, presumably because it now has the entries in DBA_HISTOGRAMS to help. (If you work out the average salary by gender twice, without running DBMS_STATS in between, Oracle does dynamic sampling both times – I checked.) I will return to this in future when I have a better understanding:

SQL> set autotrace on
SQL> select avg(salary) from salaries
  2  where gender = 'M'
  3  /
 
AVG(SALARY)
-----------
  10030.627
 
Execution Plan
----------------------------------------------------------
Plan hash value: 793938830
 
-------------------------------------------------------------------------------
| Id  | Operation          | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |          |     1 |     6 |     9   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE    |          |     1 |     6 |            |          |
|*  2 |   TABLE ACCESS FULL| SALARIES |  9902 | 59412 |     9   (0)| 00:00:01 |
-------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - filter("GENDER"='M')
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         31  consistent gets
          0  physical reads
          0  redo size
        537  bytes sent via SQL*Net to client
        491  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed
 
SQL> select avg(salary) from salaries
  2  where gender = 'F'
  3  /
 
AVG(SALARY)
-----------
  18762.898

Execution Plan
----------------------------------------------------------
Plan hash value: 3244963775
 
---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |     1 |     6 |     2   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE              |              |     1 |     6 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| SALARIES     |    98 |   588 |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | GENDER_INDEX |    98 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   3 - access("GENDER"='F')
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         29  consistent gets
          0  physical reads
          0  redo size
        537  bytes sent via SQL*Net to client
        491  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed
 
SQL>

Summary: I also ran this example on Oracle 9.2.0.7.0. After creating the index, Oracle used it to work out the average salary for both genders. No dynamic sampling was attempted. After running DBMS_STATS, 4 new entries appeared in DBA_HISTOGRAMS but Oracle did a full table scan to work out the average salary for both genders. The behaviour under Oracle 10.2.0.3.0 is a great improvement.