Logoff Triggers

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.