| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> Missing Data in Statspack Report
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_at_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_at_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_at_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
Ian MacGregor
Stanford Linear Accelerator Center
ian_at_slac.stanford.edu
-- Archives are at http://www.freelists.org/archives/oracle-l/ FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html -----------------------------------------------------------------Received on Tue Jun 22 2004 - 00:40:29 CDT
 |
 |