db_writer_processes

I wrote the first part of this example in 2012.

 

The database writer copies data blocks from the buffer cache onto disk. The db_writer_processes initialization parameter determines how many processes will do this task. Its default value is 1 or cpu_count / 8, whichever is greater. I found an Oracle 9 database on a Tru64 server with cpu_count set to 1:

 

SQL> l

  1  select value from v$parameter

  2* where name = 'cpu_count'

SQL> /

 

VALUE

------------------------------

1

 

SQL>

 

The database used the default value for db_writer_processes, which Oracle had calculated as 1:

 

SQL> select value, isdefault

  2  from v$parameter

  3  where name = 'db_writer_processes'

  4  /

 

VALUE                          ISDEFAULT

------------------------------ ---------

1                              TRUE

 

SQL>

 

(However, since I first wrote this, I have found documentation suggesting that db_writer_processes always defaulted to 1 in Oracle 9 and took no notice of cpu_count.)

 

I looked for this process in the operating system as follows (I had to squash the ps output a bit to make it fit the screen):

 

UNIX > ps -ef|grep dbw|grep TEST9

oracle 250424 1 0.0 02:07:18 ?? 0:00.87 ora_dbw0_TEST9

UNIX >

 

I found an Oracle 11 database on a Solaris server with cpu_count set to 16:

 

SQL> select value from v$parameter

  2  where name = 'cpu_count'

  3  /

 

VALUE

------------------------------

16

 

SQL>

 

It also used the default value for db_writer_processes, which Oracle had calculated as 2:

 

SQL> select value, isdefault

  2  from v$parameter

  3  where name = 'db_writer_processes'

  4  /

 

VALUE                          ISDEFAULT

------------------------------ ---------

2                              TRUE

 

SQL>

 

When I found these processes in the operating system, I saw that Oracle had given them consecutive numbers i.e. dbw0 and dbw1 (the ps output was squashed again to fit the screen):

 

UNIX > ps -ef|grep dbw|grep PROD11

oracle 12230 1 0 19:42:36 ? 1:24 ora_dbw0_PROD11

oracle 12232 1 0 19:42:36 ? 1:21 ora_dbw1_PROD11

UNIX >

 

If you don’t have enough database writer processes, you can apparently have problems with free buffer waits. I searched all our production databases and could only find two with any of these at all. This was one of them:

 

  1  select time_waited from v$system_event

  2* where event = 'free buffer waits'

SQL> /

 

TIME_WAITED

-----------

71

 

SQL>

 

As this figure is given in hundredths of a second, I decided to do nothing about it.

 

I created an Oracle 11.2.0.4 database in 2015 and set db_writer_processes to 36:

 

SQL> alter system set db_writer_processes = 36

  2  scope = spfile

  3  /

 

System altered.

 

SQL>

 

Then I bounced the database (this is not shown). When I looked for the database writer processes in the operating system, I saw that Oracle had called them dbw0 through dbw9 then dbwa through dbwz:

 

UNIX > ps -ef|grep dbw|grep BECHEDV1

oracle 50594 50565 0 17:27:03 ? 0:00 ora_dbwh_BECHEDV1

oracle 50583 50565 0 17:27:02 ? 0:00 ora_dbw6_BECHEDV1

oracle 50578 50565 0 17:27:02 ? 0:00 ora_dbw1_BECHEDV1

oracle 50611 50565 0 17:27:03 ? 0:00 ora_dbww_BECHEDV1

oracle 50589 50565 0 17:27:02 ? 0:00 ora_dbwc_BECHEDV1

oracle 50593 50565 0 17:27:03 ? 0:00 ora_dbwg_BECHEDV1

oracle 50600 50565 0 17:27:03 ? 0:00 ora_dbwn_BECHEDV1

oracle 50615 50565 0 17:27:03 ? 0:00 ora_dbwz_BECHEDV1

oracle 50612 50565 0 17:27:03 ? 0:00 ora_dbwx_BECHEDV1

oracle 50582 50565 0 17:27:02 ? 0:00 ora_dbw5_BECHEDV1

oracle 50580 50565 0 17:27:02 ? 0:00 ora_dbw3_BECHEDV1

oracle 50608 50565 0 17:27:03 ? 0:00 ora_dbwt_BECHEDV1

oracle 50588 50565 0 17:27:02 ? 0:00 ora_dbwb_BECHEDV1

oracle 50610 50565 0 17:27:03 ? 0:00 ora_dbwv_BECHEDV1

oracle 50579 50565 0 17:27:02 ? 0:00 ora_dbw2_BECHEDV1

oracle 50602 50565 0 17:27:03 ? 0:00 ora_dbwp_BECHEDV1

oracle 50595 50565 0 17:27:03 ? 0:00 ora_dbwi_BECHEDV1

oracle 50614 50565 0 17:27:03 ? 0:00 ora_dbwy_BECHEDV1

oracle 50598 50565 0 17:27:03 ? 0:00 ora_dbwl_BECHEDV1

oracle 50609 50565 0 17:27:03 ? 0:00 ora_dbwu_BECHEDV1

oracle 50590 50565 0 17:27:03 ? 0:00 ora_dbwd_BECHEDV1

oracle 50581 50565 0 17:27:02 ? 0:00 ora_dbw4_BECHEDV1

oracle 50586 50565 0 17:27:02 ? 0:00 ora_dbw9_BECHEDV1

oracle 50596 50565 0 17:27:03 ? 0:00 ora_dbwj_BECHEDV1

oracle 50584 50565 0 17:27:02 ? 0:00 ora_dbw7_BECHEDV1

oracle 50599 50565 0 17:27:03 ? 0:00 ora_dbwm_BECHEDV1

oracle 50604 50565 0 17:27:03 ? 0:00 ora_dbwr_BECHEDV1

oracle 50587 50565 0 17:27:02 ? 0:00 ora_dbwa_BECHEDV1

oracle 50585 50565 0 17:27:02 ? 0:00 ora_dbw8_BECHEDV1

oracle 50591 50565 0 17:27:03 ? 0:00 ora_dbwe_BECHEDV1

oracle 50603 50565 0 17:27:03 ? 0:00 ora_dbwq_BECHEDV1

oracle 50601 50565 0 17:27:03 ? 0:00 ora_dbwo_BECHEDV1

oracle 50606 50565 0 17:27:03 ? 0:00 ora_dbws_BECHEDV1

oracle 50597 50565 0 17:27:03 ? 0:00 ora_dbwk_BECHEDV1

oracle 50592 50565 0 17:27:03 ? 0:00 ora_dbwf_BECHEDV1

oracle 50577 50565 0 17:27:02 ? 0:00 ora_dbw0_BECHEDV1

UNIX >

 

I read somewhere that the maximum value for db_writer_processes is 36 but Oracle allowed me to change it to 37:

 

SQL> alter system set db_writer_processes = 37

  2  scope = spfile

  3  /

 

System altered.

 

SQL>

 

Then I bounced the database again:

 

SQL> shutdown

Database closed.

Database dismounted.

ORACLE instance shut down.

SQL> startup

ORACLE instance started.

 

Total System Global Area  521936896 bytes

Fixed Size                  2252448 bytes

Variable Size             306184544 bytes

Database Buffers          205520896 bytes

Redo Buffers                7979008 bytes

Database mounted.

Database opened.

SQL> exit

Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

UNIX >

 

However, when I checked in the operating system, there were still only 36 database writer processes:

 

UNIX >  ps -ef|grep dbw|grep BECHEDV1|wc -l

      36

UNIX >

 

… and there was a message in the alert log telling me that db_writer_processes had been adjusted:

 

NOTE: db_writer_processes has been changed from 37 to  36ue to NUMA requirements.

PL/SQL lock timer

I was looking through V$SYSTEM_EVENT on an Oracle 11.2 production database (as you do) and I noticed that it had waited for exactly 1 second on the PL/SQL lock timer event. Apparently this is the amount of time a database has been waiting for sessions which have been told to sleep by their application. I decided to check this out so I started a new session, slept for 6.7 seconds then looked to see how long my session had been waiting on this event:

SQL> conn /

Connected.

SQL> exec dbms_lock.sleep(6.7);

 

PL/SQL procedure successfully completed.

 

SQL> select time_waited/100

  2  from v$session_event

  3  where event = 'PL/SQL lock timer'

  4  and sid = (select distinct sid from v$mystat)

  5  /

 

TIME_WAITED/100

---------------

           6.71

 

SQL>

 

DBMS_SYSTEM.KCFRMS

 I tested this on Oracle 11.2.

 

V$SESSION_EVENT holds similar information to V$SYSTEM_EVENT but it is broken down by session (only currently logged in sessions appear - there is no history). There is a MAX_WAIT column which shows the maximum time a session has had to wait for a particular event.There is no timestamp on this so you cannot tell when the longest wait took place. However, if you have a session which is about to start another step in a process, you can zeroise MAX_WAIT so you know the maximum wait time in that step once it has finished. This zeroises all MAX_WAIT values for all events in all sessions. It also resets MAXIORTM and MAXIOWTM in V$FILESTAT. I decided to give it a try. First I checked the current values:

SQL> conn / as sysdba

Connected.

SQL> select sum(max_wait) from v$session_event

  2  /

 

SUM(MAX_WAIT)

-------------

      1323729

 

SQL> select sum(maxiortm), sum(maxiowtm)

  2  from v$filestat

  3  /

 

SUM(MAXIORTM) SUM(MAXIOWTM)

------------- -------------

         2972          8171

 

SQL>

Then I ran the command to zeroise them:

SQL> exec dbms_system.kcfrms();

 

PL/SQL procedure successfully completed.

 

SQL>

Finally I checked the figures again:

SQL> select sum(max_wait) from v$session_event

  2  /

 

SUM(MAX_WAIT)

-------------

            0

 

SQL> select sum(maxiortm), sum(maxiowtm)

  2  from v$filestat

  3  /

 

SUM(MAXIORTM) SUM(MAXIOWTM)

------------- -------------

            0             0

 

SQL>

enq: SQ – contention

This example shows how to deal with the enq: SQ – contention wait event. It was tested on Oracle 11.2. First I created a sequence and queried the amount of time already spent on this wait event:

SQL> create sequence seq1
  2  /

Sequence created.

SQL> select time_waited/100
  2  from v$system_event
  3  where event = 'enq: SQ - contention'
  4  /

no rows selected

SQL>

Then I created the following UNIX shell script to run test.sql 20 times simultaneously:

Oracle 11.2: cat test.ksh
#!/bin/ksh
export ORAENV_ASK=NO
export ORACLE_SID=ORCL
. oraenv
sqlplus / @test  0 &
sqlplus / @test  1 &
sqlplus / @test  2 &
sqlplus / @test  3 &
sqlplus / @test  4 &
sqlplus / @test  5 &
sqlplus / @test  6 &
sqlplus / @test  7 &
sqlplus / @test  8 &
sqlplus / @test  9 &
sqlplus / @test 10 &
sqlplus / @test 11 &
sqlplus / @test 12 &
sqlplus / @test 13 &
sqlplus / @test 14 &
sqlplus / @test 15 &
sqlplus / @test 16 &
sqlplus / @test 17 &
sqlplus / @test 18 &
sqlplus / @test 19 &
Oracle 11.2:

This is test.sql. It accepts a parameter and uses it to generate a SPOOL file name. Then it selects 10,000 values from the sequence created earlier:

Oracle 11.2: cat test.sql
spool test&&1
set echo on
declare
num1 number;
begin
 for a in 1..10000 loop
  select seq1.nextval into num1 from dual;
 end loop;
end;
/
exit
spool off
Oracle 11.2:

I ran test.ksh and waited until all the SPOOL files had been created.

(I first created this post in 2014. Then I checked it for relevance in 2017. At this point it was not obvious to me what the start_test1.sql, start_test2.sql, end_test1.sql and end_test2.sql files were for. I'm guessing they were used to create and drop the sequences before and after each test):

Oracle 11.2: ls -ltr
total 36
-rwxr--r--   1 oracle   dba          487 Apr 11 13:48 test.ksh
-rw-r--r--   1 oracle   dba          147 Apr 11 13:55 end_test1.sql
-rw-r--r--   1 oracle   dba          147 Apr 11 13:56 end_test2.sql
-rw-r--r--   1 oracle   dba          150 Apr 11 13:56 start_test1.sql
-rw-r--r--   1 oracle   dba          161 Apr 11 13:56 start_test2.sql
-rwxr--r--   1 oracle   dba          154 Apr 11 13:57 test.sql
-rw-r--r--   1 oracle   dba          184 Apr 11 14:43 start_test1.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test16.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test1.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test4.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test6.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test12.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test9.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test13.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test19.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test3.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test2.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test15.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test17.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test11.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test0.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test10.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test14.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test5.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test8.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test7.lst
-rw-r--r--   1 oracle   dba          206 Apr 11 16:12 test18.lst
Oracle 11.2:

Then I looked in one of them to see that it had worked OK:

Oracle 11.2: cat test18.lst
SQL> declare
  2   num1 number;
  3  begin
  4   for a in 1..10000 loop
  5    select seq1.nextval into num1 from dual;
  6   end loop;
  7  end;
  8  /

PL/SQL procedure successfully completed.

SQL> exit
Oracle 11.2:

I rechecked the amount of time spent on the wait event. This is the time Oracle spends waiting for the next value to come back from the sequence. It had gone from zero to 436.8 seconds as 20 sessions had been requesting values at the same time:

SQL> select time_waited/100
  2  from v$system_event
  3  where event = 'enq: SQ - contention'
  4  /

TIME_WAITED/100
---------------
          436.8

SQL> drop sequence seq1
  2  /

Sequence dropped.

SQL>

I recreated the sequence but this time I told Oracle to cache 10,000 values in memory:

SQL> create sequence seq1 cache 10000
  2  /

Sequence created.

SQL> select time_waited/100
  2  from v$system_event
  3  where event = 'enq: SQ - contention'
  4  /

TIME_WAITED/100
---------------
          436.8

SQL>

I reran test.ksh then rechecked the time spent on the wait event. This time it had increased by less than 20 seconds:

SQL> select time_waited/100
  2  from v$system_event
  3  where event = 'enq: SQ - contention'
  4  /

TIME_WAITED/100
---------------
         455.15

SQL> drop sequence seq1
  2  /

Sequence dropped.

SQL>

I recreated the sequence but this time I told Oracle to cache 200,000 values in memory:

SQL> create sequence seq1 cache 200000
  2  /

Sequence created.

SQL> select time_waited/100
  2  from v$system_event
  3  where event = 'enq: SQ - contention'
  4  /

TIME_WAITED/100
---------------
         455.15

SQL>

I reran test.ksh then rechecked the time spent on the wait event. This time it had not increased at all:

SQL> select time_waited/100
  2  from v$system_event
  3  where event = 'enq: SQ - contention'
  4  /

TIME_WAITED/100
---------------
         455.15

SQL> drop sequence seq1
  2  /

Sequence dropped.

SQL>

So, when you create a sequence, if you set the cache value appropriately, you can reduce the time spent on this wait event or maybe even eliminate it altogether.

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>

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>