rmoff

February 2, 2011

Instrumenting OBIEE for tracing Oracle DB calls

Filed under: log, monitoring, obiee, oracle, performance, usagetracking — rmoff @ 15:04

Cary Millsap recently published a paper “Mastering Performance with Extended SQL Trace” describing how to use Oracle trace to assist with troubleshooting the performance of database queries.
As with all of Cary Millsap’s papers it is superbly written, presenting very detailed information in a clear and understandable way. (and yes I do have a DBA crush ;-))
It discusses how you can automate the tracing of specific sessions on the database, and requiring the application to be appropriately instrumented. This reminded me of a post that I made almost exactly 12 months ago here, where I explained how to pass through the username of the OBIEE user to the database. Initially I thought it would be useful simply for being able to pin a rogue query to an end-user, but reading Cary’s paper made me realise there is more potential to it.

Why would you use it in OBIEE?

Essentially, it enables you to precisely identify DB connections coming in from OBIEE. Since you can identify the connections, you can then trace them or collect additional statistics on them.

In Production, this would be useful for helping with troubleshooting. If a query is behaving badly, the responsible user can be easily identified, and through the login ID matched back to Usage Tracking data (you do collect Usage Tracking data, right?). Conversely, if a user is complaining (unlikely, I know 😉 ) of performance issues you can easily spot their queries running on the database and get a head start on identifying the problem.

As well as tracing, you can use these attributes to collect statistics (eg I/O wait time, db time, etc) for specific users or application areas. You use the DBMS_MONITOR CLIENT_ID_STAT_ENABLE procedure and then view the stats in V$CLIENT_STAT. Similar proc & V$ table exist for module-targeted statistics collecting.

Implementation

In essence, all you do is use the OBIEE Connection Scripts setting in the appropriate Connection Pool to call one or more of the PL/SQL packages. The values that you can set on the connection are as follows:

V$SESSION column Corresponding connection command to set Max value length
MODULE dbms_application_info.set_module(module_name=>'[…]’,action_name =>NULL) 47
ACTION dbms_application_info.set_module(module_name=>'[…]’,action_name=>'[…]’)
or
dbms_application_info.set_action(action_name=>'[…]’)
31
CLIENT_INFO dbms_application_info.set_client_info 63
CLIENT_IDENTIFIER dbms_session.set_identifier 63

(Ref: DBMS_APPLICATION_INFO, DBMS_SESSION)

For example, to pass through the OBIEE username and display name (NQ_SESSION.USER and NQ_SESSION.DISPLAYNAME respectively) you would use the following code:

Connection Pool settings

When you look at V$SESSION for the connection from OBIEE, it would show up something like this:

V$SESSION showing values from OBIEE connection

Instrument individual reports

What would be really cool would be if we could pass through the details of the report being executed.
A rather clunky way of doing this is by setting a custom session variable in the Logical SQL that gets sent to BI Server:

Then add a script to the connection pool to pass this value through in the database connection:

When run this then shows up on V$SESSION as:

col client_identifier for a20
col client_info for a20
SELECT PROGRAM, CLIENT_IDENTIFIER, CLIENT_INFO, MODULE, ACTION FROM V$SESSION WHERE LOWER(PROGRAM) LIKE 'nqsserver%';

You get an error if you’ve not set a value for the variable that is referenced in the connection script (in the above example, “REPORT”). So what you could do is create a dummy session variable called REPORT with a default value (eg “<unspecified report>”), which will then be used if a report doesn’t override it:

Dummy session variable


Dummy init block

Variables

It may be my misunderstanding of the subtleties of the flavours of OBIEE variables, but the behaviours seem inconsistent to me. For example, even though I am issuing a SET VARIABLE in my logical SQL, the value of the variable REPORT doesn’t change from its default (in this example ‘NONE’) when listed in the Session Manager or queried via Narrative view. It isn’t even shown if I don’t create it as a session variable in the RPD.

Unchanging session variable value

Session variables displayed in Answers

Despite this, the modified value of the variable is what gets passed through correctly in the DB connection.

SAW_SRC_PATH

This is a variable (along with QUERY_SRC_CD) that is passed automagically by Presentation Services to BI Server in the Logical SQL it executes:

Logical SQL, as seen in NQQuery.log

If this could be harnessed and manipulated (eg right-most 63 chars) then the report details of any report could be automatically included with the DB connection string. But – try as I have I can’t access the variable through VALUEOF. Anyone know how?

References

Advertisements

August 20, 2009

Logging specific types of sawserver activity

Filed under: config, log, sawserver — rmoff @ 13:13

As well as tinkering with the sawserver (Presentation Services) logging level and format, we can specific which bits of the log we’re interested in. This is useful for two reasons:

  1. We can enable detailed logging for a specific area, without impacting performance as much as detailed logging throughout would cause
  2. By only logging in detail the area of interest we can more easily read the log output and not have to wade through pages of irrelevant information

Chapter 9 (“Using the Oracle BI Presentation Services Logging Facility”) of the Presentation Services Administration Guide details the log configuration.

To capture, for example, only inbound and outbound HTTP logs, you would amend your logconfig.xml to include this in the <Filters> section, where path is the restriction you want to apply.

<FilterRecord writerClassGroup="File" path="saw.httpserver.request" information="51" warning="100" error="100" security="41" />
<FilterRecord writerClassGroup="File" path="saw.httpserver.response" information="51" warning="100" error="100" security="41" />

If you want to write the information to a separate file, define a new Writer:

<Writers>
[...]
<Writer implementation="FileLogWriter" name="Global File Logger" writerClassId="7" dir="/tmp" filePrefix="sawodbc"/>
[...]
</Writers>

(use an unused writerClassId)
and WriterClassGroup:

 <WriterClassGroups>
[...]
<WriterClassGroup name="FileODBC">7</WriterClassGroup>
[...]
 </WriterClassGroups>

and use the newly defined WriterClassGroup in the Filter:

 <FilterRecord writerClassGroup="FileODBC" path = "saw.odbc" information="51" warning="100" error="100" security="41"/>

All of the odbc logging will now be written to a file in /tmp called sawodbc0.log.

To get a list of all possible path values, run sawserver with the -logsources commandline option

$ . ./common.sh
$ . ./sa-init.sh
$ sawserver -logsources
saw
saw.SOAP
saw.SOAP.JobManagementService
saw.answers
saw.answers.search
saw.authconfigmanager
saw.authconfigmanager.initialize
saw.cacheseeding
saw.catalog
saw.catalog.archive
saw.catalog.archive.merge
saw.catalog.archive.read
saw.catalog.archive.write
saw.catalog.archive.write.singleobject
saw.catalog.file
saw.catalog.filelock
saw.catalog.impl
saw.catalog.impl.cleanup
saw.catalog.impl.explainPermissions
[...etc etc...]

August 19, 2009

sawserver log – short format

Filed under: config, hack, log, sawserver — rmoff @ 14:02

I posted a while ago about the sawserver (Presentation Services) log configuration file.
Today I’m doing some work digging around why sawserver’s throwing an error and so increased the log detail. This parameter is really helpful to use:

fmtName=”short”

Consider in these two screenshots, the first is with the default log format and shows about six entries. The second is short log format and is about ten times as much data.

sawlog01

default log format

sawlog02

short log format

Horses for courses, but on a “fishing expedition” through a log I’d say the short format is definitely easier to work with.

To implement it update $OracleBIData/web/config/logconfig.xml and change the Writer definition:

[...]
	<Writers>
		<Writer implementation="CoutWriter" name="Global Output  Logger" writerClassId="2"/>
[...]
[...]
	<Writers>
		<Writer fmtName="short" implementation="CoutWriter" name="Global Output  Logger" writerClassId="2"/>
[...]

and restart Presentation Services. On a tangent, a lazy way to do this on unix whilst leaving time for ports to free up before restarting is:

run-saw.sh stop;sleep 60;run-saw.sh start64

July 23, 2009

sawserver logging configuration – logconfig.xml

Filed under: config, hack, log, sawserver — rmoff @ 17:40

The configuration of how Presentation Services (sawserver) does its logging is in the file web/config/logconfig.xml (same directory as instanceconfig.xml).

It’s all nice and XML’d:


Logging Detail
Change the numerical values in the FilterRecord entries to alter the detail level of the logging. Lower means less detail, higher means more.

Be aware that your log files can grow very rapidly if you set the logging too high, and unless you’re troubleshooting then leave them at the defaults.

Logging Configuration
You can change various things like how many log files are written, to what size, and also the format of the log entries:
This configuration is in the Writer definition, in the case of format set fmtName=”short”
Being able to write a single-line entry is very useful in the case of monitoring software (eg. OpenView) which can’t parse multiple line log entries.

sawserver.out.log and saw[x].log
sawserver.out.log is the stdout logging from presentation services. In Unix this is captured to sawserver.out.log, whereas in Windows I don’t think it’s captured.
saw[x].log is the file logging from presentation services

The level of information for both files is defined in logconfig.xml:

<filterrecord writerclassgroup=”Cout” path = “saw” information=”31″ warning=”41″ error=”41″ security=”41″>
<filterrecord writerclassgroup=”File” path = “saw” information=”31″ warning=”100″ error=”100″ security=”41″>

So by default you’ll more detail in your saw[x].log (writerClassGroup=”File”) than sawserver.out.log (the redirected stdout, writerClassGroup=”Cout”). In sawserver.out.log you’ll get the same Information and Security type messages as saw[x].log, but fewer (only those of greater severity) Warning and Error type messages.

More detail
See Presentation Services Administration Guide “Using the Oracle BI Presentation Services Logging Facility” for more very detailed information.

Create a free website or blog at WordPress.com.