Oracle Scratchpad

June 1, 2011

audsid

Filed under: audit,Oracle,Troubleshooting,Upgrades — Jonathan Lewis @ 5:42 pm GMT Jun 1,2011

Here’s an example of how the passing of time can allow a problem to creep up on you.

A recent client had a pair of logon/logoff database triggers to capture some information that wasn’t available in the normal audit trail, and they had been using these triggers successfully for many years, but one day they realised that the amount of redo generated per hour had become rather large, and had actually been quite bad and getting worse over the last few months for no apparent reason. (You’ve heard this one before … “honest, guv, nothing has changed”).

Here’s a clue to their problem. Their logoff trigger updated their own auditing table with the following code (although I’ve removed some columns) :

begin
        if sys_context('USERENV', 'SESSIONID') = 0 then 
                update system.user_audit a 
                set 
                        logoff_time = sysdate 
                where    audsid = sys_context('USERENV', 'SESSIONID') 
                and     logon_time = (
                                select  max(logon_time) 
                                from    system.user_audit b 
                                where   b.audsid = a.audsid 
                        ); 
        else 
                update system.user_audit 
                set 
                        logoff_time = sysdate
                where   audsid = sys_context('USERENV', 'SESSIONID'); 
        end if; 
end;

The table was suitably indexed to make the correlated update (“most recent of” subquery) operate very efficiently, so that wasn’t the problem.

You might question the validity of updating just the rows with the most recent date when the sys_context(‘userenv’,’sessioned’) is zero, and why the SQL to do the update doesn’t then use literal zeros rather than calling the sys_context() function and using a correlation column – but those are minor details.

You might wonder why zero is a special case, of course, but then you may recall that when a user connects as SYS the audsid is zero – so this code is attempting to limit the update to just the row created by the most recent logon by SYS, which may introduce a few errors but really SYS shouldn’t be connecting to a production system very often.

At this point you might ask which version of Oracle the client was running. They had started using Oracle a long time ago, but this system had gone through Oracle 9i, and was now running 10g; and if you’ve kept an eye on things like autotrace you may have noticed that the audsid used by any SYS session changed from zero to 4294967295 in the upgrade to 10g. So this code is no longer treating SYS as a special case.

By the time I was on site, the client’s audit table held about 87,000 rows for the audsid 4294967295, and every time SYS logged off the session would update every single one of them. (It took a few seconds and about 45 MB of redo for SYS to log off – and SYS sessions connected rather more frequently than expected).

Warning:

If you still have to get through the upgrade from 8i or 9i to 10g, then watch out for code that does things with the deprecated userenv(‘sessionid’) or sys_context(‘userenv’,’sessionid’).

8 Comments »

  1. So how many files did they have in $ORACLE_BASE/admin/$ORACLE_SID/adump ? And how many of those correlate with rman and other scheduled jobs? And did anyone notice?

    Comment by joel garry — June 1, 2011 @ 11:04 pm GMT Jun 1,2011 | Reply

    • Joel,

      I didn’t check – I probably should have, but we were chasing other problems at the time.

      This note was about a “user-defined” audit, though, not the builtin “audit_trail=db” thing. I don’t think you get the adump files unless you’ve set the “audit_sys_operations” parameter (and that might not be exactly the right name) to true.

      Comment by Jonathan Lewis — June 2, 2011 @ 8:50 pm GMT Jun 2,2011 | Reply

  2. See MOS AUDIT_SYS_OPERATIONS Set To FALSE Yet Audit Files Are Generated [ID 308066.1]
    One of those obvious things so many people forget about, and doesn’t have the obvious “so when did they disconnect?” that everyone would want to know, so they write logoff triggers to trip over after an upgrade. Every sysoper connection makes a file, at least several per day at most sites, a forehead-slapper when noticed after a couple of years.

    Comment by joel garry — June 2, 2011 @ 9:37 pm GMT Jun 2,2011 | Reply

    • Joel,

      Thanks for that bit of information. That’s a nice example of a “little oddity” that eventually can become a big problem – at least for a while – when “nothing changed” (except the passage of time).

      Comment by Jonathan Lewis — June 4, 2011 @ 10:18 am GMT Jun 4,2011 | Reply

  3. To solve this problem,I prefer to use userenv(‘SID’) .
    First, It is much efficient, use id to query v$session, we use the index on x$ksuse(Kernel Service User SEssion).
    Second, we use sid + serial# to assure this field to be nearly unique.

    Comment by jametong — June 3, 2011 @ 7:17 am GMT Jun 3,2011 | Reply

    • Jametong,

      The problem, though, is that you have to know that things have changed and what new alternatives there are to solve them.

      Without checking I can’t be too sure, but there was a time when userenv() didn’t have “SID” as an option – so your approach is also dependent on the passing of time. (It’s better practice to use sys_context(‘userenv’,’sid’) by the way, the userenv() calls were deprecated in 9i – even though Oracle still uses userenv(‘instance’) to pick a v$ from a gv$).

      Speaking of instances, your approach would also need the instance number to complete the identification, and also has the problem that the serial# resets on instance restart – so won’t be appropriate for everybody.
      .

      Comment by Jonathan Lewis — June 4, 2011 @ 10:24 am GMT Jun 4,2011 | Reply

  4. […] Jonathan Lewis presents an example of how the passing of time can allow a problem to creep up on […]

    Pingback by Log Buffer #223, A Carnival of the Vanities for DBAs | The Pythian Blog — June 3, 2011 @ 8:27 am GMT Jun 3,2011 | Reply

  5. […] throw error messages.  You might find that the following SQL statement (based on the contents of this article) returns different values for the SYS user depending on the Oracle Database release […]

    Pingback by Unique Index Result Error with Ref Cursor on Oracle 11g but Not on 10g « Charles Hooper's Oracle Notes — June 6, 2011 @ 12:01 pm GMT Jun 6,2011 | 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

Blog at WordPress.com.