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 11gR1

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 10gR2, 11gR2

Event 10046 – Full List of Levels

Aug10
2012
Leave a Comment Written by Christian Antognini

Extended SQL trace (a.k.a. debugging event 10046 at a level higher than 1) is one of the key features provided by Oracle to troubleshoot applications using Oracle Database. For many years the available levels were always the same (4, 8 and 12). In fact, since I wrote my first paper about it in May 2000 and the release of 11g nothing changed.

With 11g, as I described in this post, new levels (16 and 32) were introduced.

More recently, with the introduction of the fix for bug 8328200, a new one was added to the list (64).

So, I thought it was time to publish the current list of available levels…

Level Description
0 The debugging event is disabled.
1 The debugging event is enabled. For each processed database call, the following information is given: SQL statement, response time, service time, number of processed rows, number of logical reads, number of physical reads and writes, execution plan, and little additional information.
Up to 10.2 an execution plan is written to the trace file only when the cursor it is associated with is closed. The execution statistics associated to it are values aggregated over all executions.
As of 11.1 an execution plan is written to the trace file only after the first execution of every cursor. The execution statistics associated to it are the ones of the first execution only.
4 As in level 1, with additional information about bind variables. Mainly, the data type, its precision, and the value used for each execution.
8 As in level 1, plus detailed information about wait time. For each wait experienced during the processing, the following information is given: the name of the wait event, the duration, and a few additional parameters identifying the resource that has been waited for.
16 As in level 1, plus the execution plans information is written to the trace file for each execution. Available as of 11.1 only.
32 As in level 1, but without the execution plans information. Available as of 11.1 only.
64 As in level 1, plus the execution plans information might be written for executions following the first one. The condition is that, since the last write of execution plans information, a particular cursor consumed at least one additional minute of DB time. This level is interesting in two cases. First, when the information about the first execution is not enough for analysing a specific issue. Second, when the overhead of writing the information about every execution (level 16) is too high. Generally available as of 11.2.0.2 only.

In addition to the levels described in the previous table, you can also combine the levels 4 and 8 with every other level greater than 1. For example:

  • Level 12 (4 + 8): simultaneously enable level 4 and level 8.
  • Level 28 (4 + 8 + 16): simultaneously enable level 4, level 8 and level 16.
  • Level 68 (4 + 64): simultaneously enable level 4 and level 64.

If you are using dbms_monitor or dbms_session for enabling extended SQL trace, here is the mapping between the levels and the parameters:

  • Level 4: waits=FALSE, binds=TRUE, plan_stat=’first_execution’
  • Level 8: waits=TRUE, binds=FALSE, plan_stat=’first_execution’
  • Level 16: waits=FALSE, binds=FALSE, plan_stat=’all_executions’
  • Level 32: waits=FALSE, binds=FALSE, plan_stat=’never’
  • Level 64: not available yet

As you can see from the previous list, it is not possible to enable level 64 through dbms_monitor and dbms_session. Hence, statements like the following ones or ORADEBUG have to be used:

alter session set events '10046 trace name context forever, level 64'

alter session set events 'sql_trace wait=false, bind=false, plan_stat=adaptive'

I really hope that this limitation will be removed very soon.

UPDATE 2012-08-13: An Oracle employee informed me that about the limitation of dbms_monitor and dbms_session bug #14483308 has been opened. Thank you Ted!
UPDATE 2012-08-16: Bug #14483308 was rejected :-( . As a result enhancement request #14499199 was created.

Posted in 11gR2, Bug, SQL Trace

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, 10gR2, 11gR2
← Older Entries

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