Posts in category 10gR1

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

Analysing Row Lock Contention with LogMiner

Mar12
2012 9 Comments Written by Christian Antognini

Recently I had to analyse a row lock contention problem that can be illustrated by the following test case:

A session (let’s call it #1) creates a table and inserts a row into it (note that “n” is the primary key of the table):

SQL> CREATE TABLE t (n NUMBER PRIMARY KEY);

SQL> VARIABLE n NUMBER

SQL> execute :n := 1

SQL> INSERT INTO t VALUES (:n);

Another session (let’s call it #2) inserts the same data into the same table:

SQL> VARIABLE n NUMBER

SQL> execute :n := 1

SQL> INSERT INTO t VALUES (:n);

Since session #1 did not commit and that session #2 inserted a row with the same primary key, session #2 is blocked waiting for session #1 to either commit or rollback:

SQL> SELECT sid, blocking_session, event, sql_text
  2  FROM v$session LEFT OUTER JOIN v$sqlarea USING (sql_id)
  3  WHERE nvl(blocking_session,sid) IN (SELECT holding_session FROM dba_blockers);

       SID BLOCKING_SESSION EVENT                          SQL_TEXT
---------- ---------------- ------------------------------ ------------------------------
       130                  SQL*Net message from client
       197              130 enq: TX - row lock contention  INSERT INTO t VALUES (:n)

It goes without saying that in such a case the problem is the application that tried to insert two rows with the same primary key. In the real case the primary key was a natural key, not a surrogate key generated through a sequence. To help the developers troubleshoot the problem it was therefore necessary to know the actual value of the bind variable used for the two inserts. Unfortunately this information is stored in the PGA of the server processes and, therefore, it is not directly accessible. In addition I started investigating the problem only a couple of hours after the contention began and, therefore, also a view like V$SQL_BIND_CAPTURE is of no use.

As a result I decided to mine the archived redo logs to find the information I was looking for. Here is what I did:

Find out the XID of the transaction holding the row lock:

SQL> SELECT t.xidusn, t.xidslot, t.xidsqn, t.start_time, t.start_scn
  2  FROM v$transaction t JOIN v$session s ON t.addr = s.taddr
  3  WHERE s.sid = 130;

    XIDUSN    XIDSLOT     XIDSQN START_TIME            START_SCN
---------- ---------- ---------- -------------------- ----------
         7         12       1049 03/09/12 07:10:25       1462388

Find out which archived redo log contains the first redo records of that transaction:

SQL> SELECT name
  2  FROM v$archived_log
  3  WHERE 1462388 BETWEEN first_change# AND next_change# - 1;

NAME
-----------------------------------------------------------------------------------------------
/u00/app/oracle/fast_recovery_area/DBA112/archivelog/2012_03_09/o1_mf_1_94_7om7qzdx_.arc

Start LogMiner:

SQL> EXECUTE dbms_logmnr.add_logfile(logfilename=>'/u00/app/oracle/fast_recovery_area/DBA112/archivelog/2012_03_09/o1_mf_1_94_7om7qzdx_.arc')

SQL> EXECUTE dbms_logmnr.start_logmnr(options=>dbms_logmnr.dict_from_online_catalog)

Extract the redo information of the operations performed by the transaction holding the row lock and, therefore, finding that the value of the bind variable was “1”:

SQL> SELECT sql_redo
  2  FROM v$logmnr_contents
  3  WHERE xidusn = 7
  4  AND xidslt = 12
  5  AND xidsqn = 1049;

SQL_REDO
--------------------------------------------------------------------------------
set transaction read write;
insert into "CHRIS"."T"("N") values ('1');

Stop LogMiner

SQL> EXECUTE dbms_logmnr.end_logmnr

In conclusion, even though mining (archived) redo logs for extracting the value of bind variables is probably not the most typical use of LogMiner, it works well. Therefore, do not forget this possibility if you have to do it.

Posted in 10gR2, 11gR1, 11gR2, LogMiner

SQL Trace and Oracle Portal

Nov29
2011 2 Comments Written by Christian Antognini

Recently I was involved in a project where I had to trace the database calls of an application based on Oracle Portal 10.1.4. The basic requirements were the following:

Tracing takes place in the production environment
Tracing has to be enable for a single user only
Instrumentation code cannot be added to the application

Given that Oracle Portal uses a pool of connections and that for each HTTP call it can use several database sessions, statically enable SQL trace for specific sessions was not an option.

Knowing nothing about Oracle Portal I started RTFM and, gladly, I discovered that there is a simple way to inject a piece of code before and after a requested procedure is called. This is done by setting, via the administration GUI, the parameters PlsqlBeforeProcedure and PlsqlAfterProcedure.

Since Oracle Portal provides a function (WWCTX_API.GET_USER) to get the current user, I decided to create the following procedures to set/clear the client identifier before/after every call. Note that I added the call to SUBSTR and the exception handler to make sure that the procedures do not raise exceptions (hey, it’s a production system and I do not want to impact everyone!).

CREATE PROCEDURE tvd_set_client_identifier AS
BEGIN
  dbms_session.set_identifier(substr(portal.wwctx_api.get_user,1,64));
EXCEPTION
  WHEN others THEN NULL;
END;

CREATE PROCEDURE tvd_clear_client_identifier AS
BEGIN
  dbms_session.clear_identifier;
EXCEPTION
  WHEN others THEN NULL;
END;

To “enable” these procedures we did the following:

Set PlsqlBeforeProcedure=portal.tvd_set_client_identifier
Set PlsqlAfterProcedure=portal.tvd_clear_client_identifier
Restarted the application server

With this configuration in place enabling SQL trace for a single user was easily done by calling the DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE procedure by specifying the user to be traced as value for the CLIENT_ID parameter.

Posted in 10gR2, 11gR1, 11gR2, SQL Trace