This is a tiny quiz like post, to see how people diagnose to sort the problem/problems here
This is when I check around 11:30Am on 27th (please open it from “view source button” to see better- button appears right hand side when you go over the code)
SQL> @swact
SID STATE EVENT SEQ# SEC_IN_STATE P1 P2 P3 P1TRANSL SQL_ID CHN BLCKNG_SID BLCKNG_SID_S BLCKNG_INST
------- ------- ---------------------------------------- ---------- ------------ ---------- ---------- ---------- ------------------------------------------ ------------- ---- ---------- ------------ -----------
1157 WAITING Streams AQ: waiting for messages in the 31559 0 169722 4.4438E+10 5 UNKNOWN
390 WAITING db file scattered read 8831 4 122 3402637 3 49xfrap6ytmsz 0 NO HOLDER
1059 WAITING db file scattered read 2575 0 18 3540987 2 6sy5x0dnyq7gp 1 NO HOLDER
780 WAITING db file scattered read 10509 0 54 3104110 3 903wwaubvn68k 4 NO HOLDER
777 WAITING db file scattered read 43294 0 8 3525609 3 96b6hrt8csw55 1 NO HOLDER
393 WAITING db file scattered read 53359 4 122 1311756 3 96b6hrt8csw55 1 NO HOLDER
293 WAITING db file scattered read 2563 0 182 2370423 3 96b6hrt8csw55 1 NO HOLDER
584 WAITING db file sequential read 8068 0 116 2224706 1 1hx317q49q07d 1 NO HOLDER
487 WAITING db file sequential read 6848 0 98 3399221 1 6ug9z3tm0udpa 0 NO HOLDER
297 WAITING db file sequential read 1997 0 12 3694453 1 903wwaubvn68k 5 NO HOLDER
203 WAITING db file sequential read 57138 0 137 3774888 1 903wwaubvn68k 4 NO HOLDER
1068 WAITING db file sequential read 55082 0 180 457872 1 92qxw78kqu645 0 NO HOLDER
102 WAITING db file sequential read 15928 0 18 3421028 1 96b6hrt8csw55 1 NO HOLDER
1161 WAITING db file sequential read 50477 0 24 3597877 1 96b6hrt8csw55 1 NO HOLDER
586 WAITING db file sequential read 30187 0 99 2827261 1 96b6hrt8csw55 1 NO HOLDER
1351 WAITING db file sequential read 36501 0 143 3528249 1 96b6hrt8csw55 1 NO HOLDER
1061 WAITING db file sequential read 14914 0 176 2339005 1 96b6hrt8csw55 1 NO HOLDER
1162 WAITING db file sequential read 34251 0 182 1609635 1 96b6hrt8csw55 1 NO HOLDER
580 WAITING db file sequential read 59341 0 182 1736561 1 96b6hrt8csw55 1 NO HOLDER
1255 WAITING db file sequential read 14584 0 182 2002050 1 96b6hrt8csw55 1 NO HOLDER
292 WAITING db file sequential read 12400 0 182 2728806 1 96b6hrt8csw55 1 NO HOLDER
1451 WAITING db file sequential read 743 0 182 3028810 1 96b6hrt8csw55 1 NO HOLDER
106 WAITING db file sequential read 60750 0 183 1701508 1 96b6hrt8csw55 1 NO HOLDER
10 WAITING db file sequential read 55193 0 184 1736937 1 96b6hrt8csw55 1 NO HOLDER
9 WAITING db file sequential read 10210 0 184 2309535 1 96b6hrt8csw55 1 NO HOLDER
488 WAITING db file sequential read 64865 0 184 2343479 1 96b6hrt8csw55 1 NO HOLDER
391 WAITING db file sequential read 64588 0 4 1555731 1 grh2sp5vv6p52 1 NO HOLDER
871 WAITING db file sequential read 954 0 24 3316869 1 grh2sp5vv6p52 1 NO HOLDER
774 WAITING db file sequential read 11105 0 24 3398637 1 grh2sp5vv6p52 1 NO HOLDER
1446 WAITING db file sequential read 41035 0 116 2763511 1 grh2sp5vv6p52 0 NO HOLDER
7 WAITING db file sequential read 41212 0 149 3192125 1 grh2sp5vv6p52 0 NO HOLDER
5 WAITING db file sequential read 52224 0 153 2657271 1 grh2sp5vv6p52 0 NO HOLDER
394 WAITING db file sequential read 17441 0 180 2937987 1 grh2sp5vv6p52 1 NO HOLDER
200 WAITING db file sequential read 4817 0 184 3616064 1 grh2sp5vv6p52 1 NO HOLDER
779 WAITING direct path read 37544 4 122 824944 16 49wv7fcafp592 0 UNKNOWN
677 WAITING direct path read 48106 4 122 824960 16 49wv7fcafp592 0 UNKNOWN
582 WAITING direct path read 62850 4 122 825520 16 49wv7fcafp592 0 UNKNOWN
1256 WAITING direct path read 21726 4 122 1141296 16 49wv7fcafp592 0 UNKNOWN
392 WAITING direct path read 52383 4 122 1141312 16 49wv7fcafp592 0 UNKNOWN
589 WAITING direct path read 57288 4 122 477936 16 6kbpsc2jb91dq 1 UNKNOWN
204 WAITING enq: KO - fast object checkpoint 27274 3140 1263468550 65650 1 0x4B4F0006: KO mode6 0qvw20ptvsq4b 1 1249 VALID ##########
301 WAITING enq: KO - fast object checkpoint 63459 8232 1263468550 65667 1 0x4B4F0006: KO mode6 1t4r0r70xg5nw 0 1249 VALID ##########
1259 WAITING enq: KO - fast object checkpoint 4170 594 1263468550 65661 1 0x4B4F0006: KO mode6 49wv7fcafp592 0 1249 VALID ##########
1258 WAITING enq: KO - fast object checkpoint 1200 594 1263468550 65677 1 0x4B4F0006: KO mode6 49wv7fcafp592 0 1249 VALID ##########
684 WAITING enq: TX - row lock contention 32955 146961 1415053318 1703962 7965635 0x54580006: TX mode6 903wwaubvn68k 4 1256 VALID ##########
104 WAITING enq: TX - row lock contention 60635 174744 1415053318 2686999 2493927 0x54580006: TX mode6 903wwaubvn68k 2 1259 VALID ##########
1357 WAITING enq: TX - row lock contention 1018 15106 1415053318 2949135 1686270 0x54580006: TX mode6 903wwaubvn68k 5 297 VALID ##########
1450 WAITING enq: TX - row lock contention 34 141454 1415053318 3014687 1597677 0x54580006: TX mode6 903wwaubvn68k 1 1067 VALID ##########
1444 WAITING enq: TX - row lock contention 12087 135239 1415053318 3473432 1523820 0x54580006: TX mode6 903wwaubvn68k 4 779 VALID ##########
1454 WAITING enq: TX - row lock contention 34927 799 1415053318 1441817 14075933 0x54580006: TX mode6 drjnqxby1927s 0 12 VALID ##########
964 WAITING free buffer waits 15050 4 26 684518 47 1ayvhx1yt4zxp 0 961 VALID ##########
103 WAITING free buffer waits 50435 53 116 2224095 43 1hx317q49q07d 0 961 VALID ##########
195 WAITING free buffer waits 37827 15 116 2224095 43 1hx317q49q07d 1 961 VALID ##########
496 WAITING free buffer waits 4599 53 116 2224095 43 1hx317q49q07d 0 961 VALID ##########
678 WAITING free buffer waits 30372 53 116 2224100 43 1hx317q49q07d 1 961 VALID ##########
1160 WAITING free buffer waits 12865 53 116 2224100 43 1hx317q49q07d 1 961 VALID ##########
874 WAITING free buffer waits 1391 10 116 2224100 45 1hx317q49q07d 1 961 VALID ##########
683 WAITING free buffer waits 64898 20 116 2224515 47 1hx317q49q07d 1 961 VALID ##########
490 WAITING free buffer waits 61840 9 116 2224565 45 1hx317q49q07d 1 961 VALID ##########
295 WAITING free buffer waits 58320 9 116 2224565 45 1hx317q49q07d 1 961 VALID ##########
194 WAITING free buffer waits 27899 9 116 2224565 46 1hx317q49q07d 1 1057 VALID ##########
399 WAITING free buffer waits 46190 4 116 3431484 46 49wv7fcafp592 0 1057 VALID ##########
3 WAITING free buffer waits 28122 64 185 2793836 43 4wztt7u8md4f5 0 961 VALID ##########
98 WAITING free buffer waits 10526 20 186 3286834 47 4wztt7u8md4f5 0 961 VALID ##########
1154 WAITING free buffer waits 28834 10 188 2931858 43 4wztt7u8md4f5 0 961 VALID ##########
1155 WAITING free buffer waits 22844 0 116 3593900 43 6sy5x0dnyq7gp 1 961 VALID ##########
870 WAITING free buffer waits 28946 14 18 3925826 43 903wwaubvn68k 4 961 VALID ##########
1067 WAITING free buffer waits 29816 20 181 3274463 43 903wwaubvn68k 1 961 VALID ##########
681 WAITING free buffer waits 35443 0 21 3478189 43 96b6hrt8csw55 1 961 VALID ##########
12 WAITING free buffer waits 8879 2 168 46071 35 drjnqxby1927s 0 961 VALID ##########
1165 WAITING free buffer waits 11974 0 99 3293378 42 gj05bqfb8sgda 0 1057 VALID ##########
1158 WAITING free buffer waits 60839 14 153 3876852 33 grh2sp5vv6p52 0 961 VALID ##########
491 WAITING free buffer waits 49412 24 122 3402617 47 961 VALID ##########
300 WAITING free buffer waits 53971 20 122 3402618 47 961 VALID ##########
1448 WAITING read by other session 53882 0 8 3525609 1 data block obj=TABLE_XXXXXXX type=TABLE 96b6hrt8csw55 1 777 VALID ##########
SUBPARTITION
873 WAITING read by other session 44573 0 184 1736937 1 data block obj=TABLE_XXXXXXX type=TABLE 96b6hrt8csw55 1 10 VALID ##########
SUBPARTITION
1442 WAITING write complete waits 18271 10 95 10722 0 0dhchmc8q926g 0 961 VALID ##########
778 WORKING On CPU / runqueue 32331 0 1413697536 1 0 dgcp1b9y4h89a 1 NOT IN WAIT
78 rows selected.
Questions :
1- What would you check first ?
2- What would you check for free-buffer event ?
3- What might be wrong for free buffer event for me to get the picture below ?
This is free buffer events graph when I sorted that event only around 12:30 on 27th ( I only show graph of free buffer events because our problem was different which was caused by a missing index on the main table which also caused a free buffer waits after the problem sorted but it is not the point of this topic so please ignore for the 28th 🙂 )
Update 18:44 05-01-11: Think about this system as brand new system for you. You only knew main 500GB table partitioned by dbms_redefinition and partitioning finished. You got call that everything is slow and the main DBA was on holiday.
Update 10:46 07-01-11 I got very impressive and very interesting answers. I really like Charles way of thinking and Radoslavs approach.
When it comes to what I did, I checked what session 961 and 1057 doing
here is what I see when I checked 961 and 1057
SQL> @usid 961
SID PROGRAM SPID LASTCALL STATUS
-------------- -------------------- ------------------ --------
'961,1' (DBW0) 26636 255137 ACTIVE
SQL> @usid 1057
SID PROGRAM SPID LASTCALL STATUS
-------------- -------------------- -------- ---------- --------
'1057,1' (DBW1) 26638 255143 ACTIVE
I saw dbwriter then I decided to do another check.
I already did a research on free buffer wait event before and as doc says it could be that DBWR could not catch up writing the dirty buffers to disk.
Because I am completely new to this system I could not just assume system is a good design.
SQL> show parameter io NAME TYPE VALUE ------------------------------------ ----------- ---------------------------------------------------------------------------------------------------- O7_DICTIONARY_ACCESSIBILITY boolean FALSE audit_sys_operations boolean FALSE backup_tape_io_slaves boolean FALSE cell_offload_compaction string ADAPTIVE cell_offload_decryption boolean TRUE cursor_bind_capture_destination string memory+disk db_flashback_retention_target integer 1440 dbwr_io_slaves integer 0 deferred_segment_creation boolean TRUE disk_asynch_io boolean TRUE fast_start_io_target integer 0 fileio_network_adapters string filesystemio_options string directio java_max_sessionspace_size integer 0 java_soft_sessionspace_limit integer 0 license_max_sessions integer 0 license_sessions_warning integer 0 parallel_execution_message_size integer 16384 parallel_io_cap_enabled boolean FALSE replication_dependency_tracking boolean TRUE resource_manager_cpu_allocation integer 16 result_cache_remote_expiration integer 0 sec_protocol_error_further_action string CONTINUE sec_protocol_error_trace_action string TRACE session_cached_cursors integer 50 session_max_open_files integer 10 sessions integer 1536 shared_server_sessions integer star_transformation_enabled string FALSE tape_asynch_io boolean TRUE transactions integer 1689 transactions_per_rollback_segment integer 5 undo_retention integer 10800
Do you see something wrong with the parameters ?
filesystemio_options string directio
disk_asynch_io boolean TRUE
and number of dbwriters are 2 and this is asnych i/o supported linux system
I asked business to change the parameter filesystemio_options to SETALL followed by outage. Since it was qa they accepted to do that and we restarted.
After the restart no more free buffer waits left.
SQL> @swact
SID STATE EVENT SEQ# SEC_IN_STATE P1 P2 P3 P1TRANSL SQL_ID CHN BLCKNG_SID BLCKNG_SID_S BLCKNG_INST
------- ------- ---------------------------------------- ---------- ------------ ---------- ---------- ---------- ------------------------------------------ ------------- ---- ---------- ------------ -----------
394 WAITING PX Deq: Execute Reply 20003 9 200 5 0 dtz7d985utg6z 0 1063 VALID ##########
200 WAITING PX Deq: Execution Msg 4 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
1259 WAITING PX Deq: Execution Msg 3 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
493 WAITING PX Deq: Execution Msg 4 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
587 WAITING PX Deq: Execution Msg 3 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
297 WAITING PX Deq: Execution Msg 7 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
14 WAITING PX Deq: Execution Msg 3 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
684 WAITING PX Deq: Execution Msg 6 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
1353 WAITING PX Deq: Execution Msg 4 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
1450 WAITING PX Deq: Execution Msg 5 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
204 WAITING PX Deq: Execution Msg 3 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
398 WAITING PX Deq: Execution Msg 4 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
107 WAITING PX Deq: Execution Msg 5 110 268566527 56 4.4291E+10 dtz7d985utg6z 0 UNKNOWN
1062 WAITING Streams AQ: waiting for messages in the 8517 4 169722 4.3499E+10 5 UNKNOWN
291 WAITING Streams AQ: waiting for messages in the 1399 4 847866 4.3499E+10 120 UNKNOWN
388 WAITING db file scattered read 35689 0 8 3290683 14 1hx317q49q07d 0 NO HOLDER
5 WAITING db file scattered read 55938 1 8 3472309 16 1hx317q49q07d 0 NO HOLDER
776 WAITING db file scattered read 47950 0 12 3240101 16 1hx317q49q07d 0 NO HOLDER
775 WAITING db file scattered read 59251 1 78 3408813 16 1hx317q49q07d 0 NO HOLDER
198 WAITING db file scattered read 944 1 84 3308877 16 1hx317q49q07d 1 NO HOLDER
1252 WAITING db file scattered read 2141 0 110 3330992 3 1hx317q49q07d 0 NO HOLDER
967 WAITING db file scattered read 15594 1 116 2182344 8 1hx317q49q07d 0 NO HOLDER
6 WAITING db file scattered read 48153 1 116 2220207 2 1hx317q49q07d 0 NO HOLDER
486 WAITING db file scattered read 45281 1 122 2126792 16 1hx317q49q07d 0 NO HOLDER
1065 WAITING db file scattered read 51433 1 136 3369917 16 1hx317q49q07d 0 NO HOLDER
871 WAITING db file scattered read 3933 1 146 3731624 16 1hx317q49q07d 0 NO HOLDER
295 WAITING db file scattered read 47880 0 153 1968132 16 1hx317q49q07d 0 NO HOLDER
1060 WAITING db file scattered read 41096 0 138 3568753 16 6sy5x0dnyq7gp 0 NO HOLDER
1156 WAITING db file scattered read 18820 2 146 3510936 16 6sy5x0dnyq7gp 0 NO HOLDER
1164 WAITING db file scattered read 537 0 102 3364814 2 6ug9z3tm0udpa 0 NO HOLDER
1354 WAITING db file scattered read 5085 0 12 2617077 16 96b6hrt8csw55 7 NO HOLDER
13 WAITING db file scattered read 1911 0 18 840859 16 96b6hrt8csw55 7 NO HOLDER
1351 WAITING db file scattered read 20606 1 21 3732633 16 96b6hrt8csw55 5 NO HOLDER
872 WAITING db file scattered read 62586 1 29 3725313 16 96b6hrt8csw55 6 NO HOLDER
494 WAITING db file scattered read 48400 1 108 3670313 16 96b6hrt8csw55 7 NO HOLDER
389 WAITING db file scattered read 34973 1 109 3891273 16 96b6hrt8csw55 4 NO HOLDER
290 WAITING db file scattered read 63299 1 116 2766680 16 96b6hrt8csw55 3 NO HOLDER
102 WAITING db file scattered read 13642 1 116 3749032 16 96b6hrt8csw55 2 NO HOLDER
1162 WAITING db file scattered read 4001 0 120 897310 6 96b6hrt8csw55 7 NO HOLDER
586 WAITING db file scattered read 12395 1 126 3309519 16 96b6hrt8csw55 7 NO HOLDER
397 WAITING db file scattered read 227 0 136 1142460 3 96b6hrt8csw55 7 NO HOLDER
676 WAITING db file scattered read 6794 0 136 2014799 3 96b6hrt8csw55 7 NO HOLDER
582 WAITING db file scattered read 28366 1 176 1541000 16 96b6hrt8csw55 1 NO HOLDER
3 WAITING db file scattered read 42306 1 177 2842776 16 96b6hrt8csw55 0 NO HOLDER
683 WAITING db file scattered read 61960 1 181 804168 16 96b6hrt8csw55 0 NO HOLDER
1352 WAITING db file scattered read 5107 0 4 3380200 14 amhsjrzs5hyg5 0 NO HOLDER
1449 WAITING db file scattered read 1108 1 143 2164525 16 amhsjrzs5hyg5 0 NO HOLDER
103 WAITING db file scattered read 3890 0 149 2324484 16 amhsjrzs5hyg5 0 NO HOLDER
8 WAITING db file scattered read 13835 1 137 2316749 16 bcftaq4qw1ur7 0 NO HOLDER
1254 WAITING db file scattered read 61829 1 177 405028 16 bcftaq4qw1ur7 0 NO HOLDER
490 WAITING db file scattered read 42588 1 183 816616 16 bcftaq4qw1ur7 0 NO HOLDER
681 WAITING db file scattered read 39165 1 102 3670249 16 grh2sp5vv6p52 0 NO HOLDER
583 WAITING db file scattered read 44055 1 137 2171469 16 grh2sp5vv6p52 0 NO HOLDER
1257 WAITING db file scattered read 55597 1 176 3778728 16 grh2sp5vv6p52 0 NO HOLDER
1444 WAITING db file scattered read 41804 1 181 2407576 16 grh2sp5vv6p52 0 NO HOLDER
488 WAITING db file scattered read 169 1 182 1705576 16 grh2sp5vv6p52 0 NO HOLDER
392 WAITING db file scattered read 16649 1 135 3641393 16 NO HOLDER
197 WAITING db file sequential read 12387 1 124 513458 1 0dhchmc8q926g 0 NO HOLDER
964 WAITING db file sequential read 676 1 146 848005 1 5cusvg17sxdmg 0 NO HOLDER
1063 WAITING db file sequential read 3840 0 102 3840206 1 dtz7d985utg6z 0 NO HOLDER
777 WAITING db file sequential read 698 0 4 3689548 1 gj05bqfb8sgda 0 NO HOLDER
1253 WAITING direct path read 58341 1 136 3460480 16 49wv7fcafp592 0 UNKNOWN
1161 WAITING direct path read 367 0 4 3478432 16 dtz7d985utg6z 0 UNKNOWN
1451 WAITING direct path read 815 1 12 3331904 16 dtz7d985utg6z 0 UNKNOWN
782 WAITING direct path read 334 1 29 3472256 16 dtz7d985utg6z 0 UNKNOWN
202 WAITING direct path read 365 1 99 2874528 16 dtz7d985utg6z 0 UNKNOWN
1260 WAITING direct path read 461 0 126 3345856 16 dtz7d985utg6z 0 UNKNOWN
873 WAITING direct path read 734 1 135 3370016 16 dtz7d985utg6z 0 UNKNOWN
11 WAITING direct path read 807 0 136 3426896 16 dtz7d985utg6z 0 UNKNOWN
1067 WAITING direct path read 718 2 146 2682512 16 dtz7d985utg6z 0 UNKNOWN
778 WAITING direct path read 558 1 153 1912836 12 dtz7d985utg6z 0 UNKNOWN
875 WAITING direct path read 349 0 181 1457568 16 dtz7d985utg6z 0 UNKNOWN
292 WAITING enq: KO - fast object checkpoint 59339 8529 1263468550 65619 1 0x4B4F0006: KO mode6 1249 VALID ##########
1058 WAITING read by other session 2358 0 12 2617077 1 data block obj=TABLE_XXX type=TABLE 96b6hrt8csw55 7 1354 VALID ##########
Was free buffer waits our problem ? Obviously not 🙂 In my opinion and understanding Our real problem which was missing index, caused pressure in buffer cache and revealed this wrong parameter setting on the system.
FYI: The secondary free buffer waits on 28th was caused by attempt to create the index in restricted mode with parallel 10 to sort the real problem which revealed these wrong setting.
I think I did not ask the question right and should have given more clues. Hope next reader challenge will be more clear 🙂
Coskan's Approach to Oracle 
Hi Coskan,
First, I would have checked the contentions and wait events so we have a contention and a wait event in this very example. Row lock contention could happened because of the application itself. Free buffer waits are there because DBWn can not cope with the dirty buffers fast enough. Jonathan Lewis posted a nice article here –> http://jonathanlewis.wordpress.com/2006/11/21/free-buffer-waits/
So either the objects were pinned in the buffer or DBWn was not fast enough. However, i also see in the chart that we had a vicious log file switch (checkpoint incomplete) wait event for a while near Dec 28, 09:00 AM. I believe there is something wrong with the log_buffer and the online redolog sizes. If they can be tuned than the problem may dissapper before digging into a real analysis.
Ogan
Comment by Ogan Ozdogan — January 5, 2011 @ 1:18 pm
Hi Coskan,
The first thing i would check is “903wwaubvn68k” sql_id.This particular sql_id is showing “db file scattered read”,”enq: TX – row lock contention” and “free buffer waits”.Also, would have checked session id 961.
“What might be wrong for free buffer event”– free buffer events can be caused due to inefficient sqls.
Session 1442 shows “write complete waits” event which could be cause of I/O staturation.So, I/O is also to be considered for check.
Regards,
Anand
Comment by Anand — January 5, 2011 @ 3:04 pm
There really is not enough information to make an accurate guess of what is happening in this case. Is swact.sql Tanel’s session watcher script?
If I had to make a guess, I would look at the SEC_IN_STATE column and see that there are several really big numbers there, the largest at 174,744. The script seems to be showing that only one session is on the CPU (probably the session executing swact.sql), while all other sessions are listed as waiting.
SQL> SELECT 174744/60/60/24 FROM DUAL; 174744/60/60/24 --------------- 2.0225 SQL> SELECT TO_CHAR(TO_DATE('27-DEC-2010 11:30','DD-MON-YYYY HH24:MI')-2.0225,'MM/DD HH24:MI') FROM DUAL; TO_CHAR(TO_ ----------- 12/25 10:57So, that puts the first row lock contention wait at roughly 11 AM on December 25. Something, probably a scheduled job, likely started at 11 AM on Christmas day and attempted to insert a row using the SQL statement with SQL_ID 903wwaubvn68k, causing a possible primary key violation if session 1259 committed. Three other sessions also started being blocked when attempting to execute the same SQL statement (all had different CHILD_NUMBER values, one additional session was attempting to execute SQL ID drjnqxby1927s). This might suggest that the primary key is not generated by a sequence, but instead by something like:
The likely cause of that wait is probably an end-user failing to click OK to indicate that a set of documents printed (or something similar) so that a COMMIT could be performed, before leaving for the Christmas holiday.
The ‘enq: KO – fast object checkpoint’ waits typically indicate that a direct path read is about to happen, possibly due to a parallel query execution or a serial direct read of a table. The first wait of that type shown started at about 9:12 AM on December 27, and the last one at 11:20 AM. At roughly 11:20 AM you yelled at the SAN causing it to panic (blogs.sun.com/brendan/entry/unusual_disk_latency) which then triggered additional waits for blocks to be read from the SAN. The decrease in the ‘free buffer waits’ is simply an indication of less pressure on the buffer cache because all of the other sessions are still waiting for their previous IO requests to complete.
How close is my guess?
Comment by Charles Hooper — January 5, 2011 @ 5:27 pm
I can say you add different dimension to my own analysis which is good that I learn more things from my own post:)
Script is slightly modified version of SW.sql (modification is for buffer busy reads nothing to do with this post) called for active foreground sessions with a newer name @swact
This server was completely “new” to me apart from the fact that I only knew the massive core table with 500GB size was partitioned with dbms_redefinition and “partitioning” operation was finished reported as success but as I said the main index was missing that was causing other sessions suffer.
All I did was check with @swact and another check and took an action. I am after my action and the other check as answer.
Thanks for stopping by by the way
Comment by coskan — January 5, 2011 @ 6:43 pm
All I did was check with @swact and another check and took an action. I am after my action and the other check as answer
I am still trying to understand/digest all the explainations so excuse me if I am shooting in the dark but did your “another check” involve checking what the session 961 was doing? It seems session with SID 961 is causing “Free Buffer Waits”.
Comment by Narendra — January 6, 2011 @ 7:33 am
Hm, I’m not very experienced troubleshooter, but I would probably check statements with that fullscans where buffer cache is used (db file scattered read), especially: 96b6hrt8csw55 (fullscan on partitioned table)
and 903wwaubvn68k
903wwaubvn68k is very interesting it contains fullscan (scattered reads), requests an exclusive locks (so it’s modifying data) and it is also doing index reads (sequential reads)
Is it an MERGE statement? Or some update statement with IN/EXISTS?
and I would probably check what sessions 961 and 1057 are doing.
free buffer waits occurs when session cannot find free buffers to read data or *to build a consistent image of data block* – I think it’s only a symptom
Comment by Radoslav Golian — January 5, 2011 @ 10:30 pm
you saw the merge but not on the right sqlid 🙂
96b6hrt8csw55 was doing merge
903wwaubvn68k was doing an update
apart from that your analysis is very close to mine
here is what I see when I checked 961 and 1057
SQL> @usid 961 SID PROGRAM SPID LASTCALL STATUS -------------- -------------------- ------------------ -------- '961,1' (DBW0) 26636 255137 ACTIVE SQL> @usid 1057 SID PROGRAM SPID LASTCALL STATUS -------------- -------------------- -------- ---------- -------- '1057,1' (DBW1) 26638 255143 ACTIVEthen I decided to do another check
.. rest is in update
Comment by coskan — January 7, 2011 @ 1:56 pm
684 WAITING enq: TX - row lock contention 32955 146961 1415053318 1703962 7965635 0x54580006: TX mode6 903wwaubvn68k 4 1256 VALID ##########
104 WAITING enq: TX - row lock contention 60635 174744 1415053318 2686999 2493927 0x54580006: TX mode6 903wwaubvn68k 2 1259 VALID ##########
1357 WAITING enq: TX - row lock contention 1018 15106 1415053318 2949135 1686270 0x54580006: TX mode6 903wwaubvn68k 5 297 VALID ##########
1450 WAITING enq: TX - row lock contention 34 141454 1415053318 3014687 1597677 0x54580006: TX mode6 903wwaubvn68k 1 1067 VALID ##########
1444 WAITING enq: TX - row lock contention 12087 135239 1415053318 3473432 1523820 0x54580006: TX mode6 903wwaubvn68k 4 779 VALID ##########
1454 WAITING enq: TX - row lock contention 34927 799 1415053318 1441817 14075933 0x54580006: TX mode6
Seconds in wait to high and all this are on same transaction slot with mode 6. Someone might need to rollback or commit.
May be i am wrong.
Comment by Taral Desai — January 5, 2011 @ 11:38 pm
Opps. Click button earlier Also, 49wv7fcafp592 which id doing direct path io need to do object level checkpoint and this would be the object that is holding that rows
Comment by Taral Desai — January 5, 2011 @ 11:42 pm
I have updated the post with my actions
Comment by coskan — January 7, 2011 @ 1:59 pm