Missing Data in Statspack Report
- From: "MacGregor, Ian A." <ian@xxxxxxxxxxxxxxxxx>
- To: "'oracle-l@xxxxxxxxxxxxx'" <oracle-l@xxxxxxxxxxxxx>
- Date: Mon, 21 Jun 2004 22:43:12 -0700
I'm tracing a query which runs quite slowly at a certain time of day. Here are
the tkprof details
SELECT value, timestamp, nanosecs, stat, sevr, ostat from
chanarch_pack.archive_data_f_view WHERE pv_id = :CUR_PV_ID AND timestamp
BETWEEN :START_TIME_ORACLE_DATE AND :END_TIME_ORACLE_DATE AND ostat <> 1 ORDER
BY timestamp, nanosecs
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.48 0.64 0 220 280 0
Execute 10 0.02 0.01 0 0 0 0
Fetch 527 27.73 144.20 11241 13158 0 7685
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 547 28.23 144.87 11241 13378 280 7685
The query is run ten times consecutively for 10 different CUR_PV_ID's. The
trace file has the following start timestamp : 2004-06-21 04:35:03.536, and the
trace ended at about 04:37 the same day. If I look at A statspack report for
4:30 to 4:45 on the same day I see
Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 451 21-Jun-04 04:30:02 40 5,002.9
End Snap: 452 21-Jun-04 04:45:06 39 5,132.3
Elapsed: 15.07 (mins)
Some data omitted
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
2,037,562 1 2,037,562.0 91.5 508.98 695.65 523988587
Module: SQL*Plus
declare dayChar varchar2(10); i intege
r; except_rows integer; partition_suffix varchar(5);
partName varchar(15); OSTAT_FINISH_PROCESSING const
ant number(8) := 6; ARCH_PARTMGNT constant va
rchar2(25) := 'ARCH_PARTITIONMGNT'; PREVIOUS_ERR exception
1,304,434 430,693 3.0 58.6 176.38 213.12 3177912660
update tabpart$ set part# = :1 where obj# = :2 and bo# = :3
553,409 22,184 24.9 24.8 101.55 145.55 1464234701
Module: ArchiveEngineOr@opi00gtw04 (TNS V1-V3) update arch_table_data set
data_end = :DATA_END, end_nano = :END _NANO where pv_id = :PV_ID
200,216 1 200,216.0 9.0 52.71 87.29 649207481
Module: SQL*Plus
declare status integer; i integer; found integer; d
uration_days integer; partition_days integer; partition_ho
urs integer; partition_minutes integer; partition_total_mi
nutes integer; partitions_needing_creation integer; minute
s_per_day integer := 1440; partition_name varchar2(15); s
79,079 1 79,079.0 3.5 5.18 9.60 4231126065
Module: SQL*Plus
select partition_name from user_segments where segment_name = 'A RCH_DATA_F'
37,509 1 37,509.0 1.7 6.27 10.78 333476733
DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN
:= FALSE; BEGIN statspack.snap; :mydate := next_d ate; IF broken THEN :b := 1;
ELSE :b := 0; END IF; END;
36,005 1 36,005.0 1.6 1.44 2.61 1440470760
Module: SQL*Plus
INSERT into stats$sqltext ( hash_value
, text_subset , piece
, sql_text , address , comman
d_type , last_snap_id )
select st1.hash_value , ss.text_subset
30,292 1,271 23.8 1.4 4.58 5.43 4151580176
update obj$ set obj#=:6,type#=:7,ctime=:8,mtime=:9,stime=:10,sta
tus=:11,dataobj#=:13,flags=:14,oid$=:15,spare1=:16, spare2=:17 w here owner#=:1
and name=:2 and namespace=:3 and(remoteowner=:4 o r remoteowner is null and :4
is null)and(linkname=:5 or linkname is null and :5 is null)and(subname=:12 or
subname is null and :
19,704 1,554 12.7 0.9 0.93 0.93 1254950678
^LSQL ordered by Gets for DB: NLCO Instance: NLCO Snaps: 451 -452
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used
-> by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100
CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- ---------
---------- select file# from file$ where ts#=:1
13,419 2,066 6.5 0.6 2.63 3.72 3948238198
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts
=:8,extsize=:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13
, 65535, NULL, :13),groups=decode(:14, 65535, NULL, :14), cacheh int=:15,
hwmincr=:16, spare1=DECODE(:17,0,NULL,:17) where ts#=:1 and file#=:2 and
block#=:3
9,708 1 9,708.0 0.4 59.54 109.57 1113793502
Module: SQL*Plus
declare status integer; npart integer;
dayChar varchar2(10); dateform varchar2(20);
tablespace_name varchar2(50); indexspace_name varchar2(50
); subsystem constant varchar2(5) := 'PACK'; sql_s
tmt varchar2(200); begin EXECUTE IMMEDIATE 'se
----------------------------------------------------------------------------------------------------------------------
Yes the first statement is in need of tuning. But shouldn't the select
statement being traced show up between the Last two on the statspack outlet.
It doesn't show up on the physical read list either despite apparently doing
more of them than any other process.
Moving ahead one hour, the program was run and traced 0:535 and the statspack
same was from 5:30 to 5:45
SELECT value, timestamp, nanosecs, stat, sevr, ostat from
chanarch_pack.archive_data_f_view WHERE pv_id = :CUR_PV_ID AND timestamp
BETWEEN :START_TIME_ORACLE_DATE AND :END_TIME_ORACLE_DATE AND ostat <> 1 ORDER
BY timestamp, nanosecs
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.04 0.04 0 0 1 0
Execute 10 0.01 0.02 0 0 0 0
Fetch 527 26.08 84.62 10602 13114 1 7685
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 547 26.13 84.69 10602 13114 2 7685
Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 455 21-Jun-04 05:30:05 39 5,137.2
End Snap: 456 21-Jun-04 05:45:04 39 5,138.5
Elapsed: 14.98 (mins)
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
561,190 22,729 24.7 74.7 107.27 139.05 1464234701
Module: ArchiveEngineOr@opi00gtw04 (TNS V1-V3) update arch_table_data set
data_end = :DATA_END, end_nano = :END _NANO where pv_id = :PV_ID
86,759 4 21,689.8 11.5 201.13 540.52 708150226
Module: JDBC Thin Client
SELECT PV_ID, TIMESTAMP, NANOSECS, OSTAT, SEVR, STAT, VALUE from
ARCHIVE_DATA_F_VIEW where PV_ID=:1 and TIMESTAMP between :2 and
:3 order by TIMESTAMP, NANOSECS
45,090 1 45,090.0 6.0 6.39 9.12 333476733
DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN
:= FALSE; BEGIN statspack.snap; :mydate := next_d ate; IF broken THEN :b := 1;
ELSE :b := 0; END IF; END;
43,665 1 43,665.0 5.8 1.60 2.31 1440470760
Module: SQL*Plus
INSERT into stats$sqltext ( hash_value
, text_subset , piece
, sql_text , address , comman
d_type , last_snap_id )
select st1.hash_value , ss.text_subset
14,403 792 18.2 1.9 2.60 2.56 2915535579
Module: ArchiveEngineOr@opi00gtw04 (TNS V1-V3) insert into arch_wave_i values
(:PV_ID, :TIMESTAMP, :NANOSECS, :
STAT, :SEVR, :OSTAT, :VALUE)
13,364 10 1,336.4 1.8 26.27 84.86 1094517247
Module: SQL*Plus
SELECT value, timestamp, nanosecs, stat, sevr, ostat from chanar
ch_pack.archive_data_f_view WHERE pv_id = :CUR_PV_ID AND timesta mp BETWEEN
:START_TIME_ORACLE_DATE AND :END_TIME_ORACLE_DATE AND ostat <> 1 ORDER BY
timestamp, nanosecs
----------------------------------------------------------------------------------------------------------
Now the statement shows up. The two statements are exactly the same including
the supplied bind variables. Why is it on the second report and not the first?
Ian MacGregor
Stanford Linear Accelerator Center
ian@xxxxxxxxxxxxxxxxx
----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to: oracle-l-request@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------
- Follow-Ups:
- Re: Missing Data in Statspack Report
- From: Jonathan Lewis
Other related posts:
- » Missing Data in Statspack Report
- » Re: Missing Data in Statspack Report
- Re: Missing Data in Statspack Report
- From: Jonathan Lewis