Tracing Individual Users in Connection-pooled Environments with Oracle 10g

by Terry Sutton
Database Specialists, Inc.

About Database Specialists, Inc.
Database Specialists, Inc. provides remote DBA services and onsite database support for your mission critical Oracle systems. Since 1995, we have been providing Oracle database consulting in Solaris, HP-UX, Linux, AIX, and Windows environments. We are DBAs, speakers, educators, and authors. Our team is continually recognized by Oracle, at national conferences and by leading trade publications. Learn more about our remote DBA, database tuning, and consulting services. Or, call us at 415-344-0500 or 888-648-0500.

Overview

Many of us have been using Oracle’s Extended SQL Trace, also known as a 10046 trace, for years. An Extended SQL Trace can provide the most detailed information about exactly what an Oracle session is doing, including which SQL statements the session is executing, how many logical and physical reads the session is performing for each of those statements, what the session is waiting on and how long it has to wait, and more. By performing a 10046 trace we learn what the individual Oracle session is encountering, as opposed to what the database as a whole is doing. So if we can trace a portion of application code which is having performance problems, we will be able to address the issues specific to that application code.

This has worked well in two-tiered architectures where there is a one-to-one relation between a database session and an end-user session. Unfortunately the Extended SQL Trace facility never worked well in connection-pooled environments or architectures that use an application server to multiplex many end user sessions into a smaller number of database sessions. More and more systems use this model today, where one end-user session can bounce around between multiple database sessions, and many different end-user sessions use a given database session.

But in version 10g Oracle has given us the ability to trace an end-user’s session, even though connection pooling may cause each request by that user to be served by a different Oracle server process. In this paper we will walk through a real-life example of tracing an individual end-user’s actions as they use a web-based application. Although each request by the end-user may be handled by a different Oracle server process, and each Oracle server process will also handle requests for other end-users, all requests by our end-user can be traced and reported cohesively in one TKPROF report.

Background

We won’t go into great detail on the basics of tracing or interpreting the output of traces. These are discussed thoroughly in other white papers, such as Use EXPLAIN PLAN and TKPROF to Tune Your Applications, Interpreting Wait Events to Boost System Performance, and More Examples of Interpreting Wait Events to Boost System Performance. A quick summary will suffice here.

You can trace your own individual database session with one of the following commands:

EXECUTE SYS.DBMS_SUPPORT.START_TRACE
ALTER SESSION SET events '10046 trace name context forever, level 12';

You can trace another database session with one of the following commands (depending on the database version, some of these may not be available):

EXECUTE SYS.DBMS_SUPPORT.START_TRACE_IN_SESSION (sid, serial#)

oradebug setorapid [Oracle PID from v$process]
oradebug session_event 10046 trace name context forever, level 8

EXECUTE SYS.DBMS_SYSTEM.SET_EV (sid, serial#, 10046, 8, '')

Any of these commands would create a trace file in the instance’s user_dump_dest, with a name like “<ORACLE_SID>_ora_10786.trc” (the exact format of the name will vary on different O/S platforms).

Then we would use a profiling tool, such as Oracle’s TKPROF, to process the data and make a readable report out of it:

tkprof  dbrxprd_ora_10786.trc test_report.txt waits=yes 

The TKPROF report will show nicely-formatted information about each SQL statement and a summary of all the SQL statements executed by the session during the tracing period, including wait events in Oracle version 9i.

The Old Days

As previously mentioned, this all worked fine until we all started using connection pooling. But once connection pooling became common, a given end-user session started bouncing around between different database connections, and one database session could service many different end-users. So there was no way of picking out the information for one specific end-user session.

If we wanted to see what SQL was being executed by the application “in general” and which queries were using the most resources, we could use workarounds like the following script:

SPOOL traceall.sql

SET HEADING OFF FEEDBACK OFF

SELECT 'EXECUTE SYS.dbms_system.set_ev (' || TO_CHAR (sid) ||
          ', ' || TO_CHAR (serial#) || ', 10046, 8, '''')'
   FROM   v$session
   WHERE  username = 'WEB_USER';

SPOOL OFF

SET FEEDBACK ON

@traceall.sql

This would create trace files for all of the sessions connected as WEB_USER. As you can imagine, this could generate a lot of trace files and create a lot of database overhead as potentially hundreds of database sessions were traced. We could change the where clause above to specify a specific application server or take other steps to try to reduce the number of files and workload of tracing, but we would still be tracing a lot of end-users and generating many large trace files.

We would then concatenate all of the trace files into one, and run TKPROF on this enormous trace file. The report generated would tell us a lot about the database in general, but we wouldn’t know anything about a specific problem session. If some sessions were running some batch process which contained lots of queries that took a long time and used lots of resources, the data from these sessions might dominate the report. But the problem we were trying to solve might be a small set of queries which were taking 60 seconds in total (but which were supposed to take only 1 second). So it would be difficult to drill down into the problem area.

Oracle 10g Improvements

In Oracle 10g there are several improvements related to tracing. First, the DBMS_MONITOR package has been introduced. It has multiple features which make tracing easier to perform, but we’ll only touch on a couple here.

As shown above, in the past there were several different commands which could be used to initiate a trace. Some of them were not installed in the database by default, and almost all of them had complicated, difficult-to-remember syntax. Now, if you want to trace your own session, with wait and bind value details, the command is:

execute dbms_monitor.session_trace_enable(waits=>true, binds=>true)

To trace a specific database session, other than our own, with wait and bind value details:

execute dbms_monitor.session_trace_enable(<session_id>, waits=>true, binds=>true)

where session_id is the SID of the session from v$session.

The procedure in DBMS_MONITOR that we’re going to be particularly interested in is DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE. This procedure enables us to trace all activity for a given client identifier. The trace may be written to multiple trace files if more than one Oracle session does work on behalf of the specified client identifier. The client identifier will be set for a given end-user session by the application. We will use this procedure in our example.

Another procedure in DBMS_MONITOR is DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE, which will enable tracing for a given combination of service_name, module_name, and action_name. This procedure is useful if your application is properly instrumented (see “How to Make an Application Easy to Diagnose” by Cary Millsap, www.hotsos.com), and when an application MODULE and optionally known ACTION is experiencing poor performance.

The other big improvement in Oracle 10g tracing is the trcsess utility. This is the tool used to combine the multiple trace files created when the tracing is enabled using DBMS_MONITOR. The syntax is:

trcsess [output=<output file name >]  [session=<session ID>] [clientid=<clientid>] \
        [service=<service name>] [action=<action name>] [module=<module name>] \
        <trace file names>

trcsess will go through all trace files which are specified by <trace file names> and pick out the portions relevant to the specified clientid or service/module/action combination and write them to the file specified by <output file name>. We can then apply TKPROF or another profiler to this new file, and get the desired report.

Real Life Example

The best way to understand how all of these pieces work together is to go through a real-life example. We’ll show how we can trace an end-user’s steps through a web site and generate a single TKPROF report.

At Database Specialists, we provide ongoing remote DBA support for companies, and we have a web portal to provide information on client databases which we monitor with our Database Rx monitoring and alert notification service. We will log in to the web portal, enable tracing for our session, and navigate a bit through the site. Then we’ll look at the trace output.

When a user goes to the Database Rx portal, they see a screen like this:

After a user logs in, each time they go to a page the following code is called to correlate the cookie in the user’s browser to an active session:

begin
  select w.user_id, w.login_date, w.active_instance_id
    into   p_current_user_rec.user_id, v_login_date,
             p_current_user_rec.active_instance_id
      from   web_active_sessions w
      where  w.session_key = ltrim(rtrim(p_session_id));

   ... some other code checking authorization & such ...
   --
   -- Set the client identifier in the Oracle database session to
   -- match the session key for easy tracing and instrumentation.
   --
    set_ora_session_id (LTRIM (RTRIM (p_session_id)));
end;

The code above calls the set_ora_session_id procedure. The text of this procedure is:

  -- Set the session identifier attributed to the current database session.
  --
  PROCEDURE set_ora_session_id (p_session_id IN VARCHAR2)
  IS
  BEGIN
    dbms_session.set_identifier (p_session_id);
  END set_ora_session_id;

At the end of each page, the following code is executed:

  -- Clear the client identifier in the Oracle database session so that it
  -- no longer matches the session key for easy tracing and instrumentation.
  --
  psputil.clear_ora_session_id;

The clear_ora_session_id procedure is:

  -- Clear the session identifier attributed to the current database session.
  --
  PROCEDURE clear_ora_session_id
  IS
  BEGIN
    dbms_session.clear_identifier;
  END clear_ora_session_id;

After logging in to the Database Rx portal, the user is sent to the following page:

Now it’s time to turn on monitoring. We connect to the database used by the web portal, and identify our user.

SQL> select user_id from customer_users where username = 'tsutton'

   USER_ID
----------
    100003

SQL> select * from web_active_sessions where user_id=100003;

SESSION_KEY             USER_ID ACTIVE_INSTANCE_ID LOGIN_DATE         LAST_ACTIVITY_DATE
-------------------- ---------- ------------------ ------------------ ------------------
20558307491688865029     100003             100062 21-DEC-06 14:41:54 21-DEC-06 14:41:54

We see that the session_key that has been assigned to this user is 20558307491688865029. So we enable tracing for this user:

SQL> exec dbms_monitor.client_id_trace_enable -
>           ('20558307491688865029', waits=> true, binds=> true)

PL/SQL procedure successfully completed.

We go to the user_dump_dest directory and take a look:

$ cd /u01/app/oracle/admin/dbrxprd/udump
/u01/app/oracle/admin/dbrxprd/udump $ date
Thu Dec 21 14:47:41 PST 2006
/u01/app/oracle/admin/dbrxprd/udump $ ls -lt
total 1086
-rw-r-----   1 oracle   dba         6631 Dec 17 00:14 dbrxprd_ora_10786.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 05:09 dbrxprd_ora_7959.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 01:13 dbrxprd_ora_7706.trc
-rw-r-----   1 oracle   dba         6630 Dec 10 00:14 dbrxprd_ora_14396.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 05:10 dbrxprd_ora_2635.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 01:14 dbrxprd_ora_2355.trc
-rw-r-----   1 oracle   dba         6625 Dec  3 00:14 dbrxprd_ora_1033.trc

At this point we don’t see any current trace files (since the end-user hasn’t done anything yet).

So the end-user goes through some reports. We’ll look at the Instance Status Report, Tablespace Size Report, Database Growth Report, and Execution Plan Changes Report.

Consolidate and Review Reports

And now we will log out. It’s a good idea to turn off tracing before we go, as trace enabling with DBMS_MONITOR is persistent across instance starts and restarts. While it’s not likely that this client_id will ever be encountered again, it’s best to be safe.

SQL> exec dbms_monitor.client_id_trace_disable ('20558307491688865029')

PL/SQL procedure successfully completed.

If you want to see if any traces have been enabled, use the view DBA_ENABLED_TRACES.

Now, if we look at the user_dump_dest directory, we see:

/u01/app/oracle/admin/dbrxprd/udump $ date
Thu Dec 21 15:17:10 PST 2006
/u01/app/oracle/admin/dbrxprd/udump $ ls -lt
total 3342
-rw-r-----   1 oracle   dba       166014 Dec 21 14:50 dbrxprd_ora_1887.trc
-rw-r-----   1 oracle   dba       145824 Dec 21 14:49 dbrxprd_ora_1149.trc
-rw-r-----   1 oracle   dba       112760 Dec 21 14:49 dbrxprd_ora_1826.trc
-rw-r-----   1 oracle   dba       683137 Dec 21 14:48 dbrxprd_ora_1110.trc
-rw-r-----   1 oracle   dba         6631 Dec 17 00:14 dbrxprd_ora_10786.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 05:09 dbrxprd_ora_7959.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 01:13 dbrxprd_ora_7706.trc
-rw-r-----   1 oracle   dba         6630 Dec 10 00:14 dbrxprd_ora_14396.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 05:10 dbrxprd_ora_2635.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 01:14 dbrxprd_ora_2355.trc
-rw-r-----   1 oracle   dba         6625 Dec  3 00:14 dbrxprd_ora_1033.trc

There are four trace files generated by our stroll through the pages, which means that our end-user session used four different database sessions during our exercise. We need to consolidate these to analyze all the activity of our end-user session, so we’ll use trcesss:

/u01/app/oracle/admin/dbrxprd/udump $ trcsess output=test1.trc \
>                                     clientid='20558307491688865029' *.trc
/u01/app/oracle/admin/dbrxprd/udump $ date
Thu Dec 21 15:22:44 PST 2006
/u01/app/oracle/admin/dbrxprd/udump $ ls -lt
total 5518
-rw-r--r--   1 oracle   dba      1105707 Dec 21 15:22 test1.trc
-rw-r-----   1 oracle   dba       166014 Dec 21 14:50 dbrxprd_ora_1887.trc
-rw-r-----   1 oracle   dba       145824 Dec 21 14:49 dbrxprd_ora_1149.trc
-rw-r-----   1 oracle   dba       112760 Dec 21 14:49 dbrxprd_ora_1826.trc
-rw-r-----   1 oracle   dba       683137 Dec 21 14:48 dbrxprd_ora_1110.trc
-rw-r-----   1 oracle   dba         6631 Dec 17 00:14 dbrxprd_ora_10786.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 05:09 dbrxprd_ora_7959.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 01:13 dbrxprd_ora_7706.trc
-rw-r-----   1 oracle   dba         6630 Dec 10 00:14 dbrxprd_ora_14396.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 05:10 dbrxprd_ora_2635.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 01:14 dbrxprd_ora_2355.trc
-rw-r-----   1 oracle   dba         6625 Dec  3 00:14 dbrxprd_ora_1033.trc

And then we run it through TKPROF to get a report:

/u01/app/oracle/admin/dbrxprd/udump $  tkprof test1.trc test1.out

TKPROF: Release 10.1.0.3.0 - Production on Thu Dec 21 15:28:43 2006

Copyright (c) 1982, 2004, Oracle.  All rights reserved.


/u01/app/oracle/admin/dbrxprd/udump $ ls -lt
total 5854
-rw-r--r--   1 oracle   dba       156655 Dec 21 15:28 test1.out
-rw-r--r--   1 oracle   dba      1105707 Dec 21 15:22 test1.trc
-rw-r-----   1 oracle   dba       166014 Dec 21 14:50 dbrxprd_ora_1887.trc
-rw-r-----   1 oracle   dba       145824 Dec 21 14:49 dbrxprd_ora_1149.trc
-rw-r-----   1 oracle   dba       112760 Dec 21 14:49 dbrxprd_ora_1826.trc
-rw-r-----   1 oracle   dba       683137 Dec 21 14:48 dbrxprd_ora_1110.trc
-rw-r-----   1 oracle   dba         6631 Dec 17 00:14 dbrxprd_ora_10786.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 05:09 dbrxprd_ora_7959.trc
-rw-r-----   1 oracle   dba        12858 Dec 16 01:13 dbrxprd_ora_7706.trc
-rw-r-----   1 oracle   dba         6630 Dec 10 00:14 dbrxprd_ora_14396.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 05:10 dbrxprd_ora_2635.trc
-rw-r-----   1 oracle   dba        12858 Dec  9 01:14 dbrxprd_ora_2355.trc
-rw-r-----   1 oracle   dba         6625 Dec  3 00:14 dbrxprd_ora_1033.trc

And here are some pieces of the TKPROF report:

TKPROF: Release 10.1.0.3.0 - Production on Thu Dec 21 16:29:40 2006

Copyright (c) 1982, 2004, Oracle.  All rights reserved.

Trace file: test1.trc
Sort options: default

	...

The Instance Status Report:

SELECT A.INSTANCE_ID, HTF.ESCAPE_SC(A.INSTANCE_NICKNAME) INSTANCE_NICKNAME, 
  HTF.ESCAPE_SC(B.CURRENT_INSTANCE_NAME) CURRENT_INSTANCE_NAME, 
  B.INSTANCE_KEY, A.CURRENT_CUST_USER_PRIV_LEVEL, A.USER_WISHES_TO_SEE, 
  B.MOST_SEVERE_ALERT_OR_EVENT 
FROM
 CUSTOMER_USER_INSTANCE_PRIVS A, CUSTOMER_INSTANCES B WHERE A.USER_ID = :B1 
  AND B.INSTANCE_ID = A.INSTANCE_ID ORDER BY A.DISPLAY_ORDER, LOWER (NVL 
  (A.INSTANCE_NICKNAME, B.CURRENT_INSTANCE_NAME)), A.INSTANCE_ID


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.05       0.05          0          0          0           0
Fetch      252      0.13       0.11          0        908          0         248
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      260      0.18       0.16          0        908          0         248

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 40     (recursive depth: 1)

...

The Tablespace Size Report:

SELECT B.TABLESPACE_NAME, C.DATA_FILE_COUNT, C.TEMP_FILE_COUNT, 
  C.AUTOEXTENSIBLE, A.CURRENT_SIZE_IN_BYTES, A.CURRENT_SIZE_IN_BYTES - 
  A.CURRENT_TOTAL_BYTES_FREE BYTES_USED, 100 * (A.CURRENT_TOTAL_BYTES_FREE / 
  A.CURRENT_SIZE_IN_BYTES) PERCENT_FREE, A.CURRENT_BIGGEST_BYTES_FREE, 
  A.BIGGEST_NEXT_DESIRED 
FROM
 SAMPLE_TABLESPACES A, COMMON_TABLESPACES B, ( SELECT D.COMMON_TABLESPACE_ID, 
  DECODE (MAX (E.AUTOEXTENSIBLE), 'YES', 'Yes', 'NO', 'No', NULL, 'No', MAX 
  (E.AUTOEXTENSIBLE)) AUTOEXTENSIBLE, SUM (DECODE (E.TEMP_FILE, 'YES', 0, 1)) 
  DATA_FILE_COUNT, SUM (DECODE (E.TEMP_FILE, 'YES', 1, 0)) TEMP_FILE_COUNT 
  FROM SAMPLE_DATA_FILES D, COMMON_DATA_FILES E WHERE D.SAMPLE_ID = :B1 AND 
  E.COMMON_DATA_FILE_ID = D.COMMON_DATA_FILE_ID GROUP BY 
  D.COMMON_TABLESPACE_ID ) C WHERE A.SAMPLE_ID = :B1 AND 
  B.COMMON_TABLESPACE_ID = A.COMMON_TABLESPACE_ID AND C.COMMON_TABLESPACE_ID =
   B.COMMON_TABLESPACE_ID ORDER BY B.TABLESPACE_NAME


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.18       0.17          0          0          0           0
Fetch        1      0.00       0.00          1         50          0           7
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.18       0.18          1         50          0           7

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 40     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         1        0.00          0.00


...

The Database Growth Report:

SELECT A.SAMPLE_DATE_DB_LOCAL_TIME, C.CURRENT_SIZE_IN_BYTES, 
  C.CURRENT_TOTAL_BYTES_FREE, C.CURRENT_SIZE_IN_BYTES - 
  C.CURRENT_TOTAL_BYTES_FREE, C.CURRENT_SIZE_IN_BYTES / :B5 , 
  (C.CURRENT_SIZE_IN_BYTES - C.CURRENT_TOTAL_BYTES_FREE) / :B5 
FROM
 ( SELECT A1.INSTANCE_ID, 'full_stat' SAMPLE_TYPE, MIN 
  (A1.SAMPLE_DATE_DB_LOCAL_TIME) SAMPLE_DATE_DB_LOCAL_TIME FROM SAMPLES A1 
  WHERE A1.INSTANCE_ID = :B3 AND A1.SAMPLE_SEQUENCE BETWEEN :B2 AND :B1 AND 
  A1.SAMPLE_TYPE = 'full_stat' GROUP BY A1.INSTANCE_ID, TRUNC 
  (A1.SAMPLE_DATE_DB_LOCAL_TIME) ) A, SAMPLES B, SAMPLE_TABLESPACES C WHERE 
  B.INSTANCE_ID = A.INSTANCE_ID AND B.SAMPLE_TYPE = A.SAMPLE_TYPE AND 
  B.SAMPLE_DATE_DB_LOCAL_TIME = A.SAMPLE_DATE_DB_LOCAL_TIME AND C.SAMPLE_ID = 
  B.SAMPLE_ID AND C.COMMON_TABLESPACE_ID = :B4 ORDER BY 
  A.SAMPLE_DATE_DB_LOCAL_TIME DESC


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.13       0.13          0          0          0           0
Fetch        1      0.18       0.18        673        937          0          31
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.31       0.31        673        937          0          31

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 40     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                       673        0.00          0.04


...

The Execution Plan Changes Report:

SELECT A.HASH_VALUE, A.SQL_ID, A.PARSING_USER_ID, A.COMMON_SQL_TEXT_ID, 
  COUNT(UNIQUE(A.PLAN_HASH_VALUE)) PLAN_CNT 
FROM
 SAMPLE_SQL_TEXTS A, SAMPLES B WHERE B.SAMPLE_SEQUENCE BETWEEN :B3 AND :B2 
  AND B.INSTANCE_ID = :B1 AND B.SAMPLE_ID = A.SAMPLE_ID AND A.PLAN_HASH_VALUE 
  > 0 GROUP BY A.HASH_VALUE, A.SQL_ID, A.PARSING_USER_ID, 
  A.COMMON_SQL_TEXT_ID HAVING COUNT(UNIQUE(A.PLAN_HASH_VALUE)) > 1 ORDER BY 
  A.SQL_ID, A.HASH_VALUE


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.08       0.09          0          0          0           0
Fetch        1      0.08       0.16         71        303          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.16       0.25         71        303          0           0

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 40     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                        71        0.00          0.11

...

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      779      1.47       1.46          1         98          0           0
Execute   1427      3.57       3.66         23        330        866         267
Fetch     2740      1.07       1.81       1052       7444          0        4798
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4946      6.11       6.94       1076       7872        866        5065

Misses in library cache during parse: 125
Misses in library cache during execute: 108

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                      1053        0.02          0.81
  db file scattered read                          3        0.01          0.01

  181  user  SQL statements in session.
  598  internal SQL statements in session.
  779  SQL statements in session.

What about Shared Server?

Shared Server (aka Multi-Threaded Server) is another environment where using an extended SQL trace has been problematic in the past. Because each SQL statement executed by an individual session could be processed by a different Oracle process, the tracing could be spread over several different trace files. Fortunately it’s fairly easy to deal with this in Oracle 10g.

First, rather than using DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE, we use DBMS_MONITOR.SESSION_TRACE_ENABLE. This can be run either by the session itself, or by another session (specifying the SID of the session to be traced). The tracing output will be in the instance’s background_dump_dest directory, rather than the user_dump_dest. And then you use trcsess with the session_id option, where session ID is actually the SID.SERIAL# of the session (from v$session). Again you get a consolidated trace file containing just the activity of the desired session.

Summary

We’ve seen that Oracle 10g has several significant improvements in tracing. Not only has Oracle 10g made it easier to initiate tracing (and much easier to remember the syntax), but now we can pick out a single end-user session and trace their activities. This makes it much easier to diagnose performance problems from the end-user process perspective, rather than the overall database performance perspective.

We’ve shown:

With these techniques it becomes much easier to diagnose application performance problems and pinpoint specific SQL statements which are causing these problems.

About the Author

Terry Sutton, OCP, has been an Oracle DBA for 13 years, and has worked in the information technology area for 20 years. Since 2000, Terry has been a Senior Staff Consultant at Database Specialists, performing assignments ranging from production database administration to emergency troubleshooting with a particular focus on Oracle database performance tuning. He has been a speaker at the RMOUG, NoCOUG, and IOUG-Live conferences, as well as the Hotsos Symposium and various local user groups. You may contact Terry by email at tsutton@dbspecialists.com

Still Looking for Help on this Subject?

Get a Consultation
We would be happy to talk with you about our services and how our senior-level database team might help you. Call Database Specialists at 415-344-0500 or 888-648-0500 or fill out a free consultation request form.
Complimentary Newsletter
If you'd like to receive our complimentary monthly newsletter with database tips and new white paper announcements, sign up for The Specialist.


Copyright © 2007 Database Specialists, Inc. http://www.dbspecialists.com