We put the workaround for Bug 13930580 in on Friday and the results have been much better than I expected. Here is when the workaround went in as reported in the alert log:
Fri Jan 17 18:38:26 2014 ALTER SYSTEM SET _use_adaptive_log_file_sync='FALSE' SCOPE=BOTH;
Here are the log file sync average times. Notice how they go down after 7 pm Friday:
END_INTERVAL_TIME number of waits ave microseconds -------------------------- --------------- ---------------- 17-JAN-14 12.00.49.669 AM 78666 15432.6923 17-JAN-14 01.00.27.862 AM 13380 15509.9778 17-JAN-14 02.00.11.834 AM 15838 17254.2949 17-JAN-14 03.00.56.429 AM 10681 29832.4282 17-JAN-14 04.00.39.502 AM 26127 14880.2097 17-JAN-14 05.00.22.716 AM 21637 10952.5322 17-JAN-14 06.00.01.558 AM 67162 9756.44207 17-JAN-14 07.00.45.358 AM 123705 11755.6535 17-JAN-14 08.00.29.811 AM 223799 11341.2467 17-JAN-14 09.00.19.275 AM 319051 13651.4647 17-JAN-14 10.00.09.089 AM 507335 13991.5543 17-JAN-14 11.00.59.502 AM 583835 11609.8432 17-JAN-14 12.00.44.044 PM 627506 10857.4556 17-JAN-14 01.00.30.133 PM 610232 11233.9348 17-JAN-14 02.00.18.961 PM 664368 10880.3887 17-JAN-14 03.00.05.694 PM 647896 9865.96367 17-JAN-14 04.00.44.694 PM 538270 10425.6479 17-JAN-14 05.00.24.376 PM 343863 9873.98468 17-JAN-14 06.00.11.481 PM 169654 9735.80996 17-JAN-14 07.00.03.087 PM 87590 7046.92633 17-JAN-14 08.00.52.390 PM 69297 2904.62955 17-JAN-14 09.00.29.888 PM 38244 3017.15969 17-JAN-14 10.00.09.436 PM 28166 3876.77469 17-JAN-14 11.00.54.765 PM 23220 11109.3063 18-JAN-14 12.00.33.790 AM 13293 9749.99428 18-JAN-14 01.00.17.853 AM 15332 3797.76839 18-JAN-14 02.00.56.050 AM 16137 6167.15127 18-JAN-14 03.00.33.908 AM 14621 9664.63108 18-JAN-14 04.00.12.383 AM 9708 6024.9829 18-JAN-14 05.00.56.348 AM 14565 3618.76938 18-JAN-14 06.00.39.683 AM 14323 3517.45402 18-JAN-14 07.00.29.535 AM 38243 3753.46422 18-JAN-14 08.00.16.778 AM 44878 2280.22924 18-JAN-14 09.00.01.176 AM 73082 9689.52484 18-JAN-14 10.00.45.168 AM 99302 2094.03293 18-JAN-14 11.00.35.070 AM 148789 1898.40424 18-JAN-14 12.00.23.344 PM 151780 1932.64997 18-JAN-14 01.00.08.631 PM 186040 2183.18563 18-JAN-14 02.00.59.839 PM 199826 2328.87331 18-JAN-14 03.00.45.441 PM 210098 1335.9759 18-JAN-14 04.00.36.453 PM 177331 1448.39219 18-JAN-14 05.00.21.669 PM 150837 1375.07256 18-JAN-14 06.00.59.959 PM 122234 1228.21767 18-JAN-14 07.00.37.851 PM 116396 1334.64569 ... skip a few to find some higher load times... 19-JAN-14 10.00.01.434 AM 557020 2131.02737 19-JAN-14 11.00.42.786 AM 700781 1621.16596 19-JAN-14 12.00.31.934 PM 715327 1671.72335 19-JAN-14 01.00.10.699 PM 718417 1553.98083 19-JAN-14 02.00.51.524 PM 730149 2466.6241 19-JAN-14 03.00.38.088 PM 628319 2465.45829
When the system is busy we are seeing less than 3000 microseconds = 3 milliseconds log file sync which is good. We were seeing 10 milliseconds or more which isn’t that great.
Oracle support has been pushing this for a long time but our own testing wasn’t able to recreate the problem. Have to hand it to them. They were right!
Here is a link to my previous post on this issue: url
– Bobby
