No Slide Title
Download
Report
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