Striving for Optimal Performance
  • Home
  • Blog
    • Archive
    • Categories
  • Troubleshooting Oracle Performance
    • Description
    • Structure
    • Table of Contents
    • Forewords
    • Reviews
    • Downloadable Files
    • Addenda and Errata
  • Publications
  • Public Appearances
    • Past Public Appearances
  • Contact
  • Search
  • About

Posts in category 10gR2

ITL Deadlocks (script)

May01
2013
1 Comment Written by Christian Antognini

A reader of this blog, VijayS, asked me to share the script I use to demo ITL deadlocks that I mentioned in this comment. Since other readers might be interested, here is the script.

SET TERMOUT ON FEEDBACK ON VERIFY OFF SCAN ON ECHO ON

@connect

SELECT * FROM v$version WHERE rownum = 1;

REM
REM cleanup
REM

DROP TABLE t PURGE;

PAUSE

REM
REM create a test table with three completely full data blocks
REM (default tablespace is expected to have 8KB blocks)
REM

CREATE TABLE t (n NUMBER, c VARCHAR2(4000)) PCTFREE 0;

INSERT INTO t SELECT rownum, rpad('*',2679,'*') FROM dual CONNECT BY level <= 9;
COMMIT;

SELECT dbms_rowid.rowid_block_number(rowid), n
FROM t
ORDER BY n;

PAUSE

REM
REM in this session modify two rows: one in the first block and one in the
REM third block
REM

SET SQLPROMPT " 1 > "

SELECT sid FROM v$session WHERE audsid = userenv('sessionid');

UPDATE t SET n=n*10 WHERE n IN (1,7);

PAUSE

REM
REM in another session (called session #2) modify two rows: one in the first
REM block and one in the second block
REM
REM @connect
REM SET SQLPROMPT " 2 > "
REM
REM SELECT sid FROM v$session WHERE audsid = userenv('sessionid');
REM UPDATE t SET n=n*10 WHERE n IN (2,5);
REM

PAUSE

REM
REM in another session (called session #3) try to modify one row per block;
REM since all ITL slots of the first block are taken, wait...
REM
REM @connect
REM SET SQLPROMPT " 3 > "
REM
REM SELECT sid FROM v$session WHERE audsid = userenv('sessionid');
REM UPDATE t SET n=n*10 WHERE n = 9;
REM UPDATE t SET n=n*10 WHERE n = 6;
REM UPDATE t SET n=n*10 WHERE n = 3;
REM

PAUSE

REM
REM in this session try to modify one row in the second block and, in addition,
REM in session #2, try to modify one row in the third block; since all ITL slots
REM of the second and third block are taken, wait..., deadlock...
REM

REM run "UPDATE t SET n=n*10 WHERE n = 8;" in session #2

UPDATE t SET n=n*10 WHERE n = 4;

Notice that:

  • the remarks contained in the script provide important information for understanding what the script does and, as a result, for being able to produce a ITL deadlock
  • to run the script three sessions are required (when running the script I copy/paste the commands from the output of the terminal running the script to the other two terminals)

To give you an example of what it looks like when you run it, here is a recording:

You do not have the latest version of Flash installed. Please visit this link to download it: http://www.adobe.com/products/flashplayer/

The deadlock graph generated by the run that I recorded is the following one. Notice that the rows waited on are set to “no row”.

                       ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name          process session holds waits  process session holds waits
TX-00090013-00001b44        25     140     X             23     147           S
TX-0007001d-000019a9        23     147     X             25     140           S

session 140: DID 0001-0019-00000D23     session 147: DID 0001-0017-000004BC
session 147: DID 0001-0017-000004BC     session 140: DID 0001-0019-00000D23

Rows waited on:
  Session 140: no row
  Session 147: no row
Posted in 11gR1, 11gR2

Display System Activity without Enterprise Manager

Jun06
2012
11 Comments Written by Christian Antognini

I regularly use the system-level activity chart available in Enterprise Manager. In my opinion it is a simple and effective way to know how much a specific database is loaded at a specific time. This is for example an interesting way for observing how a specific load is processed (see this post for an example).
Unfortunately it also happens that this possibility is not available. The main reasons I faced in the past are the following:

  • Standard Edition is used
  • Enterprise Edition is used but Diagnostic Pack is not licensed
  • Enterprise Manager is not available
  • GUI is not available

The aim of this post is to present you a utility that I wrote to cope with these restrictions. It goes without saying that its main purpose is to display information similar to the one provided by the system-level activity chart when working in Standard Edition (or Enterprise without Diagnostic Pack) in a terminal. And that, with both 10g and 11g.

Several dynamic performance views externalize information that can be used for displaying the activity of a system. The two I chose are v$sys_time_model and v$system_wait_class. The challenge of using these views is that they provide only cumulative statistics that are incremented on a regular basis. It is therefore necessary to use a utility that samples the information they provide. In other words, to find out how much a specific statistic changes over a short period of time.

The utility is based on three scripts:

  • system_activity_setup.sql: install the objects required by the system_activity.sql script
  • system_activity.sql: show the database activity at system level
  • system_activity_teardown.sql: remove the objects required by the system_activity.sql script

To install the utility execute, as SYS, the system_activity_setup.sql script. It creates several object types, a function (the core of the utility) and a public synonym. In addition it grants the privilege to execute the function to public.

To use the utility you can directly call the system_activity function or, to have a decent output, execute the system_activity.sql script in SQL*Plus. As the following example shows the script requires two parameters:

  • The first parameter, interval, specifies in seconds how much time to wait to compute the deltas. Since the database engine does not update the statistics in real-time, specifying less than 10-15 seconds is usually pointless.
  • The second parameter, count, specifies the number of samples.
SQL> @system_activity 15 50

                                       DBS112.ANTOGNINI.CH / 2011-02-28

Time     AvgActSess Other% Queue%   Net%   Adm%  Conf%  Comm%  Appl%  Conc% Clust% SysIO% UsrIO% Sched%   CPU%
-------- ---------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ ------
06:30:19        1.1    0.0    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    1.6   89.9    0.0    7.7
06:30:34        1.5    0.0    0.0    0.0    0.0    0.0    0.9    0.0    0.3    0.0    2.2   87.5    0.0    9.2
06:30:49        1.2    0.0    0.0    0.1    0.0    0.0    0.7    0.0    0.0    0.0    1.4   91.3    0.0    6.5
06:31:04        1.2    0.7    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    1.7   89.6    0.0    7.3
06:31:19        1.1    0.0    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    1.6   86.1    0.0   11.5
06:31:34        1.4    0.0    0.0    0.0    0.0    0.0    0.6    0.0    0.2    0.0    1.3   91.8    0.0    6.0
06:31:49        1.0    0.0    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    1.7   89.6    0.0    7.9
06:32:04        1.1    0.0    0.0    0.0    0.0    0.0    0.7    0.0    0.0    0.0    1.6   90.2    0.0    7.5
06:32:19        1.1    0.0    0.0    0.1    0.0    0.0    0.8    0.0    0.0    0.0    1.7   89.1    0.0    8.4
06:32:34        1.1    0.1    0.0    0.0    0.0    0.0    0.7    0.0    0.2    0.0    1.7   89.9    0.0    7.4
06:32:49        1.0    0.0    0.0    0.0    0.0    0.0    0.6    0.0    0.0    0.0    1.7   90.3    0.0    7.3
06:33:04        1.1    0.0    0.0    0.0    0.0    0.0    0.7    0.0    0.0    0.0    1.7   90.5    0.0    7.0
06:33:19        1.1    0.0    0.0    0.0    0.0    0.0    1.2    0.0    0.0    0.0    1.9   89.4    0.0    7.4
06:33:34        1.1    0.0    0.0    0.1    0.0    0.1    0.7    0.0    0.2    0.0    1.8   88.8    0.0    8.4
06:33:49        1.3   17.3    0.0    0.0    0.0    0.0    0.6    0.0    0.0    0.0    1.5   74.7    0.0    5.9
06:34:04        1.4   22.6    0.0    0.0    0.0    0.0    0.6    0.0    0.0    0.0    1.2   69.3    0.0    6.3
06:34:19        1.1    0.0    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    1.7   89.6    0.0    8.0
06:34:34        1.0    0.0    0.0    0.0    0.0    0.0    0.7    0.0    0.2    0.0    2.2   89.3    0.0    7.7
06:34:49        1.1    0.1    0.0    0.0    0.0    0.0    0.6    0.0    0.0    0.0    1.4   91.0    0.0    6.9
06:35:04        1.2   -0.1    0.0    0.1    0.0    0.0    0.8    0.0    0.4    0.0    1.7   85.5    0.0   11.6
06:35:19        6.0    0.0    0.0    0.0    0.0    0.0    1.0    0.0    0.0    0.0    1.7   88.8    0.0    8.5
06:35:34        7.4    0.0    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    1.9   91.2    0.0    6.0
06:35:49        7.1    0.0    0.0    0.0    0.0    0.5    1.2    0.0    0.0    0.0    1.9   90.7    0.0    5.7
06:36:04        7.2    0.9    0.0    0.0    0.0    0.0    0.9    0.0    0.0    0.0    1.7   90.7    0.0    5.8
06:36:19        7.2    0.0    0.0    0.0    0.0    0.0    1.0    0.0    0.0    0.0    1.8   90.9    0.0    6.3
06:36:34        6.8    0.0    0.0    0.0    0.0    0.0    1.0    0.0    0.0    0.0    1.7   91.3    0.0    6.0
06:36:49        7.1    0.0    0.0    0.0    0.0    0.5    1.1    0.0    0.0    0.0    1.9   90.9    0.0    5.6
06:37:04        6.9    0.0    0.0    0.0    0.0    0.0    1.0    0.0    0.0    0.0    1.8   91.3    0.0    5.9
06:37:19        6.9    0.0    0.0    0.0    0.0    0.0    0.9    0.0    0.0    0.0    1.7   91.7    0.0    5.7
06:37:34        7.1    0.0    0.0    0.0    0.0    0.0    0.9    0.0    0.0    0.0    1.8   91.6    0.0    5.8
06:37:49        6.9    0.0    0.0    0.0    0.0    0.0    1.1    0.0    0.0    0.0    1.8   91.3    0.0    5.8
06:38:04        7.0    0.0    0.0    0.0    0.0    1.1    1.0    0.0    0.2    0.0    1.9   90.2    0.0    5.7
06:38:19        6.8    0.0    0.0    0.0    0.0    0.0    0.9    0.0    0.0    0.0    1.6   91.6    0.0    5.9
06:38:34        7.2    0.3    0.0    0.0    0.0    0.0    0.9    0.0    0.0    0.0    1.7   91.0    0.0    6.0
06:38:49        6.7    0.0    0.0    0.0    0.0    0.0    1.1    0.0    0.0    0.0    1.7   91.4    0.0    5.8
06:39:04        7.4    0.0    0.0    0.0    0.0    0.4    1.2    0.0    0.0    0.0    2.0   90.9    0.0    5.5
06:39:19        2.0   -0.3    0.0    0.0    0.0    0.0    1.6    0.0    0.1    0.0    2.0   86.5    0.0   10.1
06:39:34        1.1    0.0    0.0    0.1    0.0    0.0    0.7    0.0    0.2    0.0    1.7   89.2    0.0    8.1
06:39:49        1.1    0.0    0.0    0.0    0.0    0.0    0.9    0.0    0.0    0.0    1.8   89.6    0.0    7.6
06:40:04        1.1    0.0    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    2.1   89.6    0.0    7.6
06:40:19        1.5   14.4    0.0    0.0    0.0    0.0    0.7    0.0    1.1    0.0    1.3   74.3    0.0    8.3
06:40:34        1.6   -0.2    0.0    0.0    0.0    0.0    0.6    0.0    0.3    0.0    1.4   87.7    0.0   10.2
06:40:49        1.3    0.0    0.0    0.1    0.0    0.0    0.6    0.0    0.0    0.0    1.6   91.2    0.0    6.5
06:41:04        1.2    0.9    0.0    0.0    0.0    0.0    0.7    0.0    0.0    0.0    1.7   89.5    0.0    7.3
06:41:19        1.2    0.0    0.0    0.0    0.0    0.0    0.7    0.0    0.0    0.0    1.8   87.3    0.0   10.3
06:41:34        1.3    0.0    0.0    0.0    0.0    0.0    0.5    0.0    0.1    0.0    1.4   91.5    0.0    6.3
06:41:49        1.1    0.1    0.0    0.0    0.0    0.0    0.8    0.0    0.0    0.0    1.6   90.3    0.0    7.2
06:42:04        1.1    0.0    0.0    0.1    0.0    0.0    0.8    0.0    0.0    0.0    2.0   89.9    0.0    7.2
06:42:19        1.1    0.0    0.0    0.0    0.0    0.0    0.7    0.0    0.0    0.0    1.5   90.8    0.0    7.1
06:42:34        1.1    0.0    0.0    0.0    0.0    0.0    0.8    0.0    0.2    0.0    2.0   89.4    0.0    7.6

The output provides:

  • the timestamp of the end of the sampling period,
  • the number of average active sessions, and
  • the percentage of time spent for each wait class and CPU.

For comparison purposes, here is the activity chart for the very same period of time. Even though the data is not exactly the same (the activity chart is based on ASH, a completely different source of information), it is good enough to know how much a database is loaded and which wait class is the major contributor.

System Activity Chart

Any feedback or suggestion to improve the scripts is highly welcome.

Posted in 10gR1, 11gR1, 11gR2

COMMIT_WAIT and COMMIT_LOGGING

Apr05
2012
13 Comments Written by Christian Antognini

Recently I used the COMMIT_WAIT and COMMIT_LOGGING parameters for solving (or, better, working around) a problem I faced while optimizing a specific task for one of my customers. Since it was the first time I used them in a production system, I thought to write this post not only to shortly explain the purpose of the these two parameters, but also to show a case where it is sensible to use them.

The purpose of the two parameters is the following:

COMMIT_WAIT

  • Simply put this parameter specifies whether a server process that issues a commit waits for the log writer while it writes the redo data in the redo log files.
  • If it’s set to WAIT, the default value, the server process waits. And, in most situations, this is the best thing to do.
  • If it’s set to NOWAIT, it doesn’t wait. This means that, in case of a crash just after a commit, the D of ACID might be violated! Hence, in general, it is not advised to use this value.
  • If it’s set to FORCE_WAIT the behaviour is similar to WAIT. The only difference is that settings at a lower level are ignored. In other words, if it is set at the system level it overrides the setting at the session and transaction level. If it’s set at session level it overrides the setting at the transaction level.

COMMIT_LOGGING

  • Simply put this parameter specifies whether the log writer writes redo data in batches.
  • If it’s set to IMMEDIATE, the default value, it basically performs a write operation for each commit.
  • If it’s set to BATCH, it writes redo data in batches. Since with this value less but larger write operations might be performed, in case of small transactions the log writer should be able to write the redo data in a more efficient way.

Note that in 10.2, the version that introduced these features, there is a single parameter (COMMIT_WRITE) to control them. For example, it is possible to set it to “NOWAIT, BATCH”.

To illustrates how these two parameters work I wrote two scripts: commit.sh and commit.sql. Their purpose is to show the number of times specific system calls are executed by the log writer and a server process that executes the following PL/SQL block:

DECLARE
  l_dummy INTEGER;
BEGIN
  FOR i IN 1..1000
  LOOP
    INSERT INTO t VALUES (i, rpad('*',100,'*'));
    COMMIT;
    SELECT count(*) INTO l_dummy FROM dual;
  END LOOP;
END;

The two system calls I was interested in were the following:

  • semtimedop(2): simply put this one is used by the server process to wait for the log writer
  • io_submit(2): simply put this one is used by the log writer to write redo data in the redo log files

Let’s have a look the output generated by the scripts for three particular cases:

  • COMMIT_WAIT = WAIT and COMMIT_LOGGING = IMMEDIATE: Notice that the server process executes 1005 times semtimedop(2) and that the log writer executes 1016 times io_submit(2). In other words, for both of them the number of executions is approximately the number of commits performed by the PL/SQL block.
   oracle@helicon:~/commit/ [DBM11203] ./commit.sh chris ian wait immediate 2> /dev/null

   ***** Server Process *****

   % time     seconds  usecs/call     calls    errors syscall
   ------ ----------- ----------- --------- --------- ----------------
   100.00    0.069561          69      1005         1 semtimedop
   ------ ----------- ----------- --------- --------- ----------------
   100.00    0.069561                  1005         1 total

   ***** Log Writer *****

   % time     seconds  usecs/call     calls    errors syscall
   ------ ----------- ----------- --------- --------- ----------------
   100.00    0.013919          14      1016           io_submit
   ------ ----------- ----------- --------- --------- ----------------
   100.00    0.013919                  1016           total
  • COMMIT_WAIT = NOWAIT and COMMIT_LOGGING = IMMEDIATE: Notice that, for the server process, the executions of semtimedop(2) dropped to 5. No noticeable difference is observable for the log writer.
oracle@helicon:~/commit/ [DBM11203] ./commit.sh chris ian nowait immediate 2> /dev/null

  ***** Server Process *****

  % time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.002195         439         5         1 semtimedop
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.002195                     5         1 total

  ***** Log Writer *****

  % time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.010073          10      1015           io_submit
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.010073                  1015           total
  • COMMIT_WAIT = NOWAIT and COMMIT_LOGGING = BATCH: Notice that this time not only the number of executions to io_submit(2) dropped to 15, but, in total, much less time was spent for writing the redo data (10*1015 >> 36*15).
   oracle@helicon:~/commit/ [DBM11203] ./commit.sh chris ian nowait batch 2> /dev/null

  ***** Server Process *****

  % time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.002132         533         4         1 semtimedop
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.002132                     4         1 total

  ***** Log Writer *****

  % time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.000533          36        15           io_submit
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.000533                    15           total

Now that I explained what the purpose of these parameters is, let me describe a case where I successfully used them.

Few weeks ago one of my customers migrated its DMS to a new version. During the migration data had to be moved from one database to another. Unfortunately the migration code was written to process data slow by slow. Hence, to speed up the processing, parallelization was added to the picture.

The following chart (you can click on it to increase its size) shows the load generated by 20 parallel processes with default values for COMMIT_WAIT and COMMIT_LOGGING. With the default configutation the system was able to process about 1000 “objects” per second. As you can see there were a lot of waits related to the commit wait class.

Database load (20 parallel processes; COMMIT_WAIT WAIT; COMMIT_LOGGING = IMMEDIATE)

Since this was a controlled processing using COMMIT_WAIT was not considered a problem. So, we tested the very same load with COMMIT_WAIT set to NOWAIT and COMMIT_LOGGING set to BATCH. The throughput increased to about 1200 “object” per second. In other words, not dramatically. But, more importantly, as the following chart shows almost all waits in the commit wait class disappeared. This was very important because without that serialization taking place we were able to increase the number of parallel processes.

Database load (20 parallel processes; COMMIT_WAIT NOWAIT; COMMIT_LOGGING = BATCH)

The following chart shows the load generated by 50 parallel processes. Again, almost no wait related to commits. With 50 processes the system was able to process about 2300 “objects” per second.

Database load (50 parallel processes; COMMIT_WAIT NOWAIT; COMMIT_LOGGING = BATCH)

In summary, COMMIT_WAIT and COMMIT_LOGGING are not commonly used parameters but, in some specific situations, using them it might be beneficial to avoid wait events related to commits.

Posted in 11gR1, 11gR2
← Older Entries

EvoLve theme by Theme4Press  •  Powered by WordPress Striving for Optimal Performance