Here’s a little detail I was forced to re-learn yesterday; it’s one of those things where it’s easy to say “yes, obviously” AFTER you’ve had it explained so I’m going to start by posing it as a question. Here are two samples of PL/SQL that using locking to handle a simple synchronisation mechanism; one uses a table as an object that can be locked, the other uses Oracle’s dbms_lock package. I’ve posted the code for each fragment, and a sample of what you see in v$lock if two sessions execute the code one after the other:
Table locking – the second session to run this code will wait for the first session to commit or rollback:
begin
lock table t1 in exclusive mode;
end;
/
ADDR KADDR SID TY ID1 ID2 LMODE REQUEST CTIME BLOCK
---------------- ---------------- ---------- -- ---------- ---------- ---------- ---------- ---------- ----------
00007FF409E57BF8 00007FF409E57C58 15 TM 157778 0 0 6 65 0
00007FF409E57BF8 00007FF409E57C58 125 TM 157778 0 6 0 91 1
Using dbms_lock.
variable m_handle varchar2(255);
declare
n1 number;
begin
dbms_lock.allocate_unique(
lockname => 'Synchronize',
lockhandle => :m_handle
);
dbms_output.put_line(:m_handle);
n1 := dbms_lock.request(
lockhandle => :m_handle,
lockmode => dbms_lock.x_mode,
timeout => dbms_lock.maxwait,
release_on_commit => true -- the default is false !!
);
dbms_output.put_line(n1);
end;
/
ADDR KADDR SID TY ID1 ID2 LMODE REQUEST CTIME BLOCK
---------------- ---------------- ---------- -- ---------- ---------- ---------- ---------- ---------- ----------
000000008ED8F738 000000008ED8F790 15 UL 1073742427 0 0 6 42 0
000000008ED902B0 000000008ED90308 125 UL 1073742427 0 6 0 103 1
The big question is this – although the two code fragments produce the same effects in terms of lock waits and the reports from v$lock, what’s the big difference in the way that they are reported in the AWR report.
The high-level difference appears in the Time Model stats. Here are two extracts showing the difference:
Using dbms_lock.
Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 65.4 99.9
PL/SQL execution elapsed time 63.8 97.4
-> Captured SQL account for 2.8% of Total DB Time (s): 65
-> Captured PL/SQL account for 99.4% of Total DB Time (s): 65
Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
63.7 1 63.72 97.3 .0 .0 10u1qbw4a27sp
Module: SQL*Plus
declare n1 number; begin dbms_lock.allocate_unique
( lockname => 'Synchronize', lockhandle
=> :m_handle ); dbms_output.put_line(:m_handle); n
1 := dbms_lock.request( lockhandle => :m_handle,
Table locking method:
Time Model Statistics
Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 95.5 99.9
DB CPU 0.9 .9
parse time elapsed 0.1 .1
hard parse elapsed time 0.1 .1
PL/SQL execution elapsed time 0.1 .1
SQL ordered by Elapsed Time
-> Captured SQL account for 99.6% of Total DB Time (s): 96
-> Captured PL/SQL account for 98.7% of Total DB Time (s): 96
Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
93.9 1 93.88 98.3 .0 .0 8apkdghttmndx
Module: SQL*Plus
begin lock table t1 in exclusive mode; end;
93.9 1 93.88 98.3 .0 .0 29fwr53agvbc0
Module: SQL*Plus
LOCK TABLE T1 IN EXCLUSIVE MODE
The time spent waiting for the table lock is reported purely as SQL execution time in the Time Model stats; but the time spent waiting for the user-defined lock is reported as SQL execution time AND as PL/SQL execution time. I had forgotten this yesterday so, as I skipped through the various headline figures of an hourly snapshot, I was amazed to see the Time Model stats reporting 33,000 seconds of PL/SQL and 66,000 seconds of SQL – how on earth do you manage to do that much PL/SQL on any Oracle system. (To add to the embarrassment, it had only been a few moments earlier that I’d gone through the Top 5 Timed Events and said something like: “you can ignore all time spent on ‘enq: UL – contention’, it’s probably just synchronisation code”.
In this case the SQL ordered by Elapsed Time gives you a strong visual clue about what’s going on – but it won’t always be that obvious.
Bottom Line:
PL/SQL execution time includes the time spent waitng for UL locks, don’t forget that you may need to subtract wait time for ‘enq: UL – contention’ from the PL/SQL time before you start to worry about how much actual work you’re doing in PL/SQL.
