Bind variable peeking: Retrieve peeked and passed values per execution in oracle 11.2

To understand this blog post you have to know what bind variable peeking is. You can found a very good explanation into this Kerry Osborne’s blog post.

So when dealing with performance issues linked to bind variable peeking you have to know:

  • The peeked values (The ones that generate the execution plan)
  • The passed values (The ones that have been passed to the sql statement)

Kerry Osborne helped us to retrieve the peeked values from v$sql_plan view into this blog post, but what about the passed values ?  For those ones, Tanel Poder helped us to retrieve the passed values from v$sql_monitor into this blog post (This is reliable compare to v$sql_bind_capture)

Great ! So we know how to extract the peeked and the passed values. Another interesting point is that v$sql_monitor contains also the sql_exec_id field (see this blog post for more details about this field).

Here we are:  It looks like that as of 11.2 we are able to retrieve the passed and peeked values per execution (If the statement is “monitored” which  means CPU + I/O wait time >= 5 seconds per default (can be changed thanks to the _sqlmon_threshold hidden parameter).

But as your are dealing with performance issues related to bind variable peeking it is likely that the sql is monitored 😉

So let’s write the sql to do so, and let’s test it.

The sql script is the following:

SQL> !cat binds_peeked_passed.sql
set linesi 200 pages 999 feed off verify off
col bind_name format a20
col end_time format a19
col start_time format a19
col peeked format a20
col passed format a20

alter session set nls_date_format='YYYY/MM/DD HH24:MI:SS';
alter session set nls_timestamp_format='YYYY/MM/DD HH24:MI:SS';

select
pee.sql_id,
ash.starting_time,
ash.end_time,
(EXTRACT(HOUR FROM ash.run_time) * 3600
                    + EXTRACT(MINUTE FROM ash.run_time) * 60
                    + EXTRACT(SECOND FROM ash.run_time)) run_time_sec,
pee.plan_hash_value,
pee.bind_name,
pee.bind_pos,
pee.bind_data peeked,
run_t.bind_data passed
from
(
select
p.sql_id,
p.sql_child_address,
p.sql_exec_id,
c.bind_name,
c.bind_pos,
c.bind_data
from
v$sql_monitor p,
xmltable
(
'/binds/bind' passing xmltype(p.binds_xml)
columns bind_name varchar2(30) path '/bind/@name',
bind_pos number path '/bind/@pos',
bind_data varchar2(30) path '/bind'
) c
where
p.binds_xml is not null
) run_t
,
(
select
p.sql_id,
p.child_number,
p.child_address,
c.bind_name,
c.bind_pos,
p.plan_hash_value,
case
     when c.bind_type = 1 then utl_raw.cast_to_varchar2(c.bind_data)
     when c.bind_type = 2 then to_char(utl_raw.cast_to_number(c.bind_data))
     when c.bind_type = 96 then to_char(utl_raw.cast_to_varchar2(c.bind_data))
     else 'Sorry: Not printable try with DBMS_XPLAN.DISPLAY_CURSOR'
end bind_data
from
v$sql_plan p,
xmltable
(
'/*/peeked_binds/bind' passing xmltype(p.other_xml)
columns bind_name varchar2(30) path '/bind/@nam',
bind_pos number path '/bind/@pos',
bind_type number path '/bind/@dty',
bind_data  raw(2000) path '/bind'
) c
where
p.other_xml is not null
) pee,
(
select
sql_id,
sql_exec_id,
max(sample_time - sql_exec_start) run_time,
max(sample_time) end_time,
sql_exec_start starting_time
from
v$active_session_history
group by sql_id,sql_exec_id,sql_exec_start
) ash
where
pee.sql_id=run_t.sql_id and
pee.sql_id=ash.sql_id and
run_t.sql_exec_id=ash.sql_exec_id and
pee.child_address=run_t.sql_child_address and
pee.bind_name=run_t.bind_name and
pee.bind_pos=run_t.bind_pos and
pee.sql_id like nvl('&sql_id',pee.sql_id)
order by 1,2,3,7 ;

Now let’s test it:

SQL> var my_owner varchar2(50)
SQL> var my_date varchar2(30)
SQL> var my_object_id number
SQL> exec :my_owner :='BDT'

PL/SQL procedure successfully completed.

SQL> exec :my_date := '01-jan-2001'

PL/SQL procedure successfully completed.

SQL> exec :my_object_id :=1

PL/SQL procedure successfully completed.

SQL> select /*+ MONITOR */ count(*),min(object_id),max(object_id) from bdt2 where owner=:my_owner and created > :my_date and object_id > :my_object_id;

  COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
   6974365              2          18233

SQL> @binds_peeked_passed.sql
Enter value for sql_id: 

SQL_ID        STARTING_TIME       END_TIME            RUN_TIME_SEC PLAN_HASH_VALUE BIND_NAME              BIND_POS PEEKED               PASSED
------------- ------------------- ------------------- ------------ --------------- -------------------- ---------- -------------------- --------------------
bu9367qrhq28t 2013/04/29 11:01:02 2013/04/29 11:01:07        5.678      1047781245 :MY_OWNER                     1 BDT                  BDT
bu9367qrhq28t 2013/04/29 11:01:02 2013/04/29 11:01:07        5.678      1047781245 :MY_DATE                      2 01-jan-2001          01-jan-2001
bu9367qrhq28t 2013/04/29 11:01:02 2013/04/29 11:01:07        5.678      1047781245 :MY_OBJECT_ID                 3 1                    1

As this is the first execution then peeked values = passed values. Note that I used the “MONITOR” hint to force the sql to be monitored and then get an entry into v$sql_monitor.

Let’s put new passed values:

SQL> exec :my_date := '01-jan-2002'

PL/SQL procedure successfully completed.

SQL> exec :my_object_id :=100

PL/SQL procedure successfully completed.

SQL> select /*+ MONITOR */ count(*),min(object_id),max(object_id) from bdt2 where owner=:my_owner and created > :my_date and object_id > :my_object_id;

  COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
   6923776            101          18233

SQL> @binds_peeked_passed.sql
Enter value for sql_id: 

SQL_ID        STARTING_TIME       END_TIME            RUN_TIME_SEC PLAN_HASH_VALUE BIND_NAME              BIND_POS PEEKED               PASSED
------------- ------------------- ------------------- ------------ --------------- -------------------- ---------- -------------------- --------------------
bu9367qrhq28t 2013/04/29 11:01:02 2013/04/29 11:01:07        5.678      1047781245 :MY_OWNER                     1 BDT                  BDT
bu9367qrhq28t 2013/04/29 11:01:02 2013/04/29 11:01:07        5.678      1047781245 :MY_DATE                      2 01-jan-2001          01-jan-2001
bu9367qrhq28t 2013/04/29 11:01:02 2013/04/29 11:01:07        5.678      1047781245 :MY_OBJECT_ID                 3 1                    1
bu9367qrhq28t 2013/04/29 11:07:21 2013/04/29 11:07:25        4.139      1047781245 :MY_OWNER                     1 BDT                  BDT
bu9367qrhq28t 2013/04/29 11:07:21 2013/04/29 11:07:25        4.139      1047781245 :MY_DATE                      2 01-jan-2001          01-jan-2002
bu9367qrhq28t 2013/04/29 11:07:21 2013/04/29 11:07:25        4.139      1047781245 :MY_OBJECT_ID                 3 1                    100

So as you can see, peeked values are the same and passed are not: bind variable peeking in action 😉

Conclusion:

We are able to retrieve peeked and passed values per execution.

Remarks:

  1. You need Diagnostic and tuning licenses pack to query v$active_session_history and v$sql_monitor.
  2. The query is not able to retrieve the DATE values (if any) from the v$sql_plan (check the code): This is because I don’t want to create a new function into the database. If you want to extract the DATE datatype then you could create the display_raw function (see Kerry Osborne’s blog post for this) and modify the sql.
  3. If you know how to extract DATE values from RAW type without creating new function please tell me so that i can update the code 😉
Advertisements

Drill down to sql_id execution details in ASH

Some times ago I explained how we can link a huge PGA or TEMP consumption to a sql_id over a period of time into this blog post.

Now I need to extract this information not only per sql_id but also per execution. This is not so simple to extract from ash as the same session could execute many times the same sql_id over a period of time.

Hopefully, since 11g the sql_exec_id column has been added to the v$active_session_history and dba_hist_active_sess_history views. You can find a very useful description of this column into this blog post from Tanel Poder.

Basically, the sql_exec_id is a unique identifier of a sql_id execution on the database. That way we are now able to know if an ash entry for this sql_id is linked to a new execution (means new sql_exec_id) or is showing a long running execution (means same sql_exec_id).

We are also able to retrieve some useful metrics as avg, min, max execution time: You can see some good examples of sql_exec_id usage into Kyle Hailey’s blog post or Karl Arao’s one.

Back to my need:

Let’s suppose that I found (Thanks to the sql provided into this post) that the sql_id “btvk5dzpdmadh” is responsible of about 2Gb of pga over allocation during a period of time:

SQL_ID            PGA_MB         %
------------- ---------- --------- ----------
btvk5dzpdmadh       2394    100.00 **********

Now I can drill down to details to get the pga over allocation per execution that way:

alter session set nls_date_format='YYYY/MM/DD HH24:MI:SS';
alter session set nls_timestamp_format='YYYY/MM/DD HH24:MI:SS';

select sql_id,
      starting_time,
      end_time,
 (EXTRACT(HOUR FROM run_time) * 3600
                    + EXTRACT(MINUTE FROM run_time) * 60
                    + EXTRACT(SECOND FROM run_time)) run_time_sec,
      READ_IO_BYTES,
      PGA_ALLOCATED PGA_ALLOCATED_BYTES,
      TEMP_ALLOCATED TEMP_ALLOCATED_BYTES
from  (
select
       sql_id,
       max(sample_time - sql_exec_start) run_time,
       max(sample_time) end_time,
       sql_exec_start starting_time,
       sum(DELTA_READ_IO_BYTES) READ_IO_BYTES,
       sum(DELTA_PGA) PGA_ALLOCATED,
       sum(DELTA_TEMP) TEMP_ALLOCATED
       from
       (
       select sql_id,
       sample_time,
       sql_exec_start,
       DELTA_READ_IO_BYTES,
       sql_exec_id,
       greatest(PGA_ALLOCATED - first_value(PGA_ALLOCATED) over (partition by sql_id,sql_exec_id order by sample_time rows 1 preceding),0) DELTA_PGA,
       greatest(TEMP_SPACE_ALLOCATED - first_value(TEMP_SPACE_ALLOCATED) over (partition by sql_id,sql_exec_id order by sample_time rows 1 preceding),0) DELTA_TEMP
       from
       dba_hist_active_sess_history
       where
       sample_time >= to_date ('2013/04/16 00:00:00','YYYY/MM/DD HH24:MI:SS')
       and sample_time < to_date ('2013/04/16 03:10:00','YYYY/MM/DD HH24:MI:SS')
       and sql_exec_start is not null
       and IS_SQLID_CURRENT='Y'
       )
group by sql_id,SQL_EXEC_ID,sql_exec_start
order by sql_id
)
where sql_id = 'btvk5dzpdmadh'
order by sql_id, run_time_sec desc;

It will produces this kind of output:

SQL_ID        STARTING_TIME       END_TIME            RUN_TIME_SEC READ_IO_BYTES PGA_ALLOCATED_BYTES TEMP_ALLOCATED_BYTES
------------- ------------------- ------------------- ------------ ------------- ------------------- --------------------
btvk5dzpdmadh 2013/04/16 00:05:01 2013/04/16 03:09:56    11095.559    2.0417E+10           240123904           2642411520
btvk5dzpdmadh 2013/04/16 00:05:01 2013/04/16 03:09:56    11095.559    2.2207E+10           181993472           2233466880
btvk5dzpdmadh 2013/04/16 00:05:01 2013/04/16 03:09:56    11095.559    2.4342E+10           192610304           2453667840
btvk5dzpdmadh 2013/04/16 00:13:43 2013/04/16 03:09:56    10573.559    1.3095E+10           212074496           1142947840
btvk5dzpdmadh 2013/04/16 00:05:01 2013/04/16 02:10:10     7509.398    1.9374E+10           200540160           2076180480
btvk5dzpdmadh 2013/04/16 00:26:32 2013/04/16 02:05:19     5927.907    6603603968           226099200            251658240
btvk5dzpdmadh 2013/04/16 01:37:19 2013/04/16 03:09:56     5557.559    7589232640           245497856            639631360
btvk5dzpdmadh 2013/04/16 00:05:22 2013/04/16 01:36:57     5495.072    4285022208           237371392            125829120
btvk5dzpdmadh 2013/04/16 02:12:54 2013/04/16 03:09:56     3422.559    7433412608           237371392            209715200
btvk5dzpdmadh 2013/04/16 02:29:17 2013/04/16 03:09:56     2439.559    2776473600           288489472            146800640
btvk5dzpdmadh 2013/04/16 02:05:43 2013/04/16 02:29:02     1399.436    1841930240           126484480             62914560
btvk5dzpdmadh 2013/04/16 00:05:01 2013/04/16 00:22:59     1078.508    1548386304            19333120
btvk5dzpdmadh 2013/04/16 00:05:01 2013/04/16 00:13:38      517.558     652337152            19202048
btvk5dzpdmadh 2013/04/16 00:23:08 2013/04/16 00:26:29      201.867     439246848            29425664
btvk5dzpdmadh 2013/04/16 02:10:57 2013/04/16 02:12:50      113.706      97910784            53673984
btvk5dzpdmadh 2013/04/16 00:05:01 2013/04/16 00:05:17       16.703      22503424                   0

As you can see we retrieved:

  • Start time of the execution
  • End time of the execution
  • The run time of the execution
  • The number of READ_IO_BYTES of the execution
  • The PGA and TEMP over allocation of the execution

Remarks:

  1. The dba_hist_active_sess_history view is no so accurate as only a subset of the rows coming from v$active_session_history are flushed into the dba_hist_active_sess_history view.
  2. This SQL works as of 11.2.0.1.
  3. You need to purchase the Diagnostic Pack in order to be allowed to query the “v$active_session_history” view.
  4. This query is useful to diagnose “huge” PGA or TEMP consumption. It is not so helpful to find out which execution used exactly how much PGA or TEMP (As it may used already pre-allocated PGA or TEMP space and did not need over allocation: See the columns definition in the beginning of this post)