Oracle Session Tracing

Oracle Session Tracing James Koopmann, [email protected]

This is the first in a series introducing some of the new tracing concepts and options within Oracle. This installment focuses on the new CLIENT_IDENTIFIER environment variable that can be assigned to sessions. The goal of this series is to inform DBAs on how to track and trace connected sessions so that they can properly determine where sessions are experiencing performance problems. This article presents the very important concept of assigning a client identifier to a session. This client identifier will be used in future articles, as this will be one way to initiate traces. This article first presents the issue of why we should use the client identifier and then how we can utilize it when looking at sessions as they are connected in real time. To begin, we must first come to grips with the simple concept of the globalization of sessions within Oracle that occurs. The days of single dedicated server connections and one connection uniquely identifying a single user are long gone. Now many middle-tier applications make use of pooling mechanisms that hide the identity of a connected user or session that does not allow you or me to adequately track and trace effectively because of the reuse of session ids. This is where you need to start thinking of defining your own client identifier for the users that use your database systems. This is just what Oracle now has and using a client identifier allows you to either further segregate or consolidate sessions by assigning an identifier that describes the connection for a particular user or set of users. For example, suppose you have a development environment where everyone logs in as a particular schema user and because of the connection mechanisms employed, users will reuse the same session id sometimes when they connect. Well, if you ever wanted to trace these sessions to determine who was consuming vast amounts of resources or was issuing particular SQL, you would be very hard pressed to run a trace and filter for that user since the high activity would not guarantee any one user was on a particular session id. This is where you could employ the use of a client identifier since Oracle now lets us trace and report on a unique client identifier. To get this going all you need to do is invoke the DBMS_SESSION.SET_IDENTIFIER procedure when the session logs in. Figure 1 gives a very simplistic method through a logon trigger, to set the client identifier. You can use anything to distinguish the session, such as IP address, computer / host name, o/s user, or a predefined application name. I have made use of the DBMS_CONTXT calls for user environment information. Figure 1 Logon trigger to set client_identifier

CREATE OR REPLACE TRIGGER LOGON_TRIGGER AFTER LOGON ON DATABASE DECLARE v_user_identifier varchar2(64); BEGIN SELECT SYS_CONTEXT('USERENV', 'OS_USER') ||':'|| SYS_CONTEXT('USERENV', 'IP_ADDRESS') INTO v_user_identifier

FROM dual; DBMS_SESSION.SET_IDENTIFIER(v_user_identifier); END; /

Now when we look at the V$SESSION view, we can see this CLIENT_IDENTIFIER set for various sessions. Listing 1 gives this type of output. Now, if we had the same database user connect through some polling mechanism, and if we set our client identifier properly, we have the potential to see a different client identifier. In addition, if we want to set the same client identifier for a group of users, we could do that also. There are also methods of setting the client identifier from within OCI and JDBC. Listing 1 V$SESSION output

1 SELECT sid, client_identifier, 2 service_name, action, module 3* FROM V$SESSION SID ---------145 146 147 156

CLIENT_IDENTIFIER -------------------jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1

SERVICE_NAME ACTION ------------- -----------k101 k101 k101 k101

MODULE ----------msqry32.exe mmc.exe SQL*Plus slplus.exe

We will get to actually tracing in a future article, but the columns supplied in the SQL select statement in Listing 1 allow for filtering of trace statistics. I hope that you can see that by setting a client identifier, we have just added great power in determining the unknown users of our database. Through extra tracing options, we can now determine whom and what is causing problems in our database. Also, note that because this field can be changed at will, there is nothing to limit you to keeping the same CLIENT_IDENTIFIER for the life of the session. This may come in handy if your session actually performs different tasks that distinguish it from other sessions that originally had the same identifier. After setting this client identifier, we have already seen that you may view this setting by a query to the V$SESSION view. You may can also see the statistics around a particular CLIENT_IDENTIFIER from the V$ACTIVE_SESSION_HISTORY view. Listing 2 gives a query that we would typically issue to see the historical wait activity for sessions in the last 30 minutes. Notice that we have the same client identifier (CLIENT_ID) for each of the rows displayed. This is fine if you are concerned with only tracking down one session that might be experiencing high wait times but sometimes you are concerned aboutthe accumulated wait time that is caused by an application. To answer that question, we can group on the CLIENT_ID column now to get a summation for a particular client identifier. This does assume you have set your client identifier to something more than what I have set mine to, and that it is set to something in line with the application area of interest. Listing 3 shows just such a query you might issue to sum total waits for an application area or in my case user connections across multiple sessions. Listing 2 Looking at individual session wait activity

select session_id, client_id, event,

from where group order

sum(wait_time + time_waited) ttl_wait_time v$active_session_history active_session_history sample_time between sysdate - 60/2880 and sysdate by session_id, client_id, event by 2;

SESSION_ID ---------145 145 145 145 145 156 160 160 160 160

CLIENT_ID -------------------jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1

EVENT TTL_WAIT_TIME ------------------------------ ------------SQL*Net message to client 3 db file scattered read 111167 db file sequential read 59003 direct path read temp 93314 direct path write temp 2 SQL*Net message from client 243192681 db file scattered read 18657 db file sequential read 28141 direct path read temp 4887 direct path write temp 24

Listing 3 Accumulated wait activity for an application area or user defined area

select client_id, event, sum(wait_time + time_waited) ttl_wait_time from v$active_session_history active_session_history where sample_time between sysdate - 60/2880 and sysdate group by client_id, event order by 1; CLIENT_ID -------------------jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1 jkoopmann:127.0.0.1

EVENT TTL_WAIT_TIME ------------------------------ ------------SQL*Net message from client 243192681 SQL*Net message to client 3 db file scattered read 129824 db file sequential read 115553 direct path read temp 98201 direct path write temp 26

In addition, if you ever find yourself wanting to know what your CLIENT_IDENTIFIER is set to, so that you can monitor or take some form of logical action within an application, you need only issue the following SQL. SELECT SYS_CONTEXT('USERENV','CLIENT_IDENTIFIER') CLIENT_IDENTIFIER FROM DUAL; CLIENT_IDENTIFIER ------------------jkoopmann:127.0.0.1 If you ever wish to clear out the CLIENT_IDENTIFIER for a session, you need only execute the following procedure.

DBMS_SESSION.CLEAR_IDENTIFIER The use of a CLIENT_IDENTIFIER can come in handy for many situations where monitoring individual sessions or a group of sessions is required. It does not matter if those sessions connect to the same session id or different ones. If you choose your client identifier properly for groups of applications or users, you can generate true wait related information that tells you exactly what they have been doing. Stay tuned for more session tracing in the next part of this series.

We invoked a logon trigger whenever a session connected and then queried the V$SESSION view. This gave us output similar to that of Listing 1. From this output, you can see a CLIENT_IDENTIFIER that is being set. I changed the logon trigger to put in the host name instead of the IP address in this example, and you can see that the module name did get populated for the applications I used to connect from (SQL*Plus and Oracle Administrative Assistant). Also, note that the action field is blank. Also notice that the there are two connections using SQL*Plus from host FINE-ALE and one connection from host PAULANER.

Listing 1 V$SESSION output SQL> SELECT sid, client_identifier, action, module FROM V$SESSION SID CLIENT_IDENTIFIER ACTION MODULE ---- ----------------------------------------- ------------------------------------133 James?F.?Koopmann:PINEHORSE\FINE-ALE SQL*Plus 135 James?F.?Koopmann:PINEHORSE\FINE-ALE mmc.exe 149 James?F.?Koopmann:PINEHORSE\FINE-ALE SQL*Plus 132 PAULANER\Administrator:PINEHORSE\PAULANER SQL*Plus

The setting of the CLIENT_IDENTIFIER was of great importance but if we want to get finer granularity on the actual amount of resources that are being consumed within certain modules of code or within certain business units of work, we need to look at the DBMS_APPLICATION_INFO package provided by Oracle. Most applications will give some form of module name when you see connections coming across but will leave the ACTION name unset. The setting of a module name is fine for some circumstances. However, to get a real indication of where in the code resources are being done, both fields should be considered when writing applications. This naming will allow you as a DBA or developer the ability to track down unique connections that you are concerned with in real-time or for latter tracing runs. This granularity is highly desirable when debugging a performance bottleneck and you will want to pin point which application module is consuming the most resources through the MODULE name and what is being done (ACTION) within the code. To do this, it is imperative, that the applications set the name of the module and the action being performed each and every time it enters a new module or the action of the transaction changes. The module name could be the section of code or procedure being executed, while the action could be a business unit of work or an individual statement. The purpose is to be able to tie resources used to a unit of work about which you are concerned.

Calling the DBMS_APPLICATION_INFO Package Using the DBMS_APPLICATION_INFO package is quite straightforward. A simple call to SET_ACTION is all that is required to set the ACTION name. This call has the form of: DBMS_APPLICATION_INFO.SET_ACTION (action_name IN VARCHAR2);

Therefore, if you wanted to set the ACTION to 'LOGON TRIGGER' you could construct the call as: DBMS_APPLICATION_INFO.SET_ACTION('LOGON TRIGGER'); This action name should be very descriptive of the type of action being done within the code and it is always best to set this before the actual action is performed. That way when the action is being performed you will see the ACTION in the V$SESSION view and know that it is currently being done. When the transaction or specific action is complete within your code you should set it back to NULL or to the next action to be performed. This setting to NULL or a valid next transaction type is very important. If you do not adhere to this pattern, future resources will be attributed to the last ACTION and you will lose any true performance statistics. The setting of the MODULE name is done through a call to the SET_MODULE procedure and has the form of: DBMS_APPLICATION_INFO.SET_MODULE(

module_name IN VARCHAR2, action_name IN VARCHAR2);

All of the suggestions around setting the ACTION apply to setting the MODULE name as well. When setting this naming field, you want to set it before the actual execution within the code is started and you want to make sure to set the MODULE back to NULL or to the next MODULE to be executed so as to not miss-represent any statistics encountered after the true execution of the code is complete. As you might have recognized, this SET_MODULE procedure allows for the setting of the ACTION name also. You should use this to set your MODULE and ACTION name when first entering a new module of code but use the SET_ACTION procedure after, in the module. This will limit some of the overhead of setting these names, as I am sure there is some miniscule locking going on behind the scenes. Therefore, for our logon trigger if I wanted to set the actual MODULE and ACTION names it would look like the example in Figure 1. You should note that this is quite an extreme example of setting these session variables but I wanted to give you a flavor for how to do this. Notice that the MODULE name was set to 'LOGON_TRIGGER' and the ACTION is to indicate a SELECT from DUAL. Also, note that at the end of the trigger we set the MODULE and ACTION back to NULL so that we are certain not to mess up statistical collection. In addition, please note that I have put in a call to the DBMS_LOCK package to sleep so that I could see this setting of the MODULE and ACTION names. Figure 1 Logon trigger to set client_identifier, module, and action CREATE OR REPLACE TRIGGER LOGON_TRIGGER AFTER LOGON ON DATABASE DECLARE v_user_identifier varchar2(64); BEGIN

DBMS_APPLICATION_INFO.SET_MODULE( module_name => 'LOGON_TRIGGER', action_name => 'SELECT FROM DUAL'); SELECT SYS_CONTEXT('USERENV', 'OS_USER') ||':'|| SYS_CONTEXT('USERENV', 'HOST') INTO v_user_identifier FROM dual; DBMS_SESSION.SET_IDENTIFIER(v_user_identifier); dbms_lock.sleep(5); DBMS_APPLICATION_INFO.SET_MODULE(NULL,NULL); END; / Now when we query the V$SESSION view we can see the setting of these variables through Listing 2. After the DBMS_LOCK.SLEEP call is complete, the MODULE name returns to 'SQL*Plus' and the ACTION is NULL. I think this is a function of just using SQL*Plus and you should not rely on Oracle setting these back to the original call. Listing 2 V$SESSION output after setting MODULE and ACTION names SQL> SELECT sid, client_identifier, action, module FROM V$SESSION SID CLIENT_IDENTIFIER ACTION MODULE ---- ----------------------------------------- ------------------------------------133 James?F.?Koopmann:PINEHORSE\FINE-ALE SELECT FROM DUAL LOGON_TRIGGER 135 James?F.?Koopmann:PINEHORSE\FINE-ALE mmc.exe 149 James?F.?Koopmann:PINEHORSE\FINE-ALE SQL*Plus 132 PAULANER\Administrator:PINEHORSE\PAULANER SQL*Plus

Proper setting of the ACTION and MODULE name are imperative for collecting statistics around specific code functions and transactions. Once they are set you can begin getting those fine grain details about the area of code that is performing poorly. Next time we will begin looking at how to pull that fine grain information out of current sessions, to zero in on where we need to concentrate our tuning efforts. Explore how to enable and disable Oracle tracing with DBMS_MONITOR package in 10g. • •

We learned how to set the CLIENT_IDENTIFIER session variable to more accurately pinpoint resource consumption for an individual user or group of users. We did this through queries to real-time activity views such as V$SESSION and V$ACTIVE_SESSION_HISTORY. We have also learned how to set the ACTION and MODULE name so that we could track where in our code transactions where being executed and track the use of resources by transaction type or section of code.

Along with these possibly new session identifiers, there have always been three session environment variables, set from when a user connects to the database, that are important when talking about tracing a particular session or group of sessions. These variables are the SID, SERIAL#, and SERVICE_NAME. These variables have been around Oracle sessions for quite some time and are presented in Table 1, along with the three new variables presented in Parts I & II of this series, to

provide for a quick refresher. This set of six session variables now gives us the ability to activate tracing for the session in a variety of ways. Table 1

Session Variable SID SERIAL# SERVICE_NAME MODULE ACTION CLIENT_IDENTIFIER

Description Identifier for the connected session. Serial number of the connected. Service name of the session and represents the database connected to. Name to represent the module or code being executed. Name to represent the action being performed by the module. Identifier to represent the client session

DBMS_MONITOR Package In Oracle 10g, we have been given the DBMS_MONITOR package. This package allows us to interact and control the tracing and statistics gathering of sessions through a PL/SQL interface. Table 2 gives all of the programs we can call through the DBMS_MONITOR package. As you can see, our six variables are represented for us to begin tracing through. Table 3 gives a quick reference guide to the available programs within the DBMS_MONITOR package and how you might enable these traces. Table 2

Program

Description

CLIENT_ID_STAT_ENABLE

Enable / Disable

CLIENT_ID_STAT_DISABLE

Notes •

Statistics can be seen through V$CLIENT_STATS.

•

Trace data may be written to many trace files as the trace may effect multiple connected sessions with the same client identifier.

•

Statistics can be seen through V$SERV_MOD_ACT_STATS.

•

Trace data may be written to many trace files as the trace may effect multiple connected sessions.

Statistics gathering for a given Client Identifier

CLIENT_ID_TRACE_ENABLE CLIENT_ID_TRACE_DISABLE

Enable / Disable Tracing for a given Client Identifier

SERV_MOD_ACT_STAT_ENABLE SERV_MOD_ACT_STAT_DISABLE

Enable / Disable Statistics gathering for (Service Name/MODULE/ACTION) combination.

SERV_MOD_ACT_TRACE_ENABLE Enable / Disable SERV_MOD_ACT_TRACE_DISABLE

Tracing for (Service Name/MODULE/ACTION) combination.

Program

Description

SESSION_TRACE_ENABLE

Enable / Disable

SESSION_TRACE_EISABLE

Tracing for a session identifier (SID)

Notes • •

Session must exist Traces only a given session

•

Enables / Disables a trace for the instance submitter is connected to.

Program

Example How to Enable

CLIENT_ID_STAT_ENABLE

DBMS_MONITOR.CLIENT_ID_STAT_ENABLE

CLIENT_ID_STAT_DISABLE

(client_identifier);

CLIENT_ID_TRACE_ENABLE

DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE(client_id, waits, binds);

CLIENT_ID_TRACE_DISABLE

(Notes) waits : If TRUE, wait information is present in the trace. Binds : If TRUE, bind information is present in the trace. SERV_MOD_ACT_STAT_ENABLE SERV_MOD_ACT_STAT_DISABLE

DBMS_MONITOR.SERV_MOD_ACT_STAT_ENABLE (service_name, module_name, action_name); (Notes) Action_name, may be an empty field if not defined for the session. • • •

To reference ALL sessions that have an action_name defined, use the DBMS_MONITOR.ALL_ACTIONS variable. To reference ALL sessions that do not have this variable defined, use NULL. The contents of this field is actually '###ALL_ACTIONS' and you should avoid naming any actions or module names with this.

Program

Example How to Enable

DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE (service_name, module_name, action_name, SERV_MOD_ACT_TRACE_DISABLE waits, binds, instance_name); SERV_MOD_ACT_TRACE_ENABLE

(Notes) Action_name, may be an empty field if not defined for the session. • • •

To reference ALL sessions that have an action_name defined, use the DBMS_MONITOR.ALL_ACTIONS variable. To reference ALL sessions that do not have this variable defined, use NULL. The contents of this field is actually '###ALL_ACTIONS' and you should avoid naming any actions or module names with this.

waits : If TRUE, wait information is present in the trace. Binds : If TRUE, bind information is present in the trace. instance_name restricts tracing to the named instance_name.

SESSION_TRACE_ENABLE SESSION_TRACE_DISABLE

DBMS_MONITOR.SESSION_TRACE_ENABLE (session_id, serial_number, waits, binds) (Notes) session_id, Must provide. If just a session_id is given than all serial numbers will be traced. If session_id and serial_number are NULL than you trace your own current session. waits : If TRUE, wait information is present in the trace. Binds : If TRUE, bind information is present in the trace.

Examples to Enable / Disable Tracing Before you can enable or disable tracing you need to first determine the connected session or group of sessions you would like to trace. If you have set the CLIENT_IDENTIFIER, MODULE_NAME, or ACTION_NAME as prescribed in the previous parts to this series you do not necessarily need to look for them, as you should have a list that describes their actions. Although sometimes you are tuning in a more adhoc environment where you are only concerned with what is affecting your system currently. This could be an individual session or a group of sessions that will be defined by their CLIENT_IDENTIFIER, MODULE_NAME, ACTION_NAME, or SERVICE_NAME. To get a feel for what is executing currently on your system you need only query the V$SESSION view. Listing 1 gives the SQL and results of what you might see. Listing 1

1

SELECT sid, serial#, client_identifier, service_name, action, module FROM V$SESSION

SID SERIAL# CLIENT_IDENTIFIER SERVICE_NAME ACTION MODULE ---------- ------- -------------------- ------------- ------------ -----------

145 34 george:127.0.0.1 ACCT INSERT MONTH PAYROLL 146 32 johnny:127.0.0.2 ACCT CANCEL CHECK BILLPAY 147 54 suzy:127.0.0.3 HR MODVACATION 156 64 lisa:127.0.0.4 HR INSERT HIST ADDEMPLOYEE 1. Enable statistics gathering for CLIENT_IDENTIFIER webclient. EXECUTE DBMS_MONITOR.CLIENT_ID_STAT_ENABLE('WEBCLIENT');

2. Enable tracing for CLIENT_IDENTIFIER johnny:127.0.0.2 with wait information but no bind information EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE('johnny:127:0.0.2',TRUE,FALSE); 3. Enable statistics gathering for service_name ACCT, module PAYROLL, and all actions EXECUTE DBMS_MONITOR.SERV_MOD_ACT_STAT_ENABLE('ACCT','PAYROLL',DBMS_MONITOR.ALL_ACTIONS);

4. Enable tracing for servide_name HR but only for the ADDEMPLOYEE module and include wait and bind information. EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE('HR', 'ADDEMPLOYEE', DBMS_MONITOR.ALL_ACTIONS,TRUE,TRUE,NULL); 5. Enable tracing for session id 142 and include wait and bind information EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE(145,34, TRUE, TRUE); 6. Trace my current session EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE(NULL,NULL, TRUE, TRUE);

View your Enabled Tracing To look at what you have enabled tracing and statistics gathering for you need only look at the two views DBA_ENABLED_TRACES and DBA_ENABLED_AGGREGATIONS. Listing 2 gives the output from selecting from these two views for our examples. Notice that the examples 5 & 6 where we started a trace for the sessions did not show up in Listing 2. These must still be recognized by going to the user dump location on disk and looking for the trace files generated. Listing 2

SQL> select * from DBA_ENABLED_TRACES ; TRACE_TYPE INSTANCE_NAME -----------------------------------CLIENT_ID SERVICE_MODULE

SERVICE

MODULE

ACTION

WAITS BINDS

-------------------- ------------- ---------- ----- ----johnny:127:0.0.2 HR

ADDEMPLOYEE

TRUE TRUE

SQL> SELECT * FROM DBA_ENABLED_AGGREGATIONS ; AGGREGATION

SERVICE

MODULE

ACTION

FALSE TRUE

-------------------- -------------------- -------------------- -------------------CLIENT_ID webclient SERVICE_MODULE ACCT PAYROLL

Enabling and disabling tracing and statistical gathering has taken on a whole new meaning in Oracle 10g. It has become easier to enable and manage with the DBMS_MONITOR package. We are not strapped by the old methods of tracing, where we could just trace an individual session, but can now trace across sessions by using the CLIENT_IDENTIFIER, SERVICE_NAME, MODULE_NAME, and ACTION_NAME. Next time we will look at where some of the actual tracing information resides and how to query from internal tables in Oracle. Table 1 gives a breakdown of the DBA_ENABLED_AGGREGATIONS view as I have renamed some of the columns for Listing 1. Listing 1 DBA_ENABLED_AGGREGATIONS

SQL> SELECT * FROM DBA_ENABLED_AGGREGATIONS ; AGGREGATION SERVICE MODULE ACTION -------------------- -------------------- -------------------- -------------------CLIENT_ID webclient SERVICE_MODULE

ACCT

PAYROLL

Table 1 DBA_ENABLED_AGGREGATIONS

Column

Description

AGGREGATION_TYPE This is the type of statistical aggregation being done. This relates to the actual procedure called in the DBMS_MONITOR package. In Listing 1, we have called the CLIENT_ID_STAT_ENABLE and SERV_MOD_ACT_STAT_ENABLE procedures

PRIMARY_ID

This is the CLIENT_IDENTIFIER or SERVICE_NAME in the call

QUALIFIER_ID1

The module name

QUALIFIER_ID2

The action name

In the last three parts of this series, we have also zeroed in on setting different session environment variables. Those variables were CLIENT_IDENTIFIER, ACTION, and MODULE. We have also tracked some of the sessions by SID, SESSION_ID, SERVICE_NAME, and SERIAL#. I thought it might be interesting to look at where within Oracle's internal views these columns might be defined since this could help us in future needs of our investigation. Instead of searching through the endless documentation of Oracle, I instead decided to produce a query (Listing 2) in which I queried the DBA_TAB_COLUMNS view to look at what internal Oracle views or objects have these columns in common. From the output, I can then look at the definitions of those named objects that intrigue me. Listing 2 is only a partial listing and I encourage you to execute the query and see the total output. That way if you are ever interested in searching for a single column or combination of columns you will know where within the Oracle internal views this information is stored. Do not take this output too lightly. If you remember that we were enabling statistics gathering and tracing in the previous parts to this article for combinations of these columns, you can quickly see where in this listing the information is kept and where aggregates on columns are stored. Also, be warned that most of the output you will see are for Oracle's workload repository, advisories, and snapshots mechanisms and are not of any real use unless you are using those utilities. For us I have only left the objects we will be concerned

with for looking at the gathered statistics we have enabled. Table 2 gives a brief explanation of these views, how you might use them, and some things to look out for. Listing 2 Query to investigate Oracle Views that contain our statistical information

select table_name ,sum(decode(column_name,'SID',1,'SESSION_ID',1,0)) SID ,sum(decode(column_name,'CLIENT_ID',1,'CLIENT_IDENTIFIER',1,0)) CLIENT_ID ,sum(decode(column_name,'SERVICE_NAME',1,0)) SERVICE_NAME ,sum(decode(column_name,'ACTION',1,0)) ACTION ,sum(decode(column_name,'MODULE',1,0)) MODULE ,sum(decode(column_name,'SERIAL#',1,0)) SERIAL# from (select owner,table_name,column_name from dba_tab_columns where owner = 'SYS' and column_name in ('SID', 'SESSION_ID', 'CLIENT_ID', 'CLIENT_IDENTIFIER', 'SERVICE_NAME', 'ACTION', 'MODULE', 'SERIAL#')) group by table_name order by table_name / CLIENT SERVICE TABLE_NAME SID ID NAME ACTION MODULE SERIAL# ------------------------------ --- ------ ------- ------ ------ ------DBA_HIST_ACTIVE_SESS_HISTORY 1 1 0 1 1 0 V_$ACTIVE_SESSION_HISTORY 1 1 0 1 1 0 V_$CLIENT_STATS 0 1 0 0 0 0 V_$SERVICE_STATS 0 0 1 0 0 0 V_$SERV_MOD_ACT_STATS 0 0 1 1 1 0 Table 2

Table V_$ACTIVE_SESSION_HISTORY

Description • The V$ACTIVE_SESSION_HISTORY view is a holding area for sampled session data performed on your behalf from the Oracle engine. This data is sampled once per second and is a great resource for determining where the true bottleneck lies in your system. • Use this view in conjunction with setting the CLIENT_IDENTIFIER, ACTION, and MODULE to aggregate (GROUP BY) and find the largest consumers of resources within your system. •

DBA_HIST_ACTIVE_SESS_HISTORY

•

V_$CLIENT_STATS

• •

•

Take a look at another article I wrote entitled "True Session Wait Activity in Oracle 10g" for how to use this view. This view is just an historical representation of the V$ACTIVE_SESSION_HISTORY view above. While it is good for some historical information, be warned that it does not contain all of the collected statistics that were captured in the V$ACTIVE_SESSION_HISTORY view. Please read the above-mentioned article to get an understanding of how this works. If you have enabled any statistics for a CLIENT_IDENTIFIER you will see the aggregated statistics for that CLIENT_IDENTIFIER that are currently active in this view. These statistics are only good for current activity and troubleshooting and thus should only be used for getting a glimpse of what clients are consuming the most resources. Very valuable for a quick current view but if you need to drill to a particular client you will end up going to V$ACTIVE_SESSION_HISTORY.

V_$SERVICE_STATS

V_$SERV_MOD_ACT_STATS

•

Provides a reduced set of statistics that can be used to determine how well an instance is performing for the requests made upon it.

•

This is typically the SID_NAME but be aware it may be different if you are not connecting through TNS. This view provides an aggregated view for the combination of SERVICE_NAME, MODULE, and ACTION you defined when you enabled aggregated statistics.

•

Just be careful to name these aggregates appropriately so that you can quickly determine where bottlenecks reside.

The use of these views is quite straightforward. You need only query them for the statistical aggregation you have set up through the DBMS_MONITOR package. The real difficulty lies in setting up those aggregations stepped through in earlier parts of this series. Next time we will get into the new reporting options available for traces in Oracle 10g. Part five in our series will get closer to what we have, for years, experienced as Oracle's tracing mechanism. Read On and get re-acquainted with creating trace files for TKPROF. For many years, DBAs have been getting low level tracing information about sessions through the creating and reading of Oracle generated trace files. These trace files can be generated against a full system load or individual sessions. The types of information generated by these traces in Table 1 clearly show why they have been used for many years. There just was not an easy way to get this information from within Oracle's internal views. While Oracle 10g has provided quite a few mechanisms to trace the session by querying internal views, the generation of trace files is still around and still quite viable. In addition, Oracle 10g allows us to generate trace files and analyze them with added functionality. This article will focus on how we can generate trace files in Oracle 10g. Table 1 Laundry list of information gathered by tracing • • • • • • • • • • • •

SQL Statements Explain Plans Parse, execute, and fetch counts CPU and elapsed times Physical reads and logical reads Number of rows processed Misses on the library cache Username under which each parse occurred Each commit and rollback Wait event data Row operations logical, physical and elapsed times I/O types

Creating a Trace

Old Method It used to be that if you wanted to create a trace file you had to enable it at the session level using the DBM_SESSION.SQL_TRACE procedure or through the ALTER SESSION SET SQL_TRACE

command. While these accomplished the task, we will quickly see they are very limited in scope compared with the new method. Not only are they limited in scope, their usage is quite limited. In order to use these two statements you need to issue them from the connected session. That means that if you wanted to generate a trace file, your application would need to be modified to issue these commands. Many programmers got around this by reading a control structure during execution to see if they should turn on trace. Moreover, if someone wanted to trace an application he would just flip a flag in the control structure. Below are two examples, just in case you wish to try these methods or have a need. SQL> exec dbms_session.set_sql_trace(true); SQL> ALTER SESSION SET SQL_TRACE = TRUE;

New Method Using DBMS_MONITOR Package to generate trace files In Part III of this series, we discussed how to generate trace files with the DBMS_MONITOR package. Revisit Table 2 and look at the procedure calls required to generate a trace file. Be sure to look at the description box and example given as it signifies the method you can trace against (by CLIENT_IDENTIFIER, SERVICE_NAME, MODULE, ACTION or SID). In Oracle 10g, we have been given the DBMS_MONITOR package. This package allows us to interact and control the tracing and statistics gathering of sessions through a PL/SQL interface, which I think, is much easier than the old method of DBMS_SESSION and ALTER SESSION commands. In addition, these methods in table 2 give you more flexibility against what you can trace. You are now able to do fine grain or group tracing across sessions giving you, the DBA, much needed control. Also, remember from Part III that there is the audit ability of the tracing through the Oracle DBA_ENABLED_TRACES view to show you what tracing you have enabled. These new methods also give the DBA the ability to enable trace for sessions and those applications do not need to issue the command themselves.

Table 2 Click for full table

Where is my trace file When you enable traces, Oracle dumps this information out to a system file in a destination on disk referred to as USER_DUMP_DEST. This is an actual parameter within Oracle and you will need to know what it is set to if you ever want to view the contents of the trace file you just generated. There are a couple of ways that you can determine this parameter given below. SQL > show parameter user_dump_dest SQL > select value from v$parameter where name = 'user_dump_dest';

When you go searching for your trace file in the USER_DUMP_DEST area you may quickly find that it is loaded with other users' trace files. To make matters worse Oracle generates a somewhat cryptic name for your trace files that makes it somewhat hard for you to find them. You can modify the name of the trace file by adding a TRACEFILE_IDENTIFIER to it. You can do this by an ALTER SESSION command such as what is below. SQL > alter session set TRACEFILE_IDENTIFIER = 'something_here';

While we can get a lot of real-time session information through Oracle internal views, the Oracle trace is still a valuable tool for extracting statistics for a single session or across a grouping of sessions by the added functionality given through the DBMS_MONITOR package. After generating trace files, we can now use the TKPROF or new Oracle 10g trcsess utility to extract and read the collected information in a readable form. However, that is reserved for the next and final article of this series. Part VI in our series will show you how to access and generate reports off of the trace files we generated in Part V through the use of the TKPROF and trcsess utilities. In the last part of this series, we re-visited methods on how to generate trace files. These trace files that were generated were in a raw format that does not allow us to read them very easily. This article will be the last in this series and will show how to take these generated trace files and produce reports in a more readable form.

What does a trace file look like In Part IV of this series, we discussed how to find where your trace files are generated . These are typically stored in the $ORACLE_BASE/SID/udump directory of the database server. Listing 1 gives the top end of a trace file that I generated so that you could get a flavor, if you have never seen a trace file before. Through out this series we have zeroed in on setting and monitoring the SESSION_ID, CLIENT_IDENTIFIER, SERVICE_NAME, MODULE_NAME, and ACTION_NAME environment variables. At the bottom of this abbreviated trace file listing (Listing 1), you can see exactly how Oracle now stores this in each and every trace file. Note that you can change these environment variables throughout an application and these output lines may be scattered throughout a trace file. In addition, I have explicitly defined each of these client variables through my application. If they were not set, you would end up with an empty string for those variables. If we were to set these variables religiously, you can see how easy it is to issue a Unix GREP command or Windows FIND command to give you all of the trace files generated by a particular user, in a particular module, or performing a certain type of task. Listing 1 Top part of a trace file *** TRACE DUMP CONTINUED FROM FILE *** Dump file c:\oracle\admin\lager\udump\lager_ora_2100_jfk.trc Tue Jan 25 09:48:56 2005 ORACLE V10.1.0.2.0 - Production vsnsta=0 vsnsql=13 vsnxtr=3 Oracle Database 10g Enterprise Edition Release 10.1.0.2.0 - Production With the Partitioning, OLAP and Data Mining options Windows 2000 Version V5.0 Service Pack 4 CPU : 1 - type 586 Process Affinity: 0x00000000

Memory (A/P) : PH:19M/509M, PG:633M/1247M, VA:1752M/2047M Instance name: lager Redo thread mounted by this instance: 1 Oracle process number: 19 Windows thread id: 2100, image: ORACLE.EXE (SHAD) *** *** *** *** *** ***

2005-01-25 09:48:56.875 ACTION NAME:(ADD) 2005-01-25 09:48:56.859 MODULE NAME:(EMP_MAINT) 2005-01-25 09:48:56.859 SERVICE NAME:(SYS$USERS) 2005-01-25 09:48:56.859 CLIENT ID:( James?F.?Koopmann:PINEHORSE\FINE-ALE) 2005-01-25 09:48:56.859 SESSION ID:(148.12) 2005-01-25 09:48:56.859

What is the trcsess Utility After you have determined which trace files include the particular combinations of SID, CLIENT_IDENTIFIER, SERVICE_NAME, ACTION_NAM, or MODULE_NAME variables, you need to be able to pull all of the information together for analysis. The trcsess utility is a java app that is executed through the command line of your O/S and will consolidate trace information in multiple trace files for the information across these SID, CLIENT_IDENTIFIER, SERVICE_NAME, ACTION_NAME, and MODULE_NAME variables. Not to worry about invoking java, Oracle has provided a shell script for your particular operating system that can be executed instead. The output of the trcsess utility is a single file that can be the input into the TKPROF reporting utility. This is of great importance for finding true bottlenecks or an application that is consuming large amounts of resources. It would be nearly impossible to tally all of the trace files for all of the individual times an application or user accessed the database without this utility. In addition, if we set ACTION_NAME and MODULE_NAME properly, it gives us the ability to pick the statistics generated around a certain application or statement type across trace files, out of that trace file. In addition, if you are in a connection polling environment where the user's session is never the same, this utility gives you the ability to zero in and pick out that user easily from all the trace files generated during the performance tuning time slice you are interested in and giving you a true look into the user's session. Listing 2 gives the syntax for the new trcsess utility and a simple example. Listing 2 Syntax & Example for trcsess trcsess [output = output_file_name] [session = session_Id] [clientid = client_Id] [service = service_name] [action = action_name] [module = module_name] [trace_files] Example: Consolidate all trace files for everyone that has been in the Employee Maintenance Module (EMP_MAINT).

SQL > trcsess output=emp_maint.trc module=EMP_MAINT *.trc

What Can TKPROF Do Up to this point, we have just generated trace files and consolidated trace files based on a search criterion through the trcsess utility. As stated before, you can edit these trace files and read them by hand but they do tend to be cryptic. Oracle provides us with a reporting mechanism on these trace files in the form of the TKPROF utility. This utility provides for the following mechanisms. Listing 3 also gives the syntax and example on running the TKPROF utility. 1. Formats all the cryptic information in a more readable form that is understandable for you and me. 2. Breaks out each statement executed during the trace period and presents various statistics that enable us to determine where bottlenecks lay and where we might spend our time tuning application code. 3. Can generate a SQL script that allows us to store the captured statistics into a database. 4. Will determine the explain plan for executed SQL statements. 5. Provides for summary as well as detail information for collected statistics Listing 3 Syntax & Example for TKPROF tkprof trace_file [waits [sort [print [aggregate [insert [sys [table [explain [record [width

report_file = yes|no] = option] = n] = yes|no] = filename3] = yes|no] = schema.table] = user/password] = filename4] = n]

Example: Produce report for all users within the Employee Maintenance Module (EMP_MAINT). SQL > tkprof emp_maint.trc emp_maint.rpt Sample Output: TKPROF: Release 10.1.0.2.0 - Production on Tue Jan 25 10:34:27 2005 Copyright (c) 1982, 2004, Oracle.

All rights reserved.

Trace file: emp_maint.trc Sort options: default *************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing

elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call *************************************************************************** UPDATE emp SET salary = 350000 WHERE empid = 101 call count ------- -----Parse 2 Execute 2 Fetch 0 ------- -----total 4

cpu elapsed disk query current -------- ---------- ---------- ---------- ---------0.00 0.04 0 1 0 0.00 0.01 0 14 6 0.00 0.00 0 0 0 -------- ---------- ---------- ---------- ---------0.00 0.05 0 15 6

rows ---------0 2 0 ---------2

Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 77 Rows ------0 1

Row Source Operation --------------------------------------------------UPDATE (cr=7 pr=0 pw=0 time=350 us) TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=160 us)

******************************************************************************** OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count ------- -----Parse 9 Execute 11 Fetch 0 ------- -----total 20

cpu elapsed disk query current -------- ---------- ---------- ---------- ---------0.04 0.06 0 2 0 0.01 0.04 0 21 8 0.00 0.00 0 0 0 -------- ---------- ---------- ---------- ---------0.06 0.11 0 23 8

rows ---------0 3 0 ---------3

Misses in library cache during parse: 6 Misses in library cache during execute: 2 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count ------- -----Parse 2 Execute 2 Fetch 2 ------- -----total 6

cpu elapsed disk query current -------- ---------- ---------- ---------- ---------0.01 0.00 0 0 0 0.00 0.00 0 0 0 0.00 0.00 0 14 0 -------- ---------- ---------- ---------- ---------0.01 0.01 0 14 0

Misses in library cache during parse: 2

rows ---------0 0 2 ---------2

13 user SQL statements in session. 0 internal SQL statements in session. 13 SQL statements in session. ******************************************************************************** Trace file: emp_maint.trc Trace file compatibility: 10.01.00 Sort options: default 0 13 0 13 10 102 816

session in tracefile. user SQL statements in trace file. internal SQL statements in trace file. SQL statements in trace file. unique SQL statements in trace file. lines in trace file. elapsed seconds in trace file.

Tracing Enhancements The world of tracing Oracle sessions has changed drastically with Oracle 10g. Not so much the mechanisms but in the way we can initiate a trace for one session or a group of sessions. We are now able to "tag" sessions as they are connected to Oracle and move through applications. We can now accurately pinpoint where in the application a session is, the amount of resources being consumed, and more importantly if the session is having difficulty and is in need of tuning. This is extremely important in a multi-tier environment where connection polling takes place and we would be lost if it where not for these new tracing features.