DBMS_APPLICATION_INFO – Are we nearly there yet ?

Deb has come to the conclusion that, when on a long car journey, I’m not a great passenger.
“Are we nearly there yet ?” I enquire politely…usually around five minutes into a four-hour journey.
“No, not yet”, comes the patient reply.
“Are we almost nearly there yet ?”
“No, I’ll let you know when we are”, she responds with iron patience.
A few minutes pass…
“Are we almost nearly almost there ?”
At this point, I’m usually offered the option of walking the rest of the way.
It’s the same with long-running programs on the database. I want to know how far it’s gone and how far it’s got to go.
Oh, what Deb would do for an in-car equivalent of DBMS_APPLICATION_INFO.

Deb would probably have some sympathy with the DBA who gets a call from a user who has a process running and is, essentially, asking “are we nearly there yet ?”
Fortunately, with a bit of foresight and the judicious application of a little DBMS_APPLICATION_INFO magic, the answer to this question is right there in V$SESSION, or even V$SESSION_LONGOPS.

How far have we got ?

DBMS_APPLICATION_INFO provides the facility to set values in the client_info, module and action columns of the V$SESSION view programatically.
If we have a job that’s performing a number of different operations sequentially, we could do something like this :

set serveroutput on size 1000000
DECLARE
    l_module_name VARCHAR2(30) := 'task_progress.sql';
BEGIN
    DBMS_APPLICATION_INFO.SET_CLIENT_INFO( client_info => q'[Mike's Test App]');
    DBMS_APPLICATION_INFO.SET_MODULE( 
        module_name => l_module_name,
        action_name => 'Getting to work...');
    --
    -- Pretend to do some work
    --
    DBMS_LOCK.SLEEP(10);
    --
    -- Update the progress
    --
    DBMS_APPLICATION_INFO.SET_ACTION('Time for a ciggie');
    --
    -- All work and no play...
    --
    DBMS_LOCK.SLEEP(10);
    --
    -- Is it that time already ? 
    --
    DBMS_APPLICATION_INFO.SET_ACTION('Put the kettle on');
    --
    -- More hard labour
    --
    DBMS_LOCK.SLEEP(10);
    --
    -- Back to work
    --
    DBMS_APPLICATION_INFO.SET_ACTION('Home time !');
END;
/

To monitor this, we need to know which session to look for in V$SESSION and then check the progress in a separate session.
To find out which session we're looking for, we need to know the audsid of the session we're monitoring. So, before we kick off the program we need to :

SELECT userenv('sessionid') FROM dual;

This gives us the value of the audsid column in V$SESSION for the session we're monitoring.
Once we've started execution of the program in the session, we then need to switch to the monitoring session and run :

SELECT  client_info, module, action
FROM v$session
WHERE audsid = 1234
/

CLIENT_INFO	     MODULE		  ACTION 
-------------------- -------------------- -------------------- 
Mike's Test App      task_progress.sql	  Getting to work... 
 
SQL> / 

CLIENT_INFO	     MODULE		  ACTION 
-------------------- -------------------- -------------------- 
Mike's Test App      task_progress.sql	  Time for a ciggie 

SQL> / 

CLIENT_INFO	     MODULE		  ACTION 
-------------------- -------------------- -------------------- 
Mike's Test App      task_progress.sql	  Put the kettle on 

SQL> / 

CLIENT_INFO	     MODULE		  ACTION 
-------------------- -------------------- -------------------- 
Mike's Test App      task_progress.sql	  Home time ! 

where 1234 is the output we got from userenv('sessionid').

Are we nearly there yet ? - Number of records processed

If you're processing records in a loop, you could use the loop iterator and the total number of iterations to provide progress information...

set serveroutput on size 1000000
DECLARE
    l_module_name VARCHAR2(30) := 'app_info_rec.sql';
    l_max PLS_INTEGER := 100000;
BEGIN
    DBMS_APPLICATION_INFO.SET_CLIENT_INFO( client_info => q'[Mike's Test App]');
    DBMS_APPLICATION_INFO.SET_MODULE( 
        module_name => l_module_name,
        action_name => 'Getting to work...');
    FOR i IN 1..l_max LOOP
        IF MOD(i, 1000) = 0 THEN
            DBMS_APPLICATION_INFO.SET_ACTION(action_name => 'Processed '||i||' of '||l_max||' records');
            DBMS_LOCK.SLEEP(1);
        END IF;
    END LOOP;
    --
    -- Tidy up before we leave
    --
    DBMS_APPLICATION_INFO.SET_MODULE( 
        module_name => NULL,
        action_name => NULL);
END;
/

If we switch to our monitoring session, we can see...

SELECT module, action 
FROM v$session
WHERE audsid = 1234
/

MODULE		     ACTION 
-------------------- ---------------------------------------- 
app_info_rec.sql     Processed 43000 of 100000 record 

Note to self – once you get over 10000 records processed on this example, the value we're trying to set for action is too long for the column in V$SESSION. Fortunately, DBMS_SESSION simply truncates the ACTION value to 32 characters, hence the missing s at the end of records.
I think I've managed to talk my way out of that one.
Incidentally, the same applies to values you set for module ( 48 characters) and client_info (64). If ever you forget which is which, just do a describe on V$SESSION and note the length of the relevant columns.

Are we nearly there yet ? - The progress bar

Of course, if you just want details of what percentage of the total rows have been processed, you simply need to change the information you pass to the package

set serveroutput on size 1000000
DECLARE
    l_module_name VARCHAR2(30) := 'app_info_test.sql';
    l_max PLS_INTEGER := 100000;
    l_pct_done PLS_INTEGER;
BEGIN
    DBMS_APPLICATION_INFO.SET_CLIENT_INFO( client_info => q'[Mike's Test App]');
    DBMS_APPLICATION_INFO.SET_MODULE( 
        module_name => l_module_name,
        action_name => 'Getting to work...');
    FOR i IN 1..l_max LOOP
        IF MOD(i, 1000) = 0 THEN
            l_pct_done := (i/l_max) * 100;
            DBMS_APPLICATION_INFO.SET_ACTION(action_name => l_pct_done||' % complete');
            DBMS_LOCK.SLEEP(1);
        END IF;
    END LOOP;
    --
    -- Tidy up before we leave
    --
    DBMS_APPLICATION_INFO.SET_MODULE( 
        module_name => NULL,
        action_name => NULL);
END;
/

...and in the monitoring session...

SELECT module, action
FROM v$session
WHERE audsid = 1234
/

MODULE		     ACTION 
-------------------- ---------------------------------------- 
app_info_test.sql    12 % complete 

Are we almost nearly there yet?

OK, but what if you really, really want to know how much longer Oracle thinks this is going to take ?
Step forward SET_SESSION_LONGOPS. This will write the monitoring information to V$SESSION_LONGOPS and give you an estimate of the execution time remaining.
To demonstrate, here's the source for an appropriately name procedure :


CREATE OR REPLACE PROCEDURE procrastinate_pr(
    i_iterations PLS_INTEGER, i_wait_secs PLS_INTEGER,
    o_msg OUT VARCHAR2) 
AS
    --
    -- Variables for call to LONGOPS
    --
    l_rindex     PLS_INTEGER := DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS_NOHINT;
    l_slno       PLS_INTEGER;
    l_obj        PLS_INTEGER;
BEGIN
--    l_rindex := DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS_NOHINT;
    FOR i IN 1..i_iterations LOOP
        IF MOD(i, 100) = 0 THEN
            DBMS_LOCK.SLEEP(i_wait_secs);
            DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS(
                rindex => l_rindex, 
                slno => l_slno,
                op_name => 'Tea break', 
                target => l_obj, 
                context => 0, 
                sofar => i, 
                totalwork => i_iterations, 
                target_desc => 'PROCRASTINATE_PR', 
                units => 'rows processed');                
        END IF;
    END LOOP;
    o_msg := 'Procrastination is a thief of time...and so are a lot of other long words.';
END;
/

NOTE – V$SESSION_LONGOPS doesn't hold the audsid, but it does hold the session sid and serial #. To get these you need to run :

SELECT sid, serial#
FROM v$session
WHERE audsid = USERENV('sessionid');

If we now call this procedure :

set serveroutput on size 1000000
DECLARE
    --
    -- Variables for call to PROCRASTINATE_PR
    --
    l_iterations PLS_INTEGER;
    l_wait_secs PLS_INTEGER;
    l_msg VARCHAR2(4000);
    
BEGIN
    l_iterations := 1000;
    l_wait_secs := 3;
    procrastinate_pr( 
        i_iterations => l_iterations, i_wait_secs => l_wait_secs,
        o_msg => l_msg);
    --
    -- We should see something in v$session_longops...
    --
    DBMS_OUTPUT.PUT_LINE(l_msg);
END;
/

Now in our monitoring session...

SELECT opname, target_desc, elapsed_seconds, time_remaining
FROM v$session_longops
WHERE sid = 25
AND serial# = 3
/

OPNAME		     TARGET_DESC	  ELAPSED_SECONDS TIME_REMAINING
-------------------- -------------------- --------------- --------------
Tea break	     PROCRASTINATE_PR		       21	       5

SQL> /

OPNAME		     TARGET_DESC	  ELAPSED_SECONDS TIME_REMAINING
-------------------- -------------------- --------------- --------------
Tea break	     PROCRASTINATE_PR		       24	       3

Obviously, you need to replace the sid and serial# values with those of the session you're monitoring.

A point to note here – the estimated completion time is always going to be a “best guess”. In the same way that a golfer who has just completed the first 14 holes of a round in par cannot predict that they will play the next four holes in par, Oracle can only base it's prediction on what has happened so far. The actual time it takes to complete the process will always depend on what else is happening on the database, and the server it's running on....even if you cheat outrageously and use DBMS_LOCK.SLEEP.

We're off on holiday next month. Flying across the Atlantic to Canada. Deb's already started getting some things she claims we need for the trip, including for some reason, a gag. When I questioned this particular purchase, she simply said, archly, that it would help with the headaches she tends to get on long trips with me.
I've no idea what she's on about...

About these ads

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