Transcript No Slide Title

Tracing Individual Users
in Connection-pooled
Environments with
Oracle 10g
Terry Sutton
Database Specialists, Inc.
www.dbspecialists.com
Session Objectives
 Discuss the concepts behind logical session
tracing in Oracle 10g.
 See how minor application changes can make
logical session tracing of production systems
very easy.
 Follow a real-life example of how an end-user’s
actions in a web-based application can be
traced and reported with TKPROF as easily as
if the end-user were running a client/server
application.
Extended SQL Trace
 Provides detailed info about what a database
session is doing, including:
– SQL statements being executed
– Logical & Physical Reads session is performing for
each query
– Waits- what the session is waiting on and for how
long
 Works well in Client-Server configuration
Background
Trace your own session:
– EXECUTE SYS.DBMS_SUPPORT.START_TRACE
– ALTER SESSION SET events '10046 trace name
context forever, level 12';
Trace another session:
– 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, '')
 Trace file created:
– dbrxprd_ora_10786.trc
 Then use TKPROF (or another profiler) to
create a report:
– tkprof dbrxprd_ora_10786.trc
test_report.txt waits=yes
BUT— The World Now
 Connection pooled environments
 Shared (Multi-Threaded) Server
 Application Server multiplexing many end-user
sessions into (relatively) few DB connections
 One end-user session can bounce around
among multiple DB session connections
A Shotgun Approach
To get a look at SQL generated by “system”, use
shotgun approach:
SPOOL traceall.sql
SELECT 'EXECUTE SYS.dbms_system.set_ev (' || TO_CHAR (sid) ||
', ' || TO_CHAR (serial#) || ', 10046, 8, '''')'
FROM
v$session
WHERE username = 'WEB_USER';
SPOOL OFF
@traceall.sql
Oracle 10g Enhancements
The DBMS_MONITOR Package
–Trace your own session:
dbms_monitor.session_trace_enable(waits=>true,
binds=>true)
–Trace another session:
dbms_monitor.session_trace_enable(<session_id>,
waits=>true, binds=>true)
Waits=>true, binds=>false is default
Oracle 10g Enhancements
The DBMS_MONITOR Package (cont.)
DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE
DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE
Oracle 10g Enhancements
The trcsess Utility
To combine multiple trace files.
trcsess [output=<output file name >]
[session=<session ID>] [clientid=<clientid>]
[service=<service name>] [action=<action name>]
[module=<module name>] <trace file names>
Real Life Example
Database Rx web portal
After the login, 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;
set_ora_session_id procedure
-- 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 login, user goes to Instance List
Page
Turn on Tracing
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_INST LOGIN_DATE
-------------------- ------- ----------- -----------------20558307491688865029 100003
100062 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')
PL/SQL procedure successfully completed.
Check the user_dump_dest directory
$ 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
total 1086
-rw-r----1 oracle
dba
6631
-rw-r----1 oracle
dba
12858
-rw-r----1 oracle
dba
12858
-rw-r----1 oracle
dba
6630
-lt
Dec
Dec
Dec
Dec
17
16
16
10
00:14
05:09
01:13
00:14
dbrxprd_ora_10786.trc
dbrxprd_ora_7959.trc
dbrxprd_ora_7706.trc
dbrxprd_ora_14396.trc
Now the End-user Goes Through
Some Reports
 We’ll look at:
– Instance Status Report
– Tablespace Size Report
– Database Growth Report
– Execution Plan Changes Report
Instance Status
Tablespace Size
Database Growth
Execution Plan Changes
Turn Off Tracing
Now the user logs out, and we turn off tracing:
SQL> exec dbms_monitor.client_id_trace_disable('20558307491688865029')
PL/SQL procedure successfully completed.
DBA_ENABLED_TRACES will show any traces
currently enabled.
Check the user_dump_dest directory
/u01/app/oracle/admin/dbrxprd/udump $ date
Thu Dec 21 15:17:10 PST 2006
/u01/app/oracle/admin/dbrxprd/udump $ ls
total 3342
-rw-r----1 oracle
dba
166014
-rw-r----1 oracle
dba
145824
-rw-r----1 oracle
dba
112760
-rw-r----1 oracle
dba
683137
-rw-r----1 oracle
dba
6631
-rw-r----1 oracle
dba
12858
-rw-r----1 oracle
dba
12858
-rw-r----1 oracle
dba
6630
-lt
Dec
Dec
Dec
Dec
Dec
Dec
Dec
Dec
21
21
21
21
17
16
16
10
14:50
14:49
14:49
14:48
00:14
05:09
01:13
00:14
dbrxprd_ora_1887.trc
dbrxprd_ora_1149.trc
dbrxprd_ora_1826.trc
dbrxprd_ora_1110.trc
dbrxprd_ora_10786.trc
dbrxprd_ora_7959.trc
dbrxprd_ora_7706.trc
dbrxprd_ora_14396.trc
Use trcsess to consolidate the 4 trace
files into one
/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
total 5518
-rw-r--r-1 oracle
dba
1105707
-rw-r----1 oracle
dba
166014
-rw-r----1 oracle
dba
145824
-rw-r----1 oracle
dba
112760
-rw-r----1 oracle
dba
683137
-rw-r----1 oracle
dba
6631
-rw-r----1 oracle
dba
12858
-rw-r----1 oracle
dba
12858
-rw-r----1 oracle
dba
6630
-lt
Dec
Dec
Dec
Dec
Dec
Dec
Dec
Dec
Dec
21
21
21
21
21
17
16
16
10
15:22
14:50
14:49
14:49
14:48
00:14
05:09
01:13
00:14
test1.trc
dbrxprd_ora_1887.trc
dbrxprd_ora_1149.trc
dbrxprd_ora_1826.trc
dbrxprd_ora_1110.trc
dbrxprd_ora_10786.trc
dbrxprd_ora_7959.trc
dbrxprd_ora_7706.trc
dbrxprd_ora_14396.trc
Then use 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
total 5854
-rw-r--r-1 oracle
dba
156655
-rw-r--r-1 oracle
dba
1105707
-rw-r----1 oracle
dba
166014
-rw-r----1 oracle
dba
145824
-rw-r----1 oracle
dba
112760
-rw-r----1 oracle
dba
683137
-lt
Dec
Dec
Dec
Dec
Dec
Dec
21
21
21
21
21
21
15:28
15:22
14:50
14:49
14:49
14:48
test1.out
test1.trc
dbrxprd_ora_1887.trc
dbrxprd_ora_1149.trc
dbrxprd_ora_1826.trc
dbrxprd_ora_1110.trc
Here are some pieces of the TKPROF
report
TKPROF: Release 10.1.0.3.0 - Production on Thu Dec 21 15:28:43 2006
Copyright (c) 1982, 2004, Oracle.
Trace file: test1.trc
Sort options: default
All rights reserved.
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
------- -----Parse
4
Execute
4
Fetch
252
------- -----total
260
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
0.05
0.05
0
0
0
0.13
0.11
0
908
0
-------- ---------- ---------- ---------- ---------0.18
0.16
0
908
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)
rows
---------0
0
248
---------248
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
The Tablespace Size Report (continued)
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
The Database Growth Report (continued)
call
count
------- -----Parse
1
Execute
1
Fetch
1
------- -----total
3
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
0.13
0.13
0
0
0
0.18
0.18
673
937
0
-------- ---------- ---------- ---------- ---------0.31
0.31
673
937
0
rows
---------0
0
31
---------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
---------------------------------------Waited
db file sequential read
673
Max. Wait
---------0.00
Total Waited
-----------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
The Execution Plan Changes Report
(continued)
call
count
------- -----Parse
1
Execute
1
Fetch
1
------- -----total
3
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
0.08
0.09
0
0
0
0.08
0.16
71
303
0
-------- ---------- ---------- ---------- ---------0.16
0.25
71
303
0
rows
---------0
0
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
---------------------------------------Waited
db file sequential read
71
Max. Wait
---------0.00
Total Waited
-----------0.11
TKPROF Summary Section
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call
count
------- -----Parse
0
Execute
0
Fetch
0
------- -----total
0
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
0.00
0.00
0
0
0
0.00
0.00
0
0
0
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
Misses in library cache during parse: 0
rows
---------0
0
0
---------0
TKPROF Summary Section
(continued)
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call
count
------- -----Parse
779
Execute
1427
Fetch
2740
------- -----total
4946
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------1.47
1.46
1
98
0
3.57
3.66
23
330
866
1.07
1.81
1052
7444
0
-------- ---------- ---------- ---------- ---------6.11
6.94
1076
7872
866
rows
---------0
267
4798
---------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
---------------------------------------Waited
db file sequential read
1053
db file scattered read
3
181
598
779
user SQL statements in session.
internal SQL statements in session.
SQL statements in session.
Max. Wait
---------0.02
0.01
Total Waited
-----------0.81
0.01
What about MTS?
With Shared Server (formerly Multi Threaded
Server:




Tracing by client_id does NOT work.
But tracing by Session ID does.
Trace files are in background_dump_dest
Session ID is SID.SERIAL# from v$session:
trcsess output=output.trc session=152.14 *.trc
Conclusion
Oracle 10g has several enhancements to help with enduser session tracing:
– DBMS_MONITOR Package (easier to use)
– Ability to trace individual client session, or by
service/module/action
– trcsess utility to consolidate relevant portions of multiple trace
files
We’ve seen:
– How a client session can be marked with a client_id so it can
later be identified
– How to enable tracing for a client session using this client_id.
– How to consolidate the multiple trace files generated by the
trace
The White Paper
A companion white paper to this presentation is
available for free download from our company’s website
at:
www.dbspecialists.com/presentations.html
About Database Specialists
 Database Specialists, Inc. provides Oracle database consulting
in Solaris, Linux, HP-UX, AIX, and Windows environments.
 Our DBA Pro offering and Database Rx™ tools provide remote
database support and 24/7 coverage at an attractive price
point.
 Our Oracle DBAs each have a minimum of 10 years of Oracle
experience.
 Database Specialists is US-based.
Database Specialists helps you
increase uptime, improve performance,
minimize risk, and reduce costs
Tracing Individual Users
in Connection-pooled
Environments with
Oracle 10g
Terry Sutton
Database Specialists, Inc.
www.dbspecialists.com
[email protected]
415/344-0500