Skip to Main Content
  • Questions
  • Wrong SQL_ID in V$ACTIVE_SESSION_HISTORY and V$SESSION

Breadcrumb

May 4th

Question and Answer

Chris Saxon

Thanks for the question, Robert.

Asked: June 02, 2016 - 6:28 pm UTC

Last updated: June 08, 2016 - 11:08 pm UTC

Version: 10.2.0.5

Viewed 1000+ times

You Asked

Hello,

Thanks a lot for your help and for this website.

We have an odd and puzzling thing that has been happening for years.

One of our most important jobs (Oracle package.procedure) often has performance problems.
To diagnose it we use OEM and v$active_session_history, etc.
Now this procedure contains dozens of individual statements, procedure calls, etc., which can been seen when we do a 10046 trace, look in v$sql while the job is running, etc.

Here is the odd thing: The only statement that shows up in V$ACTIVE_SESSION_HISTORY or V$SESSION is the statement "SELECT SYSDATE FROM SYS.DUAL"

Do you have any idea why this is happening?

One bit of info which might be material to this is that this job (all our jobs) is scheduled from a 3rd party, home-grown scheduler built on Oracle server Forms (~15 years old), which manages queues which continually loop, sleep for 5 seconds, check for anything to execute, repeat.

Do you have any ideas why the *only* statement we continually see in V$ACTIVE_SESSION_HISTORY and V$SESSION is "SELECT SYSDATE FROM SYS.DUAL"?

Thank you,

Robert.

and Connor said...

That does seem odd...but remember that active session history is a *sampling* concept. Every second we look at what is happening *right now* and that's what we report. Here's an rudimentary example showing how easy it is for things to be missed.

SQL> create or replace
  2  procedure bad_proc is
  3    x varchar2(20);
  4  begin
  5    loop
  6       select user into x from dual;
  7    end loop;
  8  end;
  9  /

Procedure created.

SQL>
SQL> exec bad_proc


So this obviously never stops running the same SQL over and over...let me now look at ASH

SQL> select event, session_state, sql_id
  2  from v$active_session_history
  3  where session_id = 402;

EVENT                                                            SESSION SQL_ID
---------------------------------------------------------------- ------- -------------
                                                                 ON CPU  
                                                                 ON CPU  1v717nvrhgbn9
                                                                 ON CPU
                                                                 ON CPU
                                                                 ON CPU  
                                                                 ON CPU  1v717nvrhgbn9
                                                                 ON CPU  
                                                                 ON CPU  1v717nvrhgbn9
                                                                 ON CPU  
                                                                 ON CPU  
                                                                 ON CPU  1v717nvrhgbn9
                                                                 ON CPU
                                                                 ON CPU  1v717nvrhgbn9

SQL> select sql_text from v$sqlstats
  2  where sql_id = '1v717nvrhgbn9';

SQL_TEXT
----------------------------------------------
SELECT USER FROM SYS.DUAL



So even though we are running the same SQL over and over, we only picked it up a few times, just being the random time when ASH decided to grab the details. If the various calls you are making inside your procedure are very short-lived, there is a chance you might not be seeing them. Moreover, if your plsql calls have (say) an instrumentation layer that is referring to sysdate frequently, they could easily dominate the observations.

Hope this helps.

Rating

  (7 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

But we have many long lived SQL

Robert Wood, June 03, 2016 - 1:53 pm UTC

Thanks for taking my question and for your pertinent reminder, but your example doesn't seem to fit my case.

You see, this particular procedure runs for (e.g) over an hour and has many statements that are run multiple times, as it loops through each record in the batch and processes each record with lookups, then updates, inserts, etc. into several different tables.
You can see the procedure progress by observing the stats increase in (e.g.) V$SQL when you select on all the open cursors in the procedure.
What I am trying to say is there is a ton of work going on inside this procedure for a long time... but "SELECT SYSDATE FORM DUAL" is the only thing that shows up in ASH or V$SESSION.SQL_ID.

Did I entirely miss the point of your initial answer or does this shed any additional light on my problem and your understanding of it?

Thank you!

Robert Wood.
Connor McDonald
June 04, 2016 - 3:32 am UTC

You could confirm the theory with something like this:

select /*+ leading(a s) use_nl(s) no_merge */ distinct sql_Id
from   ( select 212 x from dual connect by level <= 1000 ) a,
       v$session s
where s.sid =   a.x


where '212' is the session running the proc

That in effect will sample v$session 1000 times in rapid succession and pick up an SQL_ID's (This works because v$session is not a real table, so we dont do a read consistent view).

Altneratively if its *too* quick, do the same with the plsql loop


set serverout on
declare
  type t_sql_id is table of int index by varchar2(100);
  l_sql_id_list t_sql_id;
  l_sql_id varchar2(100);
begin
  for i in 1 .. 1000 loop
    select sql_id into l_sql_id from v$session where sid = 212;
    l_sql_id_list(l_sql_id) := 1;
  end loop;
  
  l_sql_id := l_sql_id_list.first;
  loop
    dbms_output.put_line(l_Sql_Id);
    exit when l_sql_id_list.next(l_Sql_Id) is null;
    l_sql_id := l_sql_id_list.next(l_Sql_Id);
  end loop;
end;
/



That's what I was looking for!

Robert, June 04, 2016 - 2:33 pm UTC

Thank you, sir.
That's just the sort of thing I was looking for, that I never thought of.
I will plan to try that out Monday and report back with the results.
Thanks again,
Robert.
Connor McDonald
June 05, 2016 - 2:45 am UTC

Good luck ! Keep us posted

I guess it will remain a mystery

Robert, June 06, 2016 - 6:05 pm UTC

Thanks for your help.
I ran the statements you gave me for this process and it came up the sql_id for the "select sysdate from dual" always, every time, just like it always shows in v$session and v$active_session_history.

But as I said, the very odd thing about it is that if I look in v$open_cursor for this sid, and check it over and over, you can see the main statements in this process repeating (incrementing in executions, elapsed time, buffer gets, etc.) and they are all incrementing in executions at the approximate same rate as the "select sysdate from dual" statement is --- and yet this statement is the only one that is always showing up.
It seems somehow Oracle is missing all the rest of the statements in v$session and v$active_session_history. Also the elapsed time per execution for this statement is much less than most of the other statements that are executing in this sid.
I don't think there is much chance of picking up statements from other sid's because the statements, tables, etc. in this particular process are pretty identifyable. -- it is as if this statement is "stuck" in Oracle's ASH mind for this process, allowing no other statement to be recognized.

Well anyway, thanks a lot for your help.

Robert.
Chris Saxon
June 07, 2016 - 12:24 am UTC

Hmm.... if you get a chance to run a trace on the process, pop it over to asktom_us@oracle.com, and we'll see if there's anything useful we can glean from that.

Of course, if you're "over it"...thats fine too :-)

Not quite over it :)

Robert, June 07, 2016 - 1:44 pm UTC

Ha, yeah I thought I might be over it, but it looks like it is working out to be able to easily set up a trace on the job this morning. (I know I've done this before on this job but I forgot what it showed). Anyway, hopefully the trace file won't be too big.
Thanks!

File bundle sent...

Robert, June 07, 2016 - 2:30 pm UTC

Thanks.
Chris Saxon
June 08, 2016 - 12:48 am UTC

will take a look

TKPROF file sent

Robert, June 08, 2016 - 2:39 pm UTC

Hello,

I just sent, to your asktom email, a TKPROF for the trace raw trace file I sent yesterday.
This is not for the entire job (regrettably I had a limit for the dump file size), but it is for about 70 minutes more of the job and appears to have gotten some good pertenant facts in the TKPROF file.
Specifically it shows the select sysdate from dual statement to have gotten almost no execution time. (and yet as you can see from the file I sent yesterday, this statement was the only one that was showing up in v$session and v$active_session_history.)

Thanks for your help,

Robert.
Chris Saxon
June 08, 2016 - 11:08 pm UTC

I replied directly to the email - did you get it ? (references to RPC ?)

didn't see reply?

Robert Wood, June 09, 2016 - 2:28 pm UTC

Hi Connor,

I didn't see any other email than the one with the link that takes me right back here (?)

And yes I did see the RPC's -- are you thinking they may have a bearing on the issue?

Thanks,

Robert.

More to Explore

PL/SQL demos

Check out more PL/SQL tutorials on our LiveSQL tool.

PL/SQL docs

PL/SQL reference manual from the Oracle documentation library