Oracle Scratchpad

February 18, 2007

Logoff Triggers

Filed under: Infrastructure,trace files,Troubleshooting — Jonathan Lewis @ 11:44 pm GMT Feb 18,2007

A few days ago, I described a change to Statspack in 10g that allowed you to see how much time each snapshot took. In that article I suggested copying the code back to 9i; however this is a fiddly little task, and you may prefer to avoid it.

Here’s an alternative – actually a strategy with a much wider use – which does the same, but gives you even better information. Use a “before logoff” trigger to record the information you need. There are lots of ways you could create a suitable trigger;  here’s an example – with just a couple of naughty features that you might want to change:

 
create or replace trigger ses_logoff 
before logoff on perfstat.schema 
declare        

	m_output	varchar2(100) := 'Perfstat: ' || 
				to_char(sysdate,'yyyymmdd hh24:mi:ss');        

begin        

	for r in ( 
		select 
			sn.name, 
			ms.value 
		from 
			v$mystat	ms, 
			v$statname	sn 
		where 
			sn.statistic# = ms.statistic# 
		and	sn.name in ( 
				'recursive cpu usage', 
				'session connect time' 
			) 
		order by 
			sn.name 
	) loop 
		if 
			r.value < 1000000 
		then 
			r.value := r.value / 100; 
		else 
			r.value := 86400 * ( 
					sysdate - ( 
						to_date('01-jan-1970','dd-mon-yyyy') + 
						r.value/86400 
					) 
			); 
		end if;        

		m_output := m_output || to_char(r.value,'9,999,999.99');        

	end loop;        

	dbms_system.ksdwrt(2,m_output);        

end; 
/        

You’ll notice that I’ve used the undocumented package dbms_system in this trigger. The function ksdwrt() writes to the alert log (use 2 for the first parameter), or the session’s trace file (use 1 for the first parameter) or both (use 3 for the first parameter).

I’ve picked  two statistics from the current session – the CPU used (initially in hundredths of seconds), and the elapsed time since logon. The time the session connected is stored in v$mystat as the number of seconds since 1st Jan 1970, hence the rather odd looking formula for elapsed time.

This script has to be run as sys (or other suitably privileged account) to create the trigger; and after the trigger has been created the perfstat user will write a line to the alert log every time it logs off producing an output like the following:

 
Perfstat: 20070209 09:25:05          .21         1.00 

Many people already have a utility for picking information from the alert log, but a simple grep (or find) for the expression “Perfstat” will produce a list of times. You could even define the alert log as an external table to pick out the perfstat summary information with SQL.

Odd notes:

My first thought for capturing this information was simply to enable auditing (audit_trail = db in the parameter file), but if you used the spauto.sql script to set statspack running under dbms_job you’ll discover that sessions started by the job queue processes aren’t captured by the normal audit code.

Really you ought to take advantage of the utl_file package to write the output to a separate file rather than dumping it into the alert log – this script is really just a clue about using triggers and v$mystat. You might even decided to write the results into a table in the perfstat schema. (If you do decide to use utl_file, bear in mind that from 9i you no longer need to set the parameter utl_file_dir, the package can use “logical” directories created with the create directory syntax).

You will find that the alert log always shows a date and time stamp above each Perfstat line – this is normal practice; any line that is printed more than a second after the previous line gets a timestamp; I don’t know of any way to stop this happening.

If you try using this example against users logged in as sys, you will find that the “session connect time” for sys always seems to be zero.

2 Comments »

  1. always nice to see your ideas.
    I’m sure you know ansi date literals – the fixed date format spares typing some letters
    E.g.:
    date ’1970-01-01′
    instead of
    to_date(’01-jan-1970′,’dd-mon-yyyy’)
    BR,
    Martin

    Comment by Martin — February 19, 2007 @ 9:44 am GMT Feb 19,2007 | Reply

  2. Hi Jonathan,

    You obviously point out that its a bit naughty to use dbms_system.ksdwrt. I blogged about this function a long time ago and the security issues related to it. Your readers may be interested. See http://www.petefinnigan.com/weblog/archives/00000051.htm and http://www.petefinnigan.com/weblog/archives/00000054.htm

    cheers

    Pete

    Comment by Pete Finnigan — February 19, 2007 @ 5:22 pm GMT Feb 19,2007 | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Theme: Rubric. Get a free blog at WordPress.com

Follow

Get every new post delivered to your Inbox.

Join 4,430 other followers