A recent (Mar 2024) question on the MOSC DB Admin forum (needs an account) asks why a query which runs every few minutes and executes 25 times in 2 hours according to an AWR report never shows up in v$session when you query for the SQL_ID.
SQL> select * from V$session where sql_id = '0qsvkwru0agwg';
no rows selected
There are a few reasons why you might be unlucky with the timing but it seems likely that this query, if repeated very frequently for a couple of minutes, ought to be able to capture details of the session executing it, especially since the (edited) line supplied from the “SQL ordered by Elapsed Time” section of the AWR shows the average execution time of the query to be 1.93 seconds. There is, however, an obvious clue about why the OP is out of luck.
The OP has “obfuscated” the sql_id in question – which is a fairly pointless exercise since it’s not possible to reverse engineer an sql_id back to the originating text. I mention this simply because the supplied “sql_id” is 6 letters long and not the 13 that every sql_id (and my fake above) should be – it’s the type of tiny detail that leads to suggestions like: “maybe the OP just didn’t copy the sql_id correctly when querying v$session”.
Take a look at the fragment of “SQL Text” reported with the sql_id:
DECLARE V_SEUIL VARCHAR2(2) :=
This is not an SQL statement, it’s the start of an anonymous PL/SQL block. This might be the reason why the sql_id is (statistically speaking) never spotted in v$session or v$active_session_history; it also tells us what the OP probably ought to be looking for … the SQL that’s executing inside the PL/SQL, which can be found by following the link that the AWR will have supplied to the corresponding entry in the “Complete List of SQL Text”. Allowing for the way that embedded SQL is “normalised” to all capitals with excess white space removed, the text of the PL/SQL will provide some text that the OP can use to search the rest of the AWR report for more appropriate SQL ids.
Examples
Just to demonstrate the point, and note some side effects of SQL running inside PL/SQL, here’s a demonstration script with three variations on the theme; followed by the critical part of the output and a separate section with the corresponding “SQL ordered by Elapsed Time” extracts from the AWR reports generated after running the test on 11.2.0.4 (because that was the version being used by the OP):
rem
rem Script: awr_plsql.sql
rem Author: Jonathan Lewis
rem Dated: Mar 2024
rem Purpose:
rem
rem Last tested
rem 11.2.0.4
rem
create table t1 as select * from all_objects where rownum <= 10000;
create table t2 as select * from t1;
execute dbms_workload_repository.create_snapshot('TYPICAL');
set timing on
set feedback off
declare
ct number;
begin
select
/*+
leading(t1 t2)
use_nl(t2)
*/
count(*)
into ct
from
t1, t2
where
t2.object_id = t1.object_id
;
dbms_output.put_line('Count: ' || ct);
end;
/
set timing off
execute dbms_workload_repository.create_snapshot('TYPICAL');
set timing on
declare
ct number := 0;
c_tot number := 0;
begin
for r in (select * from t1) loop
select count(*)
into ct
from t2
where t2.object_id = r.object_id
;
c_tot := c_tot + ct;
end loop;
dbms_output.put_line('Count: ' || c_tot);
end;
/
set timing off
execute dbms_workload_repository.create_snapshot('TYPICAL');
set timing on
declare
ct number := 0;
c_tot number := 0;
begin
for r in (
select
/*+
leading(t1 t2)
use_nl(t2)
*/
t1.object_id
from t1,t2
where t2.object_id = t1.object_id
) loop
select count(*)
into ct
from t2
where t2.object_id = r.object_id
;
c_tot := c_tot + ct;
end loop;
dbms_output.put_line('Count: ' || c_tot);
end;
/
set timing off
execute dbms_workload_repository.create_snapshot('TYPICAL');
Output
--------
Count: 10000
Elapsed: 00:00:13.70
Count: 10000
Elapsed: 00:00:10.35
Count: 10000
Elapsed: 00:00:24.81
The three anonymous blocks do a lot of pointless work in PL/SQL: the first statement forces a simple nested loop join using full tablescans over two tables of 10,000 rows, the second statement “emulates” this using a PL/SQL loop over the first table, scanning the second table once per row; the third statement combines both pieces of idiocy, driving through the nested loop then scanning the second table once per row returned. It’s not really surprising that the three times recorded are in the order of seconds, nor that we can see T3 (time for the third block) is approximately T1 + T2. But what do the separate AWR reports say:
Test 1 – nested loop join, block run time reported as 13.70 seconds:
Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
13.6 1 13.63 92.3 98.1 .0 1sxdt7cswq8z0
Module: MyModule
declare ct number; begin select /*+ leading(t1 t2) use_nl(t2) */ c
ount(*) into ct from t1, t2 where t2.object_id = t1.object_id ; dbms_
output.put_line('Count: ' || ct); end;
13.6 1 13.63 92.3 98.1 .0 502tvyky9s2ta
Module: MyModule
SELECT /*+ leading(t1 t2) use_nl(t2) */ COUNT(*) FROM T1, T2 WHERE T2.OB
JECT_ID = T1.OBJECT_ID
The anonymous PL/SQL block appears at the top of the list reporting 13.6 seconds – but that’s nearly 100% of the total time reported, and the SQL statement inside the block also reports 13.6 seconds. The actual time Oracle spent in the PL/SQL execution engine was virtually zero, but the AWR report has (in effect) double counted the time. You’ll notice that the “pure” SQL has, except for the comments/hints, been converted to upper case and the “into ct” has been removed.
Test 2 – PL/SQL emulating an inefficient nested loop join
Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
10.2 1 10.24 90.0 98.2 .0 201ptprw6ngpq
Module: MyModule
declare ct number := 0; c_tot number := 0; begin for r in (select * from t1)
loop select count(*) into ct from t2 where t2.object_id = r.object_id
; c_tot := c_tot + ct; end loop; dbms_output.put_line('Count: ' || c_tot); e
nd;
9.5 10,000 0.00 83.5 98.2 .0 4qwg9bknnjbr0
Module: MyModule
SELECT COUNT(*) FROM T2 WHERE T2.OBJECT_ID = :B1
Again, the total time reported exceeds that elapsed execution time from the SQL*Plus output. Again the anonymous PL/SQL block is at the top of the list, but this time the SQL accounts for noticeable less time than the PL/SQL block. The time spent in the PL/SQL engine has become visible – after all, the PL/SQL has called a SQL statement 10,000 times, and it has amended a variable value 10,000 times.
Test 3 – inefficient nested loop join driving an emulated join
-> Captured SQL account for 97.4% of Total DB Time (s): 26
-> Captured PL/SQL account for 100.1% of Total DB Time (s): 26
Elapsed Elapsed Time
Time (s) Executions per Exec (s) %Total %CPU %IO SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
24.8 1 24.81 95.3 97.2 .0 a30dkwt9at2w5
Module: MyModule
declare ct number := 0; c_tot number := 0; begin for r in ( select /*+
leading(t1 t2) use_nl(t2) */ t1.object_id from t1,t2 where t2.o
bject_id = t1.object_id ) loop select count(*) into ct from t2 where t2
.object_id = r.object_id ; c_tot := c_tot + ct; end loop; dbms_output.put_
14.3 1 14.26 54.8 97.1 .0 877jph80b0t2x
Module: MyModule
SELECT /*+ leading(t1 t2) use_nl(t2) */ T1.OBJECT_ID FROM T1,T2 WHERE
T2.OBJECT_ID = T1.OBJECT_ID
10.1 10,000 0.00 38.7 97.9 .0 4qwg9bknnjbr0
Module: MyModule
SELECT COUNT(*) FROM T2 WHERE T2.OBJECT_ID = :B1
I’ve included in this example two lines from the heading of the “SQL ordered by…” section. It’s often very helpful to check for summary comments like this – and not just in SQL sections of the AWR/Statspack report – sometimes you’ll notice that some derived total is more than (maybe much more than) 100% of the figures you’re trying to address; sometimes you may notice that the “biggest, most important number” in the detail may be pretty irrelevant because the “total accounted for” is only a small fraction of the actual work done.
This example shows another fairly common pattern – a PL/SQL block where (even if you didn’t cross-check carefully at first) you might notice that there were a few SQL statements reported a little further down that conveniently summed to the total of the PL/SQL. (There’s a pretty little example of this from a production system that I published in 2007 in one of my Analysing Statspack notes).
Again you’ll notice that there’s a little extra time in the PL/SQL line than the sum of the two SQL lines – but again we have to allow for PL/SQL calling 10,000 SQL executions and summing 10,000 results. In the last two examples there’s a slightly better chance of capturing the SQL_ID of the PL/SQL block by querying v$session. In 80 samples (driven by hand) of query by the correct SID while the last example was running I saw the sql_id of the PL/SQL block in v$session.prev_sql_id once, most of the samples showed me the sql_id of the simple tablescan as the v$session.sql_id, or which roughly half showed the sql_id of the driving loop as the v$session.prev_sql_id.
Summary
If you have an AWR report that shows a PL/SQL block as an expensive item in the “SQL ordered by …” sections you may never see its sql_id in any queries you make against v$session or v$active_session_history because the component of the work done by the PL/SQL may be incredibly tiny, but the AWR is reporting the sum of the workload due to the SQL executing inside that block as if it were part of the pure PL/SQL workload.
A big hint about this appears in the summary notes above (most of) the details reports, where there may be a couple of lines telling you what percentage of the workload/time/etc. the detail has captured. Sometimes it’s vastly more than 100% (and sometimes it’s much less – which tells you that you may be looking at things that are not part of the real problem).
Oracle Scratchpad 