Tuning Using v$mystat
Mar 21, 2013 / By Marc Billette
When reviewing the performance of some queries, it is sometimes useful to review the sessions statistics for each execution of the query. These session statistics complement the wait events found in ASH and trace files. The wait events do not show this information. Many of these session level statistics can be quite revealing. They can show some execution differences that are otherwise difficult, if not impossible for some, to see with trace files and ASH data.
I had a situation that required to look at these stats so I could see why one query would run fast and sometimes much slower. ASH data was not exposing this issue clearly. In order to facilitate the comparison of the data from run to run, I wrote a simple wrapper ksh shell script for the query. It saves the session statistics in a table before and after the execution of the query and then prints out the statistics in a pivot report. This turned out to be very handy to me and therefore I chose to share it with the world :)
Below is a sample output of the report. It prints only statistics that have changed and it shows all execution stats in separate columns. The executions are labeled like “run#-HH:MI:SS.ssss”. Those labels show the query’s execution sequence and elapsed time.
NAME '1-00:00:00.0107' '2-00:00:00.0085' '3-00:00:00.0050' '4-00:00:00.0051' '5-00:00:00.0053' ------------------------------------- ----------------- ----------------- ----------------- ----------------- ----------------- CPU used by this session 1 2 1 1 calls to get snapshot scn: kcmgss 2 3 2 2 2 calls to kcmgcs 4 consistent gets 17 consistent gets from cache 17 consistent gets from cache (fastpath) 17 cursor authentications 1 enqueue releases 1 1 enqueue requests 1 1 execute count 2 3 2 2 2 global enqueue gets sync 2 2 2 global enqueue releases 2 2 2 logical read bytes from cache 139264 no work - consistent read gets 13 non-idle wait count 1 opened cursors cumulative 2 3 2 2 2 opened cursors current 1 1 1 1 1 parse count (hard) 1 1 parse count (total) 2 2 2 2 2 pinned cursors current 1 1 1 1 1 recursive calls 6 9 5 5 5 recursive cpu usage 1 2 1 1 session cursor cache hits 1 session logical reads 17 session pga memory 65536 196608 196608 196608 131072 session pga memory max 65536 196608 196608 196608 131072 session uga memory 65488 65488 65488 65488 session uga memory max 123512 123512 123512 123512 123512 table scan blocks gotten 13 table scan rows gotten 1276 table scans (short tables) 1 workarea executions - optimal 1 1 1 1 1 workarea memory allocated 50 37 37 37
Note that the execution time in the labels is the elaspe time difference between the capture of the before and after session stats. Not the real query execution elapse. The difference should be very low, like less than 0.01s as you can see from the above durations. Also, note that the PLSQL block that runs the query does not fetch the data. It only opens the cursor, which executes the query. This shows you how long the query takes to get the resultset ready and removes the network and application related overhead.
Here is the code:
#!/bin/sh
export v_sql_text=$(cat sql_runstat_source_query.sql)
echo 'Enter username:';read username
echo 'Please enter your password: ';stty -echo;read passwd;stty echo
sqlplus -S /nolog<
prompt connecting...
connect $username/$passwd
set echo off feed off verify off
set serveroutput on size 2000
col name for a50
prompt verifying the existence of the table query_stats...
declare
table_exists number;
begin
select count(*) into table_exists from dba_tables where owner = user and table_name='QUERY_STATS';
if table_exists = 0 then
execute immediate 'CREATE TABLE '||user||'.query_stats AS SELECT systimestamp as timestamp, '' '' before, 0 run, name, value FROM v\$statname NATURAL JOIN v\$mystat where 1=2';
dbms_output.put_line('Table '||user||'.query_stats created.');
else
dbms_output.put_line('Warning! Table '||user||'.query_stats exists already. Appending...');
end if;
end;
/
drop type query_stats_table_type;
create or replace type query_stats_type
as object
(TIMESTAMP TIMESTAMP(6) WITH TIME ZONE,
BEFORE CHAR(1),
RUN NUMBER,
NAME VARCHAR2(64),
VALUE NUMBER
);
/
create or replace type query_stats_table_type
as table of query_stats_type;
/
prompt executing the query and saving pre and post session stats...
declare
next_run number;
stats_before query_stats_table_type;
stats_after query_stats_table_type;
type cur_type is ref cursor;
c cur_type;
begin
-- capturing pre-stats
select nvl(max(run),-1)+1 into next_run from query_stats;
SELECT query_stats_type(systimestamp, 'Y', next_run, name, value) bulk collect into stats_before FROM v\$statname NATURAL JOIN v\$mystat;
-- executing the query from the var v_sql_text, which is loaded from file sql_runstat_source_query.sql
open c for $v_sql_text;
-- capturing post-stats
next_run := next_run + 1;
SELECT query_stats_type(systimestamp, 'N', next_run, name, value) bulk collect into stats_after FROM v\$statname NATURAL JOIN v\$mystat;
-- saving stats
insert into query_stats
select * from table(cast(stats_before as query_stats_table_type))
union all
select * from table(cast(stats_after as query_stats_table_type))
;
commit;
end;
/
prompt getting the run id list...
col max_run new_value run noprint
select max(run) max_run from query_stats;
-- get the run ids and their durations and join them as CSVs to pass to the pivot query
col runlist new_value runs noprint
select listagg(run,',') within group (order by run) runlist
from
(select ''''||ceil(run/2)||'-'||duration_H_M_S||'''' run
from ( SELECT distinct run,
to_char(extract(HOUR FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
to_char(extract(MINUTE FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
to_char(extract(SECOND FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00.0000') AS duration_H_M_S
FROM query_stats
)
where duration_H_M_S is not null
and mod(run,2)<>0
order by 1
)
;
prompt pivoting the run statistics where there is a value difference...
set linesize 200 trim on
select *
from (
select ceil(run/2)||'-'||duration_H_M_S as run,
name,
value_diff
from (
SELECT run,
name,
value,
value-lag(value) OVER (partition by name ORDER BY name, run) as value_diff,
to_char(extract(HOUR FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
to_char(extract(MINUTE FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
to_char(extract(SECOND FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00.0000') AS duration_H_M_S
FROM query_stats
)
where mod(run,2)<>0
and value_diff > 0
)
pivot (sum(value_diff) for run in (&runs))
order by name
;
prompt done!
exit
EOF
Some notes about it:
1- The ksh script runs an anonymous plsql block that gets dynamically modified to incorporate the statement you want to test.
2- The statement you want to test needs to be stored in a file called “sql_runstat_source_query.sql” located in the same folder as the ksh script.
3- Do not add a semi-colon at the end of your statement in the sql_runstat_source_query.sql file.
4- The query_stats table contains all the session statistics before and after each executions, not just those that changed and get printed by the pivot table. It also has the timestamp of the captures. You can therefore get more information from this data if needed. For example, you could tailor the column label to show you the full timestamp, or write your own analytics query to suite your needs.
5- The run numbers in the query_stats table are actually a serial number for the statistics capture, starting at 0. 0=first “before” capture, 1=first “after” capture, 2=second “before capture, and so on.
6- The script will create the query_stats table if it is missing, else it appends to it. Two user TYPEs are also created. None of these get dropped after execution so it’s up to you to remove them if you don’t want to keep them in your schema.
7- Remember to either truncate, rename or drop the query_stats table before testing a different statement.
8- You may need to alter the script to set your ORACLE environment variables.
Enjoy!
Marc
I would think Tane’s Snapper would do the job too. What do you think?
Hi Alex,
Great question. Tanel Poder’s snapper utility is awesome and very flexible. Although, I’m not an expert with the snapper utility, my understanding is that in V.4 and later, it can be used to do a before and after comparison like this script does. However, correct me if I’m wrong, but I think it works only on a single execution of a statement, or set of statements (whatever you execute in between the begin and end snapshots).
What I am sharing here is a way to run a single statement (not a set of statements) and save its before and after session stats (no ash here, just v$mystat) in a table. Then you can re-run the script as many times as you want and at any appropriate time during the day, week or whatever schedule is appropriate for your testing. This script prints the full set of executions side by side (pivoted)for comparison. It makes it easier to do the comparison of the multiple session stats. As I understand it, snapper does not store the session statistics anywhere and, although that is a nice non-intrusive feature, you have to manually do the comparison of multiple executions/tests. My goal was to be able to compare fast and slow runs and see what may have impacted the execution’s elapsed time from a session statistics point of view (not wait events) and do so without manual cut and pasting in a text file or spreasheet.
Let me know if you have anymore questions and feel free to correct any misunderstanding about snapper.
Cheers
Marc