RE: Parsing Problem - I think

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk>
Date: Thu, 27 Mar 2014 11:54:40 +0000
Message-ID: <CE70217733273F49A8A162EE074F64D901DE62C4_at_exmbx05.thus.corp>

Please send replies through oracle-l

This statement alone doesn't look as if it's responsible for the CPU starvation - but it may be one of several, and there may be others that disappear from the library cache between snapshots. Check the summary figures for the section (if they exist) showing what percentage has been captured.

Since you've got some stats you've got the SQL in the AWR, even when you don't report the buffer gets, so you can run off the awrsqrpt.sql script (or use the OEM drill down) to get the full stats and variant plans if there are any for the period when the query does much less work.

Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
_at_jloracle

From: Fred Tilly [ftilly_at_btinternet.com] Sent: 27 March 2014 11:46
To: Jonathan Lewis
Subject: Re: Parsing Problem - I think

Hi Jonathan,

Thanks for looking at this. I was convinced it was a parsing problem.

I have looked at the highest sql in terms of CPU utilization and the details are below

CPU Time (s)    Executions      CPU per Exec (s)        %Total  Elapsed Time (s)        %CPU    %IO     SQL Id  SQL Module      SQL Text
1,945.27        3,615   0.54    8.81    2,938.09
        66.21   0.00    38bgfuur8mv7t<file:///C:/Users/rdoggart/Downloads/call15371_20140321120519_report_issue.htm#38bgfuur8mv7t>

If I look at when the system is performing normally the same sql has

CPU Time (s) Executions CPU per Exec (s) %Total Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text 72.35 3,287 0.02 1.86 72.97 100.51 0.00 38bgfuur8mv7t<file:///C:/Users/rdoggart/Downloads/call15371_20140321120519_report_issue.htm#38bgfuur8mv7t>

My cpu per exec has increased dramtically.

Normally I would then look at the gets and on the poor performance report it shows

Buffer Gets     Executions      Gets per Exec   %Total  Elapsed Time (s)        %CPU    %IO     SQL Id  SQL Module      SQL Text
592,696 3,615   163.95  0.89    2,938.09        66.2    0       38bgfuur8mv7t<file:///C:/Users/rdoggart/Downloads/call15371_20140321120519_report_issue.htm#38bgfuur8mv7t>

To me 163 gets per execution is not high.

The good awr report does not show the gets for the statement.

Thanks

Fred

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk> To: Fred Tilly <ftilly_at_btinternet.com> Cc: oracle-l_at_freelists.org
Sent: Thursday, 27 March 2014, 9:04
Subject: Re: Parsing Problem - I think

So CORES=4 and CPUs = 8, and load at end of period = 8.

I'm always cautious about trusting the capacity of multi-threading CPUs, and with your figures and symptoms I'd spend a little time looking at "SQL ordered by CPU" to see if the latch/mutex/library cache problem was a side effect of CPU starvation due to CPU-intensive SQL.

Regards

Jonathan Lewis
http://jonathanlewis.wordpress.com/all-postings

Author: Oracle Core (Apress 2011)
http://www.apress.com/9781430239543

Original Message ----- From: "Fred Tilly" <ftilly_at_btinternet.com<mailto:ftilly_at_btinternet.com>> To: <jonathan_at_jlcomp.demon.co.uk<mailto:jonathan_at_jlcomp.demon.co.uk>> Sent: Tuesday, March 25, 2014 2:02 PM Subject: Re: Parsing Problem - I think

Hi Jonathan,

Here is what the OS Stats say.

Operating System Statistics
* *TIME statistic values are diffed. All others display actual values. End Value is displayed if different
* ordered by statistic type (CPU Use, Virtual Memory, Hardware Config), Name
Statistic
Value
End Value

AVG_BUSY_TIME 85,477
AVG_IDLE_TIME 270,473
AVG_SYS_TIME 71,901
AVG_USER_TIME 13,402

BUSY_TIME 2,740,786
IDLE_TIME 8,659,884
SYS_TIME 2,306,362
USER_TIME 434,424
LOAD 1 8
OS_CPU_WAIT_TIME 1,920,500
RSRC_MGR_CPU_WAIT_TIME 0
VM_IN_BYTES 65,536
PHYSICAL_MEMORY_BYTES 27,917,287,424

NUM_CPUS 32
NUM_CPU_CORES 4
NUM_CPU_SOCKETS 1
TCP_RECEIVE_SIZE_DEFAULT 49,152
TCP_RECEIVE_SIZE_MAX 1,048,576
TCP_SEND_SIZE_DEFAULT 49,152
TCP_SEND_SIZE_MAX 1,048,576

Thanks

Fred

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk<mailto:jonathan_at_jlcomp.demon.co.uk>> To: "oracle-l_at_freelists.org<mailto:oracle-l_at_freelists.org>" <oracle-l_at_freelists.org<mailto:oracle-l_at_freelists.org>> Sent: Tuesday, 25 March 2014, 13:24
Subject: RE: Parsing Problem - I think

Your "non-hard" parse time look pretty high given the small number of "soft" parses you are doing, so the first thing I'd do is look at the number of CPU cores you actually have. It's possible that you're multi-threading on a much smaller number of cores than Oracle is reporting as "CPUs" - with the result that an parse contention (latches, mutexes) is being exaggerated as soon as the CPU load gets anywhere near the number of cores.

What does the full set of OS Stats" look like ?

Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com<http://jonathanlewis.wordpress.com/>
_at_jloracle

From: oracle-l-bounce_at_freelists.org<mailto:oracle-l-bounce_at_freelists.org> [oracle-l-bounce_at_freelists.org<mailto:oracle-l-bounce_at_freelists.org>] on behalf of Fred Tilly [ftilly_at_btinternet.com<mailto:ftilly_at_btinternet.com>] Sent: 25 March 2014 12:29
To: oracle-l_at_freelists.org<mailto:oracle-l_at_freelists.org> Subject: Parsing Problem - I think

Hi All,

Looking at an AWR report from a customer site where they have had some very slow performance.

Server is 32 CPU and 26GB running Oracle 11.2.0.3

AWR is over 1 hour and shows:

Parses: 22.6 0.5
Hard parses: 5.1 0.1

Elapsed: 59.37 (mins)
DB Time: 587.12 (mins)

Buffer Nowait %: 100.00 Redo NoWait %: 100.00 Buffer Hit %: 99.91 In-memory Sort %: 100.00 Library Hit %: 94.89 Soft Parse %: 77.60 Execute to Parse %: 92.71 Latch Hit %: 99.95 Parse CPU to Parse Elapsd %: 57.49 % Non-Parse CPU: 54.03

Top 5 Timed Foreground Events
Event
Waits
Time(s)
Avg wait (ms)
% DB time
Wait Class
DB CPU 22,086 62.70
cursor: pin S wait on X 12 705 58760 2.00 Concurrency log file sync 142,183 469 3 1.33 Commit
db file sequential read 48,259 155 3 0.44 User I/O buffer busy waits 2,144 129 60 0.37 Concurrency

Statistic Name
Time (s)
% of DB Time
DB CPU 22,086.13 62.70
parse time elapsed 19,559.05 55.52
hard parse elapsed time 18,490.89 52.49
sql execute elapsed time 15,126.32 42.94

From the information in the AWR report I do not appear to be parsing a lot of statements per second, but my hard parse time seems really high.

What else do I need to look at to get to the bottom of this issue.

Thanks

Fred

No virus found in this message.
Checked by AVG - www.avg.com
Version: 2014.0.4354 / Virus Database: 3722/7247 - Release Date: 03/25/14

--
http://www.freelists.org/webpage/oracle-l

Received on Thu Mar 27 2014 - 12:54:40 CET

This message: [ Message body ]
Next message: Ls Cheng: "Re: Parsing Problem - I think"
Previous message: Mark W. Farnham: "RE: output of a select statement"
Maybe in reply to: Fred Tilly: "Parsing Problem - I think"
Next in thread: Fred Tilly: "Re: Parsing Problem - I think"
Reply: Fred Tilly: "Re: Parsing Problem - I think"

Contemporary messages sorted: [ by date ] [ by thread ] [ by subject ] [ by author ]

Original text of this message