Previously I noted how I took my early steps in figuring out what Oracle was doing with my code when I ran it. My early attempts were a combination of code instrumentation and polling of v$sql to find what queries Oracle was running and when. The key limitation as far as polling goes is that it required me to be actively monitoring the process in real time. So, how can we work out what a process did after it has been executed?
Prior to Oracle 10g the answer was not easily unless you did something like run an SQL trace on the process. Oracle 10g introduced Active Session History, which changed things for process monitoring. From the Oracle 11g Release 2 documentation:
“The V$ACTIVE_SESSION_HISTORY view provides sampled session activity in the instance. Active sessions are sampled every second and are stored in a circular buffer in SGA. Any session that is connected to the database and is waiting for an event that does not belong to the Idle wait class is considered as an active session. This includes any session that was on the CPU at the time of sampling.”
So, with Active Session History (often abbreviated to ASH), Oracle samples the database every second and stores details of every session that is considered “active”, meaning that it is waiting on a non-idle wait event or is executing on a CPU. These details are exposed via the data dictionary view v$active_session_history (or gv$active_session_history if you’re operating a RAC environment).
A key detail to note is that the underlying data store for Active Session History is a circular memory buffer. Once the buffer is full then older entries are overwritten by new ones. The question that then arises is “how long will an entry remain in the buffer before being overwritten?”. Unfortunately there is no simple answer to that question as it depends on how many active sessions there have been in the database. You may find that it takes a day or more before details are overwritten or it could be a few hours or less. You can easily find out how much ASH history you have available by running the following query:
SELECT MIN(sample_time) AS min_sample_time
FROM v$active_session_history
If you find that your process has aged out of Active Session History buffer then all is not quite lost. Every 10th sample from v$active_session_history is saved into the Active Workload Repository (AWR) and exposed via the view dba_hist_active_sess_history. From within v$active_session_history, you can tell which samples have been saved from the flag stored in the IS_AWR_SAMPLE column. Unfortunately, 10 second samples are rather too infrequent to obtain a good idea of what a process did.
So, assuming that your recently run process is somewhere in Active Session History, how do you go about getting its details. Well, similar to finding your process if it is currently being executed the first step is to identify the session that it’s running under. Again, there’s no single way to do this and all the suggestions for finding the process in v$session apply: find one or more attributes that you know about your session and filter the ASH data based on those. v$active_session_history has MODULE, ACTION, CLIENT_ID columns so if you’ve been making use of those (as I would encourage) then you’ll probably find it quite easy to locate the necessary session details.
Within v$active session_history the session SID is named SESSION_ID and the SERIAL# is named SESSION_SERIAL# (consistency in naming
with v$session would have been nice…). Once you’ve identified some session entries, obtained these two attributes and have an idea of when your process ran then you can quickly get all of the Active Session History details with the following query:
SELECT *
FROM v$active_session_history
WHERE sample_time BETWEEN :start_time and :end_time
AND session_id = :session_id
AND session_serial# = :session_serial#
ORDER BY
sample_time
Keep in mind that this query will give you an entry per second that your process was executing so there could be quite a few entries for a particularly long running process.
Analysing your process from Active Session History is quite simple once you’ve got a listing of it. The SQL_ID and SQL_CHILD_NUMBER columns give you the particular statement that executing when the sample was taken. As mentioned in the previous post, these details are sufficient to obtain the SQL statement and the execution plan used. Furthermore, Oracle 11.2 introduced the column SQL_EXEC_ID, which can be used to distinguish different executions of the same statement. This is particularly useful if your process runs the same statement frequently. Bear in mind however that it will not tell you how many times a statement has been run if your process executes it many times between the one second sample points.
The EVENT column and associated parameters are useful in determining what the process has spent time waiting on when it hasn’t been active on the CPU. However, I don’t intend to go into wait events here. You will find a listing of the various wait events in Appendix C of the Oracle Database Reference documentation.
The columns starting with BLOCKING are useful in determining if your process was blocked by another session. This can happen for various reasons, such as if another process obtained locks on rows that your process was attempting to modify. The wait event for your session will give you an idea of why your process was being blocked. You can use the blocking session details provided to re-query Active Session History to find what session was blocking your process and what it was doing.
Some other columns that I’ve found useful when using Active Session History are:
- CURRENT_OBJ# – the OBJECT_ID from the DBA_OBJECTS view of the object being referenced when the sample was taken. If this is constant across a number of samples then it can give you an idea of which area of a query Oracle is spending its time. Keep in mind that SQL monitoring may give better information in this case.
- TOP_LEVEL_SQL_ID – the SQL_ID of the top level statement that is executing, which could be the stored procedure call from the application initiating the process.
- IN_HARD_PARSE – this flags whether the process was performing a hard parse when the sample was taken. This can be useful for determining if your process is spending too much time hard parsing queries.
- SEQ# – a unique wait event identifier, which can be used to track whether a wait event is a continuation of the same event from the previous sample, i.e. the wait has lasted more than 1 second, or if it is a new wait event.
There is a wealth of information available within Active Session History and it is possible to construct all sorts of informative queries. As an example, the following query will list the SQL details of a session in the order that they executed, showing their general duration as measured by the samples:
SELECT ash.sql_id
, ash.sql_child_number
, s.sql_text
, ash.sql_exec_start
, ash.sql_exec_id
, TO_CHAR(MIN(ash.sample_time),'hh24:mi:ss') AS min_sample_time
, TO_CHAR(MAX(ash.sample_time),'hh24:mi:ss') AS max_sample_time
FROM v$active_session_history ash
, v$sql s
WHERE ash.sql_id = s.sql_id (+)
AND ash.sql_child_number = s.child_number (+)
AND ash.session_id = :session_id
AND ash.session_serial# = :session_serial#
GROUP BY
ash.sql_id
, ash.sql_child_number
, s.sql_text
, ash.sql_exec_start
, ash.sql_exec_id
ORDER BY
MIN(ash.sample_time)
When run after the following rather simplistic script:
DECLARE
TYPE t_dba_extents_tab IS TABLE OF dba_extents%ROWTYPE;
TYPE t_dba_objects_tab IS TABLE OF dba_objects%ROWTYPE;
TYPE t_dba_users_tab IS TABLE OF dba_users%ROWTYPE;
l_dba_extents_tab t_dba_extents_tab;
l_dba_objects_tab t_dba_objects_tab;
l_dba_users_tab t_dba_users_tab;
l_sid v$session.sid%TYPE;
l_serial# v$session.serial#%TYPE;
BEGIN
SELECT sid
, serial#
INTO l_sid
, l_serial#
FROM v$session
WHERE sid = SYS_CONTEXT('userenv','sid');
dbms_output.enable(null);
dbms_output.put_line ('Session ID: ' || TO_CHAR(l_sid) || ', Serial#: ' || TO_CHAR(l_serial#));
-- run a few queries in a loop so we can use up some time
FOR i IN 1..5
LOOP
SELECT *
BULK COLLECT INTO l_dba_extents_tab
FROM dba_extents
ORDER BY
owner
, segment_name
, partition_name;
SELECT *
BULK COLLECT INTO l_dba_objects_tab
FROM dba_objects
ORDER BY
owner
, object_type
, object_name;
SELECT *
BULK COLLECT INTO l_dba_users_tab
FROM dba_users
ORDER BY
username;
END LOOP;
END;
/
the results were:
SQL_ID SQL_CHILD_NUMBER SQL_TEXT SQL_EXEC_ SQL_EXEC_ID MIN_SAMP MAX_SAMP
------------- ---------------- -------------------- --------- ----------- -------- --------
7mb45hj1u38dk 1 SELECT * FROM DBA_EX 02-MAY-12 16777227 06:56:48 06:56:52
TENTS ORDER BY OWNER
, SEGMENT_NAME , PA
RTITION_NAME
5f4b3676kpnh3 1 SELECT * FROM DBA_OB 02-MAY-12 16777229 06:56:53 06:56:53
JECTS ORDER BY OWNER
, OBJECT_TYPE , OBJ
ECT_NAME
7mb45hj1u38dk 1 SELECT * FROM DBA_EX 02-MAY-12 16777228 06:56:54 06:56:58
TENTS ORDER BY OWNER
, SEGMENT_NAME , PA
RTITION_NAME
7mb45hj1u38dk 1 SELECT * FROM DBA_EX 02-MAY-12 16777229 06:56:59 06:57:03
TENTS ORDER BY OWNER
, SEGMENT_NAME , PA
RTITION_NAME
5f4b3676kpnh3 1 SELECT * FROM DBA_OB 02-MAY-12 16777231 06:57:04 06:57:04
JECTS ORDER BY OWNER
, OBJECT_TYPE , OBJ
ECT_NAME
7mb45hj1u38dk 1 SELECT * FROM DBA_EX 02-MAY-12 16777230 06:57:05 06:57:09
TENTS ORDER BY OWNER
, SEGMENT_NAME , PA
RTITION_NAME
7mb45hj1u38dk 1 SELECT * FROM DBA_EX 02-MAY-12 16777231 06:57:10 06:57:14
TENTS ORDER BY OWNER
, SEGMENT_NAME , PA
RTITION_NAME
5f4b3676kpnh3 1 SELECT * FROM DBA_OB 02-MAY-12 16777233 06:57:15 06:57:15
JECTS ORDER BY OWNER
, OBJECT_TYPE , OBJ
ECT_NAME
From the above we can see that the query against DBA_EXTENTS used up most of the time and that all 5 executions of it appeared in Active Session History. The query against DBA_OBJECTS shows up 3 times while the query against DBA_USERS doesn’t even appear once. This illustrates rather nicely the fact that the Active Session History details are sample based; if a query happens to be running when a sample is taken then its details get recorded, if not then it will not appear and you may not even be aware that it has been run.
So, what are the drawbacks to Active Session History? From a process monitoring perspective it is important to realise that Oracle records details of what a session is doing as at the point it takes the sample, as illustrated in the previous example. So, if in the one second since the previous sample your process has run half a dozen SQL statements then only the one that was being executed at the moment the sample was taken will be picked up. This means that for fast OLTP-type processes it is unlikely that you will obtain details of every statement issued by your process. If you require an in-depth analysis of what your process is doing then obtaining an SQL Trace might be the way to go… but this will have to be set-up prior to the execution of your process.
Probably the bigger drawback for Active Session History is that it requires the Oracle Diagnostics Pack license, which is only available for Enterprise Edition of the database. If you are using Standard Edition or Express Edition then Active Session History simply isn’t available to you.
Mark Hoxey 