Re: Parsing Problem - I think

From: Fred Tilly <ftilly_at_btinternet.com>
Date: Fri, 28 Mar 2014 08:26:39 +0000 (GMT)
Message-ID: <1395995199.69177.YahooMailNeo_at_web87803.mail.ir2.yahoo.com>


Hi,

The summary shows for SQL ordered by CPU:

	* Captured SQL account for 36.7% of Total CPU Time (s): 22,086
	* Captured PL/SQL account for 0.2% of Total CPU Time (s): 22,086


Thanks

Fred


________________________________
 From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk>
To: Fred Tilly <ftilly_at_btinternet.com>; "oracle-l_at_freelists.org" <oracle-l_at_freelists.org> 
Sent: Thursday, 27 March 2014, 11:54
Subject: RE: Parsing Problem - I think
 


 



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  
 

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   

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
 

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>
To: <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>
To: "oracle-l_at_freelists.org" <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
_at_jloracle


________________________________

From: oracle-l-bounce_at_freelists.org [oracle-l-bounce_at_freelists.org] on 
behalf of Fred Tilly [ftilly_at_btinternet.com]
Sent: 25 March 2014 12:29
To: 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 Fri Mar 28 2014 - 09:26:39 CET

Original text of this message