Oracle 11g Adaptive Cursor Sharing (ACS)
Ah, the long awaited fix for the Bind Variable Peeking problem.
Adaptive Cursor Sharing (ACS) sounds great if you say it fast. Unfortunately it doesn’t work quite as well as I had hoped (at least as of 11.1.0.7). I was really hoping that we’d never have to worry about plan instability due to bind variable peeking again, but it seems that will remain an elusive goal for a while longer.
So the goal of this post is to provide some data about how ACS works based on observations of a couple of production systems. By the way, this post assumes you already have a basic understanding of how ACS works. There are some links at the bottom of this post to other references and in particular, this post is a good basic description of ACS.
So here’s some background info:
Observations were made on a version 10.2.0.4 RAC database that was being migrated to an 11.1.0.7 RAC database. Both are on Redhat Linux and similar Dell hardware. The version 10 database had several queries which suffered from bind variable peeking issues which were addressed with Outlines (while the developers considered using literals). Also, the statements were using real bind variables, not the fake kind that result from setting the cursor_sharing parameter. We were hoping that ACS would solve the bind variable peeking problem without manual intervention (i.e. without using Outlines or SQL Profiles or Baselines to lock in a specific plan).
I have used several scripts in this post:
unstable_plans.sql - this one shows statements that have multiple plans with large variance in execution time
awr_plan_change.sql - history of how the statement plan changes over time
awr_plan_stats.sql - aggregate statement stats (like elapsed_time, lio, etc) grouped by plan
find_sql_acs.sql - A queries v$sql and shows ACS related columns
mismatch3.sql - A variation of Dion Cho’s script to display data from v$sql_shared_cursor (see his post here)
The first couple of these scripts I discussed in a previous post on Plan Instability. I also did a previous post that is a basic overview of the Bind Variable Peeking issue, if you want a little more background info.
So here’s a look at what’s going on with that newly migrated system:
SQL*Plus: Release 11.1.0.7.0 - Production on Mon May 4 19:53:00 2009 Copyright (c) 1982, 2008, Oracle. All rights reserved. Connected to: Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production With the Partitioning, Real Application Clusters, OLAP, Data Mining and Real Application Testing options SQL> -- find statements with multiple plans with big differences in elapsed time SQL> SQL> @unstable_plans Enter value for min_stddev: Enter value for min_etime: 1 SQL_ID SUM(EXECS) MIN_ETIME MAX_ETIME NORM_STDDEV ------------- ---------- ----------- ----------- ------------- f2pz10qx59awc 2 11.75 45.31 2.0197 5mh2127hkzbtr 70 2.64 18.06 3.0272 0hur96bxr18jn 24 1.65 9.14 3.1981 76gduk3urk91d 6 9.75 57.82 3.4880 cqxkwk9hp8rpf 31 7.18 43.77 3.6015 3u2bxt4y0740a 17 0.49 4.19 4.1316 af6j2dyzawp7w 78 6.83 60.31 4.4492 2mzzy3u2rtgqx 93 4.55 34.13 4.6025 6vb3gxdfzbhuz 33 0.63 5.21 5.1502 gc69y3vv5ws31 72 0.87 7.64 5.5128 b6zcb86sub9gv 2 0.95 8.74 5.8349 6pdbja617d2g7 2 2.24 23.55 6.7132 cc7yv55yn2wzm 5 0.26 3.05 7.4533 ach69kkyac77x 5 0.23 2.65 7.5202 09xqs3yhmnnc2 82 0.31 4.47 7.5534 3zqwzanpnddt1 2 0.69 8.75 8.2026 70zr1cg7ssfkw 2 0.71 9.04 8.2487 664tcunn5nks9 3 0.36 4.83 8.7858 39f6bx40awrms 2 0.74 10.15 9.0125 5z7v0n6amf8yx 116 9.06 125.53 9.0942 3q67n6qh7tcqv 2 0.08 1.20 9.2843 30yrz0qst88mj 68 0.21 2.97 9.3903 a1mk6hw6s20an 19 0.26 3.78 9.6454 26070mzfxps8d 72 0.18 2.75 10.0027 byznf81kmwumv 2 0.75 11.45 10.0407 1fj1qcqtmgmd1 2 0.54 9.33 11.4092 fg96c4y95u3s8 2 0.49 9.18 12.6745 chxn6vwj02xj4 2 0.65 12.27 12.7001 2xg8psmr3k7vz 2 0.76 14.38 12.7429 grysxv4s2hhkb 2 0.63 12.10 12.8338 2bfs79h84xsch 148 5.65 108.87 12.9179 4qz01hjwat4u3 39 0.27 5.50 13.6528 3wj5ngbv1sa9x 2 0.40 8.70 14.7151 g68szg2ydq6dg 14 0.26 7.48 19.4587 9vt6aaf5xcmh2 381 0.67 24.90 19.9706 cs8ng5sv7jgj4 4 1.12 35.70 21.8969 12a2xbmwn5v6z 7 0.23 8.08 23.7235 d2x7g9wr30v33 4 12.45 638.60 25.4008 4ymph98r42nbj 192 0.11 4.43 26.9188 1uby0zcw55cnp 4 0.63 31.22 34.3088 4jhx8qrkzztqg 15 1.22 66.07 37.6215 7xu6y0cvs55gh 34 0.44 30.08 37.9640 6hstnb2fghg76 77 0.65 49.01 39.2329 gzwgbycgs0fx9 265 0.08 7.37 47.4965 f028rmkp3qjvq 47 0.03 1.99 48.5307 7s1nc9wa2pc4r 2 0.19 15.53 57.6592 f2tm6xrb26y51 2 0.17 14.80 61.7260 0xz1j5y313f3c 206 0.02 2.38 71.6444 3dhwvfmkjzwtv 72 1.24 154.56 87.6684 fb90nawgwx3mj 37 0.34 51.96 108.3873 b7d0d3gu5fvqp 22 0.13 33.85 137.5321 ghdy23pftj44q 1100 0.02 5.93 143.7765 7v2jtb3u02qx6 10 0.43 139.36 172.2951 fw9ntwzhygmcq 87 0.32 100.44 220.3149 gxv6umvct0xsv 4188 0.84 333.79 225.1338 6jdu11g4zzjkh 42 0.41 137.88 234.5440 2wrngntk7v0st 183 0.11 50.61 333.9597 27wha8b8s21xw 1112 0.01 7.08 408.3026 dhmvcrmgdk3sn 881 0.05 46.99 620.1920 6u4c54k36ngwf 4329 0.00 4.39 656.4506 8jt9yh7jf8tn8 4788 0.09 160.35 1,251.5684 4fy7uznh9zz27 4723 0.03 47.16 1,256.8971 2ddh1h012t8au 12 0.03 67.62 1,491.8099 fw9hrrv37hb3v 5 0.04 100.86 1,503.5361 68wg4gjb51dsh 4411 0.01 16.44 1,539.4726 7d407h5cqmv81 4202 0.00 180.63 28,768.6107 66 rows selected. |
Please note that the unstable_plan.sql script is not guaranteed to find every statement that suffers from plan instability, because some of the good plans never make it into the AWR tables. This is due to the fact that AWR only grabs the “worst” statements in the various categories that AWR reports (i.e. elapsed time, cpu time, gets, reads, and executions). But you could argue that it will find the most important ones, because even when they run fast they still end up in the top of at least one category. Anyway, it’s obvious that there are many statements that are running with multiple plans with wide variances in their execution time.
So let’s look a little closer:
SQL> -- Let's check out the worst one on the list SQL> -- first let's see how many plans have been used and how they stack up SQL> SQL> @awr_plan_stats Enter value for sql_id: 7d407h5cqmv81 Enter value for snap_id: SQL_ID PLAN_HASH_VALUE EXECS ETIME AVG_ETIME AVG_LIO ------------- --------------- ------------ -------------- ------------ -------------- 7d407h5cqmv81 4289789142 840 2.4 0.003 273.7 7d407h5cqmv81 1007536393 551 116.2 0.211 14,563.1 7d407h5cqmv81 1723168170 2,852 44,716.2 15.679 255,603.3 7d407h5cqmv81 2337118685 1 180.6 180.629 6,495,990.0 SQL> -- So the best plan was executed 840 times and took .003 seconds on average SQL> -- The worst one was only executed once but took 180.6 seconds and did about 6.5M lios SQL> SQL> -- Now let's see if it looks like bind variable peeking - (i.e. the plan is flip-flopping) SQL> SQL> @awr_plan_change Enter value for sql_id: 7d407h5cqmv81 SNAP_ID NODE BEGIN_INTERVAL_TIME SQL_ID PLAN_HASH_VALUE EXECS AVG_ETIME AVG_LIO ---------- ------ ------------------------------ ------------- --------------- ------------ ------------ -------------- 1732 2 22-APR-09 01.00.06.582 PM 7d407h5cqmv81 1007536393 1 1.478 5,269.0 1733 2 22-APR-09 02.00.06.425 PM 7d407h5cqmv81 8 1.635 14,580.0 1734 2 22-APR-09 03.00.01.366 PM 7d407h5cqmv81 6 0.196 14,580.0 1734 3 22-APR-09 03.00.00.710 PM 7d407h5cqmv81 1723168170 2 8.891 228,740.5 1735 2 22-APR-09 04.00.19.942 PM 7d407h5cqmv81 1007536393 3 0.189 14,580.0 1736 2 22-APR-09 05.00.06.982 PM 7d407h5cqmv81 63 0.188 14,580.0 1736 3 22-APR-09 05.00.06.350 PM 7d407h5cqmv81 1723168170 22 9.564 236,902.3 1737 2 22-APR-09 06.00.03.582 PM 7d407h5cqmv81 1007536393 244 0.187 14,580.0 1737 3 22-APR-09 06.00.04.267 PM 7d407h5cqmv81 1723168170 76 9.505 236,959.9 1738 2 22-APR-09 07.00.28.278 PM 7d407h5cqmv81 1007536393 226 0.188 14,580.0 1738 3 22-APR-09 07.00.28.926 PM 7d407h5cqmv81 1723168170 71 9.395 240,745.0 1739 2 22-APR-09 08.00.09.681 PM 7d407h5cqmv81 81 11.114 253,481.2 1739 3 22-APR-09 08.00.10.422 PM 7d407h5cqmv81 22 9.866 249,882.3 1740 2 22-APR-09 09.00.43.176 PM 7d407h5cqmv81 215 13.682 256,467.0 1740 3 22-APR-09 09.00.43.910 PM 7d407h5cqmv81 80 12.605 252,606.0 1741 2 22-APR-09 10.00.16.298 PM 7d407h5cqmv81 367 20.209 256,157.1 1741 3 22-APR-09 10.00.17.072 PM 7d407h5cqmv81 214 15.039 257,287.3 1742 2 22-APR-09 11.00.28.426 PM 7d407h5cqmv81 376 17.855 257,066.5 1742 3 22-APR-09 11.00.27.666 PM 7d407h5cqmv81 178 13.437 255,902.4 1743 2 23-APR-09 12.00.16.137 AM 7d407h5cqmv81 352 18.639 257,326.6 1743 3 23-APR-09 12.00.15.386 AM 7d407h5cqmv81 182 13.787 258,192.2 1744 2 23-APR-09 01.00.03.520 AM 7d407h5cqmv81 285 16.275 256,335.3 1744 3 23-APR-09 01.00.02.838 AM 7d407h5cqmv81 94 13.492 258,508.9 1745 2 23-APR-09 02.00.21.107 AM 7d407h5cqmv81 132 14.876 258,913.5 1745 3 23-APR-09 02.00.20.482 AM 7d407h5cqmv81 103 13.113 256,821.0 1750 2 23-APR-09 07.00.33.920 AM 7d407h5cqmv81 4289789142 77 0.002 267.0 1753 2 23-APR-09 09.34.00.440 AM 7d407h5cqmv81 278 0.001 267.0 1754 2 23-APR-09 11.00.06.058 AM 7d407h5cqmv81 96 0.001 267.0 1754 3 23-APR-09 11.00.05.422 AM 7d407h5cqmv81 42 0.000 267.0 1755 2 23-APR-09 11.17.45.649 AM 7d407h5cqmv81 283 0.001 267.0 1756 2 23-APR-09 12.00.35.977 PM 7d407h5cqmv81 62 0.000 267.0 1894 3 29-APR-09 06.00.09.823 AM 7d407h5cqmv81 1 0.444 2,777.0 1900 2 29-APR-09 12.00.36.427 PM 7d407h5cqmv81 2337118685 1 180.629 6,495,990.0 1943 3 01-MAY-09 07.00.02.507 AM 7d407h5cqmv81 4289789142 1 1.199 3,426.0 34 rows selected. SQL> -- It does look like a typical bind variable peeking flip-flop pattern SQL> SQL> -- Now let's see if it's still in the shared pool and if it's bind aware SQL> SQL> @find_sql_acs Enter value for sql_text: Enter value for sql_id: 7d407h5cqmv81 Enter value for is_bind_aware: SQL_ID CHILD PLAN_HASH_VALUE IBS IBA ISH EXECS ROWS_PROCESSED AVG_ETIME AVG_CPU AVG_PIO AVG_LIO SQL_TEXT ------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- ------------------------------ 7d407h5cqmv81 0 4289789142 N N Y 2 2 0.62 0.07 315.50 1,758 SELECT COUNT(*) as total_recor 7d407h5cqmv81 1 4289789142 N N Y 2 2 0.03 0.01 1.00 264 SQL> -- It is in the shared pool, but it is not bind aware SQL> |
So the previous example showed a statement that had several plans, one of which definitely had better performance characteristics. But since there was only one plan in the shared pool at the time we examined it, there is is no reason to expect that Oracle would have recognized that the statement should be bind aware. This brings up an interesting point. It does not appear that (at least as of 11.1.0.7) Oracle keeps track of bind sensitivity of a statement persistently. That is to say, if the statement gets flushed for any reason, the optimizer appears to completely forget about any analysis it has done up to that point. Thus the painful (for the user) process of discovering which sets of bind variables should go with which plan starts all over.
So here’s another statement:
SQL> -- another example from the list of unstable_plans SQL> SQL> @awr_plan_stats Enter value for sql_id: 8jt9yh7jf8tn8 SQL_ID PLAN_HASH_VALUE EXECS ETIME AVG_ETIME AVG_LIO ------------- --------------- ------------ -------------- ------------ -------------- 8jt9yh7jf8tn8 1093407144 4,818 481.5 0.100 2,818.6 8jt9yh7jf8tn8 4076066623 21 3,269.3 155.679 5,901,988.0 SQL> @awr_plan_change Enter value for sql_id: 8jt9yh7jf8tn8 SNAP_ID NODE BEGIN_INTERVAL_TIME SQL_ID PLAN_HASH_VALUE EXECS AVG_ETIME AVG_LIO ---------- ------ ------------------------------ ------------- --------------- ------------ ------------ -------------- 1785 3 24-APR-09 05.00.13.361 PM 8jt9yh7jf8tn8 1093407144 6 1.102 2,872.7 1786 2 24-APR-09 06.00.02.510 PM 8jt9yh7jf8tn8 158 0.024 2,873.0 1786 3 24-APR-09 06.00.03.170 PM 8jt9yh7jf8tn8 223 0.023 2,873.0 1787 2 24-APR-09 07.00.30.171 PM 8jt9yh7jf8tn8 749 0.020 2,873.0 1787 3 24-APR-09 07.00.30.935 PM 8jt9yh7jf8tn8 873 0.019 2,873.0 1788 2 24-APR-09 08.00.03.359 PM 8jt9yh7jf8tn8 726 0.020 2,873.9 1788 3 24-APR-09 08.00.04.148 PM 8jt9yh7jf8tn8 871 0.020 2,873.9 1789 2 24-APR-09 09.00.28.203 PM 8jt9yh7jf8tn8 373 0.016 2,874.0 1789 3 24-APR-09 09.00.27.481 PM 8jt9yh7jf8tn8 566 0.016 2,874.0 1892 2 29-APR-09 04.00.02.385 AM 8jt9yh7jf8tn8 1 2.613 3,811.0 1894 2 29-APR-09 06.00.09.154 AM 8jt9yh7jf8tn8 2 0.462 733.0 1894 3 29-APR-09 06.00.09.823 AM 8jt9yh7jf8tn8 2 1.056 847.0 1895 2 29-APR-09 07.00.00.226 AM 8jt9yh7jf8tn8 7 1.714 2,869.6 1895 3 29-APR-09 07.00.00.921 AM 8jt9yh7jf8tn8 2 0.856 1,208.0 1896 2 29-APR-09 08.00.20.446 AM 8jt9yh7jf8tn8 9 1.635 2,103.0 1897 2 29-APR-09 09.00.09.367 AM 8jt9yh7jf8tn8 2 8.179 8,529.0 1897 3 29-APR-09 09.00.10.115 AM 8jt9yh7jf8tn8 17 1.714 3,416.5 1898 2 29-APR-09 10.00.43.551 AM 8jt9yh7jf8tn8 5 2.553 2,733.2 1898 3 29-APR-09 10.00.42.788 AM 8jt9yh7jf8tn8 6 3.751 4,484.2 1899 3 29-APR-09 11.00.10.447 AM 8jt9yh7jf8tn8 7 1.742 3,284.4 1900 3 29-APR-09 12.00.35.788 PM 8jt9yh7jf8tn8 2 1.199 966.0 1901 2 29-APR-09 01.00.18.515 PM 8jt9yh7jf8tn8 8 2.345 2,409.6 1902 3 29-APR-09 02.00.15.910 PM 8jt9yh7jf8tn8 2 3.941 2,649.5 1905 2 29-APR-09 05.00.02.254 PM 8jt9yh7jf8tn8 1 0.887 1,230.0 1918 2 30-APR-09 06.00.09.089 AM 8jt9yh7jf8tn8 1 0.653 1,248.0 1918 3 30-APR-09 06.00.08.403 AM 8jt9yh7jf8tn8 2 0.421 485.5 1919 2 30-APR-09 07.00.28.148 AM 8jt9yh7jf8tn8 1 1.152 1,242.0 1920 2 30-APR-09 08.00.03.733 AM 8jt9yh7jf8tn8 4 3.273 3,200.3 1920 3 30-APR-09 08.00.04.389 AM 8jt9yh7jf8tn8 12 2.491 3,314.2 1921 2 30-APR-09 09.00.10.125 AM 8jt9yh7jf8tn8 5 3.947 3,333.4 1921 3 30-APR-09 09.00.10.838 AM 8jt9yh7jf8tn8 2 2.416 1,769.5 1922 3 30-APR-09 10.00.25.754 AM 8jt9yh7jf8tn8 4076066623 2 54.237 2,291,432.5 1923 2 30-APR-09 11.00.17.345 AM 8jt9yh7jf8tn8 1093407144 2 0.812 975.0 1923 3 30-APR-09 11.00.18.032 AM 8jt9yh7jf8tn8 4076066623 3 134.031 933,124.3 1924 3 30-APR-09 12.00.15.448 PM 8jt9yh7jf8tn8 3 227.009 6,987,169.3 1926 2 30-APR-09 02.00.11.921 PM 8jt9yh7jf8tn8 1093407144 8 0.818 1,574.5 1926 3 30-APR-09 02.00.11.174 PM 8jt9yh7jf8tn8 4076066623 2 175.709 8,963,417.0 1927 2 30-APR-09 03.00.24.923 PM 8jt9yh7jf8tn8 1093407144 4 1.344 1,068.8 1927 3 30-APR-09 03.00.24.306 PM 8jt9yh7jf8tn8 4076066623 5 156.378 10,159,992.0 1928 2 30-APR-09 04.00.30.061 PM 8jt9yh7jf8tn8 1093407144 6 0.923 1,225.8 1928 3 30-APR-09 04.00.29.416 PM 8jt9yh7jf8tn8 4076066623 1 180.488 2,150,190.0 1930 3 30-APR-09 06.00.37.119 PM 8jt9yh7jf8tn8 2 180.371 8,255,881.5 1934 3 30-APR-09 10.00.12.055 PM 8jt9yh7jf8tn8 1 180.491 3,102,577.0 1939 2 01-MAY-09 03.00.31.764 AM 8jt9yh7jf8tn8 1093407144 21 0.825 1,041.8 1939 3 01-MAY-09 03.00.32.453 AM 8jt9yh7jf8tn8 4 0.575 1,211.8 1944 3 01-MAY-09 08.00.15.686 AM 8jt9yh7jf8tn8 6 1.328 1,788.3 1946 2 01-MAY-09 10.00.17.105 AM 8jt9yh7jf8tn8 1 1.170 2,411.0 1946 3 01-MAY-09 10.00.16.458 AM 8jt9yh7jf8tn8 4 2.041 2,414.3 1947 3 01-MAY-09 11.00.14.385 AM 8jt9yh7jf8tn8 10 1.725 2,937.1 1948 3 01-MAY-09 12.00.08.928 PM 8jt9yh7jf8tn8 3 2.232 3,415.7 1987 2 03-MAY-09 03.00.03.550 AM 8jt9yh7jf8tn8 7 1.029 901.0 1990 3 03-MAY-09 06.00.07.641 AM 8jt9yh7jf8tn8 3 1.225 1,465.7 1991 3 03-MAY-09 07.00.05.445 AM 8jt9yh7jf8tn8 26 0.370 710.5 1992 2 03-MAY-09 08.00.20.010 AM 8jt9yh7jf8tn8 6 0.213 685.7 1992 3 03-MAY-09 08.00.19.366 AM 8jt9yh7jf8tn8 3 0.658 883.0 1993 2 03-MAY-09 09.00.04.983 AM 8jt9yh7jf8tn8 8 0.769 950.9 1996 2 03-MAY-09 12.00.19.205 PM 8jt9yh7jf8tn8 2 0.101 861.5 2015 3 04-MAY-09 07.00.13.869 AM 8jt9yh7jf8tn8 4 0.376 854.5 2016 3 04-MAY-09 08.00.09.477 AM 8jt9yh7jf8tn8 6 0.143 571.0 2019 2 04-MAY-09 11.00.11.317 AM 8jt9yh7jf8tn8 12 0.937 1,352.1 2019 3 04-MAY-09 11.00.10.691 AM 8jt9yh7jf8tn8 10 1.612 1,341.9 2019 3 04-MAY-09 11.00.10.691 AM 8jt9yh7jf8tn8 4076066623 1 41.592 3,942,672.0 2020 2 04-MAY-09 12.00.06.355 PM 8jt9yh7jf8tn8 1093407144 15 1.037 1,734.6 2020 3 04-MAY-09 12.00.06.919 PM 8jt9yh7jf8tn8 4076066623 1 181.044 1,764,007.0 2022 2 04-MAY-09 02.00.26.599 PM 8jt9yh7jf8tn8 1093407144 2 2.214 2,780.5 65 rows selected. SQL> -- typical bind variable peeking pattern SQL> -- let's look at just one node - it'll be a little more clear SQL> l8 8* and ss.instance_number = S.instance_number SQL> i 9i and s.instance_number = &inst 10i SQL> SQL> / Enter value for sql_id: 8jt9yh7jf8tn8 Enter value for inst: 3 SNAP_ID NODE BEGIN_INTERVAL_TIME SQL_ID PLAN_HASH_VALUE EXECS AVG_ETIME AVG_LIO ---------- ------ ------------------------------ ------------- --------------- ------------ ------------ -------------- 1785 3 24-APR-09 05.00.13.361 PM 8jt9yh7jf8tn8 1093407144 6 1.102 2,872.7 1786 3 24-APR-09 06.00.03.170 PM 8jt9yh7jf8tn8 223 0.023 2,873.0 1787 3 24-APR-09 07.00.30.935 PM 8jt9yh7jf8tn8 873 0.019 2,873.0 1788 3 24-APR-09 08.00.04.148 PM 8jt9yh7jf8tn8 871 0.020 2,873.9 1789 3 24-APR-09 09.00.27.481 PM 8jt9yh7jf8tn8 566 0.016 2,874.0 1894 3 29-APR-09 06.00.09.823 AM 8jt9yh7jf8tn8 2 1.056 847.0 1895 3 29-APR-09 07.00.00.921 AM 8jt9yh7jf8tn8 2 0.856 1,208.0 1897 3 29-APR-09 09.00.10.115 AM 8jt9yh7jf8tn8 17 1.714 3,416.5 1898 3 29-APR-09 10.00.42.788 AM 8jt9yh7jf8tn8 6 3.751 4,484.2 1899 3 29-APR-09 11.00.10.447 AM 8jt9yh7jf8tn8 7 1.742 3,284.4 1900 3 29-APR-09 12.00.35.788 PM 8jt9yh7jf8tn8 2 1.199 966.0 1902 3 29-APR-09 02.00.15.910 PM 8jt9yh7jf8tn8 2 3.941 2,649.5 1918 3 30-APR-09 06.00.08.403 AM 8jt9yh7jf8tn8 2 0.421 485.5 1920 3 30-APR-09 08.00.04.389 AM 8jt9yh7jf8tn8 12 2.491 3,314.2 1921 3 30-APR-09 09.00.10.838 AM 8jt9yh7jf8tn8 2 2.416 1,769.5 1922 3 30-APR-09 10.00.25.754 AM 8jt9yh7jf8tn8 4076066623 2 54.237 2,291,432.5 1923 3 30-APR-09 11.00.18.032 AM 8jt9yh7jf8tn8 3 134.031 933,124.3 1924 3 30-APR-09 12.00.15.448 PM 8jt9yh7jf8tn8 3 227.009 6,987,169.3 1926 3 30-APR-09 02.00.11.174 PM 8jt9yh7jf8tn8 2 175.709 8,963,417.0 1927 3 30-APR-09 03.00.24.306 PM 8jt9yh7jf8tn8 5 156.378 10,159,992.0 1928 3 30-APR-09 04.00.29.416 PM 8jt9yh7jf8tn8 1 180.488 2,150,190.0 1930 3 30-APR-09 06.00.37.119 PM 8jt9yh7jf8tn8 2 180.371 8,255,881.5 1934 3 30-APR-09 10.00.12.055 PM 8jt9yh7jf8tn8 1 180.491 3,102,577.0 1939 3 01-MAY-09 03.00.32.453 AM 8jt9yh7jf8tn8 1093407144 4 0.575 1,211.8 1944 3 01-MAY-09 08.00.15.686 AM 8jt9yh7jf8tn8 6 1.328 1,788.3 1946 3 01-MAY-09 10.00.16.458 AM 8jt9yh7jf8tn8 4 2.041 2,414.3 1947 3 01-MAY-09 11.00.14.385 AM 8jt9yh7jf8tn8 10 1.725 2,937.1 1948 3 01-MAY-09 12.00.08.928 PM 8jt9yh7jf8tn8 3 2.232 3,415.7 1990 3 03-MAY-09 06.00.07.641 AM 8jt9yh7jf8tn8 3 1.225 1,465.7 1991 3 03-MAY-09 07.00.05.445 AM 8jt9yh7jf8tn8 26 0.370 710.5 1992 3 03-MAY-09 08.00.19.366 AM 8jt9yh7jf8tn8 3 0.658 883.0 2015 3 04-MAY-09 07.00.13.869 AM 8jt9yh7jf8tn8 4 0.376 854.5 2016 3 04-MAY-09 08.00.09.477 AM 8jt9yh7jf8tn8 6 0.143 571.0 2019 3 04-MAY-09 11.00.10.691 AM 8jt9yh7jf8tn8 4076066623 1 41.592 3,942,672.0 2019 3 04-MAY-09 11.00.10.691 AM 8jt9yh7jf8tn8 1093407144 10 1.612 1,341.9 2020 3 04-MAY-09 12.00.06.919 PM 8jt9yh7jf8tn8 4076066623 1 181.044 1,764,007.0 2031 3 04-MAY-09 11.00.03.519 PM 8jt9yh7jf8tn8 1093407144 1 0.737 482.0 2039 3 05-MAY-09 07.00.27.610 AM 8jt9yh7jf8tn8 4076066623 5 42.900 4,295,251.8 2041 3 05-MAY-09 09.00.09.829 AM 8jt9yh7jf8tn8 2 3.282 1,968,698.5 2044 3 05-MAY-09 12.00.16.920 PM 8jt9yh7jf8tn8 1093407144 2 1.535 844.5 2045 3 05-MAY-09 01.00.08.637 PM 8jt9yh7jf8tn8 2 2.384 1,683.5 41 rows selected. SQL> -- the plans are clearly flip-flopping SQL> -- and the performance of plan 1093407144 is clearly orders of magnitude better SQL> SQL> -- Let's see what's in the shared pool SQL> SQL> @find_sql_acs Enter value for sql_text: Enter value for sql_id: 8jt9yh7jf8tn8 Enter value for is_bind_aware: SQL_ID CHILD PLAN_HASH_VALUE IBS IBA ISH EXECS ROWS_PROCESSED AVG_ETIME AVG_CPU AVG_PIO AVG_LIO SQL_TEXT ------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- ----------------------------------- 8jt9yh7jf8tn8 0 4076066623 N N Y 19 6 160.35 29.28 ########## 6,222,898 SELECT row_order, cdr_id, site_id, 8jt9yh7jf8tn8 1 1093407144 N N Y 61 0 1.92 0.13 565.70 2,860 SELECT row_order, cdr_id, site_id, 8jt9yh7jf8tn8 2 N N Y 55 0 1.01 0.06 252.09 1,555 SELECT row_order, cdr_id, site_id, SQL> -- So there are children with both plans in the shared the pool (135 execs total) SQL> -- But the cursors are not marked as bind aware SQL> -- So why are there multiple child cursors? SQL> -- (using a modified version of Dion Cho's script) SQL> SQL> @mismatch3 Enter value for sql_id: 8jt9yh7jf8tn8 SQL_ID = 8jt9yh7jf8tn8 CHILD_NUMBER = 1 -------------------------------------------------- SQL_ID = 8jt9yh7jf8tn8 CHILD_NUMBER = 0 ROLL_INVALID_MISMATCH = Y -------------------------------------------------- SQL_ID = 8jt9yh7jf8tn8 CHILD_NUMBER = 2 ROLL_INVALID_MISMATCH = Y -------------------------------------------------- PL/SQL procedure successfully completed. SQL> -- none of the bind related flags show up, so it doesn't look promising for ACS SQL> -- |
Brief Digression: The ROLL_INVALID_MISMATCH flag has to do with changing stats using AUTO_INVALIDATE which does not cause cursors to be immediately invalidated, but instead let’s them be invalidated over a rolling window (_optimizer_invalidation_period which defaults to 5 hours).
So then I got to wondering if any statements were being marked as bind aware.
SQL> @find_sql_acs Enter value for sql_text: Enter value for sql_id: Enter value for is_bind_aware: Y SQL_ID CHILD PLAN_HASH_VALUE IBS IBA ISH EXECS ROWS_PROCESSED AVG_ETIME AVG_CPU AVG_PIO AVG_LIO SQL_TEXT ------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- --------------- 0qvgb3dyfg539 1 722236007 Y Y Y 2 0 .15 .02 23.00 3,487 SELECT row_orde 17uuqnvxmzxhj 1 3038781757 Y Y Y 31 31 .17 .01 43.74 1,126 SELECT COUNT(*) 3 3038781757 Y Y N 21 21 .02 .02 1.33 7,290 4 3038781757 Y Y Y 52 52 .23 .02 120.29 2,046 6 3038781757 Y Y Y 51 51 .00 .00 .10 284 34x6683rpwtxa 4 722236007 Y Y Y 18 164 .01 .00 .17 498 SELECT row_orde 3tfx8fzp64vkb 1 3038781757 Y Y Y 2 2 .01 .01 .00 1,178 SELECT COUNT(*) 4vb86f36xqc50 1 2983410489 Y Y Y 62 1683 .12 .01 53.76 960 SELECT row_orde 4 2983410489 Y Y Y 7 163 .69 .07 328.43 723 58p0j1q6rmv34 1 1144901783 Y Y Y 2 2 .02 .00 .00 335 SELECT COUNT(*) 5mxqphz5qfs4d 1 1144901783 Y Y Y 2 2 .02 .00 .00 54 SELECT COUNT(*) dt1v1cmua9cnq 1 4076066623 Y Y Y 8 37 3.47 3.41 15.63 2,233,144 SELECT row_orde ftxa99d89yzz0 1 4289789142 Y Y Y 2 2 .01 .00 .00 157 SELECT COUNT(*) g375mcpc30dy5 2 1690109023 Y Y N 1 10 .03 .01 .00 767 SELECT row_orde 3 1690109023 Y Y Y 5 24 .02 .00 2.00 362 15 rows selected. SQL> -- |
Sure enough, there are a few (10 statements to be exact with a total of 15 child cursors) that are marked as Bind Aware. However, there are only 3 statements that have multiple child cursors (sql_id: 17uuqnvxmzxhj, 4vb86f36xqc50, g375mcpc30dy5). And for each of those statements, the child cursors all have the same plan (sql_id: 17uuqnvxmzxhj, for example, has 3 children all using plan_hash_value: 3038781757). So even though they are marked Bind Aware, and have multiple child cursors, they are not producing distinct plans for those statements. So even the ones that the optimizer has noticed, do not appear to be providing us any benefit.
But back to the original question. We have many statements that are suffering from bind variable peeking issues that are apparently not being noticed. Why is that? Well I got to thinking about why ACS might be ignoring the statements that I know have this issue. One of the characteristics of these statements is that they have a relatively large number of bind variables. Some of them have as many as a couple of hundred. So I let my mind wander off into programmer land. How would the guys writing the optimizer code deal with a situation where they had a virtually unlimited number of bind variables. My first thought was to just put a hard limit on the number of variables to handle. Histograms have a relatively small number of potential buckets, and since ACS uses a histogram approach, it stands to reason the programmers might have put in a relatively small limit for their first pass. So I went off to test this idea (since this post is already so long I’ll cut right to the chase). There does appear to be a hard limit of 14 bind variables and statements that have more than that are apparently not evaluated for bind sensitivity. Here’s a test case:
> !sql sqlplus "/ as sysdba" SQL*Plus: Release 11.1.0.7.0 - Production on Mon May 11 11:16:06 2009 Copyright (c) 1982, 2008, Oracle. All rights reserved. Connected to: Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production With the Partitioning, OLAP, Data Mining and Real Application Testing options SQL> !cat t14.sql set echo off variable v1 number variable v2 varchar2(30) variable v3 varchar2(30) variable v4 varchar2(30) variable v5 varchar2(30) variable v6 varchar2(30) variable v7 varchar2(30) variable v8 varchar2(30) variable v9 varchar2(30) variable v9 varchar2(30) variable v10 varchar2(30) variable v11 varchar2(30) variable v12 varchar2(30) variable v13 varchar2(30) variable v14 varchar2(30) variable v15 varchar2(30) variable v16 varchar2(30) variable v17 varchar2(30) variable v18 varchar2(30) variable v19 varchar2(30) exec :v1 := 999999; exec :v2 := 'TESTING' exec :v3 := '01-jan-08' exec :v4 := '01-jan-09' exec :v5 := 'Y' exec :v6 := 'X' exec :v7 := 'y' exec :v8 := 'Z' exec :v9 := 'a' exec :v10 := 'b' exec :v10 := 'c' exec :v11 := 'd' exec :v12 := 'e' exec :v13 := 'f' exec :v14 := 'g' exec :v15 := 'h' exec :v16 := 'i' exec :v17 := 'j' exec :v18 := 'k' exec :v19 := 'l' set echo on select avg(pk_col) from kso.little_skew where col1 = :v1 and col2 = :v2 and col3 between :v3 and :v4 and col4 in (:v5,:v6,:v7,:v8,:v9,:v10,:v11,:v12,:v13,:v14) / SQL> @flush_pool SQL> @t14 SQL> @t14 SQL> @t14 SQL> @t14 SQL> SQL> -- 4 execs of the first bind variable set, now let's use a different set of bind variables SQL> -- t14a.sql is the same except v1=1 - which (due to histogram) wants to use a different plan SQL> SQL> @t14a SQL> @t14a SQL> @t14a SQL> @t14a SQL> @t14a SQL> @t14a SQL> @t14a SQL> SQL> -- 7 execs with the new set of bind variables, should give it plenty of info to make it bind aware SQL> -- now a few more with the original set of bind variables SQL> SQL> @t14 SQL> @t14 SQL> @t14 SQL> @t14 SQL> SQL> -- now let's see what we've got SQL> SQL> @find_sql_acs Enter value for sql_text: %v14)% Enter value for sql_id: Enter value for is_bind_aware: SQL_ID CHILD PLAN_HASH_VALUE IBS IBA ISH EXECS ROWS_PROCESSED AVG_ETIME AVG_CPU AVG_PIO AVG_LIO SQL_TEXT ------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- ----------------------------------- 2yk8hbkc4kbd5 0 376960484 N N N 8 8 .18 .18 .00 2,641 select avg(pk_col) from kso.little_ skew where col1 = :v1 and col2 = :v 2 and col3 between :v3 and :v4 and col4 in (:v5,:v6,:v7,:v8,:v9,:v10,: v11,:v12,:v13,:v14) 2yk8hbkc4kbd5 1 3746388338 N Y Y 3 3 .00 .00 .00 15 select avg(pk_col) from kso.little_ skew where col1 = :v1 and col2 = :v 2 and col3 between :v3 and :v4 and col4 in (:v5,:v6,:v7,:v8,:v9,:v10,: v11,:v12,:v13,:v14) 2yk8hbkc4kbd5 2 376960484 N Y Y 4 4 .00 .00 .00 3 select avg(pk_col) from kso.little_ skew where col1 = :v1 and col2 = :v 2 and col3 between :v3 and :v4 and col4 in (:v5,:v6,:v7,:v8,:v9,:v10,: v11,:v12,:v13,:v14) 3 rows selected. SQL> -- As expected, the optimizer has noticed and marked it Bind Aware SQL> -- Now let's try the same thing with 15 bind variables instead of 14 SQL> -- (note: t15 is the same with one more bind variable) SQL> SQL> @t15 SQL> @t15 SQL> @t15 SQL> @t15 SQL> @t15a SQL> @t15a SQL> @t15a SQL> @t15a SQL> @t15a SQL> @t15a SQL> @t15a SQL> @t15 SQL> @t15 SQL> @t15 SQL> @t15 SQL> @find_sql_acs Enter value for sql_text: %v15)% Enter value for sql_id: Enter value for is_bind_aware: SQL_ID CHILD PLAN_HASH_VALUE IOB IBA ISH EXECS ROWS_PROCESSED AVG_ETIME AVG_CPU AVG_PIO AVG_LIO SQL_TEXT ------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- ----------------------------------- 4ndg8w1ga5dth 0 376960484 N N Y 15 15 .17 .16 .00 2,465 select avg(pk_col) from kso.little_ skew where col1 = :v1 and col2 = :v 2 and col3 between :v3 and :v4 and col4 in (:v5,:v6,:v7,:v8,:v9,:v10,: v11,:v12,:v13,:v14,:v15) 1 row selected. SQL> -- no joy! SQL> SQL> -- so now I wondered if it really was just a hard limit or something more complicated SQL> -- so I wrote a little script to count the number of bind variables in Bind Aware statements SQL> SQL> !cat acs_bind_count.sql select distinct sql_id, bind_count from ( select sql_id, child_number, count(*) bind_count from v$sql_bind_capture where sql_id in ( select sql_id from v$sqlarea where is_bind_aware = 'Y') group by sql_id, child_number ) order by bind_count / SQL> @acs_bind_count.sql SQL_ID BIND_COUNT ------------- ---------- 2jmg3n6k2q82x 2 dxjvgtd3stafn 4 ck67mwdmdnaww 8 9pcw6qh83mj69 9 883uvnn2gz36u 10 4ysyd47nkap6d 11 7mygfqgs52au2 12 2744r65xx9h2h 13 2yk8hbkc4kbd5 14 9 rows selected. |
So it looks like there probably is a hard limit. Let’s see if I can disprove that by looking at a couple of production systems. Here’s the output from the same script on four production instances (note: system 1 is that same one that I referenced earlier with the statements with known Bind Variable Peeking issues, where ACS was not noticing them):
-- System 1, Node 2 SQL> @acs_bind_count SQL_ID BIND_COUNT ------------- ---------- 17uuqnvxmzxhj 8 58p0j1q6rmv34 8 5mxqphz5qfs4d 8 g375mcpc30dy5 8 3tfx8fzp64vkb 9 4vb86f36xqc50 9 34x6683rpwtxa 10 dt1v1cmua9cnq 11 ftxa99d89yzz0 11 0qvgb3dyfg539 12 10 rows selected. -- System 1, Node 3 SQL> @acs_bind_count SQL_ID BIND_COUNT ------------- ---------- 5bjg6w9btv3zn 7 17uuqnvxmzxhj 8 6n1790gk5m0hy 8 2pv7g3nutnyq5 9 4vb86f36xqc50 9 11at9nnhrw3w9 10 4p9zp29bcu927 10 4axts2hm73n98 11 ftxa99d89yzz0 11 490gh9uugyqqq 13 10 rows selected. -- System 2, Node 1 SQL> @acs_bind_count SQL_ID BIND_COUNT ------------- ---------- 4rqy85b9r413x 1 7h47mb48s19t3 1 51z6b0kbduf8m 2 djkchp3qwadu1 2 9g5ng8xjj4h05 3 amyvvzzjccvsg 3 cuv2pyzvz7b4z 3 d68jnfnqs6uh7 3 dkc2kbj7kdsu7 3 fxmfhkkhcrdj6 3 6196v5td8pk4n 4 9m63xcj6sbswu 4 0mn3xx02ww6pd 5 c7k3pwbjg4d1d 5 dy98ajwqc8s2x 5 3qh6yw37n8m1a 6 3xxgg248shg62 6 83v17f53rnzcv 6 a2271k4f7j211 6 06n7rk2jw3rsy 7 f4xr9x5wh46zt 7 48ryzfg5dxpqn 8 an9114vtxukz2 8 23 rows selected. -- System 2, Node 2 SQL> @acs_bind_count SQL_ID BIND_COUNT ------------- ---------- 4rqy85b9r413x 1 7h47mb48s19t3 1 gvj749s4654hm 1 51z6b0kbduf8m 2 6qwznvjfajh7t 2 djkchp3qwadu1 2 2mhfdtyrvhz3c 3 92a7wu0891bjk 3 9g5ng8xjj4h05 3 9p9gsakw5qyrg 3 amyvvzzjccvsg 3 bs63sfxynwtc6 3 cuv2pyzvz7b4z 3 d68jnfnqs6uh7 3 dvh3d8g2f844j 3 0341h5ytqbv7k 4 ... gj0rzh6xw2msp 4 grvh9mmkynm4u 4 0mn3xx02ww6pd 5 7ys2u732cj1ag 5 9kfj6kj32p7ku 5 dy98ajwqc8s2x 5 83v17f53rnzcv 6 d79xsp0utuvm2 6 gqkx5bsg1zfzc 6 4q3n2wwqtghma 7 f4xr9x5wh46zt 7 g7c90sr77bb78 7 7gb24h57r0spb 8 9zcy2yz537z41 8 an9114vtxukz2 8 7uwy0uxauuabz 9 80xmux45pvkrr 9 73 rows selected. |
So it appears that there probably is a hard limit and that it probably is 14 (although there certainly could be a more complicated algorithm in play). None of the 4 production systems I checked had a single statement that was marked bind aware with more than 14 bind variables.
So here are a few closing thoughts:
To me, ACS doesn’t seem to be completely cooked yet. In fact, it seems to be somewhat of a futile attempt, since in the very best case, one execution with a bad plan would be necessary for the optimizer to recognize that a bind variable peeking issue existed. This wouldn’t be so bad if the information was persisted, so that the same “learning” process wouldn’t have to be endured if/when a statement gets flushed from the shared pool. This issue alone is enough to keep this feature from being relied upon in situations where performance is critical. In my opinion, the best approach remains unchanged from version 10, that being the judicious use of literals where necessary to prevent plan instability due to bind variable peeking.
My impression of it is not completely negative though. It’s certainly better than the old approach of pick a plan and stick with it. And for systems that use a limited number of binds per statement where performance swings are not as dramatic and/or performance is not as critical, it seems to work pretty well.
Here are some other references:
OptimizerMagic Blog - Good basic description of ACS
OptimizerMagic Blog - Update on ACS
Ric Van Dyke - Intelligent Cusor Sharing in 11.1.0.6
Ric Van Dyke - Intelligent Cusor Sharing in 11.1.0.7
Section on ACS in Troubleshooting Oracle Performance By Christian Antognini
