Can someone help me to understand what is going on here?
One of the users called and said that session 8248 is already working for almost 5 days. And it's not normal.
First of all, in v$session i can see that session 8248 is repeatedly executing the same sql_id:
SQL_ID PREV_SQL_ID SQL_EXEC_START
------------- ------------- ---------------------
ftr4s16std8zv cmzykvtmuufas 16.01.2013 15:57:55
ftr4s16std8zv cmzykvtmuufas 16.01.2013 15:57:58
ftr4s16std8zv cmzykvtmuufas 16.01.2013 15:58:00
ftr4s16std8zv cmzykvtmuufas 16.01.2013 15:58:03
7pg0nhttfb6dd 45srvxj2ur5yk 16.01.2013 15:58:06
ftr4s16std8zv cmzykvtmuufas 16.01.2013 15:58:07
45srvxj2ur5yk bhspd5gvthxcg 16.01.2013 15:58:09
So it looks like this session mainly executes query with sql_id = ftr4s16std8zv.
And this query works fast:
select sql_id, executions, round(elapsed_time/executions/1e6, 2) from v$sql where sql_id = 'ftr4s16std8zv';
SQL_ID EXECUTIONS ROUND(ELAPSED_TIME/EXECUTIONS/1E6,2)
------------- ---------- ------------------------------------
ftr4s16std8zv 448022 0.82
What bothering me is the content in v$session_longops when i'm querying this sid:
select sql_id, opname, message, elapsed_seconds/60/60, time_remaining/60/60 from v$session_longops where sofar <> totalwork and sid = 8248;
SQL_ID OPNAME MESSAGE ELAPSED_SECONDS/60/60 TIME_REMAINING/60/60
------------- --------------- ----------------------------------------------------------------------------- --------------------- --------------------
b655yk3umpqaf Table Scan Table Scan: SCHEMANAME.TABLE1: 43058 out of 44871 Blocks done 123.3508333 5.193888889
Now let's take a look in v$open_cursor:
select sql_id, sql_text, last_sql_active_time, sql_exec_id, cursor_type from v$open_cursor where sid = 8248 and sql_exec_id is not null;
SQL_ID SQL_TEXT LAST_SQL_ACTIVE_TIME SQL_EXEC_ID CURSOR_TYPE
------------- ------------------------------------------------------------ --------------------- ----------- ---------------------
ftr4s16std8zv SELECT * FROM SCHEMANAME2.TABLE1CARD WHERE NOT (PERSON_MINOR 17.09.1974 21:01:54 17227295 PL/SQL CURSOR CACHED
4kx07abxnjkby BEGIN package1.procedure1 (683203,0); END; null 16777216 OPEN
b655yk3umpqaf SELECT * FROM SCHEMANAME.TABLE1 WHERE ID=:B1 null 16777216 OPEN-PL/SQL
50j9u08b5z5ns SELECT * FROM SCHEMANAME.TABLE1CARD WHERE ET=:B2 17.09.1974 21:11:15 16969198 PL/SQL CURSOR CACHED
I did a little depersonization here, but table names still correlates with ones in another views.
For me it looks like this session has executed the procedure package1.procedure1 (4kx07abxnjkby) and this procedure has executed the long running query b655yk3umpqaf hence they're have same SQL_EXEC_ID in v$open_cursor.
But i can't understand the reason for this query to running that long, 'cause SCHEMANAME.TABLE1 is not that big:
select count(*) from SCHEMANAME.TABLE1;
COUNT(*)
----------
49250
And the last thing is v$sql_monitor:
select status, sql_id, sql_text, sql_exec_start, elapsed_time/1e6 "seconds" from v$sql_monitor where sid = 8248;
STATUS SQL_ID SQL_TEXT SQL_EXEC_START seconds
------------------- ------------- ------------------------------------------------------------ --------------------- ----------
EXECUTING b655yk3umpqaf SELECT * FROM SCHEMANAME.TABLE1 WHERE ID =:B1 11.01.2013 13:26:48 36.203471
EXECUTING 4kx07abxnjkby BEGIN package1.procedure1 (683203,0); END; 11.01.2013 13:26:47 445411.5887
It says that elapsed time for b655yk3umpqaf was 36 seconds, but at the same time it appears still running in v$session_longops.
Could someone help me to put this together?
While i was writing all this i've got an idea, that maybe this pl/sql procedure just queried needed lines from SCHEMANAME.TABLE1 with b655yk3umpqaf wich took it 36 seconds to complete and now it's just fetching this rows and doing something about them? How can i see it?