Problem Description: In the RAC Database the performace is improved 4 times if the SERVICE_NAME is replaced by connecting directly to a single node.
### PROBLEM STATEMENT ###
1. Configured the applocation with the SERVICE_NAME connection string which is load balanced across 3 nodes of the RAC. Ran test for 1 hr.
2. Then reconfigured the Application with the SID of 1 node. Re-ran the test for 1 hr.
WE can get 4 times better write performace by doing the 2nd method.
### GENERAL SYSTEM/DATABASE INFORMATION ###
3 Node RAC
DB=PFPS3
Service PFPS3SRV
SID = PFPS31, PFPS32 PFPS33
==>>
SERVICE
----------
PFPS3SRV =
(DESCRIPTION =
(ADDRESS = (PROTOCOL = TCP)(HOST = ole-rac10g-ole-vip1.sensis.com.au)(PORT = 1521))
(ADDRESS = (PROTOCOL = TCP)(HOST = ole-rac10g-ole-vip2.sensis.com.au)(PORT = 1521))
(ADDRESS = (PROTOCOL = TCP)(HOST = ole-rac10g-ole-vip3.sensis.com.au)(PORT = 1521))
(LOAD_BALANCE = yes)
(CONNECT_DATA =
(SERVER = DEDICATED)
(SERVICE_NAME = PFPS3SRV)
)
)
SID
-----
PFPS31 =
(DESCRIPTION =
(ADDRESS = (PROTOCOL = TCP)(HOST = ole-rac10g-ole-vip1.sensis.com.au)(PORT = 1521))
(CONNECT_DATA =
(SERVER = DEDICATED)
(SERVICE_NAME = PFPS3)
(INSTANCE_NAME = PFPS31)
)
)
============>>>>>>>>>>
Generic Note
------------
Can you do the following and upload the results
1. Run the test in RAC environment and then collect 2-3 snapshots of AWR and ADDM reports covering timeframe of 20-30 mins when you observe slow performance.
2. Also upload AWR reports from single instance which is good.
==>>
Generic Note
------------
From AWR report using service name, I see "gc buffer busy" is top wait event
=====
Top 5 Timed Events
Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
gc buffer busy 1,036,259 17,618 17 50.6 Cluster
enq: TX - index contention 91,021 6,192 68 17.8 Concurrency
gc current block busy 115,149 3,524 31 10.1 Cluster
CPU time 3,245 9.3
enq: TX - row lock contention 3,645 1,141 313 3.3 Application
SQL ordered by Cluster Wait Time
Cluster Wait Time (s) CWT % of Elapsd Time Elapsed Time(s) CPU Time(s) Executions SQL Id SQL Module SQL Text
15,667.11 66.27 23,641.55 1,082.08 280,769 1g1nh993kad5r JDBC Thin Client insert into Search (phraseId, ...
Segments by Buffer Busy Waits
* % of Capture shows % of Buffer Busy Waits for each top segment compared
* with total Buffer Busy Waits for all segments captured by the Snapshot
Owner Tablespace Name Object Name Subobject Name Obj. Type Buffer Busy Waits % of Capture
PFP_OWNER PFP_LARGE_INDX PK_SEARCH MAY2010 INDEX PARTITION 218,851 82.08
PFP_OWNER PFP_SMALL_DATA SYSTEMACTIVITYSUMMARY TABLE 22,245 8.34
PFP_OWNER PFP_LARGE_INDX IDX_SEARCHLOCATION_02 MAY2010 INDEX PARTITION 5,892 2.21
PFP_OWNER PFP_LARGE_INDX PK_SEARCHLOCATION MAY2010 INDEX PARTITION 5,482 2.06
PFP_OWNER PFP_LARGE_INDX IDX_SEARCH_02 MAY2010 INDEX PARTITION 3,573 1.34
====
I see PK_SEARCH index partition is causing contention.
Can you please tune this or try to recreate this one.
Also upload ADDM reports during performance issue as requested.
========>>>>>>>>
you are quiet right in seeing the GC events being high when the service_name is used. The question is why is it not that high when we are connection directly to 1 node?
Also the index partition contention is only occuring when the service_name is used to connect. Not an issue when connection to the 1 node.
I have uploaded the ADDM report from the time it was running slow.
Generic Note
------------
Issue Analysis
---------------------
Performance is reported as different when connection is made through a service where load balancing is enabled versus a service where the connection is directed always at instance 1.
There is no connection occurring directly through an SID both are using SERVICE_NAME to direct the connection.
The connect string will only impact how the connection is directed to the RDBMS and ultimately which instance the session is established within.
Comments
--------
=== ODM Action Plan ===
1. Exactly what is being executed during the testing in each case, what is the SQL being executed here?
2. Has SQL trace been enabled in the session performing the workload? Have execution plans of the SQL been compared across the 2 tests to ensure that they are the same in each case? What method for collecting statistics has been implemented in the environment?
3. Is the same instance being connected to at the time each test is performed?
4. Exactly how are you measuring the difference in performance, what metrics are being used to determine the measurement and the difference? You mentioned that there is 4 times better write performance when connecting directly to instance PFPS31. How is this being measured, what were the metrics seen across the 2 tests? Please supply these via the service request.
Paul,
Answers below
1. The below SQL is what the application is running.
select this_.id as id39_0_, this_.version as version39_0_, this_.publicationStateId as publicat3_39_0_, this_.phrase as phrase39_0_, this_.floorPrice as floorPrice39_0_, this_.adultPhrase as adultPhr6_39_0_, this_.blockPhrase as blockPhr7_39_0_, this_.stopPhrase as stopPhrase39_0_, this_.watchPhrase as watchPhr9_39_0_, this_.created as created39_0_, this_.createdBy as createdBy39_0_, this_.updated as updated39_0_, this_.updatedBy as updatedBy39_0_ from Phrase this_ where this_.phrase=:1
insert into Search (phraseId, publicationChannelId, location, offset, searchTimeStamp, token, id) values (:1, :2, :3, :4, :5, :6, :7)
UPDATE PhraseSearchSummary
SET searches = searches + 1
WHERE phraseId = :NEW.phraseId
AND periodTypeCode= c_SearchSummaryPeriodMonthly
AND startDate = l_startMonthTimestamp
AND token = :NEW.token;
UPDATE ChannelPublicationSummary
SET searches = searches + 1
WHERE publicationChannelId = :NEW.publicationChannelId
AND periodTypeCode= c_PubSummaryPeriodDaily
AND startDate = l_startDayTimestamp
AND token = :NEW.token;
UPDATE SystemActivitySummary
SET searches = searches + 1
WHERE periodTypeCode = c_SystemActivityPeriodDaily
AND startDate = l_startDayTimestamp
AND token = :NEW.token;
2. Tracing hasn't been enabled. The explain plans have been compared and these are the same. Standard default statistics collection is being used.
3. Yes this is the same instance
4. There is a log table that collects statistics every 5 mins that retrieves this information. When going straight to the instance performance is much greater than going through the ServiceName.
Thanks
==>>
Name
--------
ODM Data Collection
AWR Reports Instance Specific V Load Balanced Service
----------------------------------------------
Connection via Instance Specific Connection:
PFPS3 2190308783 PFPS31 1 10.2.0.4.0 YES oledbrx05p
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 2150 02-Jun-10 15:00:01 182 .7
End Snap: 2151 02-Jun-10 16:00:03 166 .6
Elapsed: 60.04 (mins)
DB Time: 25.19 (mins)
Report Summary
Cache Sizes
Begin End
Buffer Cache: 7,008M 7,008M Std Block Size: 8K
Shared Pool Size: 816M 816M Log Buffer: 20,628K
Load Profile
Per Second Per Transaction
Redo size: 27,320.10 267.85
Logical reads: 4,269.63 41.86
Block changes: 196.74 1.93
Physical reads: 121.70 1.19
Physical writes: 8.05 0.08
User calls: 774.62 7.59
Parses: 233.23 2.29
Hard parses: 1.16 0.01
Sorts: 2.66 0.03
Logons: 0.10 0.00
Executes: 147.31 1.44
Transactions: 102.00
% Blocks changed per Read: 4.61 Recursive Call %: 20.69
Rollback per transaction %: 88.45 Rows per Sort: 64.30
Top 5 Timed Events
Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
CPU time 636 42.1
enq: TX - row lock contention 2,103 543 258 35.9 Application
gc current block busy 4,742 89 19 5.9 Cluster
db file scattered read 9,303 75 8 5.0 User I/O
log file sync 42,023 59 1 3.9 Commit
Connection via Load Balanced Service:
DB Name DB Id Instance Inst num Release RAC Host
PFPS3 2190308783 PFPS31 1 10.2.0.4.0 YES oledbrx05p
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 2148 02-Jun-10 13:00:23 154 .4
End Snap: 2149 02-Jun-10 14:00:35 194 .9
Elapsed: 60.20 (mins)
DB Time: 580.40 (mins)
Report Summary
Cache Sizes
Begin End
Buffer Cache: 7,024M 7,008M Std Block Size: 8K
Shared Pool Size: 800M 816M Log Buffer: 20,628K
Load Profile
Per Second Per Transaction
Redo size: 489,747.74 3,588.99
Logical reads: 14,631.53 107.22
Block changes: 2,733.52 20.03
Physical reads: 121.34 0.89
Physical writes: 124.28 0.91
User calls: 1,539.97 11.29
Parses: 894.03 6.55
Hard parses: 1.23 0.01
Sorts: 2.91 0.02
Logons: 0.12 0.00
Executes: 909.11 6.66
Transactions: 136.46
FileName
----------------
awrrpt_1_2150_2151_using_sid_name.html
FileComment
----------------------
FileName
----------------
awrrpt_1_2148_2149_using_service_name.html
FileComment
----------------------
As discussed with Paul, the following test will be performed and reports created.
Perform Cold Backup of DB.
Backup Messages in Sun messaging. Around 7 million messages.
Test 1
--------
Configure 3 App servers to connect to RAC direct to each instance.
App1 -> PFPS3SRV1 - > instance 1 - > PFPS31
App2 -> PFPS3SRV2 - > instance 2 - > PFPS32
App3 -> PFPS3SRV3 - > instance 1 - > PFPS33
Peform Load test.
Test 2
---------
Restore Cold DB Backup
Restore Sun Messaging.
Configure 3 App servers to Connect to RAC through Load Balanced Service Name.
App1,App2,App3 -> PFPS3SRV -> Prefered on PFPS31, PFPS32 and PFPS33
Perform load test.
AWR reports will be uploaded of each instance for each Test run.
Ranjeet Singh.
As agreed previously, here are the 2 test results with exact same test data run twice under different connection methods.
File 1:
instance_service.zip - AWR reports for duration when the App servers are connected directly to 1 instance.
File 2:
loadbalanced_service.zip - AWR reports for the duration when the App servers are connectd to a load_balanced service name.
File3:
performance_results.xls - A summary comparison of the 2 tests at 5 minute intervals for 1 particular insert statement that is the bulk of all executions.
=== ODM Research ===
http://download.oracle.com/docs/cd/B19306_01/server.102/b14211/data_acc.htm#i21879
Oracle® Database Performance Tuning Guide
10g Release 2 (10.2)
Part Number B14211-03
15 Using Indexes and Clusters
15.3 Using Partitioned Indexes for Performance
The hash method can improve performance of indexes where a small number leaf blocks in the index have high contention in multiuser OLTP environment. In some OLTP applications, index insertions happen only at the right edge of the index. This could happen when the index is defined on monotonically increasing columns. In such situations right edge of the index becomes a hotspot because of contention for index pages, buffers, latches for update, and additional index maintenance activity, which results in performance degradation.
Hi
I have uploaded the text versions of the report. Got your voicemail.
I am a bit confused as to why this index contention is only obvious in one connection methd. Because the test we did is the same load just coming in the database a different way.
=== ODM Issue Clarification ===
There is a major difference in performance seen when the middle tier application servers connect directly to instances in the cluster via instance specific services versus having each application server connect via a load balanced service that distributes the load across the cluster instances. Performance is 4 times better when the instance specific connections are made.
The environment:
Three Application Servers are connecting to a three node RAC cluster.
The 2 tests performed are:
1. Application Servers connect directly to a specific RAC instance.
Apps Server 1 -----------Instance 1 Specific Service -------------Instance 1
Apps Server 2 -----------Instance 2 Specific Service -------------Instance 2
Apps Server 3 -----------Instance 3 Specific Service ------------ Instance 3
2. All Application Servers connect through a single load balanced service that sees the connections distributed automatically across the cluster instances.
Apps Server 1 ------------| |------------------Instance 1
Apps Server 2 ------------|----------Load Balanced Service------------|------------------Instance 2
Apps Server 3 ------------| |------------------Instance 3
Name
--------
ODM Data Collection
WORKLOAD REPOSITORY report for Test 1 where a Load Balanced Service is used to establish Application Server Connections
DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
PFPS3 2190308783 PFPS31 1 10.2.0.4.0 YES oledbrx05p
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 2365 10-Jun-10 17:40:02 97 1.1
End Snap: 2371 10-Jun-10 19:40:26 114 .7
Elapsed: 120.40 (mins)
DB Time: 1,031.24 (mins)
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 7,008M 7,008M Std Block Size: 8K
Shared Pool Size: 816M 816M Log Buffer: 20,628K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 525,075.37 5,698.35
Logical reads: 16,097.35 174.70
Block changes: 2,908.22 31.56
Physical reads: 60.94 0.66
Physical writes: 112.25 1.22
User calls: 1,154.91 12.53
Parses: 867.83 9.42
Hard parses: 0.13 0.00
Sorts: 1.24 0.01
Logons: 0.08 0.00
Executes: 953.86 10.35
Transactions: 92.15
..
.
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc buffer busy 2,205,839 32,536 15 52.6 Cluster
enq: TX - index contention 230,833 12,266 53 19.8 Concurrenc
CPU time 6,805 11.0
gc current block busy 190,947 5,761 30 9.3 Cluster
gc current grant busy 104,268 1,267 12 2.0 Cluster
-------------------------------------------------------------
..
.
Global Cache Load Profile
~~~~~~~~~~~~~~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Global Cache blocks received: 377.21 4.09
Global Cache blocks served: 343.74 3.73
GCS/GES messages received: 1,292.31 14.02
GCS/GES messages sent: 1,320.13 14.33
DBWR Fusion writes: 33.55 0.36
Estd Interconnect traffic (KB) 6,277.90
Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 97.29
Buffer access - remote cache %: 2.34
Buffer access - disk %: 0.37
..
.
Wait Class DB/Inst: PFPS3/PFPS31 Snaps: 2365-2371
-> 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
-------------------- ---------------- ------ ---------------- ------- ---------
Cluster 5,269,616 .3 42,027 8 7.9
Concurrency 1,731,622 .1 13,156 8 2.6
System I/O 1,056,377 .0 1,100 1 1.6
Commit 710,332 .0 1,005 1 1.1
Other 1,105,515 41.4 454 0 1.7
User I/O 91,326 .0 341 4 0.1
Configuration 5,876 .0 81 14 0.0
Network 5,657,455 .0 14 0 8.5
Application 1,581 .0 3 2 0.0
-------------------------------------------------------------
..
.
Segments by Global Cache Buffer Busy DB/Inst: PFPS3/PFPS31 Snaps: 2365-2371
-> % of Capture shows % of GC Buffer Busy for each top segment compared
-> with GC Buffer Busy for all segments captured by the Snapshot
GC
Tablespace Subobject Obj. Buffer % of
Owner Name Object Name Name Type Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
PFP_OWNER PFP_LARGE_ PK_SEARCH JUN2010 INDEX 485,569 45.35
PFP_OWNER PFP_SMALL_ SYSTEMACTIVITYSUMMAR TABLE 207,526 19.38
PFP_OWNER PFP_LARGE_ IDX_SEARCHLOCATION_0 JUN2010 INDEX 163,480 15.27
PFP_OWNER PFP_LARGE_ IDX_IMPRESSION_03 JUN2010 INDEX 49,915 4.66
PFP_OWNER PFP_LARGE_ PK_SEARCHLOCATION JUN2010 INDEX 42,736 3.99
-------------------------------------------------------------
FileName
----------------
textversion.zip:awrrpt_1_2365_2371_PFPS3SRV3.txt
FileComment
----------------------
Oracle Support - June 17, 2010 5:18:20 AM GMT+05:30
Name
--------
ODM Data Collection
WORKLOAD REPOSITORY report for Test 2 where a Load Balanced Service is used to establish Application Server Connections
DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
PFPS3 2190308783 PFPS31 1 10.2.0.4.0 YES oledbrx05p
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 2419 11-Jun-10 11:40:14 110 .9
End Snap: 2425 11-Jun-10 13:40:01 114 .7
Elapsed: 119.78 (mins)
DB Time: 1,265.03 (mins)
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 7,072M 7,072M Std Block Size: 8K
Shared Pool Size: 752M 752M Log Buffer: 20,628K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 228,483.23 5,816.49
Logical reads: 8,311.97 211.60
Block changes: 1,295.03 32.97
Physical reads: 71.32 1.82
Physical writes: 73.46 1.87
User calls: 482.81 12.29
Parses: 361.79 9.21
Hard parses: 0.05 0.00
Sorts: 1.41 0.04
Logons: 0.07 0.00
Executes: 397.25 10.11
Transactions: 39.28
..
.
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc buffer busy 1,769,167 40,895 23 53.9 Cluster
enq: TX - index contention 127,876 17,917 140 23.6 Concurrenc
gc current block busy 230,647 9,610 42 12.7 Cluster
CPU time 3,467 4.6
buffer busy waits 250,528 1,173 5 1.5 Concurrenc
-------------------------------------------------------------
..
.
Global Cache Load Profile
~~~~~~~~~~~~~~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Global Cache blocks received: 407.96 10.39
Global Cache blocks served: 443.07 11.28
GCS/GES messages received: 1,033.65 26.31
GCS/GES messages sent: 952.65 24.25
DBWR Fusion writes: 25.62 0.65
Estd Interconnect traffic (KB) 7,196.18
Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 94.25
Buffer access - remote cache %: 4.91
Buffer access - disk %: 0.84
..
.
Wait Class DB/Inst: PFPS3/PFPS31 Snaps: 2419-2425
-> 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
-------------------- ---------------- ------ ---------------- ------- ---------
Cluster 4,834,225 .3 53,248 11 17.1
Concurrency 653,810 .8 19,112 29 2.3
System I/O 713,505 .0 579 1 2.5
Other 831,508 47.2 455 1 2.9
Commit 286,016 .0 336 1 1.0
User I/O 32,672 .0 195 6 0.1
Configuration 1,915 .6 79 41 0.0
Network 2,326,450 .0 5 0 8.2
Application 3,251 .0 4 1 0.0
-------------------------------------------------------------
..
.
Segments by Global Cache Buffer Busy DB/Inst: PFPS3/PFPS31 Snaps: 2419-2425
-> % of Capture shows % of GC Buffer Busy for each top segment compared
-> with GC Buffer Busy for all segments captured by the Snapshot
GC
Tablespace Subobject Obj. Buffer % of
Owner Name Object Name Name Type Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
PFP_OWNER PFP_LARGE_ PK_SEARCH JUN2010 INDEX 712,906 80.76
PFP_OWNER PFP_LARGE_ IDX_SEARCHLOCATION_0 JUN2010 INDEX 56,772 6.43
PFP_OWNER PFP_SMALL_ SYSTEMACTIVITYSUMMAR TABLE 53,302 6.04
PFP_OWNER PFP_LARGE_ PK_SEARCHLOCATION JUN2010 INDEX 30,380 3.44
PFP_OWNER PFP_LARGE_ IDX_IMPRESSION_03 JUN2010 INDEX 10,160 1.15
-------------------------------------------------------------
FileName
----------------
textversion.zip:awrrpt_1_2419_2425_PFPS3SRV.txt
FileComment
----------------------
Oracle Support - June 17, 2010 5:52:07 AM GMT+05:30
Generic Note
------------------------
Issue Analysis:
Test 1 - Apps Server Instances connects directly to a individual RDBMS Instances.
Test 2 - All Apps Servers connect through a load balanced service that distributes connections across the RAC Cluster.
A drop in throughput can be seen from the AWR report when the load balanced service is used, Test 1's load profile shows more redo processed and more transactions per second executed.
Test 1:
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 525,075.37 5,698.35
Executes: 953.86 10.35
Transactions: 92.15
Test 2:
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 228,483.23 5,816.49
Executes: 397.25 10.11
Transactions: 39.28
The Top waits in both tests however appear to be the same indicating the same issue is present across both tests
Test 1:
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc buffer busy 2,205,839 32, 536 15 52.6 Cluster
enq: TX - index contention 230,833 12, 266 53 19.8 Concurrenc
Test 2:
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc buffer busy 1,769,167 40, 895 23 53.9 Cluster
enq: TX - index contention 127,876 17, 917 140 23.6 Concurrenc
These 2 waits "gc buffer busy" and "enq: TX - index contention" are indicating that the RAC instances in both tests are having to wait for buffers/blocks to become available as they are in use somewhere within the cluster (gc buffer busy).
The blocks causing the contention are more than likely index blocks given the second wait is "enq: TX - index contention"
The segment predominantly causing these waits in both cases is
In Test 1
GC
Tablespace Subobject Obj. Buffer % of
Owner Name Object Name Name Type Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
PFP_OWNER PFP_LARGE_ PK_SEARCH JUN2010 INDEX 485,569 45.35
In Test 2
GC
Tablespace Subobject Obj. Buffer % of
Owner Name Object Name Name Type Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
PFP_OWNER PFP_LARGE_ PK_SEARCH JUN2010 INDEX 712,906 80.76
As seen from the statistics across the 2 tests the number of busy waits as jumped from 485,569 in Test 1 to 712,906 in Test 2 for index PK_SEARCH partition June2010. This updating of the index structure as rows are being inserted is being performed down the right hand side of the index is causing contention for specific blocks with in it. Different sessions/instances/transactions are all wanting to update the same index blocks.
The introduction of sessions connecting through load balanced services has resulted in a higher percentage of transactions contending for the same buffers across the cluster. This will be due the way the individual transactions are being distributed and executed in Test 2.
Test 1 sees this occur less than Test 2 as the index blocks updated are more often already available in the instance where the update is occurring and do not need to be shipped anywhere resulting in better performance.
Both cases are seeing many index block splits indicating this index is growing down the right hand side due an ever increasing key of some sort, for example some form of auto incrementing key.
Test 1
Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
branch node splits 222 0.0 0.0
leaf node 90-10 splits 2,351 0.3 0.0
leaf node splits 36,539 5.1 0.1
Test 2
Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
branch node splits 79 0.0 0.0
leaf node 90-10 splits 858 0.1 0.0
leaf node splits 15,095 2.1 0.1
Given this it may be better to use a hash partitioned index structure so that updates of the index can be better distributed across different index blocks as the index keys will be distributed across partitions rather than all updates of the index occurring in one partition and set of blocks.
This will mean that it is less likely that different transactions distributed across the cluster are going to require access to the same blocks and therefor introduce the waits seen in both tests.
You would need to investigate the use of either al hash partitioned or (preferred) a Range Hash partitioned index instead of what you currently appear to have which is a range based partitioned index.
A Range Hash partitioned index will have the benefit of allowing better partition level maintenance of the index structure should you use ranges of data as a mechanism for maintaining the partitioned table and index structure.
I will create these tables with range/hash partitioning and conduct the test again. Also you made the following comment
"Test 1 sees this occur less than Test 2 as the index blocks updated are more often already available in the instance where the update is occurring and do not need to be shipped anywhere resulting in better performance"
Does that mean we need to look at our interconnect as well and investigate ways of increasing the throughput? i.e. jumb frames etc.
=== ODM Action Plan ===
Ranjeet Singh, it is not the tables that require re-organisation, it is the indexes on the tables in particular PK_SEARCH.
As to:
"Test 1 sees this occur less than Test 2 as the index blocks updated are more often already available in the instance where the update is occurring and do not need to be shipped anywhere resulting in better performance"
This statement is by no means indicating there is an interconnect performance issue. It is indicating that in Test 1 and Test 2 the same performance bottleneck is seen.
However in Test 1 the problem is felt to a lesser degree as it appears the behaviour of the transaction processing when Apps Servers are connected directly to instances is incurring less of a performance hit through fewer block transfers across the interconnect.
Test 1 sees 2.3% of buffers being found in a remote instance and transferred across the interconnect , you can see it from below list …
Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 97.29
Buffer access - remote cache %: 2.34
Buffer access - disk %: 0.37
Test 2 sec 4.9% of buffers being found in a remote instance and transferred across the interconnect, you can see the out put from below list ……
Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 94.25
Buffer access - remote cache %: 4.91
Buffer access - disk %: 0.84
==>>>
I uderstand that it is index contention that is the issue that requires subpartitioning to resolve the issue. I had to composite partition the table because we only have local indexes. This is to help us in archiving data and dropping partitions with minimum effort.
We have repartitioned this table as Range/Hash composite and you are right, there is a remarkable improvement in write performance. But we still get a lot better performace going direct then via the load balanced service. I am attaching the reports again for the 2 runs.
Test 1
--------
Configure 3 App servers to connect to RAC direct to each instance.
App1 -> PFPS3SRV1 - > instance 1 - > PFPS31
App2 -> PFPS3SRV2 - > instance 2 - > PFPS32
App3 -> PFPS3SRV3 - > instance 1 - > PFPS33
Peform Load test.
Name
--------
ODM Data Collection
WORKLOAD REPOSITORY report for awrrpt_1_2923_2926_PFPS3SRV1.txt
DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
PFPS3 2190308783 PFPS31 1 10.2.0.4.0 YES oledbrx05p
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 2923 18-Jun-10 11:40:02 129 1.0
End Snap: 2926 18-Jun-10 12:40:09 125 .8
Elapsed: 60.10 (mins)
DB Time: 596.92 (mins)
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 7,040M 7,040M Std Block Size: 8K
Shared Pool Size: 784M 784M Log Buffer: 20,628K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 4,913,211.83 2,037.36
Logical reads: 44,223.94 18.34
Block changes: 30,266.88 12.55
Physical reads: 93.51 0.04
Physical writes: 497.08 0.21
User calls: 4,825.42 2.00
Parses: 2,417.11 1.00
Hard parses: 0.02 0.00
Sorts: 2.32 0.00
Logons: 0.36 0.00
Executes: 2,417.51 1.00
Transactions: 2,411.56
% Blocks changed per Read: 68.44 Recursive Call %: 34.04
Rollback per transaction %: 0.05 Rows per Sort: 39.13
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 34,171 95.4
log file sync 8,709,790 26,032 3 72.7 Commit
log file parallel write 1,604,636 1,980 1 5.5 System I/O
log file sequential read 18,236 684 37 1.9 System I/O
db file parallel write 197,143 600 3 1.7 System I/O
-------------------------------------------------------------
^LRAC Statistics DB/Inst: PFPS3/PFPS31 Snaps: 2923-2926
Begin End
----- -----
Number of Instances: 3 3
Global Cache Load Profile
~~~~~~~~~~~~~~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Global Cache blocks received: 31.12 0.01
Global Cache blocks served: 2.40 0.00
GCS/GES messages received: 960.99 0.40
GCS/GES messages sent: 1,018.51 0.42
DBWR Fusion writes: 0.36 0.00
Estd Interconnect traffic (KB) 654.78
Global Cache Efficiency Percentages (Target local+remote 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer access - local cache %: 99.72
Buffer access - remote cache %: 0.07
Buffer access - disk %: 0.21
Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Commit 8,709,790 .0 26,032 3 1.0
System I/O 1,854,132 .0 3,290 2 0.2
SQL ordered by Executions DB/Inst: PFPS3/PFPS31 Snaps: 2923-2926
-> Total Executions: 8,718,093
-> Captured SQL account for 99.9% of Total
CPU per Elap per
Executions Rows Processed Rows per Exec Exec (s) Exec (s) SQL Id
------------ --------------- -------------- ---------- ----------- -------------
8,680,310 8,677,688 1.0 0.00 0.00 da17mzv9db2qa
Module: JDBC Thin Client
INSERT INTO SEARCH_RANGE_HASH_ON_ID_32 (id, phraseId, publicationChannelId, loca
tion, offset, searchTimestamp, token) VALUES(:1, :2, :3, :4, :5, :6, :7)
SQL ordered by Cluster Wait Time DB/Inst: PFPS3/PFPS31 Snaps: 2923-2926
Cluster CWT % of Elapsed CPU
Wait Time (s) Elapsd Tim Time(s) Time(s) Executions SQL Id
------------- ---------- ----------- ----------- -------------- -------------
12.97 0.2 6,374.59 6,295.18 8,680,310 da17mzv9db2qa
Module: JDBC Thin Client
INSERT INTO SEARCH_RANGE_HASH_ON_ID_32 (id, phraseId, publicationChannelId, loca
tion, offset, searchTimestamp, token) VALUES(:1, :2, :3, :4, :5, :6, :7)
Segments by Global Cache Buffer Busy DB/Inst: PFPS3/PFPS31 Snaps: 2923-2926
-> % of Capture shows % of GC Buffer Busy for each top segment compared
-> with GC Buffer Busy for all segments captured by the Snapshot
GC
Tablespace Subobject Obj. Buffer % of
Owner Name Object Name Name Type Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
TEST_SEARC PFP_LARGE_ SEARCH_RANGE_HASH_ON N2010_SP10 TABLE 1 50.00
TEST_SEARC PFP_LARGE_ SEARCH_RANGE_HASH_ON N2010_SP30 TABLE 1 50.00
-------------------------------------------------------------
FileName
----------------
awrrpt_1_2923_2926_PFPS3SRV1.txt
FileComment
2. All Application Servers connect through a single load balanced service that sees the connections distributed automatically across the cluster instances.
Apps Server 1 ------------| |------------------Instance 1
Apps Server 2 ------------|----------Load Balanced Service------------|------------------Instance 2
Apps Server 3 ------------| |------------------Instance 3
Name
--------
ODM Data Collection
WORKLOAD REPOSITORY report for awrrpt_1_2920_2922_PFPS3SRV.txt
DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
PFPS3 2190308783 PFPS31 1 10.2.0.4.0 YES oledbrx05p
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 2920 18-Jun-10 10:40:03 119 1.1
End Snap: 2922 18-Jun-10 11:20:10 135 1.0
Elapsed: 40.12 (mins)
DB Time: 99.35 (mins)
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 7,040M 7,040M Std Block Size: 8K
Shared Pool Size: 784M 784M Log Buffer: 20,628K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 440,324.69 2,111.26
Logical reads: 6,802.05 32.61
Block changes: 2,662.07 12.76
Physical reads: 68.43 0.33
Physical writes: 62.67 0.30
User calls: 418.44 2.01
Parses: 210.28 1.01
Hard parses: 0.02 0.00
Sorts: 1.27 0.01
Logons: 0.08 0.00
Executes: 211.02 1.01
Transactions: 208.56
% Blocks changed per Read: 39.14 Recursive Call %: 36.39
Rollback per transaction %: 0.58 Rows per Sort: 70.33
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc current block busy 138,758 2,767 20 46.4 Cluster
CPU time 2,398 40.2
gc current block 2-way 1,061,320 621 1 10.4 Cluster
log file sync 499,400 577 1 9.7 Commit
gc current block 3-way 479,001 398 1 6.7 Cluster
-------------------------------------------------------------
^LRAC Statistics DB/Inst: PFPS3/PFPS31 Snaps: 2920-2922
Begin End
----- -----
Number of Instances: 3 3
Global Cache Load Profile
~~~~~~~~~~~~~~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Global Cache blocks received: 718.69 3.45
Global Cache blocks served: 699.50 3.35
GCS/GES messages received: 3,427.48 16.43
GCS/GES messages sent: 3,003.85 14.40
DBWR Fusion writes: 15.78 0.08
Estd Interconnect traffic (KB) 12,601.64
Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Cluster 1,802,206 .0 4,280 2 3.6
SQL ordered by Executions DB/Inst: PFPS3/PFPS31 Snaps: 2920-2922
-> Total Executions: 508,003
-> Captured SQL account for 99.9% of Total
CPU per Elap per
Executions Rows Processed Rows per Exec Exec (s) Exec (s) SQL Id
------------ --------------- -------------- ---------- ----------- -------------
498,939 498,935 1.0 0.00 0.01 da17mzv9db2qa
Module: JDBC Thin Client
INSERT INTO SEARCH_RANGE_HASH_ON_ID_32 (id, phraseId, publicationChannelId, loca
tion, offset, searchTimestamp, token) VALUES(:1, :2, :3, :4, :5, :6, :7)
SQL ordered by Cluster Wait Time DB/Inst: PFPS3/PFPS31 Snaps: 2920-2922
Cluster CWT % of Elapsed CPU
Wait Time (s) Elapsd Tim Time(s) Time(s) Executions SQL Id
------------- ---------- ----------- ----------- -------------- -------------
4,282.02 86.4 4,958.38 1,648.46 498,939 da17mzv9db2qa
Module: JDBC Thin Client
INSERT INTO SEARCH_RANGE_HASH_ON_ID_32 (id, phraseId, publicationChannelId, loca
tion, offset, searchTimestamp, token) VALUES(:1, :2, :3, :4, :5, :6, :7)
Segments by Global Cache Buffer Busy DB/Inst: PFPS3/PFPS31 Snaps: 2920-2922
-> % of Capture shows % of GC Buffer Busy for each top segment compared
-> with GC Buffer Busy for all segments captured by the Snapshot
GC
Tablespace Subobject Obj. Buffer % of
Owner Name Object Name Name Type Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP26 INDEX 595 3.66
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP23 INDEX 550 3.39
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP25 INDEX 550 3.39
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP29 INDEX 531 3.27
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP31 INDEX 524 3.23
FileName
----------------
awrrpt_1_2920_2922_PFPS3SRV.txt
FileComment
----------------------
Generic Note
------------------------
Issue Analysis
-----------------------
Test 1 AWR Snaps 2923-2926, Each of the 3 Application Servers are connected directly to specific instances
GC Buffer Busy waits have been eliminated altogether and there is very little inter-instance traffic/ interconnect traffic. Overall throughput has also increased significantly now that the table and index structures are using range/hash partitioning.
Test 2 AWR Snaps 2920-2922, All 3 Application Servers are using a load balanced connection across all 3 instances.
GC Buffer busy have also been eliminated from this test however the a new wait has appeared as the top wait:
gc current block busy 138,758 2,767 20 46.4 Cluster
There is vast difference between the 2 tests in terms of interconnect traffic seen.
Test 1
Estd Interconnect traffic (KB) 654.78
Test 2
Estd Interconnect traffic (KB) 12,601.64
Cluster waits are still an causing contention however it is now for a different reason (gc current block busy)
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc current block busy 138,758 2,767 20 46.4 Cluster
Avg
%Time Total Wait wait Waits
Wait Class Waits -outs Time (s) (ms) /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Cluster 1,802,206 .0 4,280 2 3.6
The index structure/segments that was causing the gc buffer busy wait in previous tests are greatly reduced and the contention on the index can now been seen being better distributed across the partitions of the index.
GC
Tablespace Subobject Obj. Buffer % of
Owner Name Object Name Name Type Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP26 INDEX 595 3.66
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP23 INDEX 550 3.39
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP25 INDEX 550 3.39
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP29 INDEX 531 3.27
TEST_SEARC PFP_LARGE_ IDX_TSTAMP_HASH_ON_I N2010_SP31 INDEX 524 3.23
The way the application load is being distributed when apps servers are connected directly to an instance versus load balanced across all instances is showing that is ensuring that blocks being updated as a result of the load have better instance affinity and therefor is reducing global cache based contention and waits and interconnect traffic.
This application level partitioning of the work load is seen to be the best approach eliminating the contention in this case.
No comments:
Post a Comment