Discussion on Shared Pool (6)
Original link:
http://www.eygle.com/internal/shared_pool-6.htm
After a few days of Shared Pool, I didn't expect to suddenly hit the problem. I wrote it as a case to give you a look.
The cause of the problem is the company's SMS group, which is the 4,000-word SMS novel of 180,000. When the group is issued, a message queue congestion occurs every other time in the database, actually to record a log in a data sheet. .
We intervene to check the problem of the database, start diagnosis in a congestion period:
SQL> SELECT SID, Event, P1, P1RAW from V $ session_wait;
SID Event P1 P1RAW ---------- ------------------------------------ ------------------------------------ -------- 76 latch free 2147535824 8000CBD0 83 latch free 2147535824 8000CBD0 148 latch free 3415346832 CB920E90 288 latch free 2147535824 8000CBD0 285 latch free 2147535824 8000CBD0 196 latch free 2147535824 8000CBD0 317 latch free 2147535824 8000CBD0 2 pmon timer 300 0000012C 1 rdbms ipc message 300 0000012C 4 RDBMS IPC Message 300 0000012C 6 RDBMS IPC Message 180000 0002BF20
SID Event P1 P1RAW ---------- ------------------------------------ ------------------------------------ -------- 18 RDBMS IPC Message 6000 00001770 102 rdbms ipc message 6000 00001770 311 rdbms ipc message 6000 00001770 194 rdbms ipc message 6000 00001770 178 rdbms ipc message 6000 00001770 3 log file parallel write 1 00000001 13 log file sync 2705 00000A91 16 log file sync 2699 00000A8B 104 log file sync 2699 00000a8b 308 log file sync 2694 00000a86 262 log file sync 2705 00000a91
SID Event P1 P1RAW ---------- ------------------------------------ -------------------------------------------- 172 log file sync 2689 00000A81 169 log file sync 2705 00000A91 108 log file sync 2694 00000A86 38 log file sync 2707 00000A93 34 db file scattered read 63 0000003F 5 smon timer 300 0000012C 27 SQL * Net message to client 1413697536 54435000 60 SQL * Net message to client 1413697536 54435000 239 SQL * Net Message to Client 1413697536 54435000 ... Ignore Some IDLE WAITING Here ... 11 SQL * Net Message from Client 675562835 28444553 12 SQL * Net Message from Clom Clom Client 1413697536 54435000170 ROWS SELECTED.
In this query, I found a lot of latch free waiting, waiting for these waiting to disappear again, the application has returned to normal.
SQL> SELECT SID, EVENT, P1, P1RAW from V $ Session_Wait Where Event Not Like 'SQL * Net%'
SID Event P1 P1RAW ---------- ------------------------------------ -------------------------------------------- 2 PMON Timer 300 0000012C 1 rdbms ipc message 300 0000012C 4 rdbms ipc message 300 0000012C 6 rdbms ipc message 180000 0002BF20 18 rdbms ipc message 6000 00001770 102 rdbms ipc message 6000 00001770 178 rdbms ipc message 6000 00001770 194 rdbms ipc message 6000 00001770 311 rdbms ipc message 6000 00001770 3 log file parallel write 1 00000001 148 log file sync 2547 000009f3sid Event P1raw -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- -------------------------------------------------- - -------- 273 Log File sync 2544 000009f0 190 log file sync 2545 000009f1 5 SMON Timer 300 00000012C
14 rows selected.
Let's take a look at these latch free waiting for what Latch.
SQL> Select Addr, Latch #, Name, Gets, Spin_Gets from v $ latch order by spin_gets; addr latch # name gets spin_gets ---------------- ----- -------------------------------------------------- ---------------------------- 80001398 3 session switching 111937 080002010 6 Longop Free List 37214 0800023a0 7 Cached Attr List 0 080002628 10 Event Group Latch 2391668 0 ..... 80003f3c 28 Message Pool Operations Parent Latch 3 0 ..... 80003060 60 Mostly Latch-Free SCN 19 080005F8C 59 File Number Translation Table 68 080005F14 58 DLM CR Bast Queue Latch 0 080005E8C 57 Name-Service Request 0 080005E14 56 Name-Service Memory Objects 0 080005DA0 55 Name-Service Namespace Bucket 0 0
AddR Latch # name gets spin_gets ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------------------------------ -------- 80005D2C 54 name-service pending queue 0 080005CB4 53 name-service request queue 0 080004E08 52 name-service entry 0 080008AB0 76 KCL lock element parent latch 0 080008A48 75 KCL instance latch 0 080007F18 73 redo copy 816 080007BBC 71 Archive Process Latch 0 080007B54 70 ARCHIVE CONTROL 1 080006a10 68 Active Checkpoint Queue Latch 2003308 0800064B0 66 LARGE MEMORY LATCH 0 080006448 65 Cache Protection Latch 0 0
AddR Latch # name gets spin_gets ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------------------------------ -------- 800060EC 61 batching SCNs 0 08000CAB0 96 global transaction 6833807 08000CA48 95 global tx free list 58258 08000C238 93 cost function 0 080009FCC 91 temp lob duration state obj allocation 0 08000995C 87 ktm global data 8118 080009228 84 transaction branch allocation 282388 080008EC4 80 Begin Backup SCN Array 6968 080008D54 79 Loader State Object FreeElist 42712 080008B80 78 KCL FREELIST LATCH 0 080008B18 77 KCL NAME TABLE LATCH 0 0
AddR Latch # name gets spin_gets ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------------------------------ -------- 8000D484 118 presentation list 0 08000D41C 117 session timer 855944 0 ..... 8000E9D0 129 process queue 44 08000E900 127 query server freelists 66 08000FC84 140 AQ Propagation Scheduling System Load 0 08000E898 126 query server process 10 08000E27C 125 job_queue_processes parameter latch 111937 08000da1c 124 NLS Data Objects 2 0
AddR Latch # name gets spin_gets ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------------------------------ -------- 8000D95C 123 ncodef allocation latch 111937 08000D674 122 virtual circuits 0 08000D60C 121 virtual circuit queues 159877 08000D5A4 120 virtual circuit buffers 0 08000D4EC 119 address list 2 0 ..... 8000CD70 102 Direct I / O Adaptor 2 0 ..... 80002408 8 GDS LATCH 30 0800092E4 85 SORT EXTENT POL 69834 18000ec 38 132 Parallel Query Alloc Buffer 80 18000E968 128 Error Message Lists 22 180001400 4 Process Group Creation 2615542 28000EAA0 131 Parallel Query Stats 14 2
AddR Latch # name gets spin_gets ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------------------------------ -------- 8000CD08 101 Token Manager 1151107 28000CB18 97 global tx hash mapping 507846 280006378 63 cache buffer handles 315924 48000EA38 130 process queue reference 190993 580003E3C 26 channel handle pool latch 2391680 1880003EAC 27 channel operations parent latch 4783425 2480009B90 89 intra txn Parallel Recovery 32654 338000FCF8 141 FIXED TABLE ROWS for x $ HS_ Session 161368 41800012C8 1 Process Allocation 2391688 15480009B28 88 Parallel TXN Reco Latch 174519 2718000cca0 100 Library Cache LOAD LOCK 14947545 5958
AddR Latch # name gets spin_gets ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------------------------------ -------- 8000C8D0 94 user lock 13086412 60788000914C 82 list of block allocation 120650357 1202480006A78 69 Checkpoint queue latch 154361751 1768680009D34 90 sequence cache 64611720 3202780009090 81 dml lock allocation 234465024 45351800091C0 83 transaction allocation 214227648 48345800096AC 86 undo global data 188271244 49641800028A0 13 Enqueue hash chains 373244264 1313280007E04 72 Redo allocation 439389808 20149880001468 5 session IDLE BIT 2039097976 20496980002838 12 enqueues 471338482 273695
AddR Latch # name gets spin_gets ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------------------------------------ -------- 80001330 2 session allocation 261826230 428312800063E0 64 multiblock read objects 1380614923 1366278800026B8 11 messages 207935758 137260680001218 0 latch wait list 203479569 144534280006310 62 cache buffers chains 3.8472E 10 25216998000A17C 92 row cache objects 1257586714 255587280007F80 74 redo writing 264722932 445804480006700 67 cache buffers lru chain SELECTECTECTION OF ENGINEERING.
SQL> SELECT Startup_time from v $ installation;
STARTUP_T --------- 13-Aug-04
Check the database startup time
We noticed that the two most difficult Latch in the current database is Shared Pool and Library Cache. Obviously this is likely to be excessive parses of SQL.
We further check v $ sqlarea found: SQL> select sql_text, VERSION_COUNT, INVALIDATIONS, PARSE_CALLS, OPTIMIZER_MODE, PARSING_USER_ID, PARSING_SCHEMA_ID, ADDRESS, HASH_VALUEfrom v $ sqlarea where version_count> 1000; 2
SQL_Text ------------------------------------------------- -------------------------------------------------- --------------------- Version_Count Invalidations Parse_Calls Optimizer_Mode Parsing_user_id Parsing_Schema_ID Address Hash_Value ------------------------------------------------------------------------------------------------------------------------------------------------ ----- ------------------------------------------- ------------------------------------ Insert Into SMS_LOG (Msgdate, Msgtime, MSGID , MSGKIND, MSGTYPE, MSGTYPE_MOMT, mSGLEN, MSGSTATUS, AREAID, IFIDDEST, IFIDSRC, ADDRSRC, ADDRDEST, ADDRFEE, ADDRUSER, SERVICECODE, PLANID, FEETYPE, FEEVALUE, DATACODING, FLAGS, SMLEN, SMCONT) values (: b0,: b1 ,: B2,: B3,: B4,: B,: B6,: B7,: B,: B9,: B10,: B11,: B12,: B13,: B14,: B15,: B16,: B17,: B18, : B19,: B20,: B21,: B22) 7023 0 1596 Multiple Children Present 36 36 C82AF1C8 3974744754 This is the code for writing logs, this code uses binding variables, but Version_Count has 7023. That is, this SQL There are 7023 knee pointers. This is unimaginable.
Through the previous sessions, we know, if this SQL has 7023 kits, then these child pointers will exist on the same BUCKET linked list, if the same SQL is executed again, Oracle will have to search This list is looking for SQL that can be shared. This will lead to a large number of library cache latch competition.
At this time, I started guessing the reason: 1. Possible code has problems, modify certain session parameters before each execution, resulting in SQL can't work 2. Maybe 8.1.5 V $ SQLAREA record has problems, we see the result Is illusion:) 3.Bug
OK, our diagnosis can not stop. The most direct me Dump memory:
SQL> Alter Session Set Events 'Immediate Trace Name Library_Cache Level 4';
Look at the TRACE file to get the following results (extracts the piece containing the segment code):
BUCKET 21049: LIBRARY OBJECT HANDLE: handle = c82af1c8 name = insert into sms_log (MSGDATE, MSGTIME, MSGID, MSGKIND, MSGTYPE, MSGTYPE_MOMT, MSGLEN, MSGSTATUS, AREAID, IFIDDEST, IFIDSRC, ADDRSRC, ADDRDEST, ADDRFEE, ADDRUSER, SERVICECODE, PLANID, Feetype, FeEvalue, Datacoding, Flags, Smlen, SmCont Values (: B0,: B1,: B2,: B3,: B4,: B,: B6,: B7,: B,: B9,: B10,: B11, : B12,: B13,: B14,: B15,: B16,: B17,: B18,: B19,: B20,: B21,: B19,: BASH = Ece9cab2 TimeStamp = 09-09-2004 12:51:29 Namespace = CRSR flags = ron / TIM / PN0 / LRG / [10010001] KKKK-DDDD-LLLL = 0000-0001-0001 lock = N pin = s latch = 5 LWT = c82af1e0 [c82af1e0, c82af1e0] ltm = c82af1e8 [c82af1e8, c82af1e8] pwt = c82af1f8 [c82af1f8, c82af1f8] ptm = c82af250 [c82af250, c82af250] ref = c82af1d0 [c82af1d0, c82af1d0] LIBRARY OBJECT: object = c1588e84 type = CRSR flags = EXS [0001] pflags = [00] status = VALD load = 0 Children: size =
7024 childle ------ -------- ---------------- 0 C1589040 C1589008 C668C2BC 1 C1589040 BFD179C4 C6EC9EE8 2 C1589040 BFD179E0 C2DD9B3C 3 c1589040 bfd179fc c5a46614 4 c1589040 bfd17a18 c35f1388 5 c1589040 bfd17a34 c77401bc 6 c1589040 bfd17a50 c4092838 7 c1589040 bfddb310 c6cd5258 8 c1589040 bfddb32c c63c6650 9 c1589040 bfddb348 c7e4e3d0 10 c1589040 bfddb364 c4c4b110 11 c1589040 bfddb380 c5950348 12 c1589040 bfddb39c c6c33aa4 13 c1589040 bfddb3b8 c672b0bc ....... ............................................... Ignore Losts of Child Cursor Here ... ........................................... 7001 BF595BC8 C641FBA0 C6467890 7002 BF595BC8 C641FBBBC C3417168 7003 BF595BC8 C641FBD8 C3417BB0 7004 BF595BC8 C641FBF4 C2FDCCBC 7005 BF595BC8 C641FC10 C7F7CA50 7006 BF595BC8 C641FC2C C7F508EC 7007 BF595BC8 C6 41fc48 c268d8d8 7008 c641fcb8 c641fc64 bec61ed8 7009 c641fcb8 c641fc80 c4a6cc5c 7010 c641fcb8 c641fc9c c1a8aa34 7011 c641fcb8 c0ae4ea0 c0ae4ddc 7012 c641fcb8 c0ae4ebc bd55fe60 7013 c641fcb8 c0ae4ed8 c226914c 7014 c641fcb8 c0ae4ef4 c51dd2e0 7015 c641fcb8 c0ae4f10 c480c468 7016 c641fcb8 c0ae4f2c c60196d0 7017 c641fcb8 c0ae4f48 c4675d2c 7018 c641fcb8 c0ae4f64 bd5e2750 7019 c641fcb8 c0ae4f80 c09b1bb0 7020 C641FCB8 C0AE4F9C BF2D6044 7021 C641FCB8 C0AE4FB8 C332C1C4 7022 C641FCB8 C0AE4FD4 CBDDE0F8 Data Blocks: Data # Heap Pointer Status Pins Change ------------ -------------- --- ------ 0 C3EF2C50 C1588F08 I / P / A 0 None
There is indeed 7023 knee query V $ SQL to get the same result:
SQL> SELECT CHILD_NUMBER, EXECUTIONS, OPTIMIZER_MODE, OPTIMIZER_COSER_MODE, OPTIMIZER_COST, PARSING_USER_ID, PARSING_SCHEMA_ID, Address, Hash_Value 2 from v $ sql where hash_value = '3974744754';
Child_Number Executions Optimizer_ Optimizer_cost Parsing_user_id Parsing_Schema_ID Address Hash_Value ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ---- - ------------------------------------------------------------------------ ---- 0 12966 CHOOSE 238150 36 36 C82AF1C8 3974744754 1 7111 CHOOSE 238150 36 36 C82AF1C8 3974744754 2 9160 CHOOSE 238150 36 36 C82AF1C8 3974744754 3 9127 CHOOSE 238150 36 36 C82AF1C8 3974744754 4 8109 CHOOSE 238150 36 36 C82AF1C8 3974744754 5 4386 CHOOSE 238150 36 36 C82AF1C8 3974744754 6 4913 Choose 238150 36 36 C82AF1C8 3974744754 7 3764 Choose 238150 36 36 C82AF1C8 3974744754 8 3287 CHOOSE 238150 36 36 C82AF1C8 3974744754 9 3156 CHOOSE 238150 36 36 C82AF1C8 3974744754 ..... 7015 1 CHOOSE 238150 36 36 C82AF1C8 3974744754 7016 1 CHOOSE 238150 36 36 C82AF1C8 3974744754 7017 0 CHOOSE 238150 36 36 C82AF1C8 3974744754
Child_Number Executions Optimizer_ Optimizer_cost Parsing_user_id Parsing_Schema_ID Address Hash_Value ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ---- - ------------------------------------------------------------------------ ---- 7018 9396 NONE 0 0 C82AF1C8 3974744754 7019 5008 CHOOSE 237913 36 36 C82AF1C8 3974744754 7020 625 CHOOSE 237913 36 36 C82AF1C8 3974744754 7021 10101 CHOOSE 237913 36 36 C82AF1C8 3974744754 7022 7859 CHOOSE 237913 36 36 C82AF1C8 39747447547023 rows selected.
There is indeed 7023 knee pointers here, and the second guess is denied, and there is no first case where the code sent from the research and development. So only the third case, Oracle's bug, OK, then we need to find a solution Method.
Search Metalink, discovery bug: 1210242 This bug is described as: on Certain SQL Statements Cursors Are Not Shared When Timed_statistics is enabled.
When I happened to TIMED_STATISTICS set to true modified TIMED_STATISTICS, after False, observed V $ SQL and found that the effective child pointer quickly dropped to 2.
SQL> SELECT CHILD_NUMBER, OPTIMIZER_COST, OPTIMIZER_MODE, Executions, Address from v $ sql where hash_value = 3974744754 and optimizer_mode = 'choose'
Child_Number Optimizer_cost Optimizer_ Executions Address ------------ --------------------- - - -------- 0 238167 Choose 63943 C82AF1C8 1 238300 Choose 28915 C82AF1C8
The next day fell to only one.
SQL> SELECT CHILD_NUMBER, OPTIMIZER_COST, OPTIMIZER_MODE, Executions, Address from v $ sql where hash_value = 3974744754 and optimizer_mode = 'choose'
Child_Number Optimizer_cost Optimizer_ Executions Address ------------ --------------------- - - -------- 0 238702 Choose 578124 C82AF1C8 SMS group is normal.
For this problem, another optional method is to set an implied parameter: _SQLEXEC_PROGRESSION_COST = 0
The specific meaning of this parameter is: SQL Execution Progression Monitoring Cost Threshold, Jere, SQL Execution Monitoring Cost Value
This parameter determines the SQL that needs to be monitored according to COST. Perform progress monitoring will introduce additional function calls and ROW SOURCES This may result in change of SQL execution plan or cost, resulting in different sub pointers ._sqlexec_progression_cost's default value is 1000, All SQLs greater than 1000 will be monitored if this parameter is set to 0, then the progress of SQL will not be tracked.
Performing progress monitoring information is recorded in the V $ session_longops view, if the time_statistics parameter is set to false, then this information will not be recorded. So, the time_statistics parameter and _sqlexec_progression_cost are two ways to solve the problem.
You can also see by querying, in this database, the SQL of Optimizer_cost> 1000 has the following five:
SQL> SELECT DISTINCT (SQL_Text) from V $ SQL Where Optimizer_cost> 1000;
SQL_Text ------------------------------------------------- ----------------------------- Insert Into SMS_Detail_ERROR (Msgdate, Addruser, Msgid, Areaid, Reason, SpNumber, Msgtime, iFiddest , msqkey, servicecode, planid, feetype, feevalue, smcont, submittimes, submitdate, submittime, msgstate_resp, errorcode_resp, msgstate_rept, errorcode_rept) values (: b0,: b1,: b2,: b3,: b4,: b5,: b6, : B7,: B8,: B9,: B10,: B11,: B12,: B13,: B14,: B15,: B16,: B17,: B18,: B16,: B17,: B18,: B19,: B20)
insert into sms_detail_success (msgdate, addruser, msgid, areaid, spnumber, msgtime, ifiddest, servicecode, planid, feetype, feevalue, smcont, submittimes, submitdate, submittime, respdate, resptime, reptdate, repttime, msqkey) values (: b0 ,: B1,: B2,: B3,: B4,: B5,: B6,: B7,: B8,: B9,: B10,: B11,: B12,: B13,: B14,: B15,: B16,: B17, : B18,: B19)
insert into sms_log (MSGDATE, MSGTIME, MSGID, MSGKIND, MSGTYPE, MSGTYPE_MOMT, MSGLEN, MSGSTATUS, AREAID, IFIDDEST, IFIDSRC, ADDRSRC, ADDRDEST, ADDRFEE, ADDRUSER, SERVICECODE, PLANID, FEETYPE, FEEVALUE, DATACODING, FLAGS, SMLEN, SMCONT) Values (: B0,: B1,: B2,: B3,: B4,: B,: B6,: B7,: B8,: B9,: B10,: B11,: B12,: B13,: B14,: B15, : b16,: b17,: b18,: b19,: b20,: b21,: b22) insert into sms_resprept_error (msgdate, areaid, addruser, msgid, submittimes, submitdate, submittime, msgid_gw, msgstate_resp, errorcode_resp, msgstate_rept, errorcode_rept, servicecode VALUES (: B0,: B1,: B2,: B3,: B4,: B,: B6,: B7,: B,: B9,: B10,: B11,: B12)
INSERT INTO SMS_STATUSREPT (ReptDate, Addruser, Msgid_GW, Repttime, Statustype, Msgid_stus, MsgState, ErrorCode) Values (: B0,: B1,: B2,: B3,: B4,: B,: B6,: B7)
In these five SQL, in V $ SQLAREA, there are four version_counts all 10 or more:
SQL> SELECT SQL_TEXT, VERSION_COUNT FROM V $ SQLAREA WHERE VERSION_COUNT> 10;
SQL_Text ------------------------------------------------- ------------------------------- Version_count ------------- Insert Into SMS_DETAIL_ERROR (Msgdate , addruser, msgid, areaid, reason, spnumber, msgtime, ifiddest, msqkey, servicecode, planid, feetype, feevalue, smcont, submittimes, submitdate, submittime, msgstate_resp, errorcode_resp, msgstate_rept, errorcode_rept) values (: b0,: b1 ,: B2,: B3,: B4,: B,: B6,: B7,: B,: B9,: B10,: B11,: B12,: B13,: B14,: B15,: B16,: B17,: B18, : B19,: B20) 42
insert into sms_log (MSGDATE, MSGTIME, MSGID, MSGKIND, MSGTYPE, MSGTYPE_MOMT, MSGLEN, MSGSTATUS, AREAID, IFIDDEST, IFIDSRC, ADDRSRC, ADDRDEST, ADDRFEE, ADDRUSER, SERVICECODE, PLANID, FEETYPE, FEEVALUE, DATACODING, FLAGS, SMLEN, SMCONT) Values (: B0,: B1,: B2,: B3,: B4,: B,: B6,: B7,: B8,: B9,: B10,: B11,: B12,: B13,: B14,: B15, : B16,: B17,: B18,: B19,: B,: B21,: B22) 7026
insert into sms_resprept_error (msgdate, areaid, addruser, msgid, submittimes, submitdate, submittime, msgid_gw, msgstate_resp, errorcode_resp, msgstate_rept, errorcode_rept, servicecode) values (: b0,: b1,: b2,: b3,: b4,: b5, : B6,: B7,: B8,: B9,: B10,: B11,: B12) 301INSERT INTO SMS_STATUSREPT (ReptDate, Addruser, MSGID_GW, Repttime, Statusty, MSGID_STUS, MSGSTATATE, ERRORCODE) VALUES (: B0,: B1,: B2,: B3,: B4,: B5,: B6,: B7) 41
Specific reference METALINK: Note62143
