Home » RDBMS Server » Performance Tuning » Help required for tuning referring AWR Reports (Oracle 10.2.0.4.0 on linux)
| Help required for tuning referring AWR Reports [message #565009] |
Thu, 30 August 2012 00:05  |
 |
orapratap
Messages: 134
Registered: November 2011
Location: Canada
|
Senior Member |
|
|
Hello
Please refer the attached AWR reports
Note that the interval between the snapshots is very small as client tried to capture why a particular screen is slow
Generally the screen takes time of the order of 10 seconds and what they need is 2-3 seconds
Here are some queries I have pertaining to these reports
report - Elapsed.ora
------------------------
elapsed time = 29 seconds (0.50 min)
DB time = 6.6 seconds (0.11 min)
CPU time = 4.22 seconds
Q [1]
Now the CPU time is part of DB time
and DB time is CPU time + I/O time + Foreground waits
So what the time (29 - 6.6) i.e. elapsed time - db time, account for?
Is that account for idle waits + wait for CPU
Q [2]
CPU time = 4 (4.22) seconds
db file sequential read = 2 seconds
log file parallel write = 2 seconds
Are there any chances that the above events occur simultaneously; If not the account account for 8 seconds and thus exceed db time of 6.6 seconds which is Not possible
Q [3]
sql execute elapsed time = 6.35
PL/SQL execution elapsed time = 1.93
Is the 1.93 above part of 6.35 i.e. pl/sql execution is part of sql execution above
If Not then it added together exceeds db time of 6.6 seconds which looks wrong
Q [4]
Most importantly, could please suggest which area I shall look into in these tiny numbered reports to bring down the time of the screen display (thus the procedure execution)?
Since the above Math was Not clear and I found CPU time as prominent constituent of DB time here and also because of parsing ratios I have asked the client to reduce hard parsing and if possible execute things as sql by eliminating logic of processing in loops if possible
regarding wait events
for db sequential read, I found data in this reports insufficient
for log file parallel write - I suggested them to check disk and log member layout, raid etc.
(may be commits in loops would be next check)
Does it look correct?
I have asked them to send dbms_profiler and tkprof report however I am unable to get it so far and I am supposed to give them analysis over these 2 reports
Note that in SQL ordred by Elapsed time, CPU time sections in these reports - "application sql" are the sql executed by "<procedure call" which is in the discussion here
Thanks and Regards
Oraratap
P.S. unfortunately Unable to attach reports due to file type limits
Elapsed.ora
----------------------
Elapsed: 0.50 (mins)
DB Time: 0.11 (mins)
Begin Snap: 7002 12-Jul-12 07:34:31 30 21.2
End Snap: 7003 12-Jul-12 07:35:00 30 25.1
Load Profile
Per Second Per Transaction
Redo size: 67,242.01 86,844.52
Logical reads: 2,287.39 2,954.22
Block changes: 274.26 354.22
Physical reads: 33.90 43.78
Physical writes: 0.34 0.43
User calls: 4.85 6.26
Parses: 31.91 41.22
Hard parses: 4.68 6.04
Sorts: 39.02 50.39
Logons: 0.00 0.00
Executes: 169.47 218.87
Transactions: 0.77
Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 98.52 In-memory Sort %: 100.00
Library Hit %: 93.51 Soft Parse %: 85.34
Execute to Parse %: 81.17 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 100.00 % Non-Parse CPU: 98.82
Shared Pool Statistics
Begin End
Memory Usage %: 21.49 21.97
% SQL with executions>1: 87.08 85.28
% Memory for SQL w/exec>1: 79.70 83.40
Top 5 Timed Events
Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
CPU time 4 65.6
db file sequential read 1,056 2 2 34.8 User I/O
log file parallel write 22 2 87 29.9 System I/O
control file parallel write 10 0 7 1.1 System I/O
log file sync 3 0 19 .9 Commit
Time Model Statistics
• Total time in database user-calls (DB Time): 6.4s
Statistic Name Time (s) % of DB Time
sql execute elapsed time 6.35 98.75
DB CPU 4.22 65.62
PL/SQL execution elapsed time 1.93 30.05
parse time elapsed 0.42 6.50
hard parse elapsed time 0.39 6.07
sequence load elapsed time 0.02 0.38
PL/SQL compilation elapsed time 0.02 0.32
hard parse (bind mismatch) elapsed time 0.00 0.04
hard parse (sharing criteria) elapsed time 0.00 0.04
repeated bind elapsed time 0.00 0.03
DB time 6.43
background elapsed time 2.03
background cpu time 0.03
Wait Class
Wait Class Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
User I/O 1,059 0.00 2 2 46.04
System I/O 108 0.00 2 18 4.70
Commit 3 0.00 0 19 0.13
Network 161 0.00 0 0 7.00
Other 2 0.00 0 0 0.09
Wait Events
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
db file sequential read 1,056 0.00 2 2 45.91
log file parallel write 22 0.00 2 87 0.96
control file parallel write 10 0.00 0 7 0.43
log file sync 3 0.00 0 19 0.13
control file sequential read 76 0.00 0 0 3.30
SQL*Net message to client 158 0.00 0 0 6.87
db file scattered read 2 0.00 0 0 0.09
SQL*Net more data to client 3 0.00 0 0 0.13
LGWR wait for redo copy 2 0.00 0 0 0.09
direct path write 1 0.00 0 0 0.04
Streams AQ: waiting for time management or cleanup tasks 1 100.00 2,322 2321850 0.04
SQL*Net message from client 158 0.00 1,970 12468 6.87
jobq slave wait 10 100.00 29 2931 0.43
Streams AQ: qmn slave idle wait 1 0.00 27 27349 0.04
Streams AQ: qmn coordinator idle wait 2 50.00 27 13674 0.09
SQL ordered by Elapsed Time
Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
3 3 1 3.14 48.85 JDBC Thin Client <procedure call>
3 1 1 2.87 44.55 AWR statement
1 1 1 0.63 9.87 Internal stmt
0 0 1 0.26 4.10 Internal stmt
0 0 1 0.21 3.34 JDBC Thin Client Application sql
0 0 4 0.05 2.95 JDBC Thin Client Application sql
0 0 152 0.00 2.14 JDBC Thin Client Application sql
0 0 13 0.01 1.94 JDBC Thin Client Application sql
0 0 150 0.00 1.69 JDBC Thin Client Application sql
0 0 63 0.00 1.47 JDBC Thin Client Application sql
0 0 13 0.01 1.38 JDBC Thin Client Application sql
0 0 30 0.00 1.25 JDBC Thin Client Application sql
0 0 1 0.08 1.24 JDBC Thin Client Application sql
0 0 13 0.01 1.21 JDBC Thin Client Application sql
0 0 43 0.00 1.18 JDBC Thin Client Application sql
0 0 13 0.01 1.18 JDBC Thin Client Application sql
0 0 1 0.06 1.00 JDBC Thin Client Application sql
SQL ordered by CPU Time
CPU Time (s) Elapsed Time (s) Executions CPU per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
3 3 1 2.75 48.85 JDBC Thin Client <procedure call>
1 3 1 1.16 44.55 AWR statement
1 1 1 0.63 9.87 Internal stmt
0 0 1 0.26 4.10 Internal stmt
0 0 1 0.21 3.34 JDBC Thin Client Application sql
0 0 4 0.05 2.95 JDBC Thin Client Application sql
0 0 13 0.01 1.94 JDBC Thin Client Application sql
0 0 13 0.01 1.38 JDBC Thin Client Application sql
0 0 150 0.00 1.69 JDBC Thin Client Application sql
0 0 13 0.01 1.21 JDBC Thin Client Application sql
0 0 30 0.00 1.25 JDBC Thin Client Application sql
0 0 152 0.00 2.14 JDBC Thin Client Application sql
0 0 63 0.00 1.47 JDBC Thin Client Application sql
0 0 1 0.03 1.24 JDBC Thin Client Application sql
0 0 13 0.00 1.18 JDBC Thin Client Application sql
0 0 1 0.01 1.00 JDBC Thin Client Application sql
0 0 43 0.00 1.18 JDBC Thin Client Application sql
Elapsed_1.ora
--------------------
Elapsed: 0.43 (mins)
DB Time: 0.12 (mins)
Begin Snap: 7019 18-Jul-12 06:36:54 30 26.7
End Snap: 7020 18-Jul-12 06:37:20 30 30.5
Load Profile
Per Second Per Transaction
Redo size: 80,539.18 130,851.00
Logical reads: 3,603.27 5,854.19
Block changes: 384.92 625.38
Physical reads: 37.35 60.69
Physical writes: 0.00 0.00
User calls: 1.85 3.00
Parses: 41.78 67.88
Hard parses: 1.15 1.88
Sorts: 63.09 102.50
Logons: 0.00 0.00
Executes: 243.66 395.88
Transactions: 0.62
Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 98.96 In-memory Sort %: 100.00
Library Hit %: 98.17 Soft Parse %: 97.24
Execute to Parse %: 82.85 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 200.00 % Non-Parse CPU: 99.71
Shared Pool Statistics
Begin End
Memory Usage %: 20.19 20.29
% SQL with executions>1: 74.71 81.89
% Memory for SQL w/exec>1: 67.97 79.39
Top 5 Timed Events
Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
CPU time 7 94.0
db file sequential read 1,015 1 1 7.5 User I/O
log file parallel write 20 0 10 2.7 System I/O
control file parallel write 13 0 6 1.1 System I/O
log file sync 3 0 9 .3 Commit
Time Model Statistics
• Total time in database user-calls (DB Time): 7.5s
Statistic Name Time (s) % of DB Time
sql execute elapsed time 7.42 99.45
DB CPU 7.01 93.95
PL/SQL execution elapsed time 4.74 63.46
parse time elapsed 0.16 2.13
hard parse elapsed time 0.13 1.77
sequence load elapsed time 0.03 0.40
PL/SQL compilation elapsed time 0.00 0.04
hard parse (bind mismatch) elapsed time 0.00 0.03
hard parse (sharing criteria) elapsed time 0.00 0.03
repeated bind elapsed time 0.00 0.03
DB time 7.47
background elapsed time 0.32
background cpu time 0.03
Wait Class
Wait Class Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
User I/O 1,015 0.00 1 1 63.44
System I/O 105 0.00 0 3 6.56
Commit 3 0.00 0 9 0.19
Network 58 0.00 0 0 3.63
Wait Events
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
db file sequential read 1,015 0.00 1 1 63.44
log file parallel write 20 0.00 0 10 1.25
control file parallel write 13 0.00 0 6 0.81
log file sync 3 0.00 0 9 0.19
control file sequential read 72 0.00 0 0 4.50
SQL*Net message to client 58 0.00 0 0 3.63
SQL*Net message from client 58 0.00 907 15632 3.63
Streams AQ: qmn slave idle wait 1 0.00 27 27348 0.06
Streams AQ: qmn coordinator idle wait 2 50.00 27 13674 0.13
jobq slave wait 9 100.00 26 2931 0.56
SQL ordered by Elapsed Time
Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
6 6 1 5.97 79.98 JDBC Thin Client <procedure call>
1 1 1 1.22 16.34 AWR statement
1 1 1 0.64 8.59 Internal stmt
0 0 1 0.27 3.66 Internal stmt
0 0 45 0.01 3.32 JDBC Thin Client Application sql
0 0 45 0.01 3.20 JDBC Thin Client Application sql
0 0 18 0.01 2.24 JDBC Thin Client Application sql
0 0 172 0.00 2.23 JDBC Thin Client Application sql
0 0 1 0.16 2.17 JDBC Thin Client Application sql
0 0 4 0.04 1.93 JDBC Thin Client Application sql
0 0 18 0.01 1.80 JDBC Thin Client Application sql
0 0 45 0.00 1.41 JDBC Thin Client Application sql
SQL ordered by CPU Time
CPU Time (s) Elapsed Time (s) Executions CPU per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
6 6 1 5.59 79.98 JDBC Thin Client <procedure call>
1 1 1 1.22 16.34 AWR statement
1 1 1 0.64 8.59 Internal stmt
0 0 1 0.27 3.66 Internal stmt
0 0 45 0.01 3.32 JDBC Thin Client Application sql
0 0 45 0.01 3.20 JDBC Thin Client Application sql
0 0 18 0.01 2.24 JDBC Thin Client Application sql
0 0 1 0.16 2.17 JDBC Thin Client Application sql
0 0 4 0.04 1.93 JDBC Thin Client Application sql
0 0 172 0.00 2.23 JDBC Thin Client Application sql
0 0 18 0.00 1.80 JDBC Thin Client Application sql
0 0 45 0.00 1.41 JDBC Thin Client Application sql
|
|
|
|
|
|
| Re: Help required for tuning referring AWR Reports [message #565136 is a reply to message #565025] |
Thu, 30 August 2012 18:08  |
 |
alan.kendall@nfl.com
Messages: 163
Registered: June 2012
Location: Culver City, California
|
Senior Member |
|
|
Great Idea John,
I have been playing around with the active session history view the last couple of days and came up with a real nice script. In the following example the sql takes two parameters first the schema to lookup and second the number of seconds to go back. Notice how in only a minute I drill down to the queries that are taking a lot of elapsed time and doing some physical reads.
First I do a wildcard schema lookup for 10 seconds:
ENWEBP1P > @GV$ACTIVE_SESSION_HISTORY_INPUT_LIKE_USERNAME_INPUT_SECONDS.sql % 10
INST USERNAME RUNTI SQL_ID RUN_SEC READ_MEG WRITE_MEG TEMP_MEG CPU_SEC SQL_TEXT
---- ---------------- ----- ------------- ---------- -------- --------- --------- -------- --------
3 SITE_USER 16:04 0ysqj1j6mzujb 10.0 .0 .0 .0 .4 /* load
1 SITE_USER 16:04 b581ycdmfc2qw 24.1 .1 .0 .0 1.4 /* load
4 ENWEBP1P 16:04 9sjh4btfbgd4y 1.3 .0 .0 .0 1.3 select a
4 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
4 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
3 SITE_USER 16:04 50dxd75z67jpa 27.1 .0 .0 .0 1.2 /* selec
4 SITE_USER 16:04 cnbuq17murbf7 4.0 .0 .0 .0 .4 /* named
3 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
3 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 select a
3 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
2 ENWEBP1P 16:04 9sjh4btfbgd4y 1.1 .0 .0 .0 1.0 select a
2 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
2 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
2 SITE_USER 16:04 21xc9na2g775r 39.1 .0 .0 .0 1.9 /* load
3 FEEDS_USER 16:04 av3kythcpqp1b 52.1 .0 .0 .0 .7 /* load
3 SITE_USER 16:04 cd1f0y4ug6jhk 16.0 .0 .0 .0 1.0 /* selec
4 SITE_USER 16:04 8cbsv290wu0qk 12.1 .0 .0 .0 .7 /* selec
2 SITE_USER 16:04 88c0trqdm23s0 1.0 .0 .0 .0 .0 /* named
4 PROFILE 16:04 7v7cv4828ptvg 124.4 .0 .0 .0 .3 select *
1 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
1 ENWEBP1P 16:04 9sjh4btfbgd4y .0 .0 .0 .0 .0 select a
3 SITE_USER 16:04 520mkxqpf15q8 16.0 .0 .0 .0 .8 select 1
2 SITE_USER 16:04 8sd1v66dnj4m4 .0 .0 .0 .0 .0 select i
2 FEEDS_USER 16:04 8sd1v66dnj4m4 .0 .0 .0 .0 .0 select i
1 SITE_USER 16:04 1az6mc0j3dys6 3.9 .0 .0 .0 .4 select *
2 PROFILE 16:04 5qqm5mwqr8vpx 208.5 .1 .0 .0 .8 select r
4 FEEDS_USER 16:04 6ycv7t22zht0g 418.0 .0 .0 .0 .7 /* load
4 BATCH_NFL_USER 16:04 fu58th0jzhpvw 8.1 2.0 .0 .0 .0 /* updat
3 SITE_USER 16:04 b581ycdmfc2qw 1.1 .0 .0 .0 .3 /* load
3 SITE_USER 16:04 b581ycdmfc2qw 3.0 .0 .0 .0 .8 /* load
3 FEEDS_USER 16:04 0y4uyjbcph278 18.0 .0 .0 .0 .2 /* load
4 SITE_USER 16:04 50dxd75z67jpa 3.0 .0 .0 .0 .3 /* selec
32 rows selected.
Then I do a 60 second lookup on one of the schemas that seems to have a long run seconds (RUN_SEC).
ENWEBP1P > @GV$ACTIVE_SESSION_HISTORY_INPUT_LIKE_USERNAME_INPUT_SECONDS.sql profile 60
INST USERNAME RUNTI SQL_ID RUN_SEC READ_MEG WRITE_MEG TEMP_MEG CPU_SEC SQL_TEXT
---- ---------------- ----- ------------- ---------- -------- --------- --------- -------- --------
4 PROFILE 16:03 5bra2u164r5vn 70.2 .0 .0 .0 .2 update r
3 PROFILE 16:03 9099qb5watjxn 17.0 .0 .0 .0 .1 insert i
4 PROFILE 16:03 drqanscppxcb7 1210.9 .2 .0 .0 1.3 insert i
1 PROFILE 16:04 8sd1v66dnj4m4 .0 .0 .0 .0 .0 select i
1 PROFILE 16:04 0159jjhwkyyf2 31.1 .0 .0 .0 .1 select *
1 PROFILE 16:04 5qqm5mwqr8vpx 37.1 .0 .0 .0 .2 select r
1 PROFILE 16:04 1bbw3g9aa2tuu 92.2 .0 .0 .0 .2 select r
2 PROFILE 16:04 5qqm5mwqr8vpx 315.8 .1 .0 .0 .6 select r
2 PROFILE 16:04 5qqm5mwqr8vpx 208.5 .1 .0 .0 .8 select r
4 PROFILE 16:04 7v7cv4828ptvg 124.4 .0 .0 .0 .3 select *
4 PROFILE 16:04 7v7cv4828ptvg 69.2 .1 .0 .0 .3 select *
11 rows selected.
The full sql follows:
col username for a16
set lines 150
set pages 40
set wrap off
col runtime for a14
col temp_meg for 999999.9
col ELAPSED_SECONDS for 99999999999.9
col CPU_SECONDS_USED for 99999999999.9
col inst for 999
select a.inst_id inst,b.username,to_char(SQL_EXEC_START,'DD-MM-YY HH24:MI') runtime,
a.sql_id,TM_DELTA_TIME/1000000 elapsed_seconds,
DELTA_READ_IO_BYTES READ_BYTES,DELTA_WRITE_IO_BYTES write_bytes,
TEMP_SPACE_ALLOCATED/1024/1024 temp_meg,
TM_DELTA_CPU_TIME/1000000 cpu_seconds,c.sql_text
from gV$ACTIVE_SESSION_HISTORY a, dba_users b,gv$sqlarea c
where a.user_id=b.user_id
and c.sql_id=a.sql_id
and a.inst_id=c.inst_id
and SQL_EXEC_START> sysdate-upper('&2')/24/60/60
and username like upper('&1%')
order by to_char(SQL_EXEC_START,'DD-MON-YYYY HH24:MI')
/
|
|
|
|
|
|
| Re: Help required for tuning referring AWR Reports [message #567634 is a reply to message #565900] |
Wed, 03 October 2012 15:34 |
|
alan.kendall@nfl.com
Messages: 163
Registered: June 2012
Location: Culver City, California
|
Senior Member |
|
|
You can see the active_session_history that shows the events and join to v$sqlarea to see the sql that ran.
ECSESBP1 > @v$ACTIVE_SESSION_HISTORY.sql
NAME USERNAME COUNT(*) HASH_VALUE SECONDS_WAIT SQL_TEXT
---------------------------- ----------- -------- ---------- ------------ -----------
control file sequential read IPSOFT 1 2999488838 .0119 SELECT
db file sequential read MEDIABIN 1 1471061867 .0038 insert into
db file sequential read MEDIABIN 1 633939815 .0044 insert into
db file sequential read MEDIABIN 1 1087005045 .0068 INSERT INTO
db file sequential read MEDIABIN 1 1067074304 .0082 insert into
gc current block busy MEDIABIN 1 2886120457 .0297 SELECT JOBI
gc current block 2-way TEAMSITE 1 918349423 .0003 DELETE FROM
gc current block 2-way TEAMSITE 1 1604865326 .0004 INSERT INTO
gc cr multi block request TEAMSITE 12 918349423 .0022 DELETE FROM
db file parallel read TEAMSITE 2 918349423 .0036 DELETE FROM
db file sequential read TEAMSITE 2 918349423 .0194 DELETE FROM
db file scattered read TEAMSITE 14 918349423 .0235 DELETE FROM
gc current block busy TEAMSITE 1 1604865326 .0296 INSERT INTO
ECSESBP1 > list
1 SELECT
2 B.NAME,d.username,
3 COUNT(*),c.hash_value,
4 SUM(TIME_WAITED)/1000000 seconds_wait,C.SQL_TEXT
5 FROM v$ACTIVE_SESSION_HISTORY A,
6 v$EVENT_NAME B,
7 v$SQLAREA C,
8 dba_users d
9 WHERE A.SAMPLE_TIME BETWEEN sysdate-.02 AND sysdate
10 and A.EVENT# = B.EVENT#
11 -- AND A.SESSION_ID=2000
12 AND A.SQL_ID = C.SQL_ID
13 and d.user_id=a.user_id
14 GROUP BY C.SQL_TEXT, B.NAME, D.username,c.hash_value
15* order by d.username,SUM(TIME_WAITED)/1000000
|
|
|
|
| Re: Help required for tuning referring AWR Reports [message #567663 is a reply to message #567634] |
Thu, 04 October 2012 02:17 |
Roachcoach
Messages: 1576
Registered: May 2010
Location: UK
|
Senior Member |
|
|
OrapratapGenerally the screen takes time of the order of 10 seconds and what they need is 2-3 seconds
Is this recent degradation, or is it someone standing at your desk making the claim?
If it's always been this way, that is likely a different problem (sql tuning) than a recent degradation (environmental changes/unscalable query).
|
|
|
|
Goto Forum:
Current Time: Sun Nov 24 12:07:11 CST 2024
|
] 
Blog
Search
Help
Members
Register
Login
Home
