The documentation states that it is :
If the session
STATUS is currently ACTIVE, then the value represents the elapsed time in seconds since the session has become active. If the session STATUS is currently INACTIVE, then the value represents the elapsed time in seconds since the session has become inactive.
(The 11.2 documentation is no different :
If the session STATUS is currently ACTIVE, then the value represents the elapsed time (in seconds) since the session has become active.
If the session STATUS is currently INACTIVE, then the value represents the elapsed time (in seconds) since the session has become inactive.)
The DBMS_STATS.GATHER_SCHEMA_STATS stored procedure actually executes different SQL statements. The SQL_IDs of those statements appear in V$SESSION but the LAST_CALL_ET does not get reset at the end of each SQL call. It continues to increment until the PLSQL call is completed. (And we are not even talking of the multiple FETCHs that might occur in an SQL SELECT).
From Session 1 (SID 144) I run this :
SQL> set time on
00:01:38 SQL>
00:01:48 SQL> exec dbms_stats.gather_schema_stats('HEMANT');
PL/SQL procedure successfully completed.
00:05:01 SQL>
00:07:06 SQL>
What do I see for the Session in the V$SESSION columns SQL_ID and LAST_CALL_ET ?
Here are some "snapshots" gathered from another session that is monitoring SID 144 :
(Note : The schema "HEMANT" has tables list MY_TEST_TABLE, OBJ_LIST, OBJ_LIST_2 and others -- many of which are extracts from DBA_OBJECTS created to test other features. That is why you will see columns that you normally would see in DBA_OBJECTS seeming to appear in the "HEMANT" schema's tables)
select to_char(sysdate,'DD-MON HH24:MI:SS') Collection_datestamp, x.last_call_et, x.status, x.sql_id,
y.sql_text
from v$session x, v$sqlarea y
where x.sql_address = y.address
and x.sql_hash_value = y.hash_value
and x.sid = &session_id
/
COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
16-AUG 00:02:06 16 ACTIVE cmc06u7m8nu5b insert /*+ append */ into sys.ora_temp_1_ds_234 select /*+ no_pa
rallel(t) no_parallel_index(t) dbms_stats cursor_sharing_exact u
se_weak_name_resl dynamic_sampling(0) no_monitoring */"OWNER","O
BJECT_NAME","SUBOBJECT_NAME","OBJECT_ID","DATA_OBJECT_ID","OBJEC
T_TYPE","CREATED","LAST_DDL_TIME","TIMESTAMP","STATUS","TEMPORAR
Y","GENERATED","SECONDARY" from "HEMANT"."MY_TEST_TABLE" sample
( 10.9418767507) t
COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
16-AUG 00:02:27 36 ACTIVE gt3fthdmp0405 select /*+ no_parallel(t) no_parallel_index(t) dbms_stats cursor
_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitor
ing */ count(*),count("OWNER"),count(distinct "OWNER"),sum(sys_o
p_opnsize("OWNER")),substrb(dump(min("OWNER"),16,0,32),1,120),su
bstrb(dump(max("OWNER"),16,0,32),1,120),count("OBJECT_NAME"),cou
nt(distinct "OBJECT_NAME"),sum(sys_op_opnsize("OBJECT_NAME")),su
bstrb(dump(min(substrb("OBJECT_NAME",1,32)),16,0,32),1,120),subs
trb(dump(max(substrb("OBJECT_NAME",1,32)),16,0,32),1,120),count(
"SUBOBJECT_NAME"),count(distinct "SUBOBJECT_NAME"),sum(sys_op_op
nsize("SUBOBJECT_NAME")),substrb(dump(min("SUBOBJECT_NAME"),16,0
,32),1,120),substrb(dump(max("SUBOBJECT_NAME"),16,0,32),1,120),c
ount("OBJECT_ID"),count(distinct "OBJECT_ID"),sum(sys_op_opnsize
("OBJECT_ID")),substrb(dump(min("OBJECT_ID"),16,0,32),1,120),sub
strb(dump(max("OBJECT_ID"),16,0,32),1,120),count("DATA_OBJECT_ID
"),count(distinct "DATA_OBJECT_ID"),sum(sys_op_opnsize("DATA_OBJ
ECT_ID")),substrb(dump(min("DATA_OBJECT_
COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
16-AUG 00:03:13 82 ACTIVE 8dhprd5dvwcux select /*+ no_parallel(t) no_parallel_index(t) dbms_stats cursor
_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitor
ing */ count(*),count("OWNER"),count(distinct "OWNER"),sum(sys_o
p_opnsize("OWNER")),substrb(dump(min("OWNER"),16,0,32),1,120),su
bstrb(dump(max("OWNER"),16,0,32),1,120),count("OBJECT_NAME"),cou
nt(distinct "OBJECT_NAME"),sum(sys_op_opnsize("OBJECT_NAME")),su
bstrb(dump(min(substrb("OBJECT_NAME",1,32)),16,0,32),1,120),subs
trb(dump(max(substrb("OBJECT_NAME",1,32)),16,0,32),1,120),count(
"SUBOBJECT_NAME"),count(distinct "SUBOBJECT_NAME"),sum(sys_op_op
nsize("SUBOBJECT_NAME")),substrb(dump(min("SUBOBJECT_NAME"),16,0
,32),1,120),substrb(dump(max("SUBOBJECT_NAME"),16,0,32),1,120),c
ount("OBJECT_ID"),count(distinct "OBJECT_ID"),sum(sys_op_opnsize
("OBJECT_ID")),substrb(dump(min("OBJECT_ID"),16,0,32),1,120),sub
strb(dump(max("OBJECT_ID"),16,0,32),1,120),count("DATA_OBJECT_ID
"),count(distinct "DATA_OBJECT_ID"),sum(sys_op_opnsize("DATA_OBJ
ECT_ID")),substrb(dump(min("DATA_OBJECT_
COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
16-AUG 00:03:40 109 ACTIVE 618vpumzuqtrn select /*+ no_parallel(t) no_parallel_index(t) dbms_stats cursor
_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitor
ing */ count(*),count("OBJECT_NAME"),count(distinct "OBJECT_NAME
"),count("SUBOBJECT_NAME"),count(distinct "SUBOBJECT_NAME"),sum(
sys_op_opnsize("SUBOBJECT_NAME")),substrb(dump(min("SUBOBJECT_NA
ME"),16,0,32),1,120),substrb(dump(max("SUBOBJECT_NAME"),16,0,32)
,1,120),count("OBJECT_ID"),count(distinct "OBJECT_ID"),count("DA
TA_OBJECT_ID"),count(distinct "DATA_OBJECT_ID"),sum(sys_op_opnsi
ze("DATA_OBJECT_ID")),substrb(dump(min("DATA_OBJECT_ID"),16,0,32
),1,120),substrb(dump(max("DATA_OBJECT_ID"),16,0,32),1,120) from
"HEMANT"."OBJ_LIST_2" sample ( .3397677313) t
COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
16-AUG 00:05:05 2 INACTIVE 579mnkw55uz8w BEGIN dbms_stats.gather_schema_stats('HEMANT'); END;
COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
16-AUG 00:05:23 20 INACTIVE 579mnkw55uz8w BEGIN dbms_stats.gather_schema_stats('HEMANT'); END;
COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
16-AUG 00:07:16 134 INACTIVE 579mnkw55uz8w BEGIN dbms_stats.gather_schema_stats('HEMANT'); END;
SQL> select sql_fulltext from v$sqlstats where sql_id = '579mnkw55uz8w';
SQL_FULLTEXT
--------------------------------------------------------------------------------
BEGIN dbms_stats.gather_schema_stats('HEMANT'); END;
The DBMS_STATS.GATHER_SCHEMA_STATS procedure actually ran a large number of *separate* SQL statements. I capture a few of them by querying V$SESSION and joining to V$SQLAREA to get the SQL_TEXT.
Even though each SQL execution is a new set of PARSE-EXECUTE-FETCH calls, the LAST_CALL_ET does not reset to zero. It keeps incrementing until the Procedure (GATHER_SCHEMA_STATS) completes execution.
At completion, LAST_CALL_ET is reset to zero. Thereafter, with the session being INACTIVE, it again starts incrementing -- now it shows the Inactive time. (That is, it shows "how many seconds has it been since the last execution completed" when no execution is running !).
I have presented one case where it seems that multiple SQLs are called and yet LAST_CALL_ET shows the total time for *all* the SQLs executed by the DBMS_STATS.GATHER_SCHEMA_STATS procedure. In this case, you will need to remember that the LAST_CALL_ET reports the PLSQL procedure time, not the SQL time.
Later I will present a few other cases.
.
.
.
1 comment:
this was helpful to understand last_call_et
Post a Comment