22 August, 2010

Trying to understand LAST_CALL_ET -- 3

Continuing the previous posts (1) and (2), in both of which I ran PLSQL procedures, I now run a test with a simple SQL select that retrieves close to 27million rows from the database server to the client (the SQLPLUS program).

The first sesion runs a SELECT with termout off but spooling to a file :

select object_id from obj_list;


Monitoring shows :

SQL> l
1 select to_char(sysdate,'DD-MON HH24:MI:SS') Collection_datestamp, x.last_call_et, x.status, x.sql_id,
2 y.sql_text
3 from v$session x, v$sqlarea y
4 where x.sql_id = y.sql_id(+)
5* and x.sid = &session_id
SQL> /
Enter value for session_id: 141
old 5: and x.sid = &session_id
new 5: and x.sid = 141

COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
22-AUG 15:51:52 0 INACTIVE bxya78ra815js select object_id from obj_list

SQL> /
Enter value for session_id: 141
old 5: and x.sid = &session_id
new 5: and x.sid = 141

COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
22-AUG 15:51:57 0 ACTIVE bxya78ra815js select object_id from obj_list

SQL> /
Enter value for session_id: 141
old 5: and x.sid = &session_id
new 5: and x.sid = 141

COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
22-AUG 15:52:04 0 ACTIVE bxya78ra815js select object_id from obj_list

SQL> /
Enter value for session_id: 141
old 5: and x.sid = &session_id
new 5: and x.sid = 141

COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
22-AUG 15:52:13 0 INACTIVE bxya78ra815js select object_id from obj_list

SQL>
SQL> /
Enter value for session_id: 141
old 5: and x.sid = &session_id
new 5: and x.sid = 141

COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
22-AUG 15:53:32 0 INACTIVE bxya78ra815js select object_id from obj_list

SQL>

SQL> select to_char(sysdate,'DD-MON HH24:MI:SS') Collection_Datestamp, executions, buffer_gets, rows_processed
2 from v$sqlstats where sql_id = 'bxya78ra815js';

COLLECTION_DATE EXECUTIONS BUFFER_GETS ROWS_PROCESSED
--------------- ---------- ----------- --------------
22-AUG 15:55:32 1 441971 13190847

SQL>
SQL> /

COLLECTION_DATE EXECUTIONS BUFFER_GETS ROWS_PROCESSED
--------------- ---------- ----------- --------------
22-AUG 15:56:04 1 505590 15090747

SQL>
SQL> /

COLLECTION_DATE EXECUTIONS BUFFER_GETS ROWS_PROCESSED
--------------- ---------- ----------- --------------
22-AUG 15:57:22 1 646127 19291147

SQL>
SQL> /

COLLECTION_DATE EXECUTIONS BUFFER_GETS ROWS_PROCESSED
--------------- ---------- ----------- --------------
22-AUG 15:58:27 1 760275 22702847

SQL>
SQL>
SQL> @sess_sql_statement
Enter value for session_id: 141
old 5: and x.sid = &session_id
new 5: and x.sid = 141

COLLECTION_DATE LAST_CALL_ET STATUS SQL_ID SQL_TEXT
--------------- ------------ -------- ------------- ----------------------------------------------------------------
22-AUG 16:00:16 27 INACTIVE

SQL>


Thus, the LAST_CALL_ET was getting reset at every new FETCH call by the client and STATUS kept switching between 'ACTIVE' and 'INACTIVE'.

The tkprof of the trace shows :

select object_id
from
obj_list


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 538612 58.38 74.70 363739 900989 0 26930545
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 538614 58.38 74.70 363739 900989 0 26930545

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
26930545 TABLE ACCESS FULL OBJ_LIST (cr=900989 pr=363739 pw=0 time=107722594 us)


A total of 538,612 FETCH calls from the client (SQLPLUS) to the server. Each FETCH call is a new call to the database server process.

.
.
.

No comments: