Solving Waits on "enq: TM - contention"
by Dean R. on Jul 14 2008 at 4:55 AM in Wait Time Analysis
Recently, I was assisting one of our customers of Ignite for Oracle trying to diagnose sessions waiting on the "enq: TM - contention" event. The blocked sessions were executing simple INSERT statements similar to:
INSERT INTO supplier VALUES (:1, :2, :3);
Waits on "enq: TM - contention" indicate there are unindexed foreign key constraints. Reviewing the SUPPLIER table, we found a foreign key constraint referencing the PRODUCT table that did not have an associated index. This was also confirmed by the Top Objects feature of Ignite for Oracle because all the time was associated with the PRODUCT table. We added the index on the column referencing the PRODUCT table and the problem was solved.
Cause
After using Ignite for Oracle's locking feature to find the blocking sessions, we found the real culprit. Periodically, as the company reviewed its vendor list, they "cleaned up" the SUPPLIER table several times a week. As a result, rows from the SUPPLIER table were deleted. Those delete statements were then cascading to the PRODUCT table and taking out TM locks on it.
Reproducing the Problem
This problem has a simple fix, but I wanted to understand more about why this happens. So I reproduced the issue to see what happens under the covers. I first created a subset of the tables from this customer and loaded them with sample data.
CREATE TABLE supplier
( supplier_id number(10) not null,
supplier_name varchar2(50) not null,
contact_name varchar2(50),
CONSTRAINT supplier_pk PRIMARY KEY (supplier_id)
);
INSERT INTO supplier VALUES (1, 'Supplier 1', 'Contact 1');
INSERT INTO supplier VALUES (2, 'Supplier 2', 'Contact 2');
COMMIT;
CREATE TABLE product
( product_id number(10) not null,
product_name varchar2(50) not null,
supplier_id number(10) not null,
CONSTRAINT fk_supplier
FOREIGN KEY (supplier_id)
REFERENCES supplier(supplier_id)
ON DELETE CASCADE
);
INSERT INTO product VALUES (1, 'Product 1', 1);
INSERT INTO product VALUES (2, 'Product 2', 1);
INSERT INTO product VALUES (3, 'Product 3', 2);
COMMIT;
I then executed statements similar to what we found at this customer:
User 1: DELETE supplier WHERE supplier_id = 1;
User 2: DELETE supplier WHERE supplier_id = 2;
User 3: INSERT INTO supplier VALUES (5, 'Supplier 5', 'Contact 5');
Similar to the customer's experience, User 1 and User 2 hung waiting on "enq: TM - contention". Reviewing information from V$SESSION I found the following:
SELECT l.sid, s.blocking_session blocker, s.event, l.type, l.lmode, l.request, o.object_name, o.object_type
FROM v$lock l, dba_objects o, v$session s
WHERE UPPER(s.username) = UPPER('&User')
AND l.id1 = o.object_id (+)
AND l.sid = s.sid
ORDER BY sid, type;
Following along with the solution we used for our customer, we added an index for the foreign key constraint on the SUPPLIER table back to the PRODUCT table:
CREATE INDEX fk_supplier ON product (supplier_id);
When we ran the test case again everything worked fine. There were no exclusive locks acquired and hence no hanging. Oracle takes out exclusive locks on the child table, the PRODUCT table in our example, when a foreign key constraint is not indexed.
Query to Find Unindexed Foreign Key Constraints
Now that we know unindexed foreign key constraints can cause severe problems, here is a script that I use to find them for a specific user (this can easily be tailored to search all schemas):
SELECT * FROM (
SELECT c.table_name, cc.column_name, cc.position column_position
FROM user_constraints c, user_cons_columns cc
WHERE c.constraint_name = cc.constraint_name
AND c.constraint_type = 'R'
MINUS
SELECT i.table_name, ic.column_name, ic.column_position
FROM user_indexes i, user_ind_columns ic
WHERE i.index_name = ic.index_name
)
ORDER BY table_name, column_position;
Tuesday, December 30, 2008
What is enq: TX - row lock contention
What is enq: TX - row lock contention
Enqueues are locks that coordinate access to database resources. enq: wait event indicates that the session is waiting for a lock that is held by another session. The name of the enqueue is as part of the form enq: enqueue_type - related_details.
The V$EVENT_NAME view provides a complete list of all the enq: wait events.
TX enqueue are acquired exclusive when a transaction initiates its first change and held until the transaction does a COMMIT or ROLLBACK.
Several Situation of TX enqueue:
--------------------------------------
1) Waits for TX in mode 6 occurs when a session is waiting for a row level lock that is already held by another session. This occurs when one user is updating or deleting a row, which another session wishes to update or delete. This type of TX enqueue wait corresponds to the wait event enq: TX - row lock contention.
The solution is to have the first session already holding the lock perform a COMMIT or ROLLBACK.
2) Waits for TX in mode 4 can occur if a session is waiting due to potential duplicates in UNIQUE index. If two sessions try to insert the same key value the second session has to wait to see if an ORA-0001 should be raised or not. This type of TX enqueue wait corresponds to the wait event enq: TX - row lock contention.
The solution is to have the first session already holding the lock perform a COMMIT or ROLLBACK.
3)Waits for TX in mode 4 is also possible if the session is waiting due to shared bitmap index fragment. Bitmap indexes index key values and a range of ROWIDs. Each ‘entry’ in a bitmap index can cover many rows in the actual table. If two sessions want to update rows covered by the same bitmap index fragment, then the second session waits for the first transaction to either COMMIT or ROLLBACK by waiting for the TX lock in mode 4. This type of TX enqueue wait corresponds to the wait event enq: TX - row lock contention.
Troubleshooting:
for which SQL currently is waiting to,
select sid, sql_text
from v$session s, v$sql q
where sid in (select sid
from v$session where state in ('WAITING')
and wait_class != 'Idle' and event='enq: TX - row lock contention'
and (
q.sql_id = s.sql_id or
q.sql_id = s.prev_sql_id));
The blocking session is,
SQL> select blocking_session, sid, serial#, wait_class, seconds_in_wait from v$session
where blocking_session is not NULL order by blocking_session;
Enqueues are locks that coordinate access to database resources. enq: wait event indicates that the session is waiting for a lock that is held by another session. The name of the enqueue is as part of the form enq: enqueue_type - related_details.
The V$EVENT_NAME view provides a complete list of all the enq: wait events.
TX enqueue are acquired exclusive when a transaction initiates its first change and held until the transaction does a COMMIT or ROLLBACK.
Several Situation of TX enqueue:
--------------------------------------
1) Waits for TX in mode 6 occurs when a session is waiting for a row level lock that is already held by another session. This occurs when one user is updating or deleting a row, which another session wishes to update or delete. This type of TX enqueue wait corresponds to the wait event enq: TX - row lock contention.
The solution is to have the first session already holding the lock perform a COMMIT or ROLLBACK.
2) Waits for TX in mode 4 can occur if a session is waiting due to potential duplicates in UNIQUE index. If two sessions try to insert the same key value the second session has to wait to see if an ORA-0001 should be raised or not. This type of TX enqueue wait corresponds to the wait event enq: TX - row lock contention.
The solution is to have the first session already holding the lock perform a COMMIT or ROLLBACK.
3)Waits for TX in mode 4 is also possible if the session is waiting due to shared bitmap index fragment. Bitmap indexes index key values and a range of ROWIDs. Each ‘entry’ in a bitmap index can cover many rows in the actual table. If two sessions want to update rows covered by the same bitmap index fragment, then the second session waits for the first transaction to either COMMIT or ROLLBACK by waiting for the TX lock in mode 4. This type of TX enqueue wait corresponds to the wait event enq: TX - row lock contention.
Troubleshooting:
for which SQL currently is waiting to,
select sid, sql_text
from v$session s, v$sql q
where sid in (select sid
from v$session where state in ('WAITING')
and wait_class != 'Idle' and event='enq: TX - row lock contention'
and (
q.sql_id = s.sql_id or
q.sql_id = s.prev_sql_id));
The blocking session is,
SQL> select blocking_session, sid, serial#, wait_class, seconds_in_wait from v$session
where blocking_session is not NULL order by blocking_session;
Perform Without Waiting
Perform Without Waiting
By Arup Nanda
OTN
Diagnose performance problems, using the wait interface in Oracle 10g.
John, the DBA at Acme Bank, is on the phone with an irate user, Bill, who complains that his database session is hanging, a complaint not unfamiliar to most DBAs. What can John do to address Bill's complaint?
Acme Bank's database is Oracle Database 10g, so John has many options. Automatic Database Diagnostic Manager (ADDM), new in Oracle Database 10g, can tell John about the current overall status and performance of the database, so John starts with ADDM to determine whether what Bill's session is experiencing is the result of a databasewide issue. The ADDM report identifies no databasewide issues that could have this impact on Bill's session, so John moves on to the next option.
One way to diagnose session-level events such as Bill's is to determine whether the session is waiting for anything, such as the reading of a block of a file, a lock on a table row, or a latch. Oracle has provided mechanisms to display the waits happening inside the database since Oracle7, and during the last several years, the model has been steadily perfected, with more and more diagnostic information added to it. In Oracle Database 10g, which makes significantly improved wait event information available, diagnosing a session slowdown has become even easier. This article shows you how to use the wait events in Oracle Database 10g to identify bottlenecks.
Session Waits
How can John the DBA determine what's causing Bill's session to hang? Actually, the session is not hanging; it's waiting for an event to happen, and that's exactly what John checks for.
To continue his investigation, John could use Oracle Enterprise Manager or he could directly access V$ views from the command line. John has a set of scripts he uses to diagnose these types of problems, so he uses the command line.
John queries the V$SESSION view to see what Bill's session is waiting for. (Note that John filters out all idle events.)
select sid, username, event, blocking_session,
seconds_in_wait, wait_time
from v$session where state in ('WAITING')
and wait_class != 'Idle';
The output follows, in vertical format.
SID : 270
USERNAME : BILL
EVENT : enq: TX - row lock contention
BLOCKING_SESSION : 254
SECONDS_IN_WAIT : 83
WAIT_TIME : 0
Looking at this information, John immediately concludes that Bill's session with SID 270 is waiting for a lock on a table and that that lock is held by session 254 (BLOCKING_SESSION).
But John wants to know which SQL statement is causing this lock. He can find out easily, by issuing the following query joining the V$SESSION and V$SQL views:
select sid, sql_text
from v$session s, v$sql q
where sid in (254,270)
and (q.sql_id = s.sql_id or
q.sql_id = s.prev_sql_id);
Listing 1 shows the result of the query. And there (in Listing 1) John sees it—both sessions are trying to update the same row. Unless session 254 commits or rolls back, session 270 will continue to wait for the lock. He explains this to Bill, who, considerably less irate now, decides that something in the application has gone awry and asks John to kill session 254 and release the locks.
Code Listing 1: V$SESSION and V$SQL query finds lock
SID SQL_TEXT
--- ---------------------------------------------------------------------
270 update accounts set balance = balance - 750 where account_no = 333
254 update accounts set balance = balance - 1000 where account_no = 333
Wait Classes
After John kills the blocking session, Bill's session continues but is very slow. John decides to check for other problems in the session. Again, he checks for any other wait events, but this time he specifically checks Bill's session.
In Oracle Database 10g, wait events are divided into various wait classes, based on their type. The grouping of events lets you focus on specific classes and exclude nonessential ones such as idle events. John issues the following against the V$SESSION_WAIT_CLASS view:
select wait_class_id, wait_class,
total_waits, time_waited
from v$session_wait_class
where sid = 270;
The output, shown in Listing 2, shows the wait classes and how many times the session has waited for events in each class. It tells John that application-related waits such as those due to row locks have occurred 17,760 times, for a total of 281,654 centiseconds (cs)—hundredths of a second—since the instance started. John thinks that this TIME_WAITED value is high for this session. He decides to explore the cause of these waits in the application wait class. The times for individual waits are available in the V$SYSTEM_EVENT view. He issues the following query to identify individual waits in the application wait class (class id 4217450380):
Code Listing 2: Waits summarized by wait classes
WAIT_CLASS_ID WAIT_CLASS TOTAL_WAITS TIME_WAITED
------------- --------------- ----------- -----------
1893977003 Other 16331 44107
4217450380 Application 17760 281654
3290255840 Configuration 834 2794
3875070507 Concurrency 1599 96981
3386400367 Commit 13865 4616
2723168908 Idle 513024 103732677
2000153315 Network 254534 379
1740759767 User I/O 32709 53182
4108307767 System I/O 103019 9921
select event, total_waits, time_waited
from v$system_event e, v$event_name n
where n.event_id = e.event_id
and wait_class_id = 4217450380;
Listing 3 shows the output of this query. It shows that lock contentions (indicated by the event enq: TX - row lock contention) constitute the major part of the waiting time in the application wait class. This concerns John. Is it possible that a badly written application made its way through to the production database, causing these lock contention problems?
Code Listing 3: Waits in a specific wait class—"application"
EVENT TOTAL_WAITS TIME_WAITED
------------------------------ ----------- -----------
enq: RO - fast object reuse 5 24
enq: TX - row lock contention 2275 280856
SQL*Net break/reset to client 15696 822
Being the experienced DBA that he is, however, John does not immediately draw that conclusion. The data in Listing 3 merely indicates that the users have experienced lock-contention-related waits a total of 2,275 times, for 280,856 cs. It is possible that mostly 1- or 2-cs waits and only one large wait account for the total wait time, and in that case, the application isn't faulty. A single large wait may be some freak occurrence skewing the data and not representative of the workload on the system. How can John determine whether a single wait is skewing the data?
Oracle 10g provides a new view, V$EVENT_HISTOGRAM, that shows the wait time periods and how often sessions have waited for a specific time period. He issues the following against V$EVENT_HISTOGRAM:
select wait_time_milli bucket, wait_count
from v$event_histogram
where event =
'enq: TX - row lock contention';
The output looks like this:
BUCKET WAIT_COUNT
----------- ----------
1 252
2 0
4 0
8 0
16 1
32 0
64 4
128 52
256 706
512 392
1024 18
2048 7
4096 843
The V$EVENT_HISTOGRAM view shows the buckets of wait times and how many times the sessions waited for a particular event—in this case, a row lock contention—for that duration. For example, sessions waited 252 times for less than 1 millisecond (ms), once less than 16 ms but more than 1 ms, and so on. The sum of the values of the WAIT_COUNT column is 2,275, the same as the value shown in the event enq: TX - row lock contention, shown in Listing 3. The V$EVENT_HISTOGRAM view shows that the most waits occurred in the ranges of 256 ms, 512 ms, and 4,096 ms, which is sufficient evidence that the applications are experiencing locking issues and that this locking is the cause of the slowness in Bill's session. Had the view showed numerous waits in the 1-ms range, John wouldn't have been as concerned, because the waits would have seemed normal.
Time Models
Just after John explains his preliminary findings to Bill, Lora walks in with a similar complaint: Her session SID 355 is very slow. Once again, John looks for the events the session is waiting for, by issuing the following query against the V$SESSION view:
select event, seconds_in_wait,
wait_time
from v$session
where sid = 355;
The output, shown in Listing 4, shows a variety of wait events in Lora's session, including latch contention, which may be indicative of an application design problem. But before he sends Lora off with a prescription for an application change, John must support his theory that bad application design is the cause of the poor performance in Lora's session. To test this theory, he decides to determine whether the resource utilization of Lora's session is extraordinarily high and whether it slows not only itself but other sessions too.
Code Listing 4: Waits experienced by a specific session
EVENT SECONDS_IN_WAIT WAIT_TIME
------------------------------- --------------- ---------
latch: cache buffers lru chain 172 0
latch: checkpoint queue latch 2 0
latch: cache buffers chains 607 0
buffer busy waits 500 0
db file sequential read 30247 0
db file scattered read 887 0
In the Time Model interface of Oracle Database 10g, John can easily view details of time spent by a session in various activities. He issues the following against the V$SESS_TIME_MODEL view:
select stat_name, value
from v$sess_time_model
where sid = 355;
The output, shown in Listing 5, displays the time (in microseconds) spent by the session in various places. From this output, John sees that the session spent 503,996,336 microseconds parsing (parse time elapsed), out of a total of 878,088,366 microseconds on all SQL execution (sql execute elapsed time), or 57 percent of the SQL execution time, which indicates that a cause of this slowness is high parsing. John gives Lora this information, and she follows up with the application design team.
Code Listing 5: Session time model
STAT_NAME VALUE
--------------------------------------------------- ----------
DB time 878239757
DB CPU 835688063
background elapsed time 0
background cpu time 0
sequence load elapsed time 0
parse time elapsed 503996336
hard parse elapsed time 360750582
sql execute elapsed time 878088366
connection management call elapsed time 7207
failed parse elapsed time 134516
failed parse (out of shared memory) elapsed time 0
hard parse (sharing criteria) elapsed time 0
hard parse (bind mismatch) elapsed time 0
PL/SQL execution elapsed time 6294618
inbound PL/SQL rpc elapsed time 0
PL/SQL compilation elapsed time 126221
Java execution elapsed time 0
OS Statistics
While going over users' performance problems, John also wants to rule out the possibility of the host system's being a bottleneck. Before Oracle 10g, he could use operating system (OS) utilities such as sar and vmstat and extrapolate the metrics to determine contention. In Oracle 10g, the metrics at the OS level are collected automatically in the database. To see potential host contention, John issues the following query against the V$OSSTAT view:
select * from v$osstat;
The output in Listing 6 shows the various elements of the OS-level metrics collected. All time elements are in cs. From the results in Listing 6, John sees that the single CPU of the system has been idle for 51,025,805 cs (IDLE_TICKS) and busy for 2,389,857 cs (BUSY_TICKS), indicating a CPU that is about 4 percent busy. From this he concludes that the CPU is not a bottleneck on this host. Note that if the host system had more than one CPU, the columns whose headings had the prefix AVG_, such as AVG_IDLE_TICKS, would show the average of these metrics over all the CPUs.
Code Listing 6: Output from V$OSSTAT view
STAT_NAME VALUE OSSTAT_ID
-------------------------- ----------- ----------
NUM_CPUS 1 0
IDLE_TICKS 51025805 1
BUSY_TICKS 2389857 2
USER_TICKS 1947618 3
SYS_TICKS 439736 4
NICE_TICKS 2503 6
AVG_IDLE_TICKS 51025805 7
AVG_BUSY_TICKS 2389857 8
AVG_USER_TICKS 1947618 9
AVG_SYS_TICKS 439736 10
AVG_NICE_TICKS 2503 12
RSRC_MGR_CPU_WAIT_TIME 0 14
IN_BYTES 16053940224 1000
OUT_BYTES 96638402560 1001
AVG_IN_BYTES 16053940224 1004
AVG_OUT_BYTES 96638402560 1005
Active Session History
So far the users have consulted John exactly when each problem occurred, enabling him to peek into the performance views in real time. This good fortune doesn't last long—Janice comes to John complaining about a recent performance problem. When John queries the V$SESSION view, the session is idle, with no events being waited for. How can John check which events Janice's session was waiting for when the problem occurred?
Oracle 10g collects the information on active sessions in a memory buffer every second. This buffer, called Active Session History (ASH), which can be viewed in the V$ACTIVE_SESSION_HISTORY dynamic performance view, holds data for about 30 minutes before being overwritten with new data in a circular fashion. John gets the SID and SERIAL# of Janice's session and issues this query against the V$ACTIVE_SESSION_HISTORY view to find out the wait events for which this session waited in the past.
select sample_time, event, wait_time
from v$active_session_history
where session_id = 271
and session_serial# = 5;
The output, excerpted in Listing 7, shows several important pieces of information. First it shows SAMPLE_TIME—the time stamp showing when the statistics were collected—which lets John tie the occurrence of the performance problems to the wait events. Using the data in the V$ACTIVE_SESSION_HISTORY view, John sees that at around 3:17 p.m., the session waited several times for the log buffer space event, indicating that there was some problem with redo log buffers. To further aid the diagnosis, John identifies the exact SQL statement executed by the session at that time, using the following query of the V$SQL view:
Code Listing 7: Output of active session history
SAMPLE_TIME EVENT WAIT_TIME
-------------------------- --------------------------- ---------
22-FEB-04 03.17.23.028 PM latch: library cache 14384
22-FEB-04 03.17.24.048 PM latch: library cache 14384
22-FEB-04 03.17.25.068 PM log file switch completion 17498
22-FEB-04 03.17.26.088 PM log file switch completion 17498
22-FEB-04 03.17.27.108 PM log buffer space 11834
22-FEB-04 03.17.28.128 PM log buffer space 11834
22-FEB-04 03.17.29.148 PM log buffer space 11834
22-FEB-04 03.17.30.168 PM log buffer space 11834
22-FEB-04 03.17.31.188 PM log buffer space 11834
select sql_text, application_wait_time
from v$sql
where sql_id in (
select sql_id
from v$active_session_history
where sample_time =
'22-FEB-04 03.17.31.188 PM'
and session_id = 271
and session_serial# = 5
);
The output is shown in Listing 8.
Code Listing 8: Text of the SQL from active session history
SQL_TEXT APPLICATION_WAIT_TIME
------------------------------------------------------- ---------------------
update accounts set balance = balance -750where950 account_no= 333
update accounts set balance = balance - 845 where 457 account_no = 451
update accounts set balance = balance - 434 where 1235 account_no = 239
The column APPLICATION_WAIT_TIME shows how long the sessions executing that SQL waited for the application wait class. In addition to the SQL_ID, the V$ACTIVE_SESSION_HISTORY view also lets John see specific rows being waited for (in case of lock contentions), client identifiers, and much more.
What if a user comes to John a little late, after the data is overwritten in this view? When purged from this dynamic performance view, the data is flushed to the Active Workload Repository (AWR), a disk-based repository. The purged ASH data can be seen in the DBA_HIST_ACTIVE_SESSION_HIST view, enabling John to see the wait events of a past session. The data in the AWR is purged by default after seven days.
Conclusion
Oracle Database 10g introduces a number of enhancements designed to automate and simplify the performance diagnostic process. Wait event information is more elaborate in Oracle Database 10g and provides deeper insight into the cause of problems, making the diagnosis of performance problems a breeze in most cases, especially in proactive performance tuning.
By Arup Nanda
OTN
Diagnose performance problems, using the wait interface in Oracle 10g.
John, the DBA at Acme Bank, is on the phone with an irate user, Bill, who complains that his database session is hanging, a complaint not unfamiliar to most DBAs. What can John do to address Bill's complaint?
Acme Bank's database is Oracle Database 10g, so John has many options. Automatic Database Diagnostic Manager (ADDM), new in Oracle Database 10g, can tell John about the current overall status and performance of the database, so John starts with ADDM to determine whether what Bill's session is experiencing is the result of a databasewide issue. The ADDM report identifies no databasewide issues that could have this impact on Bill's session, so John moves on to the next option.
One way to diagnose session-level events such as Bill's is to determine whether the session is waiting for anything, such as the reading of a block of a file, a lock on a table row, or a latch. Oracle has provided mechanisms to display the waits happening inside the database since Oracle7, and during the last several years, the model has been steadily perfected, with more and more diagnostic information added to it. In Oracle Database 10g, which makes significantly improved wait event information available, diagnosing a session slowdown has become even easier. This article shows you how to use the wait events in Oracle Database 10g to identify bottlenecks.
Session Waits
How can John the DBA determine what's causing Bill's session to hang? Actually, the session is not hanging; it's waiting for an event to happen, and that's exactly what John checks for.
To continue his investigation, John could use Oracle Enterprise Manager or he could directly access V$ views from the command line. John has a set of scripts he uses to diagnose these types of problems, so he uses the command line.
John queries the V$SESSION view to see what Bill's session is waiting for. (Note that John filters out all idle events.)
select sid, username, event, blocking_session,
seconds_in_wait, wait_time
from v$session where state in ('WAITING')
and wait_class != 'Idle';
The output follows, in vertical format.
SID : 270
USERNAME : BILL
EVENT : enq: TX - row lock contention
BLOCKING_SESSION : 254
SECONDS_IN_WAIT : 83
WAIT_TIME : 0
Looking at this information, John immediately concludes that Bill's session with SID 270 is waiting for a lock on a table and that that lock is held by session 254 (BLOCKING_SESSION).
But John wants to know which SQL statement is causing this lock. He can find out easily, by issuing the following query joining the V$SESSION and V$SQL views:
select sid, sql_text
from v$session s, v$sql q
where sid in (254,270)
and (q.sql_id = s.sql_id or
q.sql_id = s.prev_sql_id);
Listing 1 shows the result of the query. And there (in Listing 1) John sees it—both sessions are trying to update the same row. Unless session 254 commits or rolls back, session 270 will continue to wait for the lock. He explains this to Bill, who, considerably less irate now, decides that something in the application has gone awry and asks John to kill session 254 and release the locks.
Code Listing 1: V$SESSION and V$SQL query finds lock
SID SQL_TEXT
--- ---------------------------------------------------------------------
270 update accounts set balance = balance - 750 where account_no = 333
254 update accounts set balance = balance - 1000 where account_no = 333
Wait Classes
After John kills the blocking session, Bill's session continues but is very slow. John decides to check for other problems in the session. Again, he checks for any other wait events, but this time he specifically checks Bill's session.
In Oracle Database 10g, wait events are divided into various wait classes, based on their type. The grouping of events lets you focus on specific classes and exclude nonessential ones such as idle events. John issues the following against the V$SESSION_WAIT_CLASS view:
select wait_class_id, wait_class,
total_waits, time_waited
from v$session_wait_class
where sid = 270;
The output, shown in Listing 2, shows the wait classes and how many times the session has waited for events in each class. It tells John that application-related waits such as those due to row locks have occurred 17,760 times, for a total of 281,654 centiseconds (cs)—hundredths of a second—since the instance started. John thinks that this TIME_WAITED value is high for this session. He decides to explore the cause of these waits in the application wait class. The times for individual waits are available in the V$SYSTEM_EVENT view. He issues the following query to identify individual waits in the application wait class (class id 4217450380):
Code Listing 2: Waits summarized by wait classes
WAIT_CLASS_ID WAIT_CLASS TOTAL_WAITS TIME_WAITED
------------- --------------- ----------- -----------
1893977003 Other 16331 44107
4217450380 Application 17760 281654
3290255840 Configuration 834 2794
3875070507 Concurrency 1599 96981
3386400367 Commit 13865 4616
2723168908 Idle 513024 103732677
2000153315 Network 254534 379
1740759767 User I/O 32709 53182
4108307767 System I/O 103019 9921
select event, total_waits, time_waited
from v$system_event e, v$event_name n
where n.event_id = e.event_id
and wait_class_id = 4217450380;
Listing 3 shows the output of this query. It shows that lock contentions (indicated by the event enq: TX - row lock contention) constitute the major part of the waiting time in the application wait class. This concerns John. Is it possible that a badly written application made its way through to the production database, causing these lock contention problems?
Code Listing 3: Waits in a specific wait class—"application"
EVENT TOTAL_WAITS TIME_WAITED
------------------------------ ----------- -----------
enq: RO - fast object reuse 5 24
enq: TX - row lock contention 2275 280856
SQL*Net break/reset to client 15696 822
Being the experienced DBA that he is, however, John does not immediately draw that conclusion. The data in Listing 3 merely indicates that the users have experienced lock-contention-related waits a total of 2,275 times, for 280,856 cs. It is possible that mostly 1- or 2-cs waits and only one large wait account for the total wait time, and in that case, the application isn't faulty. A single large wait may be some freak occurrence skewing the data and not representative of the workload on the system. How can John determine whether a single wait is skewing the data?
Oracle 10g provides a new view, V$EVENT_HISTOGRAM, that shows the wait time periods and how often sessions have waited for a specific time period. He issues the following against V$EVENT_HISTOGRAM:
select wait_time_milli bucket, wait_count
from v$event_histogram
where event =
'enq: TX - row lock contention';
The output looks like this:
BUCKET WAIT_COUNT
----------- ----------
1 252
2 0
4 0
8 0
16 1
32 0
64 4
128 52
256 706
512 392
1024 18
2048 7
4096 843
The V$EVENT_HISTOGRAM view shows the buckets of wait times and how many times the sessions waited for a particular event—in this case, a row lock contention—for that duration. For example, sessions waited 252 times for less than 1 millisecond (ms), once less than 16 ms but more than 1 ms, and so on. The sum of the values of the WAIT_COUNT column is 2,275, the same as the value shown in the event enq: TX - row lock contention, shown in Listing 3. The V$EVENT_HISTOGRAM view shows that the most waits occurred in the ranges of 256 ms, 512 ms, and 4,096 ms, which is sufficient evidence that the applications are experiencing locking issues and that this locking is the cause of the slowness in Bill's session. Had the view showed numerous waits in the 1-ms range, John wouldn't have been as concerned, because the waits would have seemed normal.
Time Models
Just after John explains his preliminary findings to Bill, Lora walks in with a similar complaint: Her session SID 355 is very slow. Once again, John looks for the events the session is waiting for, by issuing the following query against the V$SESSION view:
select event, seconds_in_wait,
wait_time
from v$session
where sid = 355;
The output, shown in Listing 4, shows a variety of wait events in Lora's session, including latch contention, which may be indicative of an application design problem. But before he sends Lora off with a prescription for an application change, John must support his theory that bad application design is the cause of the poor performance in Lora's session. To test this theory, he decides to determine whether the resource utilization of Lora's session is extraordinarily high and whether it slows not only itself but other sessions too.
Code Listing 4: Waits experienced by a specific session
EVENT SECONDS_IN_WAIT WAIT_TIME
------------------------------- --------------- ---------
latch: cache buffers lru chain 172 0
latch: checkpoint queue latch 2 0
latch: cache buffers chains 607 0
buffer busy waits 500 0
db file sequential read 30247 0
db file scattered read 887 0
In the Time Model interface of Oracle Database 10g, John can easily view details of time spent by a session in various activities. He issues the following against the V$SESS_TIME_MODEL view:
select stat_name, value
from v$sess_time_model
where sid = 355;
The output, shown in Listing 5, displays the time (in microseconds) spent by the session in various places. From this output, John sees that the session spent 503,996,336 microseconds parsing (parse time elapsed), out of a total of 878,088,366 microseconds on all SQL execution (sql execute elapsed time), or 57 percent of the SQL execution time, which indicates that a cause of this slowness is high parsing. John gives Lora this information, and she follows up with the application design team.
Code Listing 5: Session time model
STAT_NAME VALUE
--------------------------------------------------- ----------
DB time 878239757
DB CPU 835688063
background elapsed time 0
background cpu time 0
sequence load elapsed time 0
parse time elapsed 503996336
hard parse elapsed time 360750582
sql execute elapsed time 878088366
connection management call elapsed time 7207
failed parse elapsed time 134516
failed parse (out of shared memory) elapsed time 0
hard parse (sharing criteria) elapsed time 0
hard parse (bind mismatch) elapsed time 0
PL/SQL execution elapsed time 6294618
inbound PL/SQL rpc elapsed time 0
PL/SQL compilation elapsed time 126221
Java execution elapsed time 0
OS Statistics
While going over users' performance problems, John also wants to rule out the possibility of the host system's being a bottleneck. Before Oracle 10g, he could use operating system (OS) utilities such as sar and vmstat and extrapolate the metrics to determine contention. In Oracle 10g, the metrics at the OS level are collected automatically in the database. To see potential host contention, John issues the following query against the V$OSSTAT view:
select * from v$osstat;
The output in Listing 6 shows the various elements of the OS-level metrics collected. All time elements are in cs. From the results in Listing 6, John sees that the single CPU of the system has been idle for 51,025,805 cs (IDLE_TICKS) and busy for 2,389,857 cs (BUSY_TICKS), indicating a CPU that is about 4 percent busy. From this he concludes that the CPU is not a bottleneck on this host. Note that if the host system had more than one CPU, the columns whose headings had the prefix AVG_, such as AVG_IDLE_TICKS, would show the average of these metrics over all the CPUs.
Code Listing 6: Output from V$OSSTAT view
STAT_NAME VALUE OSSTAT_ID
-------------------------- ----------- ----------
NUM_CPUS 1 0
IDLE_TICKS 51025805 1
BUSY_TICKS 2389857 2
USER_TICKS 1947618 3
SYS_TICKS 439736 4
NICE_TICKS 2503 6
AVG_IDLE_TICKS 51025805 7
AVG_BUSY_TICKS 2389857 8
AVG_USER_TICKS 1947618 9
AVG_SYS_TICKS 439736 10
AVG_NICE_TICKS 2503 12
RSRC_MGR_CPU_WAIT_TIME 0 14
IN_BYTES 16053940224 1000
OUT_BYTES 96638402560 1001
AVG_IN_BYTES 16053940224 1004
AVG_OUT_BYTES 96638402560 1005
Active Session History
So far the users have consulted John exactly when each problem occurred, enabling him to peek into the performance views in real time. This good fortune doesn't last long—Janice comes to John complaining about a recent performance problem. When John queries the V$SESSION view, the session is idle, with no events being waited for. How can John check which events Janice's session was waiting for when the problem occurred?
Oracle 10g collects the information on active sessions in a memory buffer every second. This buffer, called Active Session History (ASH), which can be viewed in the V$ACTIVE_SESSION_HISTORY dynamic performance view, holds data for about 30 minutes before being overwritten with new data in a circular fashion. John gets the SID and SERIAL# of Janice's session and issues this query against the V$ACTIVE_SESSION_HISTORY view to find out the wait events for which this session waited in the past.
select sample_time, event, wait_time
from v$active_session_history
where session_id = 271
and session_serial# = 5;
The output, excerpted in Listing 7, shows several important pieces of information. First it shows SAMPLE_TIME—the time stamp showing when the statistics were collected—which lets John tie the occurrence of the performance problems to the wait events. Using the data in the V$ACTIVE_SESSION_HISTORY view, John sees that at around 3:17 p.m., the session waited several times for the log buffer space event, indicating that there was some problem with redo log buffers. To further aid the diagnosis, John identifies the exact SQL statement executed by the session at that time, using the following query of the V$SQL view:
Code Listing 7: Output of active session history
SAMPLE_TIME EVENT WAIT_TIME
-------------------------- --------------------------- ---------
22-FEB-04 03.17.23.028 PM latch: library cache 14384
22-FEB-04 03.17.24.048 PM latch: library cache 14384
22-FEB-04 03.17.25.068 PM log file switch completion 17498
22-FEB-04 03.17.26.088 PM log file switch completion 17498
22-FEB-04 03.17.27.108 PM log buffer space 11834
22-FEB-04 03.17.28.128 PM log buffer space 11834
22-FEB-04 03.17.29.148 PM log buffer space 11834
22-FEB-04 03.17.30.168 PM log buffer space 11834
22-FEB-04 03.17.31.188 PM log buffer space 11834
select sql_text, application_wait_time
from v$sql
where sql_id in (
select sql_id
from v$active_session_history
where sample_time =
'22-FEB-04 03.17.31.188 PM'
and session_id = 271
and session_serial# = 5
);
The output is shown in Listing 8.
Code Listing 8: Text of the SQL from active session history
SQL_TEXT APPLICATION_WAIT_TIME
------------------------------------------------------- ---------------------
update accounts set balance = balance -750where950 account_no= 333
update accounts set balance = balance - 845 where 457 account_no = 451
update accounts set balance = balance - 434 where 1235 account_no = 239
The column APPLICATION_WAIT_TIME shows how long the sessions executing that SQL waited for the application wait class. In addition to the SQL_ID, the V$ACTIVE_SESSION_HISTORY view also lets John see specific rows being waited for (in case of lock contentions), client identifiers, and much more.
What if a user comes to John a little late, after the data is overwritten in this view? When purged from this dynamic performance view, the data is flushed to the Active Workload Repository (AWR), a disk-based repository. The purged ASH data can be seen in the DBA_HIST_ACTIVE_SESSION_HIST view, enabling John to see the wait events of a past session. The data in the AWR is purged by default after seven days.
Conclusion
Oracle Database 10g introduces a number of enhancements designed to automate and simplify the performance diagnostic process. Wait event information is more elaborate in Oracle Database 10g and provides deeper insight into the cause of problems, making the diagnosis of performance problems a breeze in most cases, especially in proactive performance tuning.
Here is a script that could help a DBA to see which session is blocking another and on which row exactly.
set serverout on size 1000000
set lines 132
declare
cursor cur_lock is
select sid,id1,id2,inst_id, ctime
from gv$lock
where block = 1;
vid1 number;
vid2 number;
cursor cur_locked is
select sid, inst_id, ctime
from gv$lock
where id1 = vid1
and id2 = vid2
and block <> 1;
vlocks varchar2(30);
vsid1 number;
vobj1 number;
vfil1 number;
vblo1 number;
vrow1 number;
vrowid1 varchar2(20);
vcli1 varchar2(64);
vobj2 number;
vfil2 number;
vblo2 number;
vrow2 number;
vrowid2 varchar2(20);
vcli2 varchar2(64);
vobjname varchar2(30);
vlocked varchar2(30);
ctim1 number;
ctim2 number;
begin
dbms_output.put_line('=====================================================');
dbms_output.put_line('Blocking lock list.');
dbms_output.put_line('=====================================================');
dbms_output.put_line('Block / Is blocked SID INST_ID OBJECT TIME(secs) ROWID CLIENT_IDENTIFIER');
dbms_output.put_line('------------------------- --------- ------- ------------------------------ ---------- ------------------ -----------------');
for c1 in cur_lock loop
vid1 := c1.id1;
vid2 := c1.id2;
select username,sid,row_wait_obj#,row_wait_file#,row_wait_block#,row_wait_row#,client_identifier
into vlocks,vsid1,vobj1,vfil1,vblo1,vrow1,vcli1
from gv$session where sid = c1.sid and inst_id = c1.inst_id;
if vobj1 = -1 then
vobjname := 'UNKNOWN';
else
select name into vobjname from sys.obj$ where obj# = vobj1;
select decode(vrow1,0,'MANY ROWS',dbms_rowid.rowid_create(1, vobj1, vfil1, vblo1, vrow1)) into vrowid1 from dual;
end if;
dbms_output.put_line(rpad(vlocks,25) || ' ' ||
to_char(vsid1,'999999999') || ' ' ||
to_char(c1.inst_id,'9999999') || ' ' ||
rpad(vobjname,30) || ' ' ||
to_char(c1.ctime,'999999999') || ' ' || rpad(vrowid1,18) || ' ' || vcli1);
for c2 in cur_locked loop
select username, row_wait_obj#,row_wait_file#,row_wait_block#,row_wait_row#
into vlocked, vobj2, vfil2, vblo2, vrow2
from gv$session where sid = c2.sid and inst_id = c2.inst_id;
if vobj2 = -1 then
vobjname := 'UNKNOWN';
else
select name into vobjname from sys.obj$ where obj# = vobj2;
select decode(vrow2,0,'MANY ROWS',dbms_rowid.rowid_create(1, vobj2, vfil2, vblo2, vrow2)) into vrowid2 from dual;
end if;
dbms_output.put_line(chr(9) || '\--> ' || rpad(vlocked,12) || ' ' ||
to_char(c2.sid,'999999999') || ' ' ||
to_char(c2.inst_id,'9999999') || ' ' || rpad(vobjname,30) || ' ' ||
to_char(c2.ctime,'999999999') || ' ' || rpad(vrowid2,18) || ' ' || vcli2 ) ;
end loop;
end loop;
commit;
end;
/
set lines 132
declare
cursor cur_lock is
select sid,id1,id2,inst_id, ctime
from gv$lock
where block = 1;
vid1 number;
vid2 number;
cursor cur_locked is
select sid, inst_id, ctime
from gv$lock
where id1 = vid1
and id2 = vid2
and block <> 1;
vlocks varchar2(30);
vsid1 number;
vobj1 number;
vfil1 number;
vblo1 number;
vrow1 number;
vrowid1 varchar2(20);
vcli1 varchar2(64);
vobj2 number;
vfil2 number;
vblo2 number;
vrow2 number;
vrowid2 varchar2(20);
vcli2 varchar2(64);
vobjname varchar2(30);
vlocked varchar2(30);
ctim1 number;
ctim2 number;
begin
dbms_output.put_line('=====================================================');
dbms_output.put_line('Blocking lock list.');
dbms_output.put_line('=====================================================');
dbms_output.put_line('Block / Is blocked SID INST_ID OBJECT TIME(secs) ROWID CLIENT_IDENTIFIER');
dbms_output.put_line('------------------------- --------- ------- ------------------------------ ---------- ------------------ -----------------');
for c1 in cur_lock loop
vid1 := c1.id1;
vid2 := c1.id2;
select username,sid,row_wait_obj#,row_wait_file#,row_wait_block#,row_wait_row#,client_identifier
into vlocks,vsid1,vobj1,vfil1,vblo1,vrow1,vcli1
from gv$session where sid = c1.sid and inst_id = c1.inst_id;
if vobj1 = -1 then
vobjname := 'UNKNOWN';
else
select name into vobjname from sys.obj$ where obj# = vobj1;
select decode(vrow1,0,'MANY ROWS',dbms_rowid.rowid_create(1, vobj1, vfil1, vblo1, vrow1)) into vrowid1 from dual;
end if;
dbms_output.put_line(rpad(vlocks,25) || ' ' ||
to_char(vsid1,'999999999') || ' ' ||
to_char(c1.inst_id,'9999999') || ' ' ||
rpad(vobjname,30) || ' ' ||
to_char(c1.ctime,'999999999') || ' ' || rpad(vrowid1,18) || ' ' || vcli1);
for c2 in cur_locked loop
select username, row_wait_obj#,row_wait_file#,row_wait_block#,row_wait_row#
into vlocked, vobj2, vfil2, vblo2, vrow2
from gv$session where sid = c2.sid and inst_id = c2.inst_id;
if vobj2 = -1 then
vobjname := 'UNKNOWN';
else
select name into vobjname from sys.obj$ where obj# = vobj2;
select decode(vrow2,0,'MANY ROWS',dbms_rowid.rowid_create(1, vobj2, vfil2, vblo2, vrow2)) into vrowid2 from dual;
end if;
dbms_output.put_line(chr(9) || '\--> ' || rpad(vlocked,12) || ' ' ||
to_char(c2.sid,'999999999') || ' ' ||
to_char(c2.inst_id,'9999999') || ' ' || rpad(vobjname,30) || ' ' ||
to_char(c2.ctime,'999999999') || ' ' || rpad(vrowid2,18) || ' ' || vcli2 ) ;
end loop;
end loop;
commit;
end;
/
Monday, December 29, 2008
Oracle 10g Hints for Performance Improvement
List of Oracle 10g Hints for the Oracle Optimizer so that you can dictate the execution plan of a query/statement..
Undocumented Hints
* bypass_recursive_check
* bypass_ujvc
* cache_cb
* cache_temp_table
* civ_gb
* collections_get_refs
* cube_gb
* cursor_sharing_exact
* deref_no_rewrite
* dml_update
* domain_index_no_sort
* domain_index_sort
* dynamic_sampling
* dynamic_sampling_est_cdn
* expand_gset_to_union
* force_sample_block
* gby_conc_rollup
* global_table_hints
* hwm_brokered
* ignore_on_clause
* ignore_where_clause
* index_rrs
* index_ss
* index_ss_asc
* index_ss_desc
* like_expand
* local_indexes
* mv_merge
* nested_table_get_refs
* nested_table_set_refs
* nested_table_set_setid
* no_expand_gset_to_union
* no_fact
* no_filtering
* no_order_rollups
* no_prune_gsets
* no_stats_gsets
* no_unnest
* nocpu_costing overflow_nomove
* piv_gb
* piv_ssf
* pq_map
* pq_nomap
* remote_mapped
* restore_as_intervals
* save_as_intervals
* scn_ascending
* skip_ext_optimizer
* sqlldr
* sys_dl_cursor
* sys_parallel_txn
* sys_rid_order
* tiv_gb
* tiv_ssf
* unnest
* use_ttt_for_gsets
Documented Hints
* all_rows
* first_rows
* first_rows_1
* first_rows_100
* choose
* rule
* full
* rowid
* cluster
* hash
* hash_aj
* index
* no_index
* index_asc
* index_combine
* index_join
* index_desc
* index_ffs
* no_index_ffs
* index_ss
* index_ss_asc
* index_ss_desc
* no_index_ss
* no_query_transformation
* use_concat
* no_expand
* rewrite
* norewrite
* no_rewrite
* merge
* no_merge
* fact
* no_fact
* star_transformation
* no_star_transformation
* unnest
* no_unnest
* leading
* ordered
* use_nl
* no_use_nl
* use_nl_with_index
* use_merge
* no_use_merge
* use_hash
* no_use_hash
* parallel
* noparallel / no_parallel
* pq_distribute
* no_parallel_index
* append
* noappend
* cache
* nocache
* push_pred
* no_push_pred
* push_subq
* no_push_subq
* qb_name
* cursor_sharing_exact
* driving_site
* dynamic_sampling
* spread_min_analysis
* merge_aj
* and_equal
* star
* bitmap
* hash_sj
* nl_sj
* nl_aj
* ordered_predicates
* expand_gset_to_union
Undocumented Hints
* bypass_recursive_check
* bypass_ujvc
* cache_cb
* cache_temp_table
* civ_gb
* collections_get_refs
* cube_gb
* cursor_sharing_exact
* deref_no_rewrite
* dml_update
* domain_index_no_sort
* domain_index_sort
* dynamic_sampling
* dynamic_sampling_est_cdn
* expand_gset_to_union
* force_sample_block
* gby_conc_rollup
* global_table_hints
* hwm_brokered
* ignore_on_clause
* ignore_where_clause
* index_rrs
* index_ss
* index_ss_asc
* index_ss_desc
* like_expand
* local_indexes
* mv_merge
* nested_table_get_refs
* nested_table_set_refs
* nested_table_set_setid
* no_expand_gset_to_union
* no_fact
* no_filtering
* no_order_rollups
* no_prune_gsets
* no_stats_gsets
* no_unnest
* nocpu_costing overflow_nomove
* piv_gb
* piv_ssf
* pq_map
* pq_nomap
* remote_mapped
* restore_as_intervals
* save_as_intervals
* scn_ascending
* skip_ext_optimizer
* sqlldr
* sys_dl_cursor
* sys_parallel_txn
* sys_rid_order
* tiv_gb
* tiv_ssf
* unnest
* use_ttt_for_gsets
Documented Hints
* all_rows
* first_rows
* first_rows_1
* first_rows_100
* choose
* rule
* full
* rowid
* cluster
* hash
* hash_aj
* index
* no_index
* index_asc
* index_combine
* index_join
* index_desc
* index_ffs
* no_index_ffs
* index_ss
* index_ss_asc
* index_ss_desc
* no_index_ss
* no_query_transformation
* use_concat
* no_expand
* rewrite
* norewrite
* no_rewrite
* merge
* no_merge
* fact
* no_fact
* star_transformation
* no_star_transformation
* unnest
* no_unnest
* leading
* ordered
* use_nl
* no_use_nl
* use_nl_with_index
* use_merge
* no_use_merge
* use_hash
* no_use_hash
* parallel
* noparallel / no_parallel
* pq_distribute
* no_parallel_index
* append
* noappend
* cache
* nocache
* push_pred
* no_push_pred
* push_subq
* no_push_subq
* qb_name
* cursor_sharing_exact
* driving_site
* dynamic_sampling
* spread_min_analysis
* merge_aj
* and_equal
* star
* bitmap
* hash_sj
* nl_sj
* nl_aj
* ordered_predicates
* expand_gset_to_union
Using LogMiner Viewer to Perform a Logical Recovery
Module Objectives
Purpose
In this module, you will learn how to use LogMiner to analyze your redo log files so that you can logically recover your database.
Objectives
After completing this module, you should be able to:
Use LogMiner to analyze the redo log files
Perform a logical recovery of the database
Prerequisites
Before starting this module, you should have:
Preinstallation Tasks
Install the Oracle9i Database
Postinstallation Tasks
Review the Sample Schema
Enabling Archiving
Downloaded the logminer.zip module files and unzipped them into your working directory
Reference Material
The following is a list of useful reference material if you want additional information about the topics in this module:
Documentation: A96521-01: Oracle9i Database Administrator's Guide
Overview
In this module, you will examine the following topics:
Analysis of Redo Logs
Oracle9i LogMiner
Analysis of Redo Logs
Knowing what changes have been made to data is useful for many things:
Trace and audit requirements
Application debugging
Logical recovery
Tuning and capacity planning
The redo logs provide a single source of data, including:
All of the data needed to perform recovery (a record of every change to the data and the metadata or data structures)
All of the data needed to pinpoint when a logical corruption to the database began. It is important to pinpoint this time so that you know how to perform a time-based or change-based recovery that restores the database to the state just prior to corruption.
An alternative, supplemental source of data for tuning and capacity planning
Many customers keep this data in archived files, but using redo logs as a source of this information means that the data is always available. No resources need to be used for data collection or overhead (although the data still needs to be translated into usable form).
You can analyze redo logs for historical trends, data access patterns, and frequency of changes to the database, as well as to track specific sets of changes based on transaction, user ID, table, block, and so on.
Oracle9i LogMiner Viewer
Oracle9i LogMiner is a powerful tool that reads the redo logs to provide direct access to the changes that have been made to your databases. With LogMiner, you can audit past database activity, pinpoint when logical corruption occurred and where to perform statement-level recovery. LogMiner also gives you a wealth of information for diagnosing problems with an application, analyzing resource utilization and historical performance, and tuning the database.
LogMiner Viewer is a graphical user interface integrated with Enterprise Manager. LogMiner Viewer allows you to easily specify queries to view data from the redo logs, including SQL redo and undo statements.
In Oracle8i, LogMiner was introduced as the only Oracle-supported method of accessing the redo logs. This module highlights the new features introduced with Oracle9i LogMiner Viewer: additional data types and storage types, additional DDL statements, queries based on actual data values in the redo logs, and continuous monitoring of the redo stream.
Using LogMiner: Steps
In this module, you will use LogMiner to analyze redo log files and logically recover the database. After enabling archiving in the production environment, you will perform the following steps:
1.
Perform an operation which corrupts the database.
2.
Use LogMiner Viewer to analyze the redo log files.
3.
Perform a logical recovery.
Step 3, in turn, has several substeps, which will be detailed later.
Performing an Operation Which Corrupts the Database
Go Back to List
Now you will create a situation in the database that could lead to the need to perform a logical recovery. You will change the data schema definition for the OE user in such a way that deleting a single product will leave the tables logically corrupt.
1.
From a SQL*Plus session connected to the production database, execute the following SQL script:
@alter_table.sql
CONNECT OE/OE@orcl.world
ALTER TABLE Order_Items
DROP CONSTRAINT Order_Items_Product_ID_FK;
ALTER TABLE Inventories
DROP CONSTRAINT Inventories_Product_ID_FK;
ALTER TABLE Product_Descriptions
DROP CONSTRAINT PD_Product_ID_FK;
ALTER TABLE Order_Items
ADD CONSTRAINT Order_Items_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information
ON DELETE CASCADE;
ALTER TABLE Inventories
ADD CONSTRAINT Inventories_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information
ON DELETE CASCADE;
Although these are perfectly valid DDL statements, adding the ON DELETE CASCADE clauses to these constraints causes all ORDER_ITEMS and ORDERS records to be automatically deleted whenever a product is deleted.
2. To illustrate this, delete a product from the product_information table. From a SQL*Plus session connected to the production database, execute the following SQL script:
@delete_product.sql
CONNECT OE/OE@orcl.world
DELETE FROM Product_Information
WHERE Product_Id = 3000;
COMMIT;
Although only one row has been deleted from the product_information table, rows have also been deleted from the order_items and orders tables. This may not be discovered until later, when executing a report reveals the logical corruption.
3.
Now run a report that compares the sum of all order items in an order with the total for that order. From a SQL*Plus session connected to the production database, execute the following SQL script:
@comp_totals.sql
CONNECT OE/OE@orcl.world
SELECT so.order_id, SUM(so.order_total), SUM(si.total)
FROM ( SELECT order_id, SUM((unit_price * quantity)) AS total
FROM order_items
GROUP BY order_id
) si,
orders so
WHERE so.order_id = si.order_id
GROUP BY so.order_id
HAVING SUM(so.order_total) != SUM(si.total);
The inconsistency in the data is easy to see; notice that the sale order totals no longer reflect the total of their sale item lines. The data has become logically corrupt.
4.
In the SQL*Plus Session, execute the following script:
@force_switch.sql
connect sys/oracle@orcl.world as sysdba
alter system archive log current;
archive log list;
This switch has been forced to move DML statements from the on-line redo log to archived redo logs. The undo SQL statements to fix this will be mined from the archived redo logs.
You can now use LogMiner Viewer to detect what happened, and even to undo the transactions that caused the corruption.
Using LogMiner Viewer to Analyze the Redo Log Files
Go Back to List
You are interested in finding all the transactions performed on the product_information, order_items, and orders tables which may account for the discrepancy in your report. Therefore, you decide to analyze all the transactions in the list of archived redo log files.
1.
Connect to the OMS as sysman/sysman.
2.
Select Tools > Database Applications > LogMiner Viewer
3.
LogMiner Viewer requires a database account with SYSDBA privilege. You will log on as SYS, the preferred credentials are already defined in the Enterprise Manager environment.
From the Navigator pane, Right Click on orcl.world and Select Create Query.
4.
The three tables involved in the DELETE operation were PRODUCT_INFORMATION, ORDER_ITEMS, and ORDERS. We want to search for DELETE operations performed on objects owned by OE. The search should be
OWNER=OE AND OPERATION=DELETE
First from the drop down menu select OWNER, then type OE in the box after the equal. Then click AND.
5.
Select OPERTATION and enter DELETE.
6.
Click Execute.
The DELETE operations previously performed now appear in the Query Results panel at the bottom of the window. Although one delete operation was issued, the ON DELETE CASCADE OPTION deleted two additional rows. You may review any row by double clicking on the row.
7.
Click Close, after reviewing.
8.
Select the Display Options tab. Uncheck everything but SQL_UNDO. Then click Execute.
9.
Click the Save Redo/Undo... button.
10.
Change Format to Text. Change File Name to D:\wkdir\sqlundo.sql. Then click OK.
11.
To exit click Cancel then File > Exit.
Performing a Logical Recovery
Go Back to List
Performing a logical recovery consists of several substeps:
1 Performing the logical recovery
2 Verifying the logical recovery
1. Performing the Logical Recovery
To undo the changes that were made, use the generated script by performing the following steps:
1.
In SQL*Plus connect as OE/OE and execute the script sqlundo.sql. Then type COMMIT.
connect oe/oe@orcl.world
@sqlundo.sql
commit;
2. Verifying the Logical Recovery
To test that the data has been recovered, perform the following steps:
1.
Run the same report, which compares the sum of all orderitems for an order with the total for the order. From a SQL*Plus session connected to the production database, execute the following script:
@comp_totals.sql
CONNECT OE/OE@orcl.world
SELECT so.order_id, SUM(so.total), SUM(si_total)
FROM (
SELECT si.order_id si_order_id,
SUM(si.total)AS si_total
FROM order_items si
GROUP BY si.order_id), sale_orders so
WHERE so.order_id = si_order_id
GROUP BY so.order_id
HAVING SUM(so.total) != SUM(si_total);
This time there are no sale order totals that do not equal the sum of their order items. You have fully recovered the database from the mistake.
Resetting the Environment
Now you should reset the foreign key constraints for the order_items and orders tables back to their correct versions.
1.
From a SQL*Plus session connected to the production database, enter @reset_constraints.sql to reset the constraints to their original version.
@reset_constraints.sql
CONNECT OE/OE@orcl.world
ALTER TABLE Order_Items
DROP CONSTRAINT Order_Items_Product_ID_FK;
ALTER TABLE Inventories
DROP CONSTRAINT Inventories_Product_ID_FK;
ALTER TABLE Order_Items ADD CONSTRAINT Order_Items_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information;
ALTER TABLE Inventories ADD CONSTRAINT Inventories_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information;
ALTER TABLE Product_Descriptions ADD CONSTRAINT PD_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information;
Module Summary
In this module, you should have learned how to:
Use LogMiner to analyze the redo log files
Perform a logical recovery of the database
Purpose
In this module, you will learn how to use LogMiner to analyze your redo log files so that you can logically recover your database.
Objectives
After completing this module, you should be able to:
Use LogMiner to analyze the redo log files
Perform a logical recovery of the database
Prerequisites
Before starting this module, you should have:
Preinstallation Tasks
Install the Oracle9i Database
Postinstallation Tasks
Review the Sample Schema
Enabling Archiving
Downloaded the logminer.zip module files and unzipped them into your working directory
Reference Material
The following is a list of useful reference material if you want additional information about the topics in this module:
Documentation: A96521-01: Oracle9i Database Administrator's Guide
Overview
In this module, you will examine the following topics:
Analysis of Redo Logs
Oracle9i LogMiner
Analysis of Redo Logs
Knowing what changes have been made to data is useful for many things:
Trace and audit requirements
Application debugging
Logical recovery
Tuning and capacity planning
The redo logs provide a single source of data, including:
All of the data needed to perform recovery (a record of every change to the data and the metadata or data structures)
All of the data needed to pinpoint when a logical corruption to the database began. It is important to pinpoint this time so that you know how to perform a time-based or change-based recovery that restores the database to the state just prior to corruption.
An alternative, supplemental source of data for tuning and capacity planning
Many customers keep this data in archived files, but using redo logs as a source of this information means that the data is always available. No resources need to be used for data collection or overhead (although the data still needs to be translated into usable form).
You can analyze redo logs for historical trends, data access patterns, and frequency of changes to the database, as well as to track specific sets of changes based on transaction, user ID, table, block, and so on.
Oracle9i LogMiner Viewer
Oracle9i LogMiner is a powerful tool that reads the redo logs to provide direct access to the changes that have been made to your databases. With LogMiner, you can audit past database activity, pinpoint when logical corruption occurred and where to perform statement-level recovery. LogMiner also gives you a wealth of information for diagnosing problems with an application, analyzing resource utilization and historical performance, and tuning the database.
LogMiner Viewer is a graphical user interface integrated with Enterprise Manager. LogMiner Viewer allows you to easily specify queries to view data from the redo logs, including SQL redo and undo statements.
In Oracle8i, LogMiner was introduced as the only Oracle-supported method of accessing the redo logs. This module highlights the new features introduced with Oracle9i LogMiner Viewer: additional data types and storage types, additional DDL statements, queries based on actual data values in the redo logs, and continuous monitoring of the redo stream.
Using LogMiner: Steps
In this module, you will use LogMiner to analyze redo log files and logically recover the database. After enabling archiving in the production environment, you will perform the following steps:
1.
Perform an operation which corrupts the database.
2.
Use LogMiner Viewer to analyze the redo log files.
3.
Perform a logical recovery.
Step 3, in turn, has several substeps, which will be detailed later.
Performing an Operation Which Corrupts the Database
Go Back to List
Now you will create a situation in the database that could lead to the need to perform a logical recovery. You will change the data schema definition for the OE user in such a way that deleting a single product will leave the tables logically corrupt.
1.
From a SQL*Plus session connected to the production database, execute the following SQL script:
@alter_table.sql
CONNECT OE/OE@orcl.world
ALTER TABLE Order_Items
DROP CONSTRAINT Order_Items_Product_ID_FK;
ALTER TABLE Inventories
DROP CONSTRAINT Inventories_Product_ID_FK;
ALTER TABLE Product_Descriptions
DROP CONSTRAINT PD_Product_ID_FK;
ALTER TABLE Order_Items
ADD CONSTRAINT Order_Items_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information
ON DELETE CASCADE;
ALTER TABLE Inventories
ADD CONSTRAINT Inventories_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information
ON DELETE CASCADE;
Although these are perfectly valid DDL statements, adding the ON DELETE CASCADE clauses to these constraints causes all ORDER_ITEMS and ORDERS records to be automatically deleted whenever a product is deleted.
2. To illustrate this, delete a product from the product_information table. From a SQL*Plus session connected to the production database, execute the following SQL script:
@delete_product.sql
CONNECT OE/OE@orcl.world
DELETE FROM Product_Information
WHERE Product_Id = 3000;
COMMIT;
Although only one row has been deleted from the product_information table, rows have also been deleted from the order_items and orders tables. This may not be discovered until later, when executing a report reveals the logical corruption.
3.
Now run a report that compares the sum of all order items in an order with the total for that order. From a SQL*Plus session connected to the production database, execute the following SQL script:
@comp_totals.sql
CONNECT OE/OE@orcl.world
SELECT so.order_id, SUM(so.order_total), SUM(si.total)
FROM ( SELECT order_id, SUM((unit_price * quantity)) AS total
FROM order_items
GROUP BY order_id
) si,
orders so
WHERE so.order_id = si.order_id
GROUP BY so.order_id
HAVING SUM(so.order_total) != SUM(si.total);
The inconsistency in the data is easy to see; notice that the sale order totals no longer reflect the total of their sale item lines. The data has become logically corrupt.
4.
In the SQL*Plus Session, execute the following script:
@force_switch.sql
connect sys/oracle@orcl.world as sysdba
alter system archive log current;
archive log list;
This switch has been forced to move DML statements from the on-line redo log to archived redo logs. The undo SQL statements to fix this will be mined from the archived redo logs.
You can now use LogMiner Viewer to detect what happened, and even to undo the transactions that caused the corruption.
Using LogMiner Viewer to Analyze the Redo Log Files
Go Back to List
You are interested in finding all the transactions performed on the product_information, order_items, and orders tables which may account for the discrepancy in your report. Therefore, you decide to analyze all the transactions in the list of archived redo log files.
1.
Connect to the OMS as sysman/sysman.
2.
Select Tools > Database Applications > LogMiner Viewer
3.
LogMiner Viewer requires a database account with SYSDBA privilege. You will log on as SYS, the preferred credentials are already defined in the Enterprise Manager environment.
From the Navigator pane, Right Click on orcl.world and Select Create Query.
4.
The three tables involved in the DELETE operation were PRODUCT_INFORMATION, ORDER_ITEMS, and ORDERS. We want to search for DELETE operations performed on objects owned by OE. The search should be
OWNER=OE AND OPERATION=DELETE
First from the drop down menu select OWNER, then type OE in the box after the equal. Then click AND.
5.
Select OPERTATION and enter DELETE.
6.
Click Execute.
The DELETE operations previously performed now appear in the Query Results panel at the bottom of the window. Although one delete operation was issued, the ON DELETE CASCADE OPTION deleted two additional rows. You may review any row by double clicking on the row.
7.
Click Close, after reviewing.
8.
Select the Display Options tab. Uncheck everything but SQL_UNDO. Then click Execute.
9.
Click the Save Redo/Undo... button.
10.
Change Format to Text. Change File Name to D:\wkdir\sqlundo.sql. Then click OK.
11.
To exit click Cancel then File > Exit.
Performing a Logical Recovery
Go Back to List
Performing a logical recovery consists of several substeps:
1 Performing the logical recovery
2 Verifying the logical recovery
1. Performing the Logical Recovery
To undo the changes that were made, use the generated script by performing the following steps:
1.
In SQL*Plus connect as OE/OE and execute the script sqlundo.sql. Then type COMMIT.
connect oe/oe@orcl.world
@sqlundo.sql
commit;
2. Verifying the Logical Recovery
To test that the data has been recovered, perform the following steps:
1.
Run the same report, which compares the sum of all orderitems for an order with the total for the order. From a SQL*Plus session connected to the production database, execute the following script:
@comp_totals.sql
CONNECT OE/OE@orcl.world
SELECT so.order_id, SUM(so.total), SUM(si_total)
FROM (
SELECT si.order_id si_order_id,
SUM(si.total)AS si_total
FROM order_items si
GROUP BY si.order_id), sale_orders so
WHERE so.order_id = si_order_id
GROUP BY so.order_id
HAVING SUM(so.total) != SUM(si_total);
This time there are no sale order totals that do not equal the sum of their order items. You have fully recovered the database from the mistake.
Resetting the Environment
Now you should reset the foreign key constraints for the order_items and orders tables back to their correct versions.
1.
From a SQL*Plus session connected to the production database, enter @reset_constraints.sql to reset the constraints to their original version.
@reset_constraints.sql
CONNECT OE/OE@orcl.world
ALTER TABLE Order_Items
DROP CONSTRAINT Order_Items_Product_ID_FK;
ALTER TABLE Inventories
DROP CONSTRAINT Inventories_Product_ID_FK;
ALTER TABLE Order_Items ADD CONSTRAINT Order_Items_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information;
ALTER TABLE Inventories ADD CONSTRAINT Inventories_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information;
ALTER TABLE Product_Descriptions ADD CONSTRAINT PD_Product_ID_FK
FOREIGN KEY (Product_Id)
REFERENCES Product_Information;
Module Summary
In this module, you should have learned how to:
Use LogMiner to analyze the redo log files
Perform a logical recovery of the database
How To Disable Automatic Statistics Collection in Oracle 10G
To disable the automatic statistics collection, you can execute the following procedure:
exec dbms_scheduler.disable(’GATHER_STATS_JOB’);
To check whether the job is disabled, run the following Query:
select state from dba_scheduler_jobs where job_name = ‘GATHER_STATS_JOB’;
The job details can be viewed by querying the DBA_SCHEDULER_JOBS view:
select job_name, job_type, program_name, schedule_name, job_class
from dba_scheduler_jobs
where job_name = ‘GATHER_STATS_JOB’;
The output will show that the job schedules a program called ‘GATHER_STATS_PROG’ in the ‘MAINTENANCE_WINDOW_GROUP’ time schedule. The program named ‘GATHER_STATS_PROG’ starts the DBMS_STATS.GATHER_DATABASE_STATS_JOB_PROC stored procedure:
select program_action
from dba_scheduler_programs
where program_name = ‘GATHER_STATS_PROG’;
The job is scheduled according to the value of the SCHEDULE_NAME field. In this example, the scheduled being used is: ‘MAINTENANCE_WINDOW_GROUP’. This schedule is defined in the DBA_SCHEDULER_WINGROUP_MEMBERS view:
select *
from dba_scheduler_wingroup_members
where window_group_name = ‘MAINTENANCE_WINDOW_GROUP’;
The meaning of these ‘WINDOWS’ can be found in ‘DBA_SCHEDULER_WINDOWS’:
select window_name, repeat_interval, duration
from dba_scheduler_windows
where window_name in (’WEEKNIGHT_WINDOW’,'WEEKEND_WINDOW’);
The meaning of these entries is as follows:
The WEEKNIGHT_WINDOW is schedule each week day at 10PM and should last a maximum of 8 hours. The WEEKEND_WINDOW is scheduled Saturday at 0AM and should last 2 days maximum. If the START_DATE and END_DATE columns (not shown) are NULL, then this job will run continuously. All these definitions can be found in the $ORACLE_HOME/rdbms/admin/catmwin.sql script.
The point of illustrating the Automatic Statistics Collection in Oracle 10g+ was simply to show how to check it the delivered stats job is enabled and if you need to disable or turn it off how to do so. In our case we disable the delivered job for our production databases because we execute our own custom scripts via crontab at least once a day and in some cases twice a day. We are running PeopleSoft Financials as well as HRMS. In regards to PeopleSoft Financials we rely on nVision for generating and delivering Financial Reports and we are using dynamic tree selectors. If we let Oracle generate the statistics for us via the delivered scheduled jobs some of our nVision Report Books which consist of up to 10 nVision Reports would never finish generating the report. At the end of our custom shell script to generate schema and system dictionary statistics for the CBO we delete the statistics on the PSTREESELECTxx tables. As a result the majority of our nVision Reports execute in less than 2 minutes and the Report Books with 10 nVision Reports execute in less than 20 minutes for all 10 reports.
Personally in order to ensure the best possible performance in Oracle 10g R2+ I believe it is best to keep the CBO statistics as current as possible.
exec dbms_scheduler.disable(’GATHER_STATS_JOB’);
To check whether the job is disabled, run the following Query:
select state from dba_scheduler_jobs where job_name = ‘GATHER_STATS_JOB’;
The job details can be viewed by querying the DBA_SCHEDULER_JOBS view:
select job_name, job_type, program_name, schedule_name, job_class
from dba_scheduler_jobs
where job_name = ‘GATHER_STATS_JOB’;
The output will show that the job schedules a program called ‘GATHER_STATS_PROG’ in the ‘MAINTENANCE_WINDOW_GROUP’ time schedule. The program named ‘GATHER_STATS_PROG’ starts the DBMS_STATS.GATHER_DATABASE_STATS_JOB_PROC stored procedure:
select program_action
from dba_scheduler_programs
where program_name = ‘GATHER_STATS_PROG’;
The job is scheduled according to the value of the SCHEDULE_NAME field. In this example, the scheduled being used is: ‘MAINTENANCE_WINDOW_GROUP’. This schedule is defined in the DBA_SCHEDULER_WINGROUP_MEMBERS view:
select *
from dba_scheduler_wingroup_members
where window_group_name = ‘MAINTENANCE_WINDOW_GROUP’;
The meaning of these ‘WINDOWS’ can be found in ‘DBA_SCHEDULER_WINDOWS’:
select window_name, repeat_interval, duration
from dba_scheduler_windows
where window_name in (’WEEKNIGHT_WINDOW’,'WEEKEND_WINDOW’);
The meaning of these entries is as follows:
The WEEKNIGHT_WINDOW is schedule each week day at 10PM and should last a maximum of 8 hours. The WEEKEND_WINDOW is scheduled Saturday at 0AM and should last 2 days maximum. If the START_DATE and END_DATE columns (not shown) are NULL, then this job will run continuously. All these definitions can be found in the $ORACLE_HOME/rdbms/admin/catmwin.sql script.
The point of illustrating the Automatic Statistics Collection in Oracle 10g+ was simply to show how to check it the delivered stats job is enabled and if you need to disable or turn it off how to do so. In our case we disable the delivered job for our production databases because we execute our own custom scripts via crontab at least once a day and in some cases twice a day. We are running PeopleSoft Financials as well as HRMS. In regards to PeopleSoft Financials we rely on nVision for generating and delivering Financial Reports and we are using dynamic tree selectors. If we let Oracle generate the statistics for us via the delivered scheduled jobs some of our nVision Report Books which consist of up to 10 nVision Reports would never finish generating the report. At the end of our custom shell script to generate schema and system dictionary statistics for the CBO we delete the statistics on the PSTREESELECTxx tables. As a result the majority of our nVision Reports execute in less than 2 minutes and the Report Books with 10 nVision Reports execute in less than 20 minutes for all 10 reports.
Personally in order to ensure the best possible performance in Oracle 10g R2+ I believe it is best to keep the CBO statistics as current as possible.
Subscribe to:
Posts (Atom)