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.
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.
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.
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.
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.
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.