Every quarter I download the latest patch set from Oracle’s support site by using the Recommended Patch Advisor. But the January 2020 patch sets did not show up. The RPA still recommends the October 2019 patch sets. The Recommended Patch Advisor is one of the options under the Patches and Updates tab in Oracle’s support site. I tried searching Oracle’s support site and Googling but did not find any answers. I am sure that the information is out there somewhere but the way I was searching for it did not find it. So, I thought I would post a quick note about it. The short answer is that you should use this Oracle support document to find the latest patch sets and not the Recommended Patch Advisor:
Master Note for Database Proactive Patch Program (Doc ID 756671.1)
To find this out I had to open an SR with Oracle Support. They quickly identified this document which explained the situation:
My Oracle Support: Patch and Health Recommendations No Longer Supported (Doc ID 2644769.1)
Note 2644769.1 seems to say that the Recommended Patch Advisor will continue to refer to the October 2019 patches until Oracle removes the RPA from their support site in May.
The funny thing is that I knew we had an internal document that a coworker and I had both contributed to that describes how to download the latest patch set and apply it to a database to create a tar or zip that we could use to deploy a new database. I decided to modify that document to refer to note 756671.1 and remove references to the RPA. To my surprise my coworker had already included note 756671.1 months ago in our instructions and not the RPA. I think that Oracle support must have recommended the note some time ago, but I was still using the advisor. I guess you learn something new every day.
Anyway, note to self: don’t use the Recommended Patch Advisor to find the quarterly patch updates. Use note 756671.1.
Wrote a quick and dirty script to scan the listener log for incoming connections and produce a count of how many connections came from which host. Here is the URL:
All it does is hack out the ip address from the second HOST= entry of the lines in the listener log that have HOST= in them. Then it uses the Python function socket.gethostbyaddr to get the hostname for those that can be looked up this way.
Counts the number of lines for a given ip address and sorts them from most to least connections. Might be useful to someone.
I keep forgetting that I need to bounce both the listener and the database after changing the oracle user’s group membership, so I am writing a quick note to myself here. This is the second time I have been tripped up by something like this and I spent way too much time figuring it out again.
We have some PL/SQL code that writes to files on a database server. The most recent issue was using DBMS_XSLPROCESSOR.CLOB2FILE to write a clob to a file in a certain directory. This got the following error:
ORA-22288: file or LOB operation FILEOPEN failed
Permission denied
I tried writing to the same directory using UTL_FILE.FOPEN with write permission to create a new file. I got this error:
ORA-29283: invalid file operation: cannot open file [29435]
I got a Linux admin to add the oracle Linux user to the correct group and I bounced the database and the error did not go away. Then I bounced the listener and the database, and the errors were resolved.
NOTE TO SELF: if you add the oracle user to a new group to allow PL/SQL to write to a directory using group permissions bounce the database and the listener!
Bobby
P.S. This is on Oracle 19c on Redhat Linux 7 but should apply to a wide range of Oracle versions and Unix like platforms.
Last night, the plan change monitor script we have setup on one of our production databases alerted us about query with a SQL Analyze hint. It looked weird.
The query has sql_id 48tfz5d37xk28 and starts like this:
/* SQL Analyze(3141,1) */ select ...
The weird thing is the output of my sqlstat.sql script for this sql_id value:
It looks like one of the database’s built in processes was running this query with various plans. Plan_hash_value 3992115155 tripped the alert. I guess it was 10 times as long as plan 3597180003. The plan change monitor script could be improved in many ways to eliminate false positives like this, but I just added a condition to exclude all queries run by user SYS:
258c258,259
< m.sql_id not in ('dkqs29nsj23jq','58r2wgh5xx1bg','3m2su959r6tp8','3z60x9386n1v8','bx81s3m9zxutb','czwbdwxx5aqsk','001wbydnwaa7n','6quugay8yt73u')
---
> m.sql_id not in
('dkqs29nsj23jq','58r2wgh5xx1bg','3m2su959r6tp8','3z60x9386n1v8','bx81s3m9zxutb','czwbdwxx5aqsk','001wbydnwaa7n','6quugay8yt73u')
and s.username <> 'SYS'
This is the first time I remember seeing something like this cause an alert, but the workaround was easy.
I forget that Oracle’s AWR only records the top 30 SQL statements in each snapshot by default. I am not sure how long this link will last but here is a 19c manual page describing the default: 19c manual – see the topnsql setting. A lot of my query tuning assumes that the problem query is in the AWR but for very efficient queries on active systems they may mysteriously disappear or be absent from the AWR. It sometimes takes me a while to remember that the snapshots only include a fixed number of SQLs.
I use my sqlstat.sql query to look at a history of a particular sql_id’s executions. Often it shows the query running faster on one plan_hash_value than another. Then I look at why the sql_id changed plans. But what about when the good plan does not show up at all? Several times I have looked at sqlstat.sql output and thought that a query had not run in the past with an efficient query even though it had. It had run so efficiently that it was not on the report, so it looked like the query was a new, slow, SQL statement.
Often I will fix a query’s plan with a SQL Profile and rerun sqlstat.sql on a busy system after manually running dbms_workload_repository.create_snapshot to capture the most recent activity and the problem query with the new plan will not show up. Usually I remember that it is not in the top 30 queries and that is why it is missing but sometimes I forget. Here is a partial sqlstat.sql output showing a long running SQL disappearing after I fixed its plan on Wednesday:
SQL_ID PLAN_HASH_VALUE END_INTERVAL_TIME EXECUTIONS_DELTA Elapsed Ave ms
------------- --------------- --------------------- ---------------- ------------------
acn0557p77na2 3049654342 12-FEB-20 05.00.01 AM 1 16733.256
acn0557p77na2 3049654342 12-FEB-20 06.00.03 AM 2 49694.32
acn0557p77na2 3049654342 12-FEB-20 07.00.53 AM 6 47694.527
acn0557p77na2 3049654342 12-FEB-20 08.00.54 AM 11 50732.0651
acn0557p77na2 3049654342 12-FEB-20 09.00.33 AM 15 53416.5183
acn0557p77na2 3049654342 12-FEB-20 10.00.43 AM 21 86904.4385
acn0557p77na2 3049654342 12-FEB-20 11.00.02 AM 27 84249.859
acn0557p77na2 3049654342 12-FEB-20 12.00.20 PM 27 125287.757
acn0557p77na2 3049654342 12-FEB-20 01.00.36 PM 69 156138.176
Sometimes I query the V$ tables to verify it is currently running a good plan. Here is example output from vsqlarea.sql showing the good plan running today.
This is just a quick note to me as much as anyone else. A query that is missing from an AWR report or my sqlstat.sql report may not have run at all, or it may have run so well that it is not a top 30 query.
Quick note. During my 11.2.0.4 to 19c upgrade that I have been writing about we found a difference in behavior of DBMS_UTILITY.FORMAT_CALL_STACK. I tested it on several versions, and it switched in 12.2. Now it puts the procedure name within the package in the stack.
Old output:
----- PL/SQL CALL STACK -----
OBJECT LINE OBJECT
HANDLE NUMBER NAME
0X15BFA6930 9 PACKAGE BODY MYUSER.MYPKG
0X10C988058 1 ANONYMOUS BLOCK
New output:
----- PL/SQL CALL STACK -----
OBJECT LINE OBJECT
HANDLE NUMBER NAME
0XA796DF28 9 PACKAGE BODY MYUSER.MYPKG.MYPROC
0X7ADFEEB8 1 ANONYMOUS BLOCK
Test code:
select * from v$version;
CREATE OR REPLACE PACKAGE MYPKG
AS
PROCEDURE MYPROC;
END MYPKG;
/
SHOW ERRORS
CREATE OR REPLACE PACKAGE BODY MYPKG
AS
PROCEDURE MYPROC
IS
BEGIN
DBMS_OUTPUT.PUT_LINE(UPPER(dbms_utility.format_call_stack));
END MYPROC;
END MYPKG;
/
SHOW ERRORS;
execute mypkg.myproc;
show errors;
Might be useful to someone else. We had some code that depended on the package name being the last thing on its line, but the new version includes the name of the procedure after the package name.
I wanted to install the latest Python on Linux in a low powered user’s home directory and not have the install interfere with the Python that comes with Linux. I wanted my own local copy of Python that I could install Python packages to without interfering with anything else. I was willing to use root to install the needed Linux packages, but everything else was done with my low powered user.
I did a yum update on my Oracle Enterprise Linux 7.7 install before I started to get everything on the latest version. As root I used yum to install the Linux packages I needed to install Python 3.8.1 from source:
I must have already installed these on this VM. I did the rest of these steps as my low powered user “bobby”. The next thing I did was download the latest Python source, the 3.8.1 version. I had to use the -k option to get around certificate issues:
[bobby@pythonvm ~]$ curl -k -O https://www.python.org/ftp/python/3.8.1/Python-3.8.1.tgz
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 22.8M 100 22.8M 0 0 7830k 0 0:00:02 0:00:02 --:--:-- 7828k
For some reason I had to do this twice. The first download failed. Next I gunzipped and untarred this archive under my home directory:
I created a directory called “python” under my home directory to use as the top-level directory for my Python install. This directory tree will hold the binaries and any Python packages that I install.
[bobby@pythonvm ~]$ mkdir python
After changing directory to where I untarred the source files I configured the Python make and install to use the directory I just created as a “prefix”:
[bobby@pythonvm ~]$ cd Python-3.8.1
[bobby@pythonvm Python-3.8.1]$ pwd
/home/bobby/Python-3.8.1
./configure --prefix=/home/bobby/python
config.status: creating Misc/python-embed.pc
config.status: creating Misc/python-config.sh
config.status: creating Modules/ld_so_aix
config.status: creating pyconfig.h
creating Modules/Setup.local
creating Makefile
If you want a release build with all stable optimizations active (PGO, etc),
please run ./configure --enable-optimizations
Then I did the make and make altinstall from the same directory:
So, now Python 3.8.1 is installed in /home/bobby/python but I want to put the bin directory in the path so I can run python or pip and by default have them be this version. The install created python and pip as python3.8 and pip3.8 but I created links to them so that I could access them without 3.8 at the end of their names:
[bobby@pythonvm Python-3.8.1]$ cd /home/bobby/python/bin
[bobby@pythonvm bin]$ ls -al
total 16704
drwxr-xr-x. 2 bobby bobby 4096 Feb 10 15:36 .
drwxrwxr-x. 6 bobby bobby 52 Feb 10 15:36 ..
-rwxrwxr-x. 1 bobby bobby 109 Feb 10 15:36 2to3-3.8
-rwxrwxr-x. 1 bobby bobby 249 Feb 10 15:36 easy_install-3.8
-rwxrwxr-x. 1 bobby bobby 107 Feb 10 15:36 idle3.8
-rwxrwxr-x. 1 bobby bobby 231 Feb 10 15:36 pip3.8
-rwxrwxr-x. 1 bobby bobby 92 Feb 10 15:36 pydoc3.8
-rwxr-xr-x. 1 bobby bobby 17075312 Feb 10 15:35 python3.8
-rwxr-xr-x. 1 bobby bobby 3095 Feb 10 15:36 python3.8-config
[bobby@pythonvm bin]$ ln -s python3.8 python
[bobby@pythonvm bin]$ ln -s pip3.8 pip
Then I added/home/bobby/python/bin to the front of the path to keep these new python and pip links ahead of the python links or binaries in the rest of the path.
[bobby@pythonvm bin]$ cd
[bobby@pythonvm ~]$ vi .bashrc
export ORACLE_HOME=/home/oracle/app/oracle/product/12.1.0/client_1
export PATH=$PATH:$ORACLE_HOME/bin
export LD_LIBRARY_PATH=/home/oracle/app/oracle/product/12.1.0/client_1/lib
export PATH=/home/bobby/python/bin:$PATH
~
~
~
~
~
~
".bashrc" 17L, 451C written
I logged out and in as bobby and tried python and pip to see that they were the correct version:
[bobby@pythonvm ~]$ python
Python 3.8.1 (default, Feb 10 2020, 15:33:01)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-39.0.3)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>>
[bobby@pythonvm ~]$ pip list
Package Version
---------- -------
pip 19.2.3
setuptools 41.2.0
WARNING: You are using pip version 19.2.3, however version 20.0.2 is available.
You should consider upgrading via the 'pip install --upgrade pip' command.
[bobby@pythonvm ~]$
Finally, I updated pip just to show that we can update something in this new install. Then I installed numpy to see if I could install a new package.
This is a quick and dirty post, but I want to remember these steps for myself and it might be helpful for someone who uses Redhat/Centos/OEL.
This week I investigated an issue with a query that was suddenly a lot slower in one test environment than another. It runs about 2 seconds in the good case as well as in production. But it was now running more than 10 seconds which is painfully slow through the GUI and impacting the team’s ability to finish a software release. I was able to figure out that the query was running a worse plan and get it to run the good plan and helped the team finish their testing.
I thought I would write this blog post documenting the tools that I used and my reasoning while trying to resolve the issue. This post may be redundant with some of my other posts because they document similar tools and approaches, but I thought it could not hurt to put together a complete example. I considered just writing about one part of the process to focus in on that, but I thought I would write a longer post instead that shows the overall process with details along the way. This blog is my experience as an Oracle Database Administrator/Architect, and I work for an individual company so my experiences may not apply to everyone else’s situation. You may work somewhere that has licensed different versions or features of the Oracle database so your choices would be different. But I still can put out there what I am doing and let others apply it to their situation as they can. Also, there are lots of very sharp and hardworking Oracle people out there that write about these same topics and have contributed their own tools to the Oracle community so I wonder about the value of putting my tools on GitHub and writing about how I use them. Why not use their tools and their approaches? Maybe they will work better? Sure, but I know that my approach and tools work well for me. Also most of the ideas I use came from books, talks, and posts by the same sharp people that I have in mind so my approach really reflects my translation of ideas that are out there in the Oracle community with additions of my own so it is not a choice of me versus them. Anyway, I thought I would work through this example on this post so others can review it and find value where they can. Inevitably I will get a lot out of writing it down myself and it will help me remember what I was thinking at this time when I read this post in the future. Hopefully others will benefit as well.
Here is what I knew when I first looked at the problem. A coworker emailed me the SQL for the problem query and verified that the tables in both test environments were about the same size. Sometimes our test environments can be much smaller than production and different from each other in terms of data volume. Usually, when I get a performance question, I ask for two things: the name of the database and the date and time that the issue stopped and started, including time zone. In this case I knew the database name but not the time frame. But I figured that they had been working on it during the current day, so I just got an AWR report for that day from 8 am to present assuming they worked roughly in working hours.
Fortunately, the AWR report had the problem query as the top query so I did not have trouble finding it. It helped that I already knew the text of the SQL statement. The main thing I got from the AWR report at first is the SQL_ID value. I already had the SQL text, but it helps to get the SQL_ID to plug into other scripts I used.
Trimmed down version of AWR report showing problem SQL_ID 4n5ssud3fgsyq
My next step was to run my sqlstat.sql script to see if the problem query, 4n5ssud3fgsyq, has changed plans. Not sure why I did not use the updated version, sqlstat3.sql. I manually updated the query with the SQL_ID value:
where ss.sql_id = '4n5ssud3fgsyq'
and then I looked for plan changes in the output:
I use the PLAN_HASH_VALUE as a name for the plan. I verified that the good plan, 65249283, was run on the other test server that was fine and that it was used in production. So, I had to figure out why the plan changed to 2414495514 on this one test server.
At some point in this process I paused and considered using a SQL Profile to just force the plan back to the good plan. I have written a number of posts about SQL Profiles but this did not seem like a situation where one made sense. Why not spend a couple hours trying to figure out why the plan changed? If I use a SQL Profile, then I will have to migrate the profile to production. And if the query changes the tiniest bit in a future release the SQL Profile will no longer be valid. I have one situation where we have a partitioned table with some almost empty partitions and queries that access the table with the partitioning column passed into the where clause as bind variables. I have been using SQL Profiles to handle that situation on this particular set of production and test databases, but it is a big pain. The last release I had to redo 7-9 SQL Profiles. I’m probably going to have to bite the bullet and find another way around it rather than updating profiles when a release modifies the affected queries. Probably will have to fake the stats on the empty partitions or see if they can be removed. I doubt I will be able to get development to take the partitioning columns out of bind variables. I guess some set of hints might work as well. But anyway, the point is that in this situation that this particular post is about I decided to dig into it and try to find the underlying problem instead of using a SQL Profile band aid.
Having decided to move forward with figuring out why the plan changed I next looked at the two plans. I used my getplans.sql script to extract the plans from the AWR based on SQL_ID and PLAN_HASH_VALUE. I just ran this when logged into the problem database using sqlplus:
@getplans 4n5ssud3fgsyq
I noticed that the slow plan did full table scans on two tables that the fast plan did index lookups on.
SQL_ID 4n5ssud3fgsyq
--------------------
...
Plan hash value: 65249283 - GOOD PLAN
----------------------------------------------------------
| Id | Operation | Name |
----------------------------------------------------------
...
| 16 | TABLE ACCESS BY INDEX ROWID | TABLE1 |
| 17 | INDEX RANGE SCAN | TABLE1_2 |
...
| 47 | TABLE ACCESS BY INDEX ROWID | TABLE2 |
| 48 | INDEX UNIQUE SCAN | TABLE2_0 |
Plan hash value: 2414495514 - BAD PLAN
----------------------------------------------------------
| Id | Operation | Name |
----------------------------------------------------------
...
| 16 | TABLE ACCESS FULL | TABLE1 |
...
| 48 | TABLE ACCESS FULL | TABLE2 |
----------------------------------------------------------
I also looked at the Segments part of the AWR report and TABLE2 was at the top of the logical and physical reads reports.
Edited picture of AWR report. Top Table is TABLE2 in execution plans.
So, at this point in my attempt to understand why the plan changed I have the clue that the bad plan has full table scans, and that one of the two tables with the full scans has a substantial percentage of the overall I/O on the database. So, I had two ideas in mind. First, I wanted to check that the two tables had the same indexes as on the working system. Maybe the indexes got dropped during some development work. If the indexes were there, I could just look at the optimizer statistics for the two tables and compare them to what they have on the working test system and production.
I use my optimizer statistics scripts to look at indexes and information that the optimizer uses to choose the best plan. I know that there are other ways to get the same information, such as in a graphical program like Toad or OEM, but I like having scripts that give me exactly the information that I know is important. It is a little clunky to use but not difficult. The top level script is all.sql and I usually comment out the calls to scripts that produce an excessive amount of output. I probably should put all.sql out like this in GitHub:
Seeing all the histogram information for every partition on a table with thousands of partitions is a lot of output and not really needed. If you have many subpartitions you might comment out tabsubpartstats.sql also. To use these scripts you just put your table owners and names in tablelist.sql and run all.sql. The script indexstats.sql listed out the indexes and statistics on them and indexcolumns.sql showed what columns the indexes were on. Unfortunately, in this case the indexes and their columns were the same for the two full scan tables on both test environments and on production. So the switch of the plan to full scans was not due to the lack of indexes. These tables were not partitioned so the tablestats.sql and columnstats.sql reports were the main ones I looked at to compare statistics. Maybe one of them had very out of date or even missing statistics. Unfortunately, the statistics on the two tables looked pretty similar on all three databases. So, my look at the indexes and statistics of the two tables with full scans on the bad plan did not explain the change in plan.
At some point in this process I decided to run the problem query to see if it gave me clues about the plan change. I am putting this post together remembering the steps I went through, but I may not have the exact chronological order. But I should be able to capture the main things I thought about in an order that makes sense. In order to test the query, I needed to come up with values for the bind variables. I used my bind2.sql script to extract some of the bind variable values on the problem test database. I edited bind2.sql to have the problem SQL_ID, 4n5ssud3fgsyq. I chose the most recent two sets of bind variable values to plug into the problem query. I extracted the query text using dumpsql.sql and used Toad to format it nicely. Then I plugged the formatted query into my test2.sql script. To use test2.sql you need to replace the select statement that is there on GitHub:
SELECT /*+gather_plan_statistics*/ * from dual where dummy <> ' ';
with your own query. But you have to make sure that the gather_plan_statistics hint stays in the select statement. There are different ways to handle bind variables and their values in a test script like this but in this case, I manually edited the test script replacing the bind variables with literals that I got from bind2.sql. I chose two sets because one set had nulls for a couple of values so I thought the nulls might cause the bad plan. There might be some odd choice of bind variable values on this test system that was causing the bad plan, or so I thought. But I ran the test2.sql script as described and it ran slow on the one test system for both sets of bind variable values and fast on the other.
My tests with the bind variable values showed that the problem was not related to those sets of bind variable values and that even with literals in place the problem query runs slow on the problem test database. The plan was not the same as the bad plan I had extracted for the original query, but it still had the two full scans. In the same way, my tests had index lookups on the two tables on the other test environment even with the literals replacing the bind variables. So, all this really proved so far was that the two sets of bind variable values that I chose did not affect the problem.
To go further I started looking at the output of test2.sql. The way I get the plan here shows estimated and actual rows. If I find discrepancies in estimated and actual row counts that could point me to where the problem lies. This query in test2.sql dumps out the plan in a format that shows estimated and actual rows:
select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS'));
Here is the edited output for the bad plan for the two full scan tables:
But I am not sure what this is telling me. For TABLE1 the optimizer expected 1593K rows and got 3186K. It expected 1.5 million rows but got 3 million. Similarly, about 1.6 million and 3.3. But how does this help me figure out what the problem is? I looked at the good plan in the same way but was equally puzzled:
-------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
-------------------------------------------------------------------------------------
...
| 16 | TABLE ACCESS BY INDEX ROWID | TABLE1 | 0 | 1 | 0 |
|* 17 | INDEX RANGE SCAN | TABLE1_2 | 0 | 1 | 0 |
...
| 47 | TABLE ACCESS BY INDEX ROWID | TABLE2 | 0 | 1 | 0 |
|* 48 | INDEX UNIQUE SCAN | TABLE2_0 | 0 | 1 | 0 |
-------------------------------------------------------------------------------------
Here the estimated rows is 1 but actual is 0. But how do I use that to figure out what changed the plan on the one test environment? Then I got the key insight to solve this whole thing. It was not new to me, but I don’t do this every day and it was a good reminder and I wanted to blog about it. I considered blogging about just this one point and maybe I should edit this post down to just this idea. But then I wouldn’t put out the overall steps and tools I used to get to this point. The key insight was to use a full set of outline hints to force the bad plan and good plan to run in both environments and to compare the estimated and actual rows with each plan. I am not sure how this post will end but that is the most important point. Presumably the optimizer considered both plans and gave each of them a cost and chose the lowest cost plan to run. On our problem system the much slower plan has a lower cost than the faster one. The opposite is true on the working systems. What we want is to force the query to run the bad plan both places and see where the estimated rows differ. Then do the same for the good plan. A key idea that I learned about query tuning from people like Tom Kyte, Jonathan Lewis, and others is that the optimizer chooses a bad plan because of bad row estimates or bad estimates of the cost per row of certain operations. Most of the time it comes down to bad row estimates. So, which table is getting the bad row estimates and why? My way of finding it out in this case was to use outline hints to force the same plan to run on both databases and then use the test2.sql output to look at estimated and actual rows.
I was not sure how to extract the plans from the AWR and get the outline hints. I’m sure there is a way but in my hurry I ended up just using my plan.sql script to use EXPLAIN PLAN to get the plan and pull the outline hint from there. I checked the plans to make sure they had the same index versus full scan issues as I have been seeing. At the end of the output for plan.sql is an outline hint section that starts like this:
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
You just copy and paste everything from /*+ through */ as your hint. I put this in my test2.sql script that I had used before with one set of the bind variable values as constants and I merged the gather_plan_statistics hint with the outline hint so the query started like this:
This way the gather_plan_statistics hint collects the actual and estimated rows and the outline hint forces the plan to be used.
At first, I looked at the estimated and actual rows on the good and bad plans on both systems for the two tables that switched to full scans on the problem system.
Good DB Bad Plan Full Scan Tables
------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
------------------------------------------------------------------------------------
...
| 16 | TABLE ACCESS FULL | TABLE1 | 1 | 1590K| 1593K|
...
| 48 | TABLE ACCESS FULL | TABLE2 | 1 | 1957K| 1957K|
------------------------------------------------------------------------------------
Bad DB Bad Plan Full Scan Tables
Plan hash value: 1397976319
------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
------------------------------------------------------------------------------------
...
| 16 | TABLE ACCESS FULL | TABLE1 | 1 | 1593K| 1593K|
...
| 48 | TABLE ACCESS FULL | TABLE2 | 1 | 1628K| 1672K|
------------------------------------------------------------------------------------
Good DB Good Plan Full Scan Tables
-------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
-------------------------------------------------------------------------------------
...
| 16 | TABLE ACCESS BY INDEX ROWID | TABLE1 | 16 | 1 | 18 |
|* 17 | INDEX RANGE SCAN | TABLE1_2 | 16 | 1 | 18 |
...
| 47 | TABLE ACCESS BY INDEX ROWID | TABLE2 | 12 | 1 | 12 |
|* 48 | INDEX UNIQUE SCAN | TABLE2_0 | 12 | 1 | 12 |
-------------------------------------------------------------------------------------
Bad DB Good Plan Full Scan Tables
-------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
-------------------------------------------------------------------------------------
...
| 16 | TABLE ACCESS BY INDEX ROWID | TABLE1 | 16 | 1 | 18 |
|* 17 | INDEX RANGE SCAN | TABLE1_2 | 16 | 2 | 18 |
...
| 47 | TABLE ACCESS BY INDEX ROWID | TABLE2 | 12 | 1 | 11 |
|* 48 | INDEX UNIQUE SCAN | TABLE2_0 | 12 | 1 | 11 |
-------------------------------------------------------------------------------------
No obvious pattern shows up on these to me. It seems like the optimizer has the same estimates for these two tables on both databases for both plans. But then I got the second key idea: look at the other tables. It is typical when a plan switches to a full scan for there to be something wrong with that table’s stats. But nothing pointed to that in this situation. So, I got the idea of stepping back and looking at the other tables. That led to me finding the actual issue. Two tables that were not the ones with the full scans had different degrees of discrepancies between actual and estimated rows on the bad and good databases.
Good DB Bad Plan Other Tables
-------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
-------------------------------------------------------------------------------------
...
| 12 | TABLE ACCESS BY INDEX ROWID | TABLE3 | 1 | 3 | 6 |
|* 13 | INDEX RANGE SCAN | TABLE3_1 | 1 | 3 | 6 |
| 14 | TABLE ACCESS BY INDEX ROWID | TABLE4 | 6 | 55 | 11 |
|* 15 | INDEX RANGE SCAN | TABLE4_1 | 6 | 55 | 11 |
...
-------------------------------------------------------------------------------------
Bad DB Bad Plan Other Tables
-------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
-------------------------------------------------------------------------------------
...
| 12 | TABLE ACCESS BY INDEX ROWID | TABLE3 | 1 | 22 | 6 |
|* 13 | INDEX RANGE SCAN | TABLE3_1 | 1 | 22 | 6 |
| 14 | TABLE ACCESS BY INDEX ROWID | TABLE4 | 6 | 153 | 11 |
|* 15 | INDEX RANGE SCAN | TABLE4_1 | 6 | 153 | 11 |
...
-------------------------------------------------------------------------------------
Good DB Good Plan Other Tables
----------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
----------------------------------------------------------------------------------
...
| 12 | TABLE ACCESS BY INDEX ROWID | TABLE3 | 1 | 3 | 6 |
|* 13 | INDEX RANGE SCAN | TABLE3_1 | 1 | 3 | 6 |
| 14 | TABLE ACCESS BY INDEX ROWID | TABLE4 | 6 | 55 | 11 |
|* 15 | INDEX RANGE SCAN | TABLE4_1 | 6 | 55 | 11 |
----------------------------------------------------------------------------------
Bad DB Good Plan Other Tables
----------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
----------------------------------------------------------------------------------
...
| 12 | TABLE ACCESS BY INDEX ROWID | TABLE3 | 1 | 22 | 6 |
|* 13 | INDEX RANGE SCAN | TABLE3_1 | 1 | 22 | 6 |
| 14 | TABLE ACCESS BY INDEX ROWID | TABLE4 | 6 | 153 | 11 |
|* 15 | INDEX RANGE SCAN | TABLE4_1 | 6 | 153 | 11 |
...
----------------------------------------------------------------------------------
Looking at these two tables the bad database had significantly higher row estimates than the good database and the actual rows was the same on both. Errors in estimated rows multiply through the plan as joins are considered. So, at this point I thought it could be that the estimates on these tables (TABLE3 and TABLE4) led to the switch to full scans on TABLE1 and TABLE2. So, I went back to my optimizer statistics scripts and took TABLE1 and 2 out of tablelist.sql and put TABLE3 and 4 in and looked for differences. I found the difference in the columnstats.sql output. The NUM_BUCKETS value for the first column of TABLE3 and TABLE4 was 1 on the bad database and 254 or 255 on the good. So, column statistics had been gathered differently on these two tables on the bad database at some point. Maybe in the process of testing or developing on this system statistics were gathered in a non-standard way. The database in question uses Oracle’s default statistics job. (This is 11.2.0.3, HP Unix Itanium by the way). So, I thought I would try gathering statistics on the two tables with dbms_stats.gather_table_stats with default options because that would be similar to what the default stats job would do. I did something like this:
After gathering stats on the two tables I verified that the first column of each had a 254/5 bucket histogram. Then I just tested the problem query on both, and they ran the same fast plan. Then the development team tested through the application and verified that it was back to normal. I flushed the shared pool before turning it over to them in case the bad plan was cached.
This problem was a little tricky because the stats were wrong on two tables that were not the ones that switched to full scans. A lot of times the situation is simpler such as a table is missing statistics altogether. But I thought it would be helpful to work through a description of the process that I took to get to that point and the tools that I used. The key point is the one I put in bold above which is to look at the estimated and actual rows for the same plan on both databases and look for differences. Once I did that it was just a matter of finding the tables with the different estimates on the two dbs. That led me to look at their statistics and to regather them in a better way. It took a little time to figure this out, but it was nice to find the problem and do the least amount of change necessary to resolve the issue instead of just randomly trying things. Sometimes people will just gather stats on all the tables in the query. That probably would have worked here if they gathered them in the right way. Or you could just use a SQL Profile and forget trying to figure out why the new plan popped up. But it was worthwhile to understand why the plan changed in this case. For one thing I was concerned whether the same plan change would happen in production, so I wanted to know why it changed on the test environment. Knowing that the two tables had statistics gathered on them in a way that we would not use in production I have more confidence that prod is fine. There really is value in digging into why a query’s plan has changed but it does take some work. Often the bad plan is a result of a bad row estimate in some part of the plan and it makes sense to track down which table has the bad row estimate and dig into why the estimate was off. In many cases bad row estimates relate to how and when statistics were gathered on the problem table as was the case with our two tables in this situation.
P.S. sqlstat3.sql no longer exists. Here is my post about how I merged my sqlstat scripts:
I have not yet had time to build a test case and prove this out, but I wanted to document one last bug that we found so far in our 11.2.0.4 to 19c upgrade. We tried copying a bunch of partitioned tables on our source database to the new one using Datapump Import (impdp) over a database link. We got a boatload of errors like this:
There are many Oracle bugs like this, but they seem to have been fixed in 11.2.0.4. For example:
Bug 12591399 – ORA-600[qesmagetpamr-nullctx] / ORA-14091 with distributed query with local partition table (Doc ID 12591399.8)
Puzzling. We ended up just exporting to disk and that has worked well so no big deal, but I wonder if this is some sort of recession of a fixed bug.
Anyway, I am off for the rest of the year. This should be my last post unless I mess with Nethack over vacation and post something about that. I hope everyone out there has a good new year.
Bobby
P.S. Created a simple partitioned table with 2 partitions and 100 rows in each one. I got the error importing over a link from 11.2.0.4 to 19c. It worked perfectly going from 11.2.0.4 to 11.2.0.4. Same source table. Parfile:
CREATE TABLE test
(
PART_COL NUMBER,
data NUMBER
)
PARTITION BY RANGE (PART_COL)
(
PARTITION PART_COL_1 VALUES LESS THAN (100),
PARTITION PART_COL_2 VALUES LESS THAN (200)
)
;
PPS. Works fine going from 11.2.0.4 to 18c. Going to try a different 19c database just to be sure it isn’t the one that has the problem.
PPPS. Definitely a 19c bug. It fails on two different 19c databases but not on 18c. In every case source is same 11.2.0.4 database and same small partitioned table.
1/6/2020 update – created SR. Trying to be a good Oracle community citizen.
Bug is already fixed. Patch 30321076. Oracle is way ahead of me!
