OLF: Creating Dynamic Logging
One of the real benefits to using a logging tool is being able to dynamically set log levels. Whether it’s for a single user, program or task you don’t want to have to stop everything, reset a config file and then restart the application. You really want to be able to set the logging dynamically on the fly. The problem with this approach is that to effectively do that means checking every time a logging call is made to see what the current log configuration is. This seems expensive since it usually means querying a table in the database for every call.
A new feature in Oracle 11g is the SQL Query Result Cache which stores the results of SQL queries in an area in the shared pool. By simply supplying a hint and having the result cache enabled, repetitive queries that return the same results are cached, causing almost no work for the database. The following is an example using code from the Oracle Logging Framework.
First a table to store our logging configuration data:
CREATE TABLE dblog_config
(
config_id NUMBER CONSTRAINT dblog_config_nn1 NOT NULL ENABLE,
module_name VARCHAR2(30),
action_name VARCHAR2(30),
username VARCHAR2(30),
sid NUMBER,
inst_id NUMBER,
log_level VARCHAR(10) DEFAULT 'INFO' CONSTRAINT dblog_config_nn2 NOT NULL ENABLE,
trace_enabled CHAR(1) CONSTRAINT dblog_config_nn3 NOT NULL ENABLE,
CONSTRAINT dblog_config_ck1 CHECK(log_level IN ('ALL','DEBUG','INFO','WARN','ERROR','FATAL','TIMED','OFF')),
CONSTRAINT dblog_config_ck2 CHECK(trace_enabled IN ('Y','N')),
CONSTRAINT dblog_config_pk PRIMARY KEY (config_id) ENABLE
)
NOCOMPRESS
LOGGING;
--
I have added a single row for our testing:
SQL> select * from dbamon.dblog_config;
CONFIG_ID MODULE_NAME ACTION_NAME USERNAME SID INST_ID LOG_LEVEL TRACE_ENABLED
--------- ----------- ----------- -------- ----- ------- --------- -------------
1 module action INFO Y
SQL>
The following query can then be used by our logging code to determine the current configuration for “module” and “action”. This query also allows other fields in our configuration table to trigger actions, but for now we’ll focus on module and action:
SELECT /*+ RESULT_CACHE */ debugid,module_name,action_name,
username,sid,inst_id,UPPER(log_level) AS log_level,
UPPER(trace_enabled) AS trace_enabled
FROM dbamon.dblog_config
WHERE (UPPER(module_name)=UPPER('&&module')
AND UPPER(action_name)=UPPER('&&action')
AND username IS NULL
AND sid IS NULL)
--
OR (UPPER(module_name)=UPPER('&&module')
AND UPPER(action_name)=UPPER('&&action')
AND UPPER(username)=UPPER(USER)
AND sid IS NULL)
--
OR ( UPPER(module_name)=UPPER('&&module')
AND UPPER(action_name)=UPPER('&&action')
AND username IS NULL
AND (sid=SYS_CONTEXT('USERENV','SID')
AND inst_id=SYS_CONTEXT('USERENV','INSTANCE')))
--
OR ( UPPER(module_name)=UPPER('&&module')
AND UPPER(action_name)=UPPER('&&action')
AND UPPER(username)=UPPER(USER)
AND (sid=SYS_CONTEXT('USERENV','SID')
AND inst_id=SYS_CONTEXT('USERENV','INSTANCE')))
--
--
OR ( module_name IS NULL
AND UPPER(action_name)=UPPER('&&action')
AND username IS NULL
AND sid IS NULL )
--
OR ( module_name IS NULL
AND UPPER(action_name)=UPPER('&&action')
AND UPPER(username)=UPPER(USER)
AND sid IS NULL )
--
OR ( module_name IS NULL
AND UPPER(action_name)=UPPER('&&action')
AND username IS NULL
AND (sid=SYS_CONTEXT('USERENV','SID')
AND inst_id=SYS_CONTEXT('USERENV','INSTANCE')) )
--
OR ( module_name IS NULL
AND UPPER(action_name)=UPPER('&&action')
AND UPPER(username)=UPPER(USER)
AND (sid=SYS_CONTEXT('USERENV','SID')
AND inst_id=SYS_CONTEXT('USERENV','INSTANCE')) )
--
--
OR ( module_name IS NULL
AND action_name IS NULL
AND username IS NULL
AND sid IS NULL )
--
OR ( module_name IS NULL
AND action_name IS NULL
AND UPPER(username)=UPPER(USER)
AND sid IS NULL )
--
OR ( module_name IS NULL
AND action_name IS NULL
AND username IS NULL
AND (sid=SYS_CONTEXT('USERENV','SID')
AND inst_id=SYS_CONTEXT('USERENV','INSTANCE')) )
--
OR ( module_name IS NULL
AND action_name IS NULL
AND (sid=SYS_CONTEXT('USERENV','SID')
AND inst_id=SYS_CONTEXT('USERENV','INSTANCE')) )
/
The cost to run this query the first time is shown below:
CONFIG_ID MODULE_NAME ACTION_NAME USERNAME SID INST_ID LOG_LEVEL TRACE_ENABLED
--------- ----------- ----------- -------- ----- ------- --------- -------------
1 module action INFO Y
Execution Plan
----------------------------------------------------------
Plan hash value: 2514110033
-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 24 | 3 (0)| 00:00:01 |
| 1 | RESULT CACHE | fq5ph52dq320u241n2r7pxkxn5 | | | | |
|* 2 | TABLE ACCESS FULL| DBLOG_CONFIG | 1 | 24 | 3 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter(UPPER("MODULE_NAME")='MODULE' AND UPPER("ACTION_NAME")='ACTION' AND
"USERNAME" IS NULL AND "SID" IS NULL OR UPPER("MODULE_NAME")='MODULE' AND
UPPER("ACTION_NAME")='ACTION' AND UPPER("USERNAME")=UPPER(USER@!) AND "SID" IS NULL OR
UPPER("MODULE_NAME")='MODULE' AND UPPER("ACTION_NAME")='ACTION' AND
"SID"=TO_NUMBER(SYS_CONTEXT('USERENV','SID')) AND
"INST_ID"=TO_NUMBER(SYS_CONTEXT('USERENV','INSTANCE')) AND "USERNAME" IS NULL OR
UPPER("MODULE_NAME")='MODULE' AND UPPER("ACTION_NAME")='ACTION' AND
UPPER("USERNAME")=UPPER(USER@!) AND "SID"=TO_NUMBER(SYS_CONTEXT('USERENV','SID')) AND
"INST_ID"=TO_NUMBER(SYS_CONTEXT('USERENV','INSTANCE')) OR "MODULE_NAME" IS NULL AND
UPPER("ACTION_NAME")='ACTION' AND "USERNAME" IS NULL AND "SID" IS NULL OR "MODULE_NAME"
IS NULL AND UPPER("ACTION_NAME")='ACTION' AND UPPER("USERNAME")=UPPER(USER@!) AND "SID"
IS NULL OR "MODULE_NAME" IS NULL AND UPPER("ACTION_NAME")='ACTION' AND
"SID"=TO_NUMBER(SYS_CONTEXT('USERENV','SID')) AND
"INST_ID"=TO_NUMBER(SYS_CONTEXT('USERENV','INSTANCE')) AND "USERNAME" IS NULL OR
"MODULE_NAME" IS NULL AND UPPER("ACTION_NAME")='ACTION' AND
UPPER("USERNAME")=UPPER(USER@!) AND "SID"=TO_NUMBER(SYS_CONTEXT('USERENV','SID')) AND
"INST_ID"=TO_NUMBER(SYS_CONTEXT('USERENV','INSTANCE')) OR "MODULE_NAME" IS NULL AND
"ACTION_NAME" IS NULL AND "USERNAME" IS NULL AND "SID" IS NULL OR "MODULE_NAME" IS NULL
AND "ACTION_NAME" IS NULL AND UPPER("USERNAME")=UPPER(USER@!) AND "SID" IS NULL OR
"MODULE_NAME" IS NULL AND "ACTION_NAME" IS NULL AND
"SID"=TO_NUMBER(SYS_CONTEXT('USERENV','SID')) AND
"INST_ID"=TO_NUMBER(SYS_CONTEXT('USERENV','INSTANCE')) AND "USERNAME" IS NULL OR
"MODULE_NAME" IS NULL AND "ACTION_NAME" IS NULL AND
"SID"=TO_NUMBER(SYS_CONTEXT('USERENV','SID')) AND
"INST_ID"=TO_NUMBER(SYS_CONTEXT('USERENV','INSTANCE')))
Result Cache Information (identified by operation id):
------------------------------------------------------
1 - column-count=8; dependencies=(DBAMON.DBLOG_CONFIG); parameters=(uid, nls, sys_context); name="SELECT /*+ RESULT_CACHE */ config_id,module_name,action_name,
username,sid,inst_id,UPPER(log_level) AS log_level,
UPPER(trace_en"
Statistics
----------------------------------------------------------
127 recursive calls
0 db block gets
153 consistent gets
0 physical reads
0 redo size
887 bytes sent via SQL*Net to client
419 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
6 sorts (memory)
0 sorts (disk)
1 rows processed
Note that the explain plan contains a result cache operation so our hint was accepted. Subsequent runs show the advantage of the result cache. No logical I/Os are required once the results are cached:
Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 0 consistent gets 0 physical reads 0 redo size 887 bytes sent via SQL*Net to client 419 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed
The second query is almost “free”. What happens if we change a value in our “config” table? If we change the debug level from “INFO” to “DEBUG” then Oracle has to do a little more work:
CONFIG_ID MODULE_NAME ACTION_NAME USERNAME SID INST_ID LOG_LEVEL TRACE_ENABLED
--------- ----------- ----------- -------- ----- ------- --------- -------------
1 module action DEBUG Y
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
7 consistent gets
0 physical reads
0 redo size
888 bytes sent via SQL*Net to client
419 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
Note that I didn’t show it, but the execution plan stays the same, and the query now requires 7 logical I/Os. The database had to access the table to get the updated data. A subsequent query shows the use of the query result cache again:
CONFIG_ID MODULE_NAME ACTION_NAME USERNAME SID INST_ID LOG_LEVEL TRACE_ENABLED
--------- ----------- ----------- -------- ----- ------- --------- -------------
1 module action DEBUG Y
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
0 consistent gets
0 physical reads
0 redo size
888 bytes sent via SQL*Net to client
419 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
So if we use this technique to query our configuration table during each call from the framework the cost of being able to dynamically adjust logging is pretty low. This means we can easily change the logging level, or enable or disable logging or tracing on the fly for any session that uses the framework.
Note: I changed the name of the configuration table from what I had originally posted and this is now reflected in the examples. The configuration table will be called “dblog_config” in the first version of the OLF.
Entries