1 / 41

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

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.

africa
Download Presentation

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

An Image/Link below is provided (as is) to download presentation Download Policy: Content on the Website is provided to you AS IS for your information and personal use and may not be sold / licensed / shared on other websites without getting consent from its author. Content is provided to you AS IS for your information and personal use only. Download presentation by click this link. While downloading, if for some reason you are not able to download a presentation, the publisher may have deleted the file from their server. During download, if you can't get a presentation, the file might be deleted by the publisher.

E N D

Presentation Transcript

  1. Tracing Individual Users in Connection-pooled Environments with Oracle 10g Terry Sutton Database Specialists, Inc. www.dbspecialists.com

  2. 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.

  3. 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

  4. 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, '')

  5. 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

  6. 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

  7. 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

  8. 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

  9. Oracle 10g Enhancements The DBMS_MONITOR Package (cont.) DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE

  10. 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>

  11. Real Life ExampleDatabase Rx web portal

  12. 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;

  13. 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;

  14. 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;

  15. After login, user goes to Instance List Page

  16. 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.

  17. 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 -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

  18. 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

  19. Instance Status

  20. Tablespace Size

  21. Database Growth

  22. Execution Plan Changes

  23. 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.

  24. 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 -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

  25. 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 -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

  26. 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 -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

  27. 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. All rights reserved. Trace file: test1.trc Sort options: default

  28. 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)

  29. 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

  30. 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

  31. 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

  32. The Database Growth Report (continued) 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

  33. 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

  34. The Execution Plan Changes Report (continued) 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

  35. TKPROF Summary Section 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

  36. TKPROF Summary Section (continued) 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.

  37. 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

  38. Conclusion Oracle 10g has several enhancements to help with end-user 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

  39. 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

  40. 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

  41. Tracing Individual Users in Connection-pooled Environments with Oracle 10g Terry Sutton Database Specialists, Inc. www.dbspecialists.com tsutton@dbspecialists.com 415/344-0500

More Related