dynamic logging with global application context
Application context was introduced in Oracle 8i to support Fine Grained Access Control. It has many other good uses (such as in parameterised views) and there are plenty of examples available in the online technical forums. Global application context was introduced in Oracle 9i to support shared-session applications (such as web-applications using connection pools). Global application context can be manipulated or accessed across sessions (unlike the original implementation that was session-based).
We can exploit the fact that global application context is available across sessions to find alternative uses for this feature. This article will demonstrate one such alternative. We will use global application context to interactively and dynamically control the depth of trace information that is emitted from our PL/SQL programs. We will call this "interactive logging".
what is interactive logging?
Most developers will have used Oracle's own instrumentation, particularly SQL Trace. This instrumentation enables us to emit different levels of detail on the execution of SQL cursors within our session. The same developers should also be aware that SQL Trace can be activated and de-activated from outside our running sessions using DBMS_SYSTEM, DBMS_SUPPORT or more recently DBMS_MONITOR (though it is usually the DBA who will have the power to do this).
If we now consider our own instrumentation, we usually include logging or debug information in our PL/SQL packages. We might use UTL_FILE to write this information to file or alternatively use a table-based logging mechanism to retain all information in the database. The decision on whether to activate logging or debugging (from now on we will call this "logging") is usually parameter-driven or lookup-driven. From 10g Release 2, we might even conditionally compile logging into our packages (this can also be backported over a couple of releases). Typically, however, once a package is stable, logging tends to be de-activated. Low-level trace information tends to be largely irrelevant for most applications outside of their test environments.
There is a critical limitation with this, however. Once the packaged code is running, we cannot change its logging level. In most cases, we either log or we don't log. In some cases, we only log high-level details. In the event that one of our sessions starts to display unusual behaviour (such as poor performance or strange results), we cannot change the fact that we started the program with little-to-no logging (though we can enable SQL Trace, of course). Global application context changes this, however, and provides an efficient means of toggling user-instrumentation levels from outside a running session. We will call this "dynamic logging" and demonstrate it in this article.
a note on the examples
The examples in this article are simple approximations of what a logging package might look like. They should not be considered as final implementations and are kept deliberately simple for the sake of clarity. A good case in point is that all versions use DBMS_OUTPUT as a means of emitting trace information!
global application context
Global application contexts are created in a similar manner to their session-based equivalents, with some additional syntax ("ACCESSED GLOBALLY"). As with session-based contexts, we must include the name of the trusted code that can set and clear attributes within the context. Attributes are accessed using the SYS_CONTEXT function. Given this, we will create a global application context for our interactive logging examples, as follows.
SQL> CREATE CONTEXT log_ctx USING log_pkg ACCESSED GLOBALLY;
Context created.
We now have our global context and must create the package to set its attributes.
a simple logging package
For our first example, we will create a simple logging package, using the name we supplied in the CREATE CONTEXT statement. The package specification for LOG_PKG is as follows.
SQL> CREATE OR REPLACE PACKAGE log_pkg AS 2 3 PROCEDURE start_log( 4 p_id IN VARCHAR2, 5 p_lvl IN PLS_INTEGER DEFAULT 1 6 ); 7 8 PROCEDURE log( 9 p_id IN VARCHAR2, 10 p_msg IN VARCHAR2, 11 p_lvl IN PLS_INTEGER DEFAULT 1 12 ); 13 14 PROCEDURE set_logging_level( 15 p_id IN VARCHAR2, 16 p_lvl IN PLS_INTEGER 17 ); 18 19 PROCEDURE end_log( 20 p_id IN VARCHAR2 21 ); 22 23 END log_pkg; 24 /
Package created.
We can see that this is quite simple. We have "start and stop" APIs, the LOG procedure itself and also a procedure to set logging levels. This is included because our logging package will support different levels of trace to control how much or how little information we output. The initial logging level is set in the START_LOG procedure but we will be able to modify it interactively. We will now implement a small package body for LOG_PKG, as follows.
SQL> CREATE OR REPLACE PACKAGE BODY log_pkg AS
2
3 -------------------------------------------------------------
4
5 PROCEDURE start_log(
6 p_id IN VARCHAR2,
7 p_lvl IN PLS_INTEGER DEFAULT 1
8 ) IS
9 BEGIN
10 set_logging_level(p_id, p_lvl);
11 END start_log;
12
13 -------------------------------------------------------------
14
15 FUNCTION logging_level(
16 p_id IN VARCHAR2
17 ) RETURN INTEGER IS
18 BEGIN
19 RETURN TO_NUMBER(SYS_CONTEXT('log_ctx', UPPER(p_id)));
20 END logging_level;
21
22 -------------------------------------------------------------
23
24 PROCEDURE log(
25 p_id IN VARCHAR2,
26 p_msg IN VARCHAR2,
27 p_lvl IN PLS_INTEGER DEFAULT 1
28 ) IS
29 BEGIN
30 IF logging_level(p_id) >= p_lvl THEN
31 DBMS_OUTPUT.PUT_LINE(
32 TO_CHAR(SYSDATE,'HH24:MI:SS ": "') || p_msg
33 );
34 END IF;
35 END log;
36
37 -------------------------------------------------------------
38
39 PROCEDURE set_logging_level(
40 p_id IN VARCHAR2,
41 p_lvl IN PLS_INTEGER
42 ) IS
43 BEGIN
44 DBMS_SESSION.SET_CONTEXT(
45 'log_ctx', UPPER(p_id), TO_CHAR(p_lvl)
46 );
47 END set_logging_level;
48
49 -------------------------------------------------------------
50
51 PROCEDURE end_log(
52 p_id IN VARCHAR2
53 ) IS
54 BEGIN
55 DBMS_SESSION.CLEAR_CONTEXT('log_ctx', NULL, UPPER(p_id));
56 END end_log;
57
58 END log_pkg;
59 /
Package body created.
The SET_LOG_LEVEL procedure is what we use to assign the logging level of the calling program to the global application context. The same information is cleared when we complete our logging session (using the END_LOG procedure). The LOG procedure determines whether the incoming trace message should be emitted by comparing the requested logging level for the message with that already set in the application context. Only messages with an equivalent or lower level setting will be output. This is not a great deal different from the standard "IF p_debug = TRUE THEN log... END IF;" that we are familiar with, except it gives us slightly more control.
a non-interactive test
We will test our logging package with a simple, single-session example of dynamic logging, before we move onto interactive examples. In the following example, we will begin with a level of 2 and attempt to output some trace lines at levels between 1 and 4. We will then increase the logging level for our program and try again.
SQL> DECLARE 2 3 c_id CONSTANT VARCHAR2(100) := 'SCOTT.DEMO_ANON'; 4 5 BEGIN 6 7 log_pkg.start_log(c_id, 2); 8 9 log_pkg.log(c_id, 'Line 1 at level 1', 1); 10 log_pkg.log(c_id, 'Line 2 at level 2', 2); 11 log_pkg.log(c_id, 'Line 3 at level 3', 3); 12 log_pkg.log(c_id, 'Line 4 at level 4', 4); 13 14 log_pkg.set_logging_level(c_id, 4); 15 16 log_pkg.log(c_id, 'Line 5 at level 4', 4); 17 18 log_pkg.end_log(c_id); 19 20 END; 21 /
21:29:25 : Line 1 at level 1 21:29:25 : Line 2 at level 2 21:29:25 : Line 5 at level 4 PL/SQL procedure successfully completed.
Although a non-interactive example, this demonstrates quite clearly how the logging levels work. Lines 3 and 4 were overlooked because their levels were too high but line 5 was emitted because the logging level was raised.
an interactive test
Moving on, we will now focus on the subject of this article and see an interactive example of dynamic logging with two sessions. Session 1 will run a PL/SQL block that starts logging at level 2 and attempts to emit 10 lines at level 5 in a loop, sleeping between each iteration to simulate a long-running session. We will start session 1 and record its SID and start time as follows.
SQL> SELECT sid 2 , TO_CHAR(SYSDATE,'HH24:MI:SS') AS time 3 FROM v$mystat 4 WHERE ROWNUM = 1;
SID TIME
---------- --------
150 21:55:37
1 row selected.
SQL> DECLARE 2 c_id CONSTANT VARCHAR2(100) := 'SCOTT.DEMO_ANON'; 3 BEGIN 4 log_pkg.start_log(c_id, 2); 5 FOR i in 1 .. 10 LOOP 6 log_pkg.log(c_id, 'Logging on iteration ' || i, 5); 7 DBMS_LOCK.SLEEP(1); 8 END LOOP; 9 --log_pkg.end_log(c_id); --<-- leave context set for demo 10 END; 11 /
While this is running, session 2 will modify the logging level for the program running in session 1. Session 2 begins by querying global context to see the current logging details of the running program (assume that session 2 knows that session 1 is running 'SCOTT.DEMO_ANON').
SQL> SELECT namespace 2 , attribute 3 , value 4 FROM global_context;
NAMESPACE ATTRIBUTE VALUE ---------- ------------------------------ ---------- LOG_CTX SCOTT.DEMO_ANON 2 1 row selected.
Session 2 will now increase the logging level of session 1. We will output the time first as it will make the output easier to follow. The SID is included for demonstration purposes (i.e. to show that we are using a separate session).
SQL> SELECT sid 2 , TO_CHAR(SYSDATE,'HH24:MI:SS') AS time 3 FROM v$mystat 4 WHERE ROWNUM = 1;
SID TIME
---------- --------
156 21:55:42
1 row selected.
SQL> exec log_pkg.set_logging_level( 'SCOTT.DEMO_ANON', 5);
PL/SQL procedure successfully completed.
We can see that session 1 started at 21:55:37 and session 2 increased its logging level some 5 seconds later at roughly 21:55:42. The output from session 1 is as follows.
10 END; 11 /
21:55:43 : Logging on iteration 7 21:55:44 : Logging on iteration 8 21:55:45 : Logging on iteration 9 21:55:46 : Logging on iteration 10 PL/SQL procedure successfully completed.
SQL> SELECT namespace 2 , attribute 3 , value 4 FROM global_context;
NAMESPACE ATTRIBUTE VALUE ---------- ------------------------------ ---------- LOG_CTX SCOTT.DEMO_ANON 5 1 row selected.
Session 1 starts to emit trace information at 21:55:43, just 1 second after session 2 raised the logging level to 5. The global application context records this fact. This clearly demonstrates dynamic, interactive logging.
dynamic logging in a multi-user environment
Our examples so far have assumed that a unique set of program names will be executing at any one time. It is far more likely that we will have PL/SQL packages in our application that are being invoked by more than one session at a time. Unless we cater for this, the logging levels for say, package X, will be global across all sessions invoking package X. If we interactively modify the level of one session that is executing package X, we will change the logging level in all package X sessions. We can avoid this by changing our logging package to be multi-session.
The simplest way to do this is to append a unique identifier for each session to the name of the program and use this as the logging ID (which sets the unique ATTRIBUTE column in the application context). For example, we could append each session's SID to its program name, as in the following example of LOG_PKG.
SQL> CREATE OR REPLACE PACKAGE log_pkg AS 2 3 FUNCTION start_log( 4 p_id IN VARCHAR2, 5 p_lvl IN PLS_INTEGER DEFAULT 1 6 ) RETURN VARCHAR2; 7 8 PROCEDURE log( 9 p_id IN VARCHAR2, 10 p_msg IN VARCHAR2, 11 p_lvl IN PLS_INTEGER DEFAULT 1 12 ); 13 14 PROCEDURE set_logging_level( 15 p_id IN VARCHAR2, 16 p_lvl IN PLS_INTEGER 17 ); 18 19 PROCEDURE end_log( 20 p_id IN VARCHAR2 21 ); 22 23 END log_pkg; 24 /
Package created.
Note that the START_LOG procedure from our previous examples is now a function. We will see its implementation below, in the revised package body.
SQL> CREATE OR REPLACE PACKAGE BODY log_pkg AS
2
3 -------------------------------------------------------------
4
5 FUNCTION start_log(
6 p_id IN VARCHAR2,
7 p_lvl IN PLS_INTEGER DEFAULT 1
8 ) RETURN VARCHAR2 IS
9
10 v_sid INTEGER;
11 v_id VARCHAR2(100);
12
13 BEGIN
14
15 SELECT sid INTO v_sid FROM v$mystat WHERE ROWNUM = 1;
16
17 v_id := p_id||':'||v_sid;
18
19 set_logging_level(v_id, p_lvl);
20
21 RETURN v_id;
22
23 END start_log;
24
25 -------------------------------------------------------------
26
27 FUNCTION logging_level(
28 p_id IN VARCHAR2
29 ) RETURN INTEGER IS
30 BEGIN
31 RETURN TO_NUMBER(SYS_CONTEXT('log_ctx', UPPER(p_id)));
32 END logging_level;
33
34 -------------------------------------------------------------
35
36 PROCEDURE log(
37 p_id IN VARCHAR2,
38 p_msg IN VARCHAR2,
39 p_lvl IN PLS_INTEGER DEFAULT 1
40 ) IS
41 BEGIN
42 IF logging_level(p_id) >= p_lvl THEN
43 DBMS_OUTPUT.PUT_LINE(
44 TO_CHAR(SYSDATE,'HH24:MI:SS ": "') || p_msg
45 );
46 END IF;
47 END log;
48
49 -------------------------------------------------------------
50
51 PROCEDURE set_logging_level(
52 p_id IN VARCHAR2,
53 p_lvl IN PLS_INTEGER
54 ) IS
55 BEGIN
56 DBMS_SESSION.SET_CONTEXT(
57 'log_ctx', UPPER(p_id), TO_CHAR(p_lvl)
58 );
59 END set_logging_level;
60
61 -------------------------------------------------------------
62
63 PROCEDURE end_log(
64 p_id IN VARCHAR2
65 ) IS
66 BEGIN
67 DBMS_SESSION.CLEAR_CONTEXT('log_ctx', NULL, UPPER(p_id));
68 END end_log;
69
70 END log_pkg;
71 /
Package body created.
The START_LOG function simply appends the calling session's SID to its ID and returns this value. This will enable multiple sessions to execute the same piece of code and maintain their own dynamic logging levels. We will test this below. Two sessions will execute the same code (i.e. with the same ID) and a third session will query GLOBAL_CONTEXT for their logging levels. First we will run a logging session at level 2, as follows.
SQL> DECLARE
2 v_id VARCHAR2(100);
3 BEGIN
4 v_id := log_pkg.start_log('SCOTT.DEMO_ANON', 2);
5 FOR i in 1 .. 10 LOOP
6 log_pkg.log(v_id, 'Logging on iteration ' || i, 5);
7 DBMS_LOCK.SLEEP(1);
8 END LOOP;
9 log_pkg.end_log(v_id);
10 END;
11 /
PL/SQL procedure successfully completed.
From another session, we will execute the same code, but at a higher logging level, as follows.
SQL> DECLARE
2 v_id VARCHAR2(100);
3 BEGIN
4 v_id := log_pkg.start_log('SCOTT.DEMO_ANON', 4);
5 FOR i in 1 .. 10 LOOP
6 log_pkg.log(v_id, 'Logging on iteration ' || i, 5);
7 DBMS_LOCK.SLEEP(1);
8 END LOOP;
9 log_pkg.end_log(v_id);
10 END;
11 /
PL/SQL procedure successfully completed.
From a third session, we will query GLOBAL_CONTEXT (while the other sessions are still running), as follows.
SQL> SELECT namespace 2 , attribute 3 , value 4 FROM global_context;
NAMESPACE ATTRIBUTE VALUE ---------- ------------------------------ ---------- LOG_CTX SCOTT.DEMO_ANON:150 2 LOG_CTX SCOTT.DEMO_ANON:159 4 2 rows selected.
We now have two logging sessions loaded at different levels for the same code. The ATTRIBUTE column gives us the ID value with which to change these levels interactively, should we wish to increase or decrease the trace output of a given session.
multi-user dynamic logging with client_identifier
An alternative solution to interactive, dynamic logging in multi-user environments is to use CLIENT_IDENTIFIER. This was introduced in Oracle 9i as a means to set and get user-specific information in a shared global context such as a connection pool (where the schema name is meaningless). When a "real user", such as a user of a website, is routed to a session in the connection pool, the client identifier property can be set for that particular user to make the application understand precisely who is connected at any given time.
We will use CLIENT_IDENTIFIER to extend our previous multi-user version of LOG_PKG. First we will replace the package specification, as follows.
SQL> CREATE OR REPLACE PACKAGE log_pkg AS 2 3 TYPE log_handle_rt IS RECORD 4 ( id VARCHAR2(100) 5 , sid INTEGER 6 , uname VARCHAR2(30) ); 7 8 FUNCTION start_log( 9 p_lvl IN INTEGER DEFAULT 1 10 ) RETURN log_handle_rt; 11 12 PROCEDURE log( 13 p_hdl IN log_handle_rt, 14 p_msg IN VARCHAR2, 15 p_lvl IN INTEGER DEFAULT 1 16 ); 17 18 PROCEDURE end_log( 19 p_hdl IN log_handle_rt 20 ); 21 22 PROCEDURE set_logging_level( 23 p_sid IN INTEGER, 24 p_lvl IN INTEGER 25 ); 26 27 FUNCTION logging_level( 28 p_sid IN INTEGER 29 ) RETURN INTEGER; 30 31 END log_pkg; 32 /
Package created.
Note the key differences as follows.
- we have a new record type, which will contain logging handle information for a calling program;
- the START_LOG function does not require an ID to be passed in. The LOG_PKG will determine the name of the calling program and return a logging handle for use in subsequent procedure calls; and
- the logging level will be interactively set using a session's SID as the identifier. It will no longer be necessary to know the program name being executed in the target session.
The package body for this version of LOG_PKG is as follows.
SQL> CREATE OR REPLACE PACKAGE BODY log_pkg AS
2
3 c_ctx CONSTANT VARCHAR2(10) := 'LOG_CTX';
4
5 -------------------------------------------------------------
6
7 FUNCTION get_caller RETURN VARCHAR2 IS
8 v_stk VARCHAR2(4000) := DBMS_UTILITY.FORMAT_CALL_STACK;
9 v_dpt PLS_INTEGER := 6;
10 v_pos PLS_INTEGER := 21;
11 v_dlm VARCHAR2(1) := CHR(10);
12 BEGIN
13 RETURN NVL(
14 SUBSTR(
15 SUBSTR(
16 v_stk,
17 INSTR( v_stk, v_dlm ,1,(v_dpt-1))+1,
18 INSTR( v_stk, v_dlm ,1, v_dpt) -
19 (INSTR( v_stk, v_dlm, 1, (v_dpt-1)))-1
20 ),
21 v_pos ),
22 '[unknown]' );
23 END get_caller;
24
25 -------------------------------------------------------------
26
27 FUNCTION get_sid RETURN INTEGER IS
28 v_sid INTEGER;
29 BEGIN
30 SELECT sid INTO v_sid FROM v$mystat WHERE ROWNUM = 1;
31 RETURN v_sid;
32 END get_sid;
33
34 ---------------------------------------------------------------
35
36 FUNCTION get_handle(
37 p_sid IN INTEGER
38 ) RETURN log_handle_rt IS
39
40 r_hdl log_handle_rt;
41
42 BEGIN
43
44 SELECT attribute, client_identifier, username INTO r_hdl
45 FROM global_context
46 WHERE client_identifier = TO_CHAR(p_sid);
47
48 RETURN r_hdl;
49
50 EXCEPTION
51 WHEN NO_DATA_FOUND THEN
52 RAISE_APPLICATION_ERROR(
53 -20000, 'SID not found in logging context'
54 );
55 END get_handle;
56
57 ---------------------------------------------------------------
58
59 PROCEDURE set_identifier(
60 p_sid IN INTEGER
61 ) IS
62 BEGIN
63 DBMS_SESSION.SET_IDENTIFIER(TO_CHAR(p_sid));
64 END set_identifier;
65
66 ---------------------------------------------------------------
67
68 PROCEDURE clear_identifier IS
69 BEGIN
70 DBMS_SESSION.CLEAR_IDENTIFIER;
71 END clear_identifier;
72
73 ---------------------------------------------------------------
74
75 PROCEDURE set_logging_level_internal(
76 p_hdl IN log_handle_rt,
77 p_lvl IN INTEGER
78 ) IS
79 BEGIN
80 DBMS_SESSION.SET_CONTEXT(
81 c_ctx, p_hdl.id, TO_CHAR(p_lvl), p_hdl.uname,
82 TO_CHAR(p_hdl.sid)
83 );
84 END set_logging_level_internal;
85
86 ---------------------------------------------------------------
87
88 FUNCTION start_log(
89 p_lvl IN INTEGER DEFAULT 1
90 ) RETURN log_handle_rt IS
91
92 v_caller VARCHAR2(100);
93 r_handle log_handle_rt;
94
95 BEGIN
96
97 v_caller := get_caller();
98
99 r_handle.id := SUBSTR(v_caller,INSTR(v_caller,'.')+1);
100 r_handle.sid := get_sid();
101 r_handle.uname := SUBSTR(
102 SUBSTR(v_caller,1,INSTR(v_caller,'.')-1),
103 INSTR(v_caller,' ',-1)+1
104 );
105
106 set_identifier(r_handle.sid);
107 set_logging_level_internal(r_handle, p_lvl);
108 clear_identifier();
109
110 RETURN r_handle;
111
112 END start_log;
113
114 ---------------------------------------------------------------
115
116 FUNCTION logging_level(
117 p_hdl IN log_handle_rt
118 ) RETURN INTEGER IS
119 BEGIN
120 RETURN TO_NUMBER(SYS_CONTEXT('log_ctx',p_hdl.id));
121 END logging_level;
122
123 ---------------------------------------------------------------
124
125 FUNCTION logging_level(
126 p_sid IN INTEGER
127 ) RETURN INTEGER IS
128 r_hdl log_handle_rt;
129 v_lvl INTEGER;
130 BEGIN
131 set_identifier(p_sid);
132 r_hdl := get_handle(p_sid);
133 v_lvl := logging_level(r_hdl);
134 clear_identifier();
135 RETURN v_lvl;
136 END logging_level;
137
138 ---------------------------------------------------------------
139
140 PROCEDURE log( p_hdl IN log_handle_rt,
141 p_msg IN VARCHAR2,
142 p_lvl IN INTEGER DEFAULT 1 ) IS
143 BEGIN
144 set_identifier(p_hdl.sid);
145 IF logging_level(p_hdl) >= p_lvl THEN
146 DBMS_OUTPUT.PUT_LINE(
147 TO_CHAR(SYSDATE,'HH24:MI:SS ": "') || p_msg
148 );
149 END IF;
150 clear_identifier();
151 END log;
152
153 ---------------------------------------------------------------
154
155 PROCEDURE end_log(
156 p_hdl IN log_handle_rt
157 ) IS
158 BEGIN
159 set_identifier(p_hdl.sid);
160 DBMS_SESSION.CLEAR_CONTEXT(
161 c_ctx, TO_CHAR(p_hdl.sid), p_hdl.id
162 );
163 clear_identifier();
164 END end_log;
165
166 ---------------------------------------------------------------
167
168 PROCEDURE set_logging_level(
169 p_sid IN INTEGER,
170 p_lvl IN INTEGER
171 ) IS
172 r_hdl log_handle_rt;
173 BEGIN
174 set_identifier(p_sid);
175 r_hdl := get_handle(p_sid);
176 set_logging_level_internal(r_hdl, p_lvl);
177 clear_identifier();
178 END set_logging_level;
179
180 ---------------------------------------------------------------
181
182 END log_pkg;
183 /
Package body created.
This version of the package body is noticeably larger than previous examples. The main point to note is how CLIENT_IDENTIFIER and global application context interact. When CLIENT_IDENTIFIER is set, only sessions with the same identifier can share the context data. In essence, the global context data becomes "private" to a given identifier. In our LOG_PKG, before we attempt to access any client-specific context attributes, we must "attach" to it first using SET_IDENTIFIER. Once we have set or retrieved the context data (in our case the logging level), we "detach" from the context by clearing the CLIENT_IDENTIFIER for our session.
We are using SID as the client identifier in this case (this distinguishes one session running package X from another). It is therefore easy to interactively or dynamically modify the logging level of another session, as we will see below.
To test this new version of LOG_PKG, we will create a small user-procedure called DEMO_PROC. This procedure will simply log and sleep in a loop of a given number of iterations. The procedure is as follows.
SQL> CREATE PROCEDURE demo_proc (
2 p_workload IN PLS_INTEGER
3 ) AS
4
5 v_lh log_pkg.log_handle_rt;
6
7 BEGIN
8
9 DBMS_APPLICATION_INFO.SET_MODULE('DEMO_PROC', TO_CHAR(p_workload));
10
11 v_lh := log_pkg.start_log(1);
12
13 log_pkg.log(v_lh, 'Opening logging message at level 1', 1);
14
15 -- Intensive processing...
16 FOR i in 1 .. p_workload LOOP
17 log_pkg.log(v_lh, 'Logging at level 4 on iteration ' || i, 4);
18 DBMS_LOCK.SLEEP(1);
19 END LOOP;
20
21 log_pkg.log(v_lh, 'Closing logging message at level 1', 1);
22
23 log_pkg.end_log(v_lh);
24
25 END;
26 /
Procedure created.
We will start three sessions, two of which will be running different workloads using the DEMO_PROC procedure. We will start these as follows.
SQL> exec demo_proc(50);
SQL> exec demo_proc(20);
While we are running the two invocations of DEMO_PROC, we will dynamically alter the session with the heavier workload to increase its logging level. Because we included a call to DBMS_APPLICATION_INFO in DEMO_PROC, we can use V$SESSION to determine which sessions are running this package as follows. Remember that unless we attach to a specific CLIENT_IDENTIFIER, the global context information is hidden from us.
SQL> SELECT sid, module, action, log_pkg.logging_level(sid) AS log_lvl 2 FROM v$session 3 WHERE status = 'ACTIVE' 4 AND module = 'DEMO_PROC';
SID MODULE ACTION LOG_LVL
---------- ----------------- --------------- --------
156 DEMO_PROC 20 1
158 DEMO_PROC 50 1
2 rows selected.
Still in the third session, we will raise the logging level of the session with the heaviest workload.
SQL> exec log_pkg.set_logging_level( &sid, 5);
Enter value for sid: 158 PL/SQL procedure successfully completed.
SQL> SELECT TO_CHAR(SYSDATE,'HH24:MI:SS') AS time 2 FROM dual;
TIME -------- 08:07:48 1 row selected.
SQL> SELECT sid, module, action, log_pkg.logging_level(sid) AS log_lvl 2 FROM v$session 3 WHERE status = 'ACTIVE' 4 AND module = 'DEMO_PROC';
SID MODULE ACTION LOG_LVL
---------- ----------------- --------------- --------
156 DEMO_PROC 20 1
158 DEMO_PROC 50 5
2 rows selected.
We modified session 158's logging level at 08:07:48 and our v$session query confirms its new value. We can see below that the session with the lighter workload completes 3 seconds later without emitting any low-level logging information.
SQL> exec demo_proc(20);
08:07:31 : Opening logging message at level 1 08:07:51 : Closing logging message at level 1 PL/SQL procedure successfully completed.
The output for session 158 is as follows. Note how the low-level trace information starts to appear 1 second after we raised the logging level of DEMO_PROC for this session.
SQL> exec demo_proc(50);
08:07:25 : Opening logging message at level 1 08:07:49 : Logging at level 4 on iteration 25 08:07:50 : Logging at level 4 on iteration 26 08:07:51 : Logging at level 4 on iteration 27 08:07:52 : Logging at level 4 on iteration 28 08:07:53 : Logging at level 4 on iteration 29 08:07:54 : Logging at level 4 on iteration 30 08:07:55 : Logging at level 4 on iteration 31 08:07:56 : Logging at level 4 on iteration 32 08:07:57 : Logging at level 4 on iteration 33 08:07:58 : Logging at level 4 on iteration 34 08:07:59 : Logging at level 4 on iteration 35 08:08:00 : Logging at level 4 on iteration 36 08:08:01 : Logging at level 4 on iteration 37 08:08:02 : Logging at level 4 on iteration 38 08:08:03 : Logging at level 4 on iteration 39 08:08:04 : Logging at level 4 on iteration 40 08:08:05 : Logging at level 4 on iteration 41 08:08:06 : Logging at level 4 on iteration 42 08:08:07 : Logging at level 4 on iteration 43 08:08:08 : Logging at level 4 on iteration 44 08:08:09 : Logging at level 4 on iteration 45 08:08:10 : Logging at level 4 on iteration 46 08:08:11 : Logging at level 4 on iteration 47 08:08:12 : Logging at level 4 on iteration 48 08:08:13 : Logging at level 4 on iteration 49 08:08:14 : Logging at level 4 on iteration 50 08:08:15 : Closing logging message at level 1 PL/SQL procedure successfully completed.
using a table instead of global application context
Most readers will have realised quite early on that we could just as easily use a table to store transient logging parameters such as the logging level. To complete this article, we will return to our simplified multi-user version of LOG_PKG and create an equivalent table-based version. We will then compare the performance of the two approaches.
We will begin by creating a very simple logging configuration table as follows.
SQL> CREATE TABLE log_cfg 2 ( id VARCHAR2(100) PRIMARY KEY 3 , logging_level INTEGER 4 ) 5 ORGANIZATION INDEX;
Table created.
This table will store the session-specific identifier (e.g. SCOTT.DEMO_ANON:123) of a program instance in our database and its logging level. The LOG_PKG package body implementation using this table is as follows (the specification is the unchanged).
SQL> CREATE OR REPLACE PACKAGE BODY log_pkg AS 2 3 ------------------------------------------------------------- 4 5 FUNCTION start_log( 6 p_id IN VARCHAR2, 7 p_lvl IN PLS_INTEGER DEFAULT 1 8 ) RETURN VARCHAR2 IS 9 10 v_sid INTEGER; 11 v_id VARCHAR2(100); 12 13 BEGIN 14 15 SELECT sid INTO v_sid FROM v$mystat WHERE ROWNUM = 1; 16 17 v_id := p_id||':'||v_sid; 18 19 set_logging_level(v_id, p_lvl); 20 21 RETURN v_id; 22 23 END start_log; 24 25 ------------------------------------------------------------- 26 27 FUNCTION logging_level( 28 p_id IN VARCHAR2 29 ) RETURN INTEGER IS 30 31 v_lvl INTEGER; 32 33 BEGIN 34 35 SELECT logging_level INTO v_lvl 36 FROM log_cfg 37 WHERE id = p_id; 38 39 RETURN v_lvl; 40 41 EXCEPTION 42 WHEN NO_DATA_FOUND THEN 43 RAISE_APPLICATION_ERROR( 44 -20000, 'ID not found in logging context' 45 ); 46 END logging_level; 47 48 ------------------------------------------------------------- 49 50 PROCEDURE log( 51 p_id IN VARCHAR2, 52 p_msg IN VARCHAR2, 53 p_lvl IN PLS_INTEGER DEFAULT 1 54 ) IS 55 BEGIN 56 IF logging_level(p_id) >= p_lvl THEN 57 DBMS_OUTPUT.PUT_LINE( 58 TO_CHAR(SYSDATE,'HH24:MI:SS ": "') || p_msg 59 ); 60 END IF; 61 END log; 62 63 ------------------------------------------------------------- 64 65 PROCEDURE set_logging_level( 66 p_id IN VARCHAR2, 67 p_lvl IN PLS_INTEGER 68 ) IS 69 70 PRAGMA AUTONOMOUS_TRANSACTION; 71 72 BEGIN 73 74 MERGE 75 INTO log_cfg tgt 76 USING ( 77 SELECT p_id AS id 78 , p_lvl AS logging_level 79 FROM dual 80 ) src 81 ON (src.id = tgt.id) 82 WHEN MATCHED 83 THEN 84 UPDATE 85 SET tgt.logging_level = src.logging_level 86 WHEN NOT MATCHED 87 THEN 88 INSERT (tgt.id, tgt.logging_level) 89 VALUES (src.id, src.logging_level); 90 91 COMMIT; 92 93 END set_logging_level; 94 95 ------------------------------------------------------------- 96 97 PROCEDURE end_log( 98 p_id IN VARCHAR2 99 ) IS 100 PRAGMA AUTONOMOUS_TRANSACTION; 101 BEGIN 102 DELETE FROM log_cfg WHERE id = p_id; 103 COMMIT; 104 END end_log; 105 106 END log_pkg; 107 /
Package body created.
As stated, we are deliberately using the simplified multi-user version of LOG_PKG. We can see that the global application calls have been replaced with equivalent table-based operations. To compare the runtimes, we will use the following anonymous block.
SQL> set timing on
SQL> DECLARE
2
3 v_id VARCHAR2(100);
4
5 BEGIN
6
7 v_id := log_pkg.start_log('SCOTT.DEMO_ANON',2);
8
9 FOR i IN 1 .. 1000000 LOOP
10 log_pkg.log(
11 v_id,
12 'Iteration ' || i || ' will not be logged',4
13 );
14 END LOOP;
15
16 log_pkg.end_log(v_id);
17
18 END;
19 /
For the timing test, we will not bother with interactive, dynamic logging. We will simply loop 1 million times at a level that will not be emitted. The timings are as follows.
| Attributes in Context | Context Timing (s) | Table Timing (s) |
| 1 | 6.75 | 41.14 |
| 100 | 6.90 | 42.25 |
| 1000 | 6.79 | 42.60 |
We can see that the number of attributes set in the context has no impact on the timings and the application context method is considerably faster (the same is true of the more complex CLIENT_IDENTIFIER version of the context-based package). We will not spend any more time comparing these implementations. The above examples are unsophisticated but show that we can use a table-based implementation for interactive logging, but we will pay a performance cost. Global application context is an efficient way to interact across sessions and provides an added dimension to our instrumentation techniques.
The above performance comparison was conducted on a 10g Release 2 database. Users of Oracle 9i might discover that logging with global application context actually performs worse than the table-based logging implementation. Some further investigation with SQL Trace and the STANDARD package source leads us to the reason. When we call the SYS_CONTEXT function from within PL/SQL in 9i, Oracle queries DUAL to evaluate it (i.e. Oracle issues SELECT SYS_CONTEXT(:b1, :b2) INTO c FROM dual. This has a significant performance penalty. In 10g, however, Oracle optimises this in two ways (which is why context-based logging is much quicker in 10g, as confirmed by our performance tests). First, there is a new primary method of accessing the context namespace directly from memory, with a fall-back to the original DUAL method only if the new codepath returns a NULL result. The absence of any references to SYS_CONTEXT evaluation in 10g and 11g SQL Trace files suggests that this fall-back method has not been required. Second, if the fall-back to DUAL is required, Oracle has a new "FAST DUAL" optimisation that has no I/O costs.
acknowledgements
Thanks to Madis Priilinn for discovering that 9i context-based logging is slower than the table-based equivalent.
further reading
To read more about application context and its uses, see the Security Guide. Documentation on DBMS_SESSION is also available in the online PL/SQL Packages and Types Reference.
source code
The source code for the examples in this article can be downloaded from here.
Adrian Billington, September 2007 (updated April 2009)
Back to Top