Hi Tom,

I've found you site v.useful and usually spot on, however (dare I?) . . .

Where did "hsecs" come from? Surely 1/100 of a second should be a centisecond or cs (as the statspack report says). The "h" prefix is the ISO standard for a MULTIPLIER of 100 (hecto) and so should not be used that way - e.g:
</code> http://www.pyxidium.co.uk/metric/ <code>

OOPS Sorry, not ISO - they are SI prefixes.

You can lose Mars probes by messing up units . . .

Thanks For making clear what NOT TO expect from a STATSPACK report..

What I had running at the time of this STATSPACK report was 4 heavy duty batch
jobs which of course did not finish during this 10 min. observation window. According to you,
they may not have contributed CPU time to this report (fact that, CPU is reported at the end of a call)
What about the IO, is that reported at the end of the call as well? hope not because I see a lot of IO happening here.



Just From this section "Top 5 Timed Events" what can one make out, can I say that system in general was IO bound (because I have MOST WAIT of 906 Secs for "db file sequential read") BUT for sometime it was CPU bound as somebody (or everbody) had to wait for the CPU for 54 Secs. OR they are both interconnected as high LIO inherently raises the CPU usage ?


Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 187,787 906 88.60
SQL*Net more data to client 49,707 57 5.55
CPU time 54 5.33
log file parallel write 1,011 2 .22
latch free 6,226 2 .16
-------------------------------------------------------------




Also the question for me is that if all 4 of these batch jobs were still running at the time then who could be consuming the CPU I am really not sure, I need to find out ? what does "CPU Time (s)" and " Elapsd Time (s)" for queries below tell us ?



CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
1,615,721 100,901 16.0 14.3 73.73 82.29 1598629429
Module: SQL*Plus
INSERT Into Modeled_Property_Values ( BASE_REC_ID
, SOURCE_OWNER, HEDONIC_VERSION,
HEDONIC_VALUE, HEDONIC_CALC_DATE,
ASSESSED_VAL_VERSION, ASSESSED_VAL_
VALUE, ASSESSED_VAL_CALC_DATE, RSI

1,040,726 324,654 3.2 9.2 38.12 41.19 3502769403
Module: SQL*Plus
SELECT * From ( Select to_char(VO_Appraisal_Date,'y
yyy') vo_Appr_calEndar_year, to_char(VO_Appraisal_Date,'Q')
vo_Appr_calEndar_qtr, nvl(VO_Appraised_value,0), VO_Ap
praisal_Date From Value_Only_Appraisals Where
Source_Owner = :b3 and base_rec_id = :b2 and

Why level 12 10046 trace?

I always thought that level 8 was sufficient. Doesn't a level 12 add in the bind variable values only (on top of wait information)?

Also, aren't level 12's only interesting to those that understand the raw trace? As far as I know (up to 9iR2) tkprof doesn't show any of the level 12 info. Does tkprof behave the same in 10G?

Tom,

Here is the snippet of a STATSPACK report. If you look at the "SQL ordered by Gets for DB" section, you will see an INSERT statement which takes so many buffer gets about 1,110,061 of them. My question is, why would INSERT take some many buffer gets -- I can't think that this is because of the triggers on the table...or it's some kind of recursive SQL issued by the Oracle. Could you please comment on it and suggest if anything can be done to improve it.

Thanks So much for your help.
Neeraj

STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
PROD 4134911948 PROD 1 9.2.0.4.0 NO KOBE

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 3579 14-Apr-05 18:37:59 30 13.0
End Snap: 3580 14-Apr-05 18:44:30 28 14.2
Elapsed: 6.52 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 7,824M Std Block Size: 16K
Shared Pool Size: 1,024M Log Buffer: 1,024K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 543,142.26 526,969.29
Logical reads: 48,335.14 46,895.88
Block changes: 2,519.94 2,444.91
Physical reads: 335.49 325.50
Physical writes: 26.69 25.90
User calls: 30.22 29.32
Parses: 179.25 173.91
Hard parses: 0.00 0.00
Sorts: 1,121.99 1,088.59
Logons: 0.00 0.00
Executes: 2,828.85 2,744.62
Transactions: 1.03

% Blocks changed per Read: 5.21 Recursive Call %: 99.60
Rollback per transaction %: 0.00 Rows per Sort: 2.29

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.31 In-memory Sort %: 100.00
Library Hit %: 100.00 Soft Parse %: 100.00
Execute to Parse %: 93.66 Latch Hit %: 99.88
Parse CPU to Parse Elapsd %: 39.22 % Non-Parse CPU: 84.98

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 93.01 93.00
% SQL with executions>1: 33.44 33.44
% Memory for SQL w/exec>1: 23.60 23.60

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 130,477 819 82.07
SQL*Net more data to client 23,902 96 9.64
CPU time 61 6.08
latch free 14,732 18 1.77
log file parallel write 1,001 4 .35
-------------------------------------------------------------
Wait Events for DB: PROD Instance: PROD Snaps: 3579 -3580
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read 130,477 0 819 6 323.8
SQL*Net more data to client 23,902 0 96 4 59.3
latch free 14,732 1,568 18 1 36.6
log file parallel write 1,001 0 4 4 2.5
db file scattered read 45 0 0 9 0.1
control file sequential read 169 0 0 2 0.4
control file parallel write 130 0 0 1 0.3
LGWR wait for redo copy 61 0 0 1 0.2
buffer busy waits 6 0 0 3 0.0
log file sync 5 0 0 1 0.0
direct path read 609 0 0 0 1.5
wait list latch free 1 0 0 2 0.0
db file single write 1 0 0 1 0.0
direct path write 44 0 0 0 0.1
async disk IO 1 0 0 0 0.0
SQL*Net message from client 11,825 0 2,831 239 29.3
SQL*Net more data from clien 24,116 0 70 3 59.8
SQL*Net message to client 11,822 0 0 0 29.3
-------------------------------------------------------------
Background Wait Events for DB: PROD Instance: PROD Snaps: 3579 -3580
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file parallel write 1,002 0 4 4 2.5
control file sequential read 73 0 0 3 0.2
control file parallel write 128 0 0 1 0.3
db file scattered read 9 0 0 10 0.0
LGWR wait for redo copy 61 0 0 1 0.2
latch free 4 0 0 3 0.0
db file sequential read 1 0 0 5 0.0
rdbms ipc message 1,630 385 1,586 973 4.0
pmon timer 130 130 388 2985 0.3
smon timer 1 1 307 ###### 0.0
-------------------------------------------------------------
SQL ordered by Gets for DB: PROD Instance: PROD Snaps: 3579 -3580
-> 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
--------------- ------------ -------------- ------ -------- --------- ----------
10,129,996 672 15,074.4 53.6 59.50 159.29 2551952595
Module: SQL*Plus
SELECT /*+ index(fncprod.properties, idx_prop_census)*/ p.fi
ps_state_county, p.fips_township, p.source_owner, p.bas
e_rec_id, p.census_tract, p.census_block_group, p.gross
_living_area, p.bedrooms, p.bathrooms_total, p.rooms,
p.lot_size, p.land_use_dq, p.year_built, p.sales_date_
<----------------------------------------->
1,110,061 34,489 32.2 5.9 76.60 210.02 2242458687
Module: SQL*Plus
INSERT INTO modeled_property_values ( BASE_REC_ID,
SOURCE_OWNER, HEDONIC_VERSION,
HEDONIC_VALUE, HEDONIC_CALC_DATE,
ASSESSED_VAL_VERSION, ASSESSED_VAL_VALUE,
ASSESSED_VAL_CALC_DATE, RSI_VERSION,
<----------------------------------------->
604,150 34,501 17.5 3.2 49.81 111.81 367509209

Module: SQL*Plus
UPDATE modeled_property_values set
ASSESSED_VAL_VERSION = :b7, ASSESSED_VAL_VALUE
= :b6, ASSESSED_VAL_CALC_DATE = sysdate,
-- MEAN_VALUE = v_mean_value, -- RELIABILIT
Y_SCORE = v_RELIABILITY_SCORE, DATETIME_LAST_UPDA

555,227 38,346 14.5 2.9 42.65 142.44 2949035804
Module: SQL*Plus
UPDATE Modeled_Property_Values set hedonic_VALUE = trun
c(:b6), hedonic_CALC_DATE = sysdate, hedon
ic_VERSION = :b5, -- MEAN_VALUE = trunc(v_mean_value
), -- RELIABILITY_SCORE = trunc(v_RELIABILITY_SCO
RE), DATETIME_LAST_UPDATE = SYSDATE,

368,961 19,815 18.6 2.0 36.53 85.69 2650819819

Tom,

Yes, It is a very active table however, there is only one (PK )index on it. There are about 3 to 5 heavy duty batch programs which try to insert or update millions of rows in this table (update statment is also visible in the statpack report).

Seems like, it should not even take 32.2 gets per execution -- if you compare it with 14.5 gets per execution for the UPDATE statement on the same table (which at least goes out and first selects the record to be updated)

Thanks,
Neeraj

And here is the table structure, you can see that most of the columns are nullable columns. So I would tend to think, INSERT statement would should not be too heavy.


10:55:12 PRODUCTION ... SQL> desc modeled_property_values
 Name                                                                     Null?    Type
 ------------------------------------------------------------------------ -------- -----------------
 BASE_REC_ID                                                              NOT NULL NUMBER(9)
 SOURCE_OWNER                                                             NOT NULL CHAR(4)
 HEDONIC_VERSION                                                                   NUMBER(5)
 HEDONIC_VALUE                                                                     NUMBER(9)
 HEDONIC_CALC_DATE                                                                 DATE
 ASSESSED_VAL_VERSION                                                              NUMBER(5)
 ASSESSED_VAL_VALUE                                                                NUMBER(9)
 ASSESSED_VAL_CALC_DATE                                                            DATE
 RSI_VERSION                                                                       NUMBER(5)
 RSI_VALUE                                                                         NUMBER(9)
 RSI_CALC_DATE                                                                     DATE
 MEAN_VALUE                                                               NOT NULL NUMBER(9)
 RELIABILITY_SCORE                                                        NOT NULL NUMBER(3)
 LAST_SALE_DATE_USED                                                               DATE
 LAST_CLOSING_PRICE_USED                                                           NUMBER(9)
 DATETIME_REC_ADDED                                                                DATE
 DATETIME_LAST_UPDATE                                                              DATE
 UPDATE_USER                                                                       VARCHAR2(20)
 UPDATE_PROG                                                                       VARCHAR2(20)
 FINAL_VALUE                                                                       NUMBER
 RELIABILITY_SCORE2                                                                NUMBER(3)
 APPR_EMUL_VALUE                                                                   NUMBER(9)
 APPR_EMUL_CALC_DATE                                                               DATE
 APPR_EMUL_RESULT                                                                  CHAR(1)
 

Thanks very much for "to the point" answers.

Neeraj

<quote>
it is the consistent reads on the index and table. the index is being modified
as you are trying to read it and modify it yourself.

You can reduce that by bulking up, insert N rows at a time using array
processing instead of a row at a time for example.
</quote>

If every insert-a-row operation belongs to a different transaction, can we still use array processing?

Tom,
Please see the following from the statspack report.I want to know if the db_file_sequential_read is a matter of concern or not. My main concerns in this report are high hard parses per sec and very low soft parse percentage.

Thanks

System: Transactional
Report Duration: 15 minutes
CPUs: 8
Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 1301 07-Jun-05 22:13:19 51 11.7

End Snap: 1302 07-Jun-05 22:28:19 49 9.9

Elapsed: 15.00 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 656M Std Block Size:
8K
Shared Pool Size: 128M Log Buffer:
1,600K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 11,901.51 2,892.62
Logical reads: 14,147.82 3,438.57
Block changes: 75.05 18.24
Physical reads: 299.25 72.73
Physical writes: 4.10 1.00
User calls: 184.95 44.95
Parses: 65.74 15.98
Hard parses: 4.48 1.09
Sorts: 6.50 1.58
Logons: 0.06 0.01
Executes: 176.17 42.82
Transactions: 4.11

% Blocks changed per Read: 0.53 Recursive Call %: 71.13
Rollback per transaction %: 0.00 Rows per Sort: 641.45

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.84 Redo NoWait %: 100.00
Buffer Hit %: 97.88 In-memory Sort %: 100.00
Library Hit %: 97.79 Soft Parse %: 93.19
Execute to Parse %: 62.68 Latch Hit %: 99.91
Parse CPU to Parse Elapsd %: 97.59 % Non-Parse CPU: 91.88

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 88.92 86.25
% SQL with executions>1: 5.88 5.63
% Memory for SQL w/exec>1: 17.59 17.91

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file sequential read 252,136 634 58.00
CPU time 413 37.80
buffer busy waits 20,415 30 2.73
db file scattered read 3,821 6 .59
log file sync 2,814 3 .25
-------------------------------------------------------------

Actually these results are from unattended load test. The load test results are analyzed by the overall page response time. No one has complained so far, so I assume that queries are running fast enough. This makes the db_file_sequential_read a non-issue here. Thanks for pointing this out. Sorry, I got carried away by the technical details and forgot about the "compulsive tuning disorder" syndrome...

Hi Tom
I am studying a system , which has fours CPU.I took a sna shot for an hour.During this hour we have scheduled four different batch process against four different schemas.Two of the process completed in 45 minutes, the other two took about 90 minutes.
In the top five , I have log file sync which is approximately 23 minutes, library cache lock 23 minutes and also log file parallel write.
On investigation
One of our batch process written in java is commiting frequently.From reading your site and your book , I know it is not good to commit unless it is a business requirement.(Since this is a old code written as 20 multi threaded connections using connection pool, we are not touching the code).
From refering to your latest book In chapter 4 memory structure .It is said that while LGWR is writing Redo buffer,other sessions could be filling it up.
In chapter 5 under data base block writer "..DBWn does it slow job ....while LGWR does its faster job while user waits..."

1. I believe here when you say user , the user who has commited the transaction , not others.

2. In chapter nine under Log contention it is said "If you observe log file sync and log file parallel write ....log files are not written fast enough". Does it mean After avoiding the commit problem , should we concentrate on the action plan you have provided in the same heading.

3. I am wondering whether this is effecting the performance of the other three batch process whic are commiting at the end.(Since I have problems in tracing these sessions because of a bug, I haven't done yet).When I run stand alone they run in 40 minutes time.

4. If I follow the suggestions in this link
https://asktom.oracle.com/Misc/oramag/my-first-day-with-the-new-release.html
for the commit , will it solve the log file sync problem.


I was following this link www.jlcomp.demon.co.uk/statspack_01.html
unfortunately it is not working for last two days

Thank you very much for your time.

Sir,
In the statspack report's Top Timed Events,one event is CPU time.What does this represent?By definition that it is no of cpu seconds we consumed.But what we can tke out from this,I mean that whether this really indicates some problem or not?And how to correlate it with the %Elapsed time?
Regards
Aman....

Hi Tom,

You mentioned this in one of your responses.

<<So, a procedure that has been running for 10 hours and finished in your window would dump ALL of its cpu time into your window.>>

Could you please clarify if this logic of dumping the time in the snapshot at the end of the procedure call also applies to I/O related data and elapsed time of SQLs?

Also, I assume that the same goes with AWR reports as well. Isn't it?

Thanks,
Mahesh

ops$tkyte%ORA9IR2> create or replace function get_stat_val( p_name in varchar2 ) return number
  2  as
  3          l_val number;
  4  begin
  5      select b.value
  6            into l_val
  7        from v$statname a, v$mystat b
  8       where a.statistic# = b.statistic#
  9         and a.name = p_name;
 10
 11          return l_val;
 12  end;
 13  /

Function created.

ops$tkyte%ORA9IR2>
ops$tkyte%ORA9IR2> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle9i Enterprise Edition Release 9.2.0.8.0 - Production
PL/SQL Release 9.2.0.8.0 - Production
CORE    9.2.0.8.0       Production
TNS for Linux: Version 9.2.0.8.0 - Production
NLSRTL Version 9.2.0.8.0 - Production

ops$tkyte%ORA9IR2> exec dbms_output.put_line( 'cpu before = ' || get_stat_val( 'CPU used by this session' ) );
cpu before = 4

PL/SQL procedure successfully completed.

ops$tkyte%ORA9IR2> begin
  2          for x in (select rownum r, big_table.* from big_table.big_table where rownum <= 100000)
  3          loop
  4                  if (mod(x.r,10000) = 0)
  5                  then
  6                          dbms_output.put_line
  7                          ( to_char(x.r,'999,999,999') ||
  8                            ') consistent gets= ' || get_stat_val( 'consistent gets' ) ||
  9                            ' physical reads= ' || get_stat_val( 'physical reads' ) ||
 10                            ' cpu time= ' || get_stat_val( 'CPU used by this session' ) );
 11
 12                  end if;
 13          end loop;
 14  end;
 15  /
10,000) consistent gets= 10161 physical reads= 151 cpu time= 5
20,000) consistent gets= 20161 physical reads= 293 cpu time= 5
30,000) consistent gets= 30161 physical reads= 435 cpu time= 5
40,000) consistent gets= 40161 physical reads= 577 cpu time= 5
50,000) consistent gets= 50162 physical reads= 719 cpu time= 5
60,000) consistent gets= 60162 physical reads= 875 cpu time= 5
70,000) consistent gets= 70162 physical reads= 1017 cpu time= 5
80,000) consistent gets= 80162 physical reads= 1159 cpu time= 5
90,000) consistent gets= 90162 physical reads= 1301 cpu time= 5
100,000) consistent gets= 100162 physical reads= 1443 cpu time= 5

PL/SQL procedure successfully completed.

ops$tkyte%ORA9IR2> exec dbms_output.put_line( 'cpu after = ' || get_stat_val( 'CPU used by this session' ) );
cpu after = 258

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Prod
PL/SQL Release 10.2.0.4.0 - Production
CORE    10.2.0.4.0      Production
TNS for Linux: Version 10.2.0.4.0 - Production
NLSRTL Version 10.2.0.4.0 - Production

ops$tkyte%ORA10GR2> exec dbms_output.put_line( 'cpu before = ' || get_stat_val( 'CPU used by this session' ) );
cpu before = 69

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> begin
  2          for x in (select rownum r, big_table.* from big_table.big_table where rownum <= 100000)
  3          loop
  4                  if (mod(x.r,10000) = 0)
  5                  then
  6                          dbms_output.put_line
  7                          ( to_char(x.r,'999,999,999') ||
  8                            ') consistent gets= ' || get_stat_val( 'consistent gets' ) ||
  9                            ' physical reads= ' || get_stat_val( 'physical reads' ) ||
 10                            ' cpu time= ' || get_stat_val( 'CPU used by this session' ) );
 11
 12                  end if;
 13          end loop;
 14  end;
 15  /
10,000) consistent gets= 2823 physical reads= 262 cpu time= 77
20,000) consistent gets= 3072 physical reads= 388 cpu time= 84
30,000) consistent gets= 3321 physical reads= 514 cpu time= 91
40,000) consistent gets= 3564 physical reads= 640 cpu time= 98
50,000) consistent gets= 3807 physical reads= 766 cpu time= 104
60,000) consistent gets= 4040 physical reads= 892 cpu time= 112
70,000) consistent gets= 4288 physical reads= 1144 cpu time= 119
80,000) consistent gets= 4535 physical reads= 1270 cpu time= 126
90,000) consistent gets= 4779 physical reads= 1396 cpu time= 133
100,000) consistent gets= 5019 physical reads= 1522 cpu time= 139

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> exec dbms_output.put_line( 'cpu after = ' || get_stat_val( 'CPU used by this session' ) );
cpu after = 139

PL/SQL procedure successfully completed.

Hi Tom,

This being my very first question to you, I'm happy to get your help so admirably soon. I'm not trying to flattter you here but can't avoid mentioning the help you do to the herd:)

I've got a few AWR reports from the consecutive snaps. The data has been skewed in terms of the “elapsed time” and “cpu time” not making much sense. For instance, a poorly performing query was reported with an elapsed time of 763 seconds (1 executions) in the 1st report, 1761 seconds (0 executions) in the 2nd and 643 seconds (0 executions) in the 3rd report. I understand that the cumulative run time of the query as of 2nd report can be taken as 1761s but I assume that the 3rd report number should’ve been greater than 1761s, but it is not. Btw, the Oracle version I use is 10.2.0.3.

Please let me know if I'm missing something here.

Thanks,
Mahesh

Tom,

For example, I'm getting an elapsed time of 15369 seconds for one query, which is topping the charts in all sections of the report. If the numbers in AWR reports are not cumulative and belong only to that snap window, could you please clarify how an elapsed time of more than 4 hours is reported in a snap time of 30 minutes? Please oblige if my questions are silly.

Thanks,
Mahesh

Thanks Tom.

<<If 10,000 people run a query for 10 seconds in a ten second window - you would have 100,000 seconds of elapsed time in that window.>>

I think the number of executions in the above scenario will also get reflected in the same report for that particular snap window. I assume that this number will be 10,000 in the above mentioned scenario.

In my case, I get a zero as number of executions.
My questions are
1. Atleast one of the report taken in another snap window should reflect the real number of executions for that particular query, isn't it?
2. If the answer is no the above question, or like in my case, I see only "1" execution in one of the 3 reports (snap window) and "0" in the other two. What does it infer?

I know that you'd have referred me to the right page in the documentation if there's been one available, where I can find answers for my questions so far. So, please let me know from where I can get information on intricacies such as these about AWR & ASH, apart from experience :)

Thanks,
Mahesh

Thanks Tom.

I'm having a top query in my AWR report which has taken an about 4 hours to execute in a 30 minutes snap window. I've taken reports for a total of 8 hours (16 reports) and this query is present across all the reports with number of executions as 0. This query uses parallel hint and is declared as a cursor, opened & limit bulk collected. It is executed only once as part of the batch program and there's no other session which has executed this query.

I think that the elapsed time mentioned in the AWR report is the total time taken by each parallel process in a snap window to complete its operation, like how you mentioned about 10000 users running the same query. Please confirm if my understanding is right.

If this is the case, I can get the real elapsed time taken (cursor open & fetches) from an AWR report for this particular query, Isnt it?

Thanks,
Mahesh

Thanks Tom.

..If this is the case, I can get the real elapsed time taken (cursor open & fetches) from an AWR report for this particular query, Isnt it?..

What I meant by that was, if I can get the exact time taken (elapsed time) for a query by generating an AWR report for that sql id. If even this will confuse the timings, please suggest the way in which I can get the exact run time of the query.

Thanks,
Mahesh

Hi Tom,

Can we create Statspack report using 11g standard edition?



Thanks,
Ashish

Hi,

In tablespace IO wait, I am getting following


Tablespace Reads Av Reads/s Av Rd(ms) Av Blks/Rd Writes Av Writes/s Buffer Waits Av Buf Wt(ms)
TFW_DATA 9,908,515 117 0.51 4.93 7 ,526 0 9,926,092 1.01

So much of reads and buffer wait ( 9,908,515, 9,926,092) what does it indicates ?

thanks & regards
PJP

Hi Tom,

I have seen that in AWR Report for one tablespace
Reads are : 12,824,321 and
Buffer Waits : 50,367,930

I have not understood how buffer waits can be more than reads request. As per my understanding buffer waits can be less than or equal to reads.

Can you pl explain in which situation(s) buffer waits can be more than reads request ?

thanks & regards
parag

Dear Tom,
good day to you, I am going through one of the AWR shared with us for some performance issues at a site.

As per AWR shared one of the query has

elapsed time : 1013.78 seconds
executions : 0 (zero)
cpu time : 20.62 seconds
user I/O time : 999.81 seconds
gets per exec : blank
physical reads : 464713

But for the same query awr sql report has plan statistics with below figures

elapsed time : 377984 (ms)
cpu time : 34770 (ms)
user I/O wait time : 345210 (ms)
buffer gets : 699119
physical reads : 657255

I believe the time snapshot was taken this query was still executing and hence the executions is zero and buffer gets blank, but I am not able to understand why there's a difference in elapsed time, user I/O wait time and cpu time.

If you can please throw some light on this.Thanking you for your help and time on this.

Regards,
jvs.

I guess exection 0 means - the query was still in progess- it was getting executed , so you have taken the AWR's last snap before the query has actually completed.that is why the difference is.

Dear Tom,
good day to you, apologies for my previous post.Re-phrasing what I wanted to ask.

The below output is from AWR for a particular query.

elapsed time : 1013.78 seconds
executions : 0 (zero)
cpu time : 20.62 seconds
user I/O time : 999.81 seconds
gets per exec : blank
physical reads : 464713

Below are the details for the same query from AWR SQL report (plan statistics)

elapsed time : 377984 (ms)
cpu time : 34770 (ms)
user I/O wait time : 345210 (ms)
buffer gets : 699119
physical reads : 657255

1) I believe the time snapshot was taken the query was still executing and hence the executions is
zero and buffer gets blank.

2) I am not able to understand why there's a difference in elapsed time, user I/O wait time and cpu time.

If you can please throw some light on this.Thanking you for your help and time on this.

Regards,
jvs.

Hi Tom,

We are completely broked with a simple login query. We have generated a awr report and found out that:

In SQL oredered by gets,

NO of executions: 2334
Gets per Exec :815.00
CPU Time (s) :9.03
Elapsed Time (s):9.04


In Sql Ordered by executions:

Executions:2334
CPU per Exec (s) : 0.00
Elap per Exec (s) : 0.00

My questions are:

1)In sql ordered by gets it clearly shows that it took 9 secs on an average to execute that query. but why it is showing as 0 in sql ordered by executions. Please correct me,if i am wrong. Will the session be in INACTIVE at the time of logical reads?

2)What does a session with INACTIVE status and sql_hash_value='VALUE' mean and What does a session with INACTIVE status and sql_hash_value=0 mean.

For this query all the sessions are being in inactive state with sql_hash_value and no session waits on that query? What does it mean Tom .Please hemp me.

HI Tom,

Follow up of above question.

I am using 10.2.0.3 hp-ux 11.23 version.

Below are the outputs taken from awr report for the sql_id= d9ynx29rg884b

SQL ordered by gets


Gets CPU Elapsed
Buffer Gets Executions per Exec %Total Time (s) Time (s) SQL Id
-------------- ------------ ------------ ------ -------- --------- -------------

2,320,398 2,847 815.0 2.0 14.76 15.06 d9ynx29rg884b

SQL ordered by executions.

CPU per Executions Rows Processed Rows per Exec Exec (s)
Elap per
Exec (s) SQL Id
------------ --------------- -------------- ---------- ----------- -------------

2,847 11,670 5.00 0.00 0.00 d9ynx29rg884b



My understandind is the elapsed time for executions in SQL ordered by executions shows that it took 0.00 secs on an average for execution of that query
But in sql ordered by gets it shows that it took 15.06 secs to execute.

1)What is the difference between elapsed time in sql ordered by gets and sql ordered by executions.


2)Yes tom, We can simulate the problem everytime we perform load testing with 700-800 users.

The query with same sql_id(d9ynx29rg884b) is going to the inactive state with sql_hash_value='1861492875'.What does a inactive session with sql_hash_value mean. Do we need to worry about it?

I am attaching a sample output from v$session FUR.

Sid Ser# LOGIN Last call
In Secs STATUS SQL_HASH_VALUE
------ -------- ----------- --------- ------
116 18163 14Mar 07:41:00 PM 676 INACTI 1861492875
119 17329 14Mar 07:39:00 PM 813 INACTI 1861492875
126 5441 14Mar 07:35:00 PM 1016 INACTI 1861492875
135 11385 14Mar 07:35:00 PM 1019 INACTI 1861492875
141 52983 14Mar 07:37:00 PM 904 INACTI 1861492875
143 28428 14Mar 07:38:00 PM 857 INACTI 1861492875
149 27809 14Mar 07:39:00 PM 768 INACTI 1861492875
160 27749 14Mar 07:37:00 PM 905 INACTI 1861492875
164 21369 14Mar 07:35:00 PM 1047 INACTI 1861492875
167 43675 14Mar 07:35:00 PM 1011 INACTI 1861492875
169 43197 14Mar 07:41:00 PM 677 INACTI 1861492875
170 42543 14Mar 07:36:00 PM 959 INACTI 1861492875
173 20685 14Mar 04:54:00 PM 10632 INACTI 1861492875
180 32646 14Mar 07:35:00 PM 1049 INACTI 1861492875
182 5914 14Mar 07:39:00 PM 817 INACTI 1861492875
186 6209 14Mar 07:39:00 PM 771 INACTI 1861492875
194 42786 14Mar 07:37:00 PM 904 INACTI 1861492875
196 42880 14Mar 07:36:00 PM 967 INACTI 1861492875
198 15671 14Mar 07:34:00 PM 1109 INACTI 1861492875
200 18306 14Mar 07:40:00 PM 728 INACTI 1861492875
201 30886 14Mar 07:33:00 PM 1138 INACTI 1861492875
203 41503 14Mar 07:39:00 PM 813 INACTI 1861492875
206 7434 14Mar 07:35:00 PM 1044 INACTI 1861492875
207 21280 14Mar 07:39:00 PM 794 INACTI 1861492875
208 51951 14Mar 07:35:00 PM 1046 INACTI 1861492875
212 41638 14Mar 07:38:00 PM 839 INACTI 1861492875
215 34940 14Mar 07:39:00 PM 820 INACTI 1861492875
217 19682 14Mar 07:34:00 PM 1112 INACTI 1861492875
223 5670 14Mar 07:39:00 PM 775 INACTI 1861492875
229 42021 14Mar 02:42:00 PM 18563 INACTI 1861492875
232 50871 14Mar 07:33:00 PM 1136 INACTI 1861492875
234 23258 14Mar 07:41:00 PM 678 INACTI 1861492875
242 55169 14Mar 07:40:00 PM 720 INACTI 1861492875
252 51136 14Mar 07:36:00 PM 955 INACTI 1861492875
253 3054 14Mar 07:38:00 PM 855 INACTI 1861492875
254 5875 14Mar 07:37:00 PM 911 INACTI 1861492875
260 6443 14Mar 07:35:00 PM 1052 INACTI 1861492875
274 43294 14Mar 07:38:00 PM 858 INACTI 1861492875
279 19888 14Mar 07:40:00 PM 716 INACTI 1861492875
280 17974 14Mar 07:39:00 PM 818 INACTI 1861492875
287 2448 14Mar 07:36:00 PM 956 INACTI 1861492875
290 32877 14Mar 07:39:00 PM 801 INACTI 1861492875
296 23838 14Mar 07:38:00 PM 823 INACTI 1861492875
297 19468 14Mar 07:38:00 PM 827 INACTI 1861492875
303 32839 14Mar 07:34:00 PM 1111 INACTI 1861492875
306 4102 14Mar 07:35:00 PM 1052 INACTI 1861492875
310 43554 14Mar 07:35:00 PM 1050 INACTI 1861492875
326 39736 14Mar 07:39:00 PM 816 INACTI 1861492875
330 31194 14Mar 07:39:00 PM 801 INACTI 1861492875
332 47532 14Mar 07:40:00 PM 719 INACTI 1861492875
341 43603 14Mar 07:34:00 PM 1082 INACTI 1861492875
342 35340 14Mar 07:38:00 PM 819 INACTI 1861492875
343 29222 14Mar 07:39:00 PM 814 INACTI 1861492875
349 37882 14Mar 07:39:00 PM 812 INACTI 1861492875
350 30784 14Mar 07:36:00 PM 954 INACTI 1861492875
351 22179 14Mar 07:37:00 PM 904 INACTI 1861492875
354 13320 14Mar 07:34:00 PM 1111 INACTI 1861492875
358 34913 14Mar 07:36:00 PM 963 INACTI 1861492875
359 43233 14Mar 07:34:00 PM 1108 INACTI 1861492875
361 50312 14Mar 07:36:00 PM 961 INACTI 1861492875
362 18387 14Mar 07:34:00 PM 1109 INACTI 1861492875
371 31310 14Mar 07:39:00 PM 803 INACTI 1861492875
379 39002 14Mar 07:36:00 PM 962 INACTI 1861492875
386 41214 14Mar 07:36:00 PM 952 INACTI 1861492875
394 6443 14Mar 07:39:00 PM 766 INACTI 1861492875
397 49195 14Mar 07:37:00 PM 918 INACTI 1861492875
401 24916 14Mar 07:37:00 PM 903 INACTI 1861492875
406 35292 14Mar 07:35:00 PM 1052 INACTI 1861492875
414 52399 14Mar 07:36:00 PM 958 INACTI 1861492875
420 26596 14Mar 07:41:00 PM 678 INACTI 1861492875
424 47141 14Mar 07:36:00 PM 957 INACTI 1861492875
432 22773 14Mar 07:38:00 PM 825 INACTI 1861492875
434 20228 14Mar 07:37:00 PM 918 INACTI 1861492875
436 26281 14Mar 07:41:00 PM 677 INACTI 1861492875
437 41141 14Mar 07:38:00 PM 827 INACTI 1861492875
438 16737 14Mar 07:37:00 PM 903 INACTI 1861492875
450 35459 14Mar 07:36:00 PM 967 INACTI 1861492875
452 41251 14Mar 07:35:00 PM 1024 INACTI 1861492875
458 3717 14Mar 07:40:00 PM 720 INACTI 1861492875
465 20551 14Mar 07:41:00 PM 677 INACTI 1861492875
468 40321 14Mar 07:39:00 PM 805 INACTI 1861492875
473 52425 14Mar 07:39:00 PM 798 INACTI 1861492875
479 24585 14Mar 07:40:00 PM 718 INACTI 1861492875
481 15943 14Mar 07:40:00 PM 727 INACTI 1861492875
483 31345 14Mar 07:35:00 PM 1015 INACTI 1861492875
484 27965 14Mar 07:35:00 PM 1012 INACTI 1861492875
485 13789 14Mar 07:35:00 PM 1050 INACTI 1861492875
489 33487 14Mar 07:39:00 PM 772 INACTI 1861492875
493 52732 14Mar 07:39:00 PM 771 INACTI 1861492875
494 56745 14Mar 07:38:00 PM 837 INACTI 1861492875
498 25353 14Mar 07:37:00 PM 906 INACTI 1861492875
499 15206 14Mar 07:36:00 PM 961 INACTI 1861492875
502 40872 14Mar 07:40:00 PM 729 INACTI 1861492875
505 18231 14Mar 07:39:00 PM 797 INACTI 1861492875
509 54263 14Mar 07:41:00 PM 678 INACTI 1861492875
512 32253 14Mar 07:41:00 PM 678 INACTI 1861492875
516 18311 14Mar 07:37:00 PM 906 INACTI 1861492875
525 13011 14Mar 07:37:00 PM 921 INACTI 1861492875
532 37502 14Mar 07:35:00 PM 1015 INACTI 1861492875
536 64883 14Mar 07:36:00 PM 954 INACTI 1861492875
537 14937 14Mar 07:38:00 PM 823 INACTI 1861492875
538 46457 14Mar 07:38:00 PM 825 INACTI 1861492875
539 47124 14Mar 07:37:00 PM 903 INACTI 1861492875
544 32778 14Mar 07:33:00 PM 1133 INACTI 1861492875
547 35375 14Mar 07:41:00 PM 677 INACTI 1861492875
551 17762 14Mar 07:40:00 PM 721 INACTI 1861492875
556 65126 14Mar 07:38:00 PM 868 INACTI 1861492875
557 30126 14Mar 07:34:00 PM 1112 INACTI 1861492875
567 53635 14Mar 07:37:00 PM 906 INACTI 1861492875
572 8724 14Mar 07:35:00 PM 1012 INACTI 1861492875
586 16199 14Mar 07:34:00 PM 1109 INACTI 1861492875
594 60290 14Mar 07:35:00 PM 1024 INACTI 1861492875
596 32287 14Mar 07:39:00 PM 772 INACTI 1861492875
598 21243 14Mar 07:39:00 PM 770 INACTI 1861492875
599 43234 14Mar 07:39:00 PM 803 INACTI 1861492875
601 47140 14Mar 07:35:00 PM 1050 INACTI 1861492875
604 29756 14Mar 07:37:00 PM 906 INACTI 1861492875
607 43124 14Mar 07:36:00 PM 954 INACTI 1861492875
611 37348 14Mar 07:34:00 PM 1080 INACTI 1861492875
612 13177 14Mar 07:37:00 PM 911 INACTI 1861492875
614 29141 14Mar 07:38:00 PM 856 INACTI 1861492875
616 19317 14Mar 07:37:00 PM 919 INACTI 1861492875
618 17945 14Mar 07:37:00 PM 908 INACTI 1861492875
619 27170 14Mar 07:33:00 PM 1135 INACTI 1861492875
622 17670 14Mar 07:37:00 PM 904 INACTI 1861492875
623 11438 14Mar 07:36:00 PM 963 INACTI 1861492875
627 18195 14Mar 07:40:00 PM 719 INACTI 1861492875
629 4698 14Mar 07:35:00 PM 1010 INACTI 1861492875
634 35807 14Mar 07:37:00 PM 903 INACTI 1861492875
635 31757 14Mar 07:36:00 PM 963 INACTI 1861492875
641 32878 14Mar 07:37:00 PM 905 INACTI 1861492875
644 37312 14Mar 07:36:00 PM 964 INACTI 1861492875
645 1574 14Mar 07:41:00 PM 679 INACTI 1861492875
653 47655 14Mar 07:34:00 PM 1078 INACTI 1861492875
658 23732 14Mar 07:39:00 PM 769 INACTI 1861492875
664 37663 14Mar 07:39:00 PM 772 INACTI 1861492875
669 39546 14Mar 07:37:00 PM 921 INACTI 1861492875
672 48975 14Mar 07:38:00 PM 826 INACTI 1861492875
680 17612 14Mar 07:39:00 PM 795 INACTI 1861492875
684 63948 14Mar 07:34:00 PM 1080 INACTI 1861492875
686 31676 14Mar 07:35:00 PM 1022 INACTI 1861492875
689 42709 14Mar 07:40:00 PM 728 INACTI 1861492875
703 13705 14Mar 07:39:00 PM 818 INACTI 1861492875
704 50857 14Mar 07:41:00 PM 680 INACTI 1861492875
705 55655 14Mar 07:36:00 PM 956 INACTI 1861492875
712 23943 14Mar 07:37:00 PM 905 INACTI 1861492875
723 41238 14Mar 07:35:00 PM 1025 INACTI 1861492875
725 65433 14Mar 07:36:00 PM 965 INACTI 1861492875
728 55855 14Mar 07:34:00 PM 1079 INACTI 1861492875
731 58873 14Mar 07:39:00 PM 800 INACTI 1861492875
735 41257 14Mar 07:35:00 PM 1047 INACTI 1861492875
750 22935 14Mar 07:34:00 PM 1082 INACTI 1861492875
753 46853 14Mar 07:35:00 PM 1018 INACTI 1861492875
757 43939 14Mar 07:39:00 PM 772 INACTI 1861492875
768 29709 14Mar 07:37:00 PM 904 INACTI 1861492875
771 7411 14Mar 07:39:00 PM 818 INACTI 1861492875
776 12502 14Mar 07:37:00 PM 907 INACTI 1861492875
782 26533 14Mar 07:38:00 PM 832 INACTI 1861492875
794 36801 14Mar 07:39:00 PM 812 INACTI 1861492875
795 684 14Mar 07:39:00 PM 811 INACTI 1861492875
797 9531 14Mar 07:39:00 PM 795 INACTI 1861492875
799 44590 14Mar 07:35:00 PM 1011 INACTI 1861492875
801 12094 14Mar 07:38:00 PM 857 INACTI 1861492875
808 18990 14Mar 07:35:00 PM 1012 INACTI 1861492875
814 31670 14Mar 07:38:00 PM 819 INACTI 1861492875
830 35065 14Mar 07:33:00 PM 1138 INACTI 1861492875
832 42459 14Mar 07:36:00 PM 967 INACTI 1861492875
839 45390 14Mar 07:37:00 PM 918 INACTI 1861492875
840 32330 14Mar 07:39:00 PM 780 INACTI 1861492875
842 28826 14Mar 07:38:00 PM 856 INACTI 1861492875
846 28759 14Mar 07:35:00 PM 1050 INACTI 1861492875
847 56802 14Mar 07:39:00 PM 802 INACTI 1861492875
848 34471 14Mar 07:35:00 PM 1011 INACTI 1861492875
850 56950 14Mar 07:37:00 PM 908 INACTI 1861492875
851 42640 14Mar 07:40:00 PM 728 INACTI 1861492875
852 61138 14Mar 07:39:00 PM 799 INACTI 1861492875
861 2255 14Mar 07:38:00 PM 869 INACTI 1861492875
863 56879 14Mar 07:38:00 PM 858 INACTI 1861492875
905 3448 14Mar 07:34:00 PM 1109 INACTI 1861492875
923 23248 14Mar 07:36:00 PM 963 INACTI 1861492875
935 25950 14Mar 07:37:00 PM 903 INACTI 1861492875
937 21869 14Mar 07:39:00 PM 775 INACTI 1861492875
943 31784 14Mar 07:41:00 PM 678 INACTI 1861492875
948 26007 14Mar 07:40:00 PM 728 INACTI 1861492875
949 34612 14Mar 07:39:00 PM 820 INACTI 1861492875
951 4382 14Mar 07:34:00 PM 1080 INACTI 1861492875
952 5331 14Mar 07:35:00 PM 1016 INACTI 1861492875
954 47550 14Mar 07:37:00 PM 908 INACTI 1861492875
955 12208 14Mar 07:36:00 PM 959 INACTI 1861492875
956 36608 14Mar 07:37:00 PM 911 INACTI 1861492875
960 16074 14Mar 07:33:00 PM 1136 INACTI 1861492875
966 3941 14Mar 07:38:00 PM 867 INACTI 1861492875
978 37790 14Mar 07:36:00 PM 952 INACTI 1861492875
982 34129 14Mar 07:36:00 PM 951 INACTI 1861492875
983 48099 14Mar 07:34:00 PM 1080 INACTI 1861492875
985 47411 14Mar 07:39:00 PM 770 INACTI 1861492875
990 31657 14Mar 07:34:00 PM 1077 INACTI 1861492875
993 58125 14Mar 07:37:00 PM 906 INACTI 1861492875
998 5970 14Mar 07:38:00 PM 825 INACTI 1861492875
1002 29036 14Mar 07:36:00 PM 963 INACTI 1861492875
1008 3930 14Mar 07:38:00 PM 827 INACTI 1861492875
1009 40851 14Mar 07:38:00 PM 855 INACTI 1861492875
1014 22783 14Mar 07:39:00 PM 813 INACTI 1861492875
1017 3965 14Mar 07:37:00 PM 904 INACTI 1861492875
1019 43698 14Mar 07:34:00 PM 1080 INACTI 1861492875
1021 6222 14Mar 07:41:00 PM 676 INACTI 1861492875
1022 41839 14Mar 07:37:00 PM 911 INACTI 1861492875
1025 5386 14Mar 07:36:00 PM 964 INACTI 1861492875
1032 40767 14Mar 07:36:00 PM 963 INACTI 1861492875
1034 32036 14Mar 07:35:00 PM 1048 INACTI 1861492875
1039 5209 14Mar 07:36:00 PM 956 INACTI 1861492875
1043 25857 14Mar 07:34:00 PM 1111 INACTI 1861492875
1045 39165 14Mar 07:36:00 PM 953 INACTI 1861492875
1049 35147 14Mar 07:39:00 PM 801 INACTI 1861492875
1058 62026 14Mar 07:35:00 PM 1052 INACTI 1861492875
1063 51617 14Mar 07:37:00 PM 905 INACTI 1861492875
1065 36081 14Mar 07:39:00 PM 768 INACTI 1861492875
1072 23474 14Mar 07:37:00 PM 906 INACTI 1861492875
1079 46856 14Mar 07:39:00 PM 802 INACTI 1861492875
1083 49738 14Mar 07:34:00 PM 1080 INACTI 1861492875
1085 41932 14Mar 07:39:00 PM 802 INACTI 1861492875
1092 41591 14Mar 07:41:00 PM 674 INACTI 1861492875
1099 40036 14Mar 07:41:00 PM 672 INACTI 1861492875
1101 44457 14Mar 07:35:00 PM 1046 INACTI 1861492875
1102 28395 14Mar 07:36:00 PM 962 INACTI 1861492875
1104 14479 14Mar 07:34:00 PM 1112 INACTI 1861492875
1107 23453 14Mar 07:36:00 PM 953 INACTI 1861492875
1108 54099 14Mar 07:38:00 PM 823 INACTI 1861492875
1112 60200 14Mar 07:39:00 PM 761 INACTI 1861492875
1113 65483 14Mar 07:34:00 PM 1080 INACTI 1861492875
1116 45146 14Mar 07:39:00 PM 798 INACTI 1861492875
1117 59544 14Mar 07:38:00 PM 869 INACTI 1861492875
1118 32987 14Mar 07:37:00 PM 904 INACTI 1861492875
1120 21800 14Mar 07:39:00 PM 770 INACTI 1861492875
1123 22570 14Mar 07:37:00 PM 906 INACTI 1861492875
1124 25225 14Mar 07:38:00 PM 834 INACTI 1861492875
1125 64739 14Mar 07:39:00 PM 814 INACTI 1861492875
1126 263 14Mar 07:38:00 PM 824 INACTI 1861492875
1134 28025 14Mar 07:38:00 PM 869 INACTI 1861492875
1135 11527 14Mar 07:35:00 PM 1013 INACTI 1861492875
1136 43500 14Mar 07:33:00 PM 1137 INACTI 1861492875
1143 34564 14Mar 07:40:00 PM 729 INACTI 1861492875
1147 56909 14Mar 07:41:00 PM 680 INACTI 1861492875
1151 5105 14Mar 07:36:00 PM 959 INACTI 1861492875
1153 29126 14Mar 07:37:00 PM 920 INACTI 1861492875
1154 54085 14Mar 07:38:00 PM 867 INACTI 1861492875
1158 17726 14Mar 07:37:00 PM 901 INACTI 1861492875
1161 22592 14Mar 07:38:00 PM 820 INACTI 1861492875
1166 48352 14Mar 07:39:00 PM 806 INACTI 1861492875
1169 24251 14Mar 07:39:00 PM 804 INACTI 1861492875
1171 4728 14Mar 07:38:00 PM 825 INACTI 1861492875
1184 22446 14Mar 07:36:00 PM 962 INACTI 1861492875
1186 30560 14Mar 07:38:00 PM 858 INACTI 1861492875
1187 38166 14Mar 07:41:00 PM 676 INACTI 1861492875
1196 25375 14Mar 07:39:00 PM 800 INACTI 1861492875
1203 45172 14Mar 07:37:00 PM 904 INACTI 1861492875
1205 46049 14Mar 07:33:00 PM 1136 INACTI 1861492875
1207 41868 14Mar 07:38:00 PM 856 INACTI 1861492875
1209 36559 14Mar 07:37:00 PM 908 INACTI 1861492875
1216 41315 14Mar 07:34:00 PM 1111 INACTI 1861492875

ops$tkyte%ORA11GR2> select 15.06/2847 from dual;

15.06/2847
----------
.005289779

I am attaching a sample output from v$session FUR.

Sid    Ser#    LOGIN                  Last call
                                       In Secs    STATUS     SQL_HASH_VALUE    
------    --------    -----------           --------- ------    
116    18163    14Mar    07:41:00 PM    676    INACTI    1861492875    
119    17329    14Mar    07:39:00 PM    813    INACTI    1861492875    
126    5441    14Mar    07:35:00 PM    1016    INACTI    1861492875
...

1216    41315    14Mar    07:34:00 PM    1111    INACTI    1861492875    

Hi Tom,

Please find the sql statement associated to above mentioned sql hash value.

SELECT
T4.CONFLICT_ID,
T4.LAST_UPD,
T4.CREATED,
T4.LAST_UPD_BY,
T4.CREATED_BY,
T4.MODIFICATION_NUM,
T4.ROW_ID,
T6.BASE_CURCY_CD,
T6.LOC,
T6.NAME,
T3.NAME,
T5.NAME,
T5.BU_FLG,
T6.PAR_BU_ID,
T4.PAR_PARTY_ID,
T2.NAME,
T4.NAME,
T4.PARTY_TYPE_CD,
T6.PRTNR_FLG,
T1.NAME,
T6.PR_MGR_POSTN_ID,
T4.ROOT_PARTY_FLG,
T6.PR_ADDR_ID,
T6.CMPT_FLG,
T5.ROW_ID,
T5.PAR_ROW_ID,
T5.MODIFICATION_NUM,
T5.CREATED_BY,
T5.LAST_UPD_BY,
T5.CREATED,
T5.LAST_UPD,
T5.CONFLICT_ID,
T5.PAR_ROW_ID,
T6.ROW_ID,
T6.PAR_ROW_ID,
T6.MODIFICATION_NUM,
T6.CREATED_BY,
T6.LAST_UPD_BY,
T6.CREATED,
T6.LAST_UPD,
T6.CONFLICT_ID,
T6.PAR_ROW_ID
FROM
SIEBEL.S_POSTN T1,
SIEBEL.S_ORG_EXT T2,
SIEBEL.S_ORG_EXT T3,
SIEBEL.S_PARTY T4,
SIEBEL.S_BU T5,
SIEBEL.S_ORG_EXT T6
WHERE
T6.PAR_BU_ID = T3.PAR_ROW_ID (+) AND
T4.PAR_PARTY_ID = T2.PAR_ROW_ID (+) AND
T6.PR_MGR_POSTN_ID = T1.PAR_ROW_ID (+) AND
T4.ROW_ID = T5.PAR_ROW_ID (+) AND
T4.ROW_ID = T6.PAR_ROW_ID AND
(T6.INT_ORG_FLG = 'Y')
ORDER BY
T6.NAME

Tom,

We noticed that our DB gets slower over period of time and not sure what could be the reason. I am not a sysadmin or a DBA but our DB runs on a VM. Following is the top portion of the top command:

top - 16:59:27 up 29 days, 6:25, 7 users, load average: 2.74, 2.88, 2.80
Tasks: 109 total, 3 running, 106 sleeping, 0 stopped, 0 zombie
Cpu(s): 21.5% us, 49.4% sy, 0.0% ni, 8.6% id, 20.0% wa, 0.5% hi, 0.0% si
Mem: 1701048k total, 1686016k used, 15032k free, 928k buffers
Swap: 8385824k total, 1262724k used, 7123100k free, 1450512k cached

Following is the excerpts of AWR report. Cold you please help me decipher the issue? Also I am not sure why there are negative numbers in the report. Sorry for the long post though. Please let me know if you need more information.

===========================================================
WORKLOAD REPOSITORY report for

DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
ORA10G 4001902797 ora10g 1 10.2.0.4.0 NO contentdbus.

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 14356 10-Mar-11 01:01:38 18 2.0
End Snap: 14358 15-Mar-11 02:00:17 20 2.1
Elapsed: 7,258.65 (mins)
DB Time: -4,907.75 (mins)

Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 1,184M 1,376M Std Block Size: 16K
Shared Pool Size: 320M 128M Log Buffer: 64,296K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: -557,202.52 1,102,009.44
Logical reads: -2,395.63 4,737.97
Block changes: -1,461.49 2,890.46
Physical reads: -601.19 1,189.01
Physical writes: -43.88 86.78
User calls: -363.15 718.22
Parses: -22.94 45.37
Hard parses: -0.30 0.60
Sorts: -25.85 51.13
Logons: -0.10 0.19
Executes: -298.80 590.95
Transactions: -0.51

% Blocks changed per Read: 61.01 Recursive Call %: 30.28
Rollback per transaction %: 0.00 Rows per Sort: 505.15

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.99 Redo NoWait %: 100.00
Buffer Hit %: 75.34 In-memory Sort %: 100.00
Library Hit %: 99.68 Soft Parse %: 98.69
Execute to Parse %: 92.32 Latch Hit %: 99.99
Parse CPU to Parse Elapsd %: 22.76 % Non-Parse CPU: 99.19

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 72.94 64.25
% SQL with executions>1: 95.06 58.86
% Memory for SQL w/exec>1: 85.45 59.72

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
PX Deq: Test for msg 1 0 19 -0.0 Other
PX qref latch 1 0 6 -0.0 Other
PX Deq: Signal ACK 1 0 4 -0.0 Other
-------------------------------------------------------------
Time Model Statistics DB/Inst: ORA10G/ora10g Snaps: 14356-14358

No data exists for this section of the report.
-------------------------------------------------------------

Wait Class DB/Inst: ORA10G/ora10g Snaps: 14356-14358
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc

Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Other 3 33.3 0 10 -0.0
-------------------------------------------------------------

Wait Events DB/Inst: ORA10G/ora10g Snaps: 14356-14358
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
PX Deq: Test for msg 1 .0 0 19 -0.0
PX qref latch 1 100.0 0 6 -0.0
PX Deq: Signal ACK 1 .0 0 4 -0.0
PX Deque wait 1 .0 0 0 -0.0
-------------------------------------------------------------

Background Wait Events DB/Inst: ORA10G/ora10g Snaps: 14356-14358
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
cursor: pin S wait on X 2 100.0 0 11 -0.0
-------------------------------------------------------------

Operating System Statistics DB/Inst: ORA10G/ora10g Snaps: 14356-14358

Statistic Total
-------------------------------- --------------------
BUSY_TIME -26,263,443
IDLE_TIME -299,492,286
IOWAIT_TIME -9,102,070
NICE_TIME -691
SYS_TIME -18,267,608
USER_TIME -7,416,447
LOAD 3
RSRC_MGR_CPU_WAIT_TIME 0
PHYSICAL_MEMORY_BYTES 1,741,873,152
NUM_CPUS 2
-------------------------------------------------------------

Service Statistics DB/Inst: ORA10G/ora10g Snaps: 14356-14358
-> ordered by DB Time

Physical Logical
Service Name DB Time (s) DB CPU (s) Reads Reads
-------------------------------- ------------ ------------ ---------- ----------
SYS$BACKGROUND 0.0 0.0 -179,297 ##########
ora10g -9,257.8 -5,028.0 -3,602,520 ##########
SYS$USERS -285,244.2 -171,987.1 ########## ##########
-------------------------------------------------------------

Service Wait Class Stats DB/Inst: ORA10G/ora10g Snaps: 14356-14358
-> Wait Class info for services in the Service Statistics section.
-> Total Waits and Time Waited displayed for the following wait
classes: User I/O, Concurrency, Administrative, Network
-> Time Waited (Wt Time) in centisecond (100th of a second)

Service Name
----------------------------------------------------------------
User I/O User I/O Concurcy Concurcy Admin Admin Network Network
Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time
--------- --------- --------- --------- --------- --------- --------- ---------
SYS$BACKGROUND
-172186 -104290 -19231 -450276 0 0 0 0
SYS$USERS
-28931336 -8180562 -13557 -111483 0 0 ######### -602732
-------------------------------------------------------------

SQL ordered by Elapsed Time DB/Inst: ORA10G/ora10g Snaps: 14356-14358
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100

Elapsed CPU Elap per % Total
Time (s) Time (s) Executions Exec (s) DB Time SQL Id
---------- ---------- ------------ ---------- ------- -------------
3,592 1,952 62 57.9 -1.2 48mmp4v5f42xz


Parameter Name Begin value (if different)
----------------------------- --------------------------------- --------------
_gby_hash_aggregation_enabled FALSE
audit_file_dest /u01/app/oracle/admin/ora10g/adum
background_dump_dest /u01/app/oracle/admin/ora10g/bdum
compatible 10.2.0.1.0
control_files /u01/oradata/ora10g/control01.ctl
core_dump_dest /u01/app/oracle/admin/ora10g/cdum
cursor_sharing EXACT
db_block_size 16384

Tom,

Our UI progressively gets sluggish and grinds to halt (almost). We cant perform any operations. Usually our sysadmin restarts the database and/or the tomcat server and things become normal. I took the snap_id from 14356 to 14358 consecutively for 3hrs. I am not sure why it is showing 10th march for 14356. What do you recommend? should i generate report for each hr interval for the time range of 3hrs?

Thanks!

Hi Tom,

I have two AWR reports. One for the base line and another when application was slow, in HTML format. Please let me know how I could post the reports.

Many thanks!

shutting down application server fix the issue,problem seems to be in application server,also check cpu time in awr,and sorting

Hi,

I am getting Elapsed Time from AWR report which is very high when I compare with application log.

FROM AWR (its like 4Hrs+)

  Elapsed      CPU                  Elap per  % Total
  Time (s)   Time (s)  Executions   Exec (s)  DB Time    SQL Id
---------- ---------- ------------ ---------- ------- -------------
    18,951      1,611            1    18950.8    52.2 9djf8mt70qjfk
Module: armServ@KNPRAP03 (TNS V1-V3)
SELECT /*+ full(cb) full(ac) full(c) full(a) full(p) parallel(cb,8) parallel(ac,
2) parallel(a,4) parallel(c,2) parallel(p,4) */ AC.ACCOUNT_NO, :B3 , :B3 , :B3 ,
 SUM(CB.BALANCE_DUE) BALANCE, AC.TRACKING_ID, AC.TRACKING_ID_SERV, AC.EXT_EVENT_
ID, AC.EXT_EVENT_TYPE, AC.COLLECTABLE_ID, AC.COLLECTABLE_SERV, C.CURRENCY_CODE F

However in application it shows only 52 mins.

/* Command(sequence 667798) start: 08/25/11 04:39:17 */
 BEGIN arm_cure_collectables_site(v_use_arm_work_list=>:v_use_arm_work_list,v_work_id=>:v_work_id,v_balance_calculation=>:v_balance_calculation,arm_cure_collectables_site_cv=>:ar
m_cure_collectables_site_cv); END;
Input values:
        v_use_arm_work_list: 1
        v_work_id: 2020
        v_balance_calculation: 13
/* Command(sequence 667798) end: 08/25/11 05:32:15. Elapsed time in seconds: 3178.377 */

The arm_cure_collectables_site function calls the SQL present in AWR report.

This is 24 cores machine.

Thanks for you help.

Regards,

Laxman

WORKLOAD REPOSITORY report for

DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
ANAD1 3886838561 ANAD1 1 10.2.0.4.0 NO ANAD-db1

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 20103 30-Sep-11 10:00:50 454 21.5
End Snap: 20105 30-Sep-11 11:00:26 370 22.1
Elapsed: 59.60 (mins)
DB Time: 5,159.14 (mins)

Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 77,696M 77,696M Std Block Size: 16K
Shared Pool Size: 2,016M 2,016M Log Buffer: 33,792K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 19,530,842.94 133,872.09
Logical reads: 764,124.21 5,237.61
Block changes: 80,073.77 548.86
Physical reads: 7,024.62 48.15
Physical writes: 3,462.74 23.74
User calls: 7,046.74 48.30
Parses: 5,159.45 35.36
Hard parses: 2.16 0.01
Sorts: 467.66 3.21
Logons: 0.54 0.00
Executes: 208,087.26 1,426.31
Transactions: 145.89

% Blocks changed per Read: 10.48 Recursive Call %: 96.75
Rollback per transaction %: 0.01 Rows per Sort: 1077.00

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.98 Redo NoWait %: 99.99
Buffer Hit %: 99.54 In-memory Sort %: 100.00
Library Hit %: 98.69 Soft Parse %: 99.96
Execute to Parse %: 97.52 Latch Hit %: 99.11
Parse CPU to Parse Elapsd %: 43.44 % Non-Parse CPU: 99.74

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 61.56 57.32
% SQL with executions>1: 76.56 81.82
% Memory for SQL w/exec>1: 66.62 84.03

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 4,613,002 147,609 32 47.7 User I/O
CPU time 101,708 32.9
db file scattered read 537,408 12,911 24 4.2 User I/O
direct path read 725,521 10,741 15 3.5 User I/O
PX Deq: Table Q qref 8,129 9,819 1208 3.2 Other
-------------------------------------------------------------
Time Model Statistics DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> Total time in database user-calls (DB Time): 309548.4s
-> Statistics including the word "background" measure background process
time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time 301,119.9 97.3
DB CPU 101,708.4 32.9
PL/SQL execution elapsed time 16,788.7 5.4
parse time elapsed 998.2 .3
hard parse elapsed time 487.6 .2
sequence load elapsed time 274.6 .1
PL/SQL compilation elapsed time 30.3 .0
hard parse (sharing criteria) elapsed time 4.5 .0
repeated bind elapsed time 3.6 .0
connection management call elapsed time 1.7 .0
hard parse (bind mismatch) elapsed time 1.0 .0
failed parse elapsed time 0.1 .0
DB time 309,548.4 N/A
background elapsed time 14,185.3 N/A
background cpu time 1,113.4 N/A
-------------------------------------------------------------

Wait Class DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc

Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
User I/O 6,651,500 .0 184,141 28 12.8
Other 210,576 15.1 17,369 82 0.4
System I/O 3,649,396 .0 13,724 4 7.0
Concurrency 504,312 5.5 4,393 9 1.0
Commit 342,196 .5 4,198 12 0.7
Configuration 79,686 1.2 2,119 27 0.2
Application 6,374 1.4 448 70 0.0
Network 16,218,995 .0 39 0 31.1
-------------------------------------------------------------

Wait Events DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file sequential read 4,613,002 .0 147,609 32 8.8
db file scattered read 537,408 .0 12,911 24 1.0
direct path read 725,521 .0 10,741 15 1.4
PX Deq: Table Q qref 8,129 49.6 9,819 1208 0.0
direct path read temp 352,200 .0 7,640 22 0.7
log file sequential read 70,405 .0 7,276 103 0.1
enq: PS - contention 3,949 73.5 7,086 1794 0.0
read by other session 219,495 .0 4,513 21 0.4
db file parallel write 3,044,794 .0 4,339 1 5.8
log file sync 342,196 .5 4,198 12 0.7
enq: TX - index contention 145,048 .0 3,799 26 0.3
log buffer space 2,673 35.5 1,252 468 0.0
log file parallel write 429,308 .0 1,121 3 0.8
control file sequential read 28,152 .0 942 33 0.1
log file switch completion 5,298 .0 759 143 0.0
direct path write temp 160,995 .0 536 3 0.3
enq: TX - row lock contentio 3,447 2.6 394 114 0.0
PX Deq Credit: send blkd 11,035 .7 338 31 0.0
cursor: pin S wait on X 27,703 99.9 271 10 0.1
buffer busy waits 311,726 .0 192 1 0.6
direct path write 42,860 .0 188 4 0.1
enq: SQ - contention 70,959 .0 92 1 0.1
enq: CF - contention 128 10.9 65 509 0.0
SQL*Net break/reset to clien 2,716 .0 51 19 0.0
latch: In memory undo latch 2,263 .0 44 20 0.0
control file parallel write 7,560 .0 42 6 0.0
SGA: allocation forcing comp 4,087 98.3 40 10 0.0
library cache load lock 132 1.5 33 249 0.0
row cache lock 134 7.5 32 241 0.0
SQL*Net message to client 15,683,045 .0 19 0 30.1
SQL*Net more data to client 408,515 .0 18 0 0.8
enq: HW - contention 300 .0 14 48 0.0
latch: cache buffers chains 10,002 .0 11 1 0.0
os thread startup 159 .0 9 59 0.0
latch free 1,204 .0 7 6 0.0
Streams AQ: qmn coordinator 1 100.0 5 4883 0.0
rdbms ipc reply 203 .0 3 16 0.0
enq: TX - allocate ITL entry 75 .0 2 26 0.0
enq: RO - fast object reuse 203 .0 2 9 0.0
SQL*Net more data from clien 127,435 .0 2 0 0.2
kksfbc child completion 46 82.6 2 40 0.0
LGWR wait for redo copy 22,014 .2 2 0 0.0
log file single write 276 .0 2 6 0.0
db file parallel read 12 .0 2 131 0.0
Log archive I/O 68,901 .0 2 0 0.1
latch: library cache 912 .0 1 1 0.0
cursor: pin S 135,513 .0 1 0 0.3
latch: cache buffers lru cha 208 .0 1 2 0.0
latch: redo allocation 241 .0 0 2 0.0
PX Deq: Table Q Get Keys 47 .0 0 9 0.0
enq: KO - fast object checkp 8 .0 0 50 0.0
latch: shared pool 755 .0 0 1 0.0
PX Deq: Signal ACK 1,620 7.3 0 0 0.0
latch: messages 577 .0 0 0 0.0
latch: redo writing 381 .0 0 1 0.0
latch: object queue header o 235 .0 0 1 0.0
enq: TX - contention 25 .0 0 10 0.0
reliable message 219 .0 0 1 0.0
latch: library cache lock 177 .0 0 1 0.0
buffer deadlock 19,313 98.7 0 0 0.0
Wait Events DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
latch: library cache pin 206 .0 0 1 0.0
latch: enqueue hash chains 67 .0 0 1 0.0
latch: row cache objects 14 .0 0 3 0.0
latch: checkpoint queue latc 35 .0 0 1 0.0
latch: session allocation 27 .0 0 1 0.0
latch: undo global data 7 .0 0 2 0.0
local write wait 7 .0 0 2 0.0
cursor: mutex X 5,081 .0 0 0 0.0
PX qref latch 1,637 89.6 0 0 0.0
enq: FB - contention 7 .0 0 0 0.0
kkdlgon 2 .0 0 0 0.0
SQL*Net message from client 15,683,055 .0 464,749 30 30.1
PX Deq: Execution Msg 119,138 78.4 183,186 1538 0.2
PX Deq: Table Q Normal 853,346 6.7 126,717 148 1.6
PX Idle Wait 34,927 95.1 65,760 1883 0.1
PX Deq: Execute Reply 27,335 23.7 14,477 530 0.1
Streams AQ: qmn slave idle w 3,118 .0 14,208 4557 0.0
class slave wait 2,645 .8 6,806 2573 0.0
ASM background timer 5,792 .0 3,544 612 0.0
virtual circuit status 121 100.0 3,541 29262 0.0
Streams AQ: qmn coordinator 1,145 45.7 3,532 3085 0.0
jobq slave wait 1,193 97.7 3,460 2900 0.0
Streams AQ: waiting for time 3 66.7 1,538 512695 0.0
PX Deq Credit: need buffer 25,395 .1 67 3 0.0
PX Deq: Table Q Sample 172 5.8 17 100 0.0
PX Deq: Parse Reply 1,395 .0 3 2 0.0
KSV master wait 2,598 .0 2 1 0.0
PX Deq: Join ACK 995 .0 0 0 0.0


Operating System Statistics DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105

Statistic Total
-------------------------------- --------------------
AVG_BUSY_TIME 168,938
AVG_IDLE_TIME 194,127
AVG_IOWAIT_TIME 0
AVG_SYS_TIME 12,856
AVG_USER_TIME 155,979
BUSY_TIME 10,820,209
IDLE_TIME 12,431,611
IOWAIT_TIME 0
SYS_TIME 830,196
USER_TIME 9,990,013
LOAD 20
OS_CPU_WAIT_TIME 219,400
RSRC_MGR_CPU_WAIT_TIME 0
VM_IN_BYTES 5,423,104
VM_OUT_BYTES 0
PHYSICAL_MEMORY_BYTES 137,419,796,480
NUM_CPUS 64
-------------------------------------------------------------

Service Statistics DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> ordered by DB Time

Physical Logical
Service Name DB Time (s) DB CPU (s) Reads Reads
-------------------------------- ------------ ------------ ---------- ----------
SYS$USERS 308,109.0 101,682.6 ########## ##########
ANAD1 1,253.5 95.2 15,829 3,032,915
ANAD1XDB 0.0 0.0 0 0
SYS$BACKGROUND 0.0 0.0 20,310 159,187
-------------------------------------------------------------

Service Wait Class Stats DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> Wait Class info for services in the Service Statistics section.
-> Total Waits and Time Waited displayed for the following wait
classes: User I/O, Concurrency, Administrative, Network
-> Time Waited (Wt Time) in centisecond (100th of a second)

Service Name
----------------------------------------------------------------
User I/O User I/O Concurcy Concurcy Admin Admin Network Network
Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time
--------- --------- --------- --------- --------- --------- --------- ---------
SYS$USERS
6615013 18356240 504274 435909 0 0 16213620 3835
ANAD1
12294 41749 0 0 0 0 6506 16
SYS$BACKGROUND
26042 19350 117 3529 0 0 0 0
-------------------------------------------------------------

SQL ordered by Elapsed Time DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100

Elapsed CPU Elap per % Total
Time (s) Time (s) Executions Exec (s) DB Time SQL Id
---------- ---------- ------------ ---------- ------- -------------
91,002 57,809 33 2757.6 29.4 6kqa63f9ut6gj
Module: JDBC Thin Client
BEGIN load_csv.RUN_DATA_UPLOAD(:1,:2,:3,:4,:5,:6,:7,:8); END;

53,330 435 27,471 1.9 17.2 7188cbmj1c0ax
Module: JDBC Thin Client
insert into track_session(consumer_id, application_instance_id, created_date, tr
acking_code, expiry_date, partner_id, control_group_session, personalized_offer_
id) values (:1, :2, :3, :4, :5, :6, :7, :8) LOG ERRORS INTO err$_track_session
REJECT LIMIT UNLIMITED

48,185 4,070 2,084,799 0.0 15.6 59yz2hvnn2avr
Module: JDBC Thin Client
insert into ARC_OUT_MESSAGE (MESSAGE, PRIORITY, PAYLOAD, SENDER, STATUS_ID, APPL
ICATION_INSTANCE_ID, CONSUMER_ID, PARTNER_ID, ROUTE_ID, DESTINATION, MESSAGE_TYP
E_ID, TARIFF_ID, CREATED_TIME, SENT_TIME, OUT_MESSAGE_ID) values (:1, :2, :3, :4
, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, :15)

10,393 3,301 0 N/A 3.4 7grxvau0xja37
Module: JDBC Thin Client
select replace(replace(tet.EVENT_TYPE_NAME,chr(:"SYS_B_00"),:"SYS_B_01"),chr(:"S
YS_B_02"),:"SYS_B_03") as "EventType", tet.event_type_id as "EventTypeId", to_ch
ar(te.event_date, :"SYS_B_04") as "EventTime", ac.address as "ConsumerAddress",
replace(replace(carrier.partner_name,chr(:"SYS_B_05"),:"SYS_B_06"),chr(:"SYS_B_0

7,076 7,045 0 N/A 2.3 37ks5b26kmb2m
Module: JDBC Thin Client
create table broadcast_all_556644 NOLOGGING as /** Registration List Only Quer
y Section M - EVENT_AND_PROFILE_TYPE_AND **/ select c.consumer_id, c.carrier_id
, c.address,cp10122.pf_str1 pf_str1, case when list.dnc is null then 1
else 0 end SEND_MESSAGE, 0 BATCH_NO, case when list.dnc is null then

6,906 3,325 0 N/A 2.2 6af2qcw089590
Module: JDBC Thin Client
select replace(replace(tet.EVENT_TYPE_NAME,chr(:"SYS_B_00"),:"SYS_B_01"),chr(:"S
YS_B_02"),:"SYS_B_03") as "EventType", tet.event_type_id (vsn,1,2) || substr(vsn,4,2) || s

54 75 4vq1ftszqjpkx
Module: JDBC Thin Client
select p.broadcast_partition_pf_id, ppf.field_name, p.partner_id from partner_pt
n_key_shared_partner sp, partner p, app_partner_profile_field ppf where ppf.part
ner_profile_field_id = p.broadcast_partition_pf_id and sp.partner_id = p.partner
_id and sp.shared_partner_id = :"SYS_B_0" and rownum < :"SYS_B_1"

54 69 9rfqm06xmuwu0
select intcol#, toid, version#, intcols, intcol#s, flags, synobj# from subcoltyp
e$ where obj#=:1 order by intcol# asc

50 300 f8pavn1bvsj7t
select con#,obj#,rcon#,enabled,nvl(defer,0) from cdef$ where robj#=:1

48 26 0fr8zhn4ymu3v
SQL ordered by Version Count DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> Only Statements with Version Count greater than 20 are displayed

Version
Count Executions SQL Id
-------- ------------ -------------
select intcol#,type,flags,lobcol,objcol,extracol,schemaoid, elemnum from opqtyp
e$ where obj# = :1 order by intcol# asc

47 935 2q93zsrvbdw48
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ w
here obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by grantee#
HELI_ADHOC
201 0 0.2 1.0 44 0 0 0.0
HELI_2K
88 0 1.5 1.0 43 0 0 0.0
HELI_32K
44 0 0.2 1.0 43 0 0 0.0
RMAN
44 0 0.0 1.0 43 0 0 0.0
-------------------------------------------------------------

File IO Stats DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> ordered by Tablespace, File

Tablespace Filename
------------------------ ----------------------------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
HELI +ANAD1/ANAD1/datafile/HELI.275.704666401
80,859 23 26.0 2.9 69,272 19 1,818 13.0
HELI +ANAD1/ANAD1/datafile/HELI.279.711914449
58,813 16 26.7 2.8 50,284 14 1,561 13.2
HELI +ANAD1/ANAD1/datafile/HELI.290.707540479
90,289 25 24.5 3.0 85,583 24 1,587 24.5
HELI +ANAD1/ANAD1/datafile/HELI.291.707540521
64,592 18 27.1 3.0 79,935 22 2,302 4.9
HELI +ANAD1/ANAD1/datafile/HELI.302.725725251
42,811 12 23.8 4.0 45,072 13 1,623 14.0
HELI +ANAD1/ANAD1/datafile/HELI.320.755180231
28,735 8 22.3 2.3 33,390 9 1,520 15.5
HELI +ANAD1/ANAD1/datafile/HELI.321.737642745
41,262 12 21.4 2.4 70,046 20 1,370 12.7
-------------------------------------------------------------

PGA Aggr Summary DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105
-> PGA cache hit % - percentage of W/A (WorkArea) data processed only in-memory

PGA Cache Hit % W/A MB Processed Extra W/A MB Read/Written
--------------- ------------------ --------------------------
68.7 444,720 202,164
-------------------------------------------------------------



init.ora Parameters DB/Inst: ANAD1/ANAD1 Snaps: 20103-20105

End value
Parameter Name Begin value (if different)
----------------------------- --------------------------------- --------------
audit_file_dest /data/oracle/admin/adump
background_dump_dest /data/oracle/admin/bdump
compatible 10.2.0.3.0
control_files +ANAD1/ANAD1/controlfile/curr
core_dump_dest /data/oracle/admin/cdump
cursor_sharing SIMILAR
db_16k_cache_size 0
db_block_size 16384
db_create_file_dest +ANAD1
db_domain
db_file_multiblock_read_count 16
db_name ANAD1
db_recovery_file_dest /data/oracle/flash_recovery_area
db_recovery_file_dest_size 4396972769280
dispatchers (PROTOCOL=TCP) (SERVICE=ANAD1XD
job_queue_processes 10
log_archive_format %t_%s_%r.dbf
log_archive_max_processes 10
nls_language ENGLISH
nls_territory UNITED KINGDOM
open_cursors 600
optimizer_dynamic_sampling 3
parallel_execution_message_si 8192
parallel_max_servers 320
parallel_threads_per_cpu 2
pga_aggregate_target 12884901888
processes 1500
recyclebin OFF
remote_login_passwordfile EXCLUSIVE
session_cached_cursors 300
sessions 1655
sga_max_size 83751862272
sga_target 83751862272
undo_management AUTO
undo_retention 1200
undo_tablespace UNDOTBS1
user_dump_dest /data/oracle/admin/udump
-------------------------------------------------------------

End of Report

Tom,

Any comments on AWR report above ? It is more of OLTP system using JAVA/webbased frontend

thanks
Jack

_partner_id = :"SYS_B_0" and rownum < :"SYS_B_1"

Tom,

After going thro' the various statspack threads, I guess the db is doing a lot of parsing(soft parse though) per second.

Parses: 5,159.45 35.36

Parse CPU to Parse Elapsd %: 43.44

For every CPU second of parsing, it has to wait for more than 1 second to complete a parsing. How can I know whether it is CPU wait or waiting for something else ?

thanks
Jack

I'd like to take an opportunity to boost Tyler Muth's AWR Formatter, Ver 1.6.
For me, it adds a lot of value to AWR information.
The Top SQL Combined tab in particular is awesome!
Being able to see the combined SQL by most common metrics, having the pop-up to "color" SQL, xplan it, AWR-SQL doubles or triples the AWR value.
I really hope to see this functionality folded into the next version of AWR.