Bobby Durrett's DBA Blog

Subscribe to Bobby Durrett's DBA Blog feed
Oracle database performance
Updated: 3 hours 54 min ago

Optimizer bug fix makes a query run more than 3 times slower

Wed, 2017-04-12 15:39

I’m working on an 11.1.0.7 to 11.2.0.4 upgrade and found a handful of queries that run more than 3 times longer on 11.2.0.4 than 11.1.0.7. The data and optimizer statistics are very similar on the two test databases. I’m pretty sure that an optimizer bug fix caused this difference. So, the irony is that a fix to the optimizer that we get with the upgrade to the very stable 11.2.0.4 release is causing a 3x slowdown in the query.

For my testing I’m using the gather_plan_statistics hint and this query to dump out the plan after executing the query:

select * from table(dbms_xplan.display_cursor(null,null,’ALLSTATS’));

I used an outline hint to force the 11.2.0.4 plan to run under 11.1.0.7 and then I looked at the estimated and actual row counts to find a discrepancy. I found one table with estimated row counts that did not look correct on 11.1.0.7 but made sense on 11.2.0.4.

11.1.0.7

---------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem |  O/1/M   |
---------------------------------------------------------------------------------------------------------------------------------------------------------
|* 29 |           TABLE ACCESS BY INDEX ROWID  | MY_TABLE                  |     17 |      1 |      0 |00:00:07.34 |   96306 |       |       |          |
|* 30 |            INDEX RANGE SCAN            | MY_TABLE_PK               |     17 |     16 |    102 |00:00:01.20 |   96255 |       |       |          |

11.2.0.4

---------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem |  O/1/M   |
---------------------------------------------------------------------------------------------------------------------------------------------------------
|* 29 |           TABLE ACCESS BY INDEX ROWID  | MY_TABLE                  |     17 |      8 |      0 |00:00:07.44 |   96306 |       |       |          |
|* 30 |            INDEX RANGE SCAN            | MY_TABLE_PK               |     17 |     17 |    102 |00:00:01.22 |   96255 |       |       |          |

After the range scan in step 30 in the plan in 11.1.0.7 you have an estimate of 16 rows but the table access in step 29 has an estimate of only 1. In 11.2.0.4 the estimate for step 29 is 8 rows.  Given the optimizer statistics, the optimizer should have estimated 8 rows step 29 in 11.1.0.7. It appears that 11.2.0.4 fixed a bug like this.

Here are the predicates for step 29 in the plan:

29 – filter((“PCP”.”MY_FLAG”=’M’ OR “PCP”.”MY_FLAG”=’Y’))

So the column could have value M or Y. The optimizer statistics have 4 distinct values for the column and no histogram. So the optimizer should assume that 1/4 of the rows meet each criteria. So the optimizer should have estimated 1/4 + 1/4 = 1/2 of the rows from step 30 meet the criteria in step 29. So, 17/2 = 8, rounding down. But in 11.1.0.7 it seems that they multiplied the rows from step 30 by 1/4 two times making it 16*1/4*1/4 = 1. It seems that in 11.1.0.7 the optimizer multiplied by 1/4 twice instead of adding them and then multiplying. There is a known bug related to OR conditions in where clauses:

Bug 10623119 – wrong cardinality with ORs and columns with mostly nulls (Doc ID 10623119.8)

Our 11.2.0.4 database includes this bug fix but I don’t know if this fix caused the difference in behavior that I saw. It seems possible that it did.

The interesting thing is that the real row count for step 29 is 0. So, the pre-bug fix plan in 11.1.0.7 actually estimated the row count more accurately by accident. It estimated 1 and the real count was 0. The correct estimate should have been 8, but that is not as close to 0 as 1 is. I think we just happened to have a few queries where the bug resulted in a more accurate estimate than a properly functioning optimizer. But, I’m only looking at the queries whose performance is worse after the upgrade. There may have been other queries that performed better because of this bug fix.

I ended up passing this and a similar query back to a senior SQL developer and he took one look at the query and described it as “ugly”. He fixed both of them in no time so that both queries now run just as fast or faster on 11.2.0.4 than they did on 11.1.0.7.

So, the original query ran faster when the optimizer was not working properly. A human developer simplified the query and then it ran faster when the optimizer was working properly. Maybe the moral of the story is to build simpler and cleaner SQL queries to begin with and if you find a query whose performance declines with better optimizer information then consider improving the query so that it works well with the better functioning optimizer.

Bobby

P.S. Well, I used a cardinality hint to give the 11.2.0.4 optimizer the correct number of rows for the step in the plan and it didn’t change the plan. So, the change in the way the number of rows was calculated may not be the real reason, or the only reason, for the worse plan on 11.2.0.4. Plus, I tried the alter session command mentioned in the comments and it didn’t change the plan either. I guess that something else in 11.2.0.4 caused the change to the less efficient plan but I can’t say what. Still, a developer fixed the queries in no time so that is still the main point…

Categories: DBA Blogs

_small_table_threshold=1000000 results in > 5x query speedup

Fri, 2017-04-07 16:41

Today I sped a query up by over 5 times by setting _small_table_threshold=1000000.

Here is the query elapsed time and a piece of the plan showing its behavior before setting the parameter:

Elapsed: 00:28:41.67

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                              | Name                   | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem |  O/1/M   |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|  69 |              PARTITION RANGE ITERATOR                  |                        |   9125 |      1 |   9122 |00:13:02.42 |    3071K|   3050K|       |       |          |
|* 70 |               TABLE ACCESS FULL                        | SIS_INV_DTL            |   9125 |      1 |   9122 |00:13:02.25 |    3071K|   3050K|       |       |          |

I think that this part of the plan means that the query scanned a range of partitions  9125 times resulting in over three million physical reads. These reads took about 13 minutes. If you do the math it works out to between 200-300 microseconds per read. I have seen similar times from repeated reads from a storage server that has cached the data in memory. I have seen this with a SAN and with Delphix.

Here is my math for fun:

>>> 1000000*((60*13)+2.25)/3050000
256.4754098360656

About 256 microseconds per read.

I ran this query again and watched the wait events in Toad’s session browser to verify that the query was doing a bunch of direct path reads. Even though the query was doing full scans on the partition range 9000 times the database just kept on doing direct path reads for 13 minutes.

So, I got the idea of trying to increase _small_table_threshold. I was not sure if it would work with parallel queries. By the way, this is on 11.2.0.4 on HP-UX Itanium platform. So, I tried

alter session set "_small_table_threshold"=1000000;

I ran the query again and it ran in under 5 minutes. I had to add a comment to the query to get the plan to come back cleanly. So, then I reran the query again and I guess because of caching it came back in under 2 minutes:

First run:

Elapsed: 00:04:28.83

Second run:

Elapsed: 00:01:39.69

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                              | Name                   | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem |  O/1/M   |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|  69 |              PARTITION RANGE ITERATOR                  |                        |   9125 |      1 |   9122 |00:00:45.33 |    3103K|      0 |       |       |          |
|* 70 |               TABLE ACCESS FULL                        | SIS_INV_DTL            |   9125 |      1 |   9122 |00:00:45.27 |    3103K|      0 |       |       |          |

The second execution did zero physical reads on these partitions instead of the 3 million that we had without the parameter!

So, it seems that if you have a query that keeps doing full scans on partitions over and over it can run a lot faster if you disable direct path read by upping _small_table_threshold.

Bobby

Categories: DBA Blogs

Jetpack 4.8 outage

Wed, 2017-04-05 17:18

I just got my bobbydurrettdba.com blog back online. It seems that an automatic update of Jetpack to version 4.8 took it down last night. I thought I would post a quick comment on how I resolved it because it is slightly different from what the Jetpack support site says.

When I tried to get into my blog today I just got a white screen saying there was a problem. I could not get into the wp-admin screen to do anything. Then I found out that Jetpack 4.8 had been pushed out and had brought down a lot of WordPress sites. Then I found out that Jetpack 4.8.1 had just come out today to fix it.

Here is the url for the 4.8.1 fix to this issue: fix

The fix points to the manual plugin install url which talks about deleting your /wp-content/plugins/jetpack folder and then manually installing by downloading the 4.8.1 jetpack zip, unzipping it, and ftping it up to /wp-content/plugins.

But all I had to do, after backing up /wp-content/plugins/jetpack was to rename it to /wp-content/plugins/jetpack.old. Then I was able to get into my site and to update the plugin to 4.8.1 through the normal web-based process.

Strangely enough the Jetpack plugin update removed my /wp-content/plugins/jetpack.old directory and replaced it with /wp-content/plugins/jetpack.

Here is what the directory looked like after I ran the update from my blogs admin page:

I never did ftp the 4.8.1 jetpack directory over though I had it unzipped and ready to go on my laptop.

Anyway, I didn’t delete my jetpack directory.  I just renamed it to jetpack.old. Then I ran the normal plugin update process.

Bobby

p.s. My site stats for today are not looking so good with the blog down all day:

Categories: DBA Blogs

Information Technology Jobs Posted

Thu, 2017-03-30 10:15

My company, US Foods, has posted a number of information technology jobs that are in Chicago (Rosemont)  or Phoenix (Tempe). Here is the web site:

https://usfood.taleo.net/careersection/usf_external/jobsearch.ftl

Enter Information Technology as the Job Field to see all the posted IT jobs.

Bobby

Categories: DBA Blogs

Using Delphix to support Oracle upgrade

Wed, 2017-03-22 17:47

I’m working on upgrading a very buggy unpatched 11.1.0.7 Oracle database to a fully patched 11.2.0.4 version. I’m using Delphix to support the upgrade and it has been a big help so far. This is on the HP-UX 11.31 Itanium platform.

The great thing about using Delphix to support an upgrade is that my very first pass through the upgrade scripts was with a full-sized clone of production. In the past I probably started with a tiny subset or even an out of the box demo database for my first upgrade pass and even when I got to QA it wasn’t a full test of a production upgrade. This time, my first test was with all the data and that was very cool.

The main example of how this helped is that we had a lot of data in the SYS.WRI$_OPTSTAT_HISTGRM_HISTORY and SYS.WRI$_OPTSTAT_HISTHEAD_HISTORY tables in production and this made the first upgrade of its clone take a long time. After two or three attempts at other ways to speed things up, I ended up applying patch 12683802 on an 11.1.0.7 Oracle home and this allowed me to truncate these two tables.

Delphix helped me here because I had an unused 11.1.0.7 Oracle home on a different host from the one I was doing the upgrade on. I didn’t want to apply a patch on the upgrade host because there were three other databases using the home and I didn’t want to bring them down or patch them. Delphix let me move the VDB that I was upgrading over to the host that had the unused home. Then I applied the patch there and ran the truncate using the dbms_stats.purge_stats(dbms_stats.purge_all) procedure call that the patch enabled.

Then I moved the VDB back to the host where I intended to do the upgrade, which already had the fully patched 11.2.0.4 binaries installed, and ran the upgrade there. Pretty cool. I think I did the most recent upgrade in about 3.5 hours with the empty OPTSTAT tables.

By the way, doing an upgrade within Delphix is easy. You just bring the VDB up on the old oracle home, do the upgrade as you normally would include all the shutdown and startup commands, and then within the Delphix GUI you let Delphix know the VDB is now on a new Oracle home by shutting it down, choosing the new home, and bringing it back up. Piece of cake.

Bobby

Categories: DBA Blogs

Simple Python for Oracle database tuning example

Thu, 2017-02-16 16:14

I ran across a stackoverflow question and it gave me an idea for a simpler use of Python to graph some Oracle database performance information. I looked at my PythonDBAGraphs scripts and I’m not sure that it is worth modifying them to try to simplify those scripts since I like what they do. But they may make people think that Python scripts to graph Oracle performance data are difficult to write.  But, I think if someone just wants to put together some graphs using Python, Matplotlib, and cx_Oracle they could do it more simply than I have in my PythonDBAGraphs scripts and it still could be useful.

Here is an example that looks at db file sequential read waits and graphs the number of waits per interval and the average wait time in microseconds:

import cx_Oracle
import matplotlib.pyplot as plt
import matplotlib.dates as mdates

connect_string = "MYUSER/MYPASSWORD@MYDATABASE"
con = cx_Oracle.connect(connect_string)
cur = con.cursor()

query="""
select sn.END_INTERVAL_TIME,
(after.total_waits-before.total_waits) "number of waits",
(after.time_waited_micro-before.time_waited_micro)/
(after.total_waits-before.total_waits) "ave microseconds"
from 
DBA_HIST_SYSTEM_EVENT before, 
DBA_HIST_SYSTEM_EVENT after,
DBA_HIST_SNAPSHOT sn
where before.event_name='db file sequential read' and
after.event_name=before.event_name and
after.snap_id=before.snap_id+1 and
after.instance_number=1 and
before.instance_number=after.instance_number and
after.snap_id=sn.snap_id and
after.instance_number=sn.instance_number and
(after.total_waits-before.total_waits) > 0
order by after.snap_id
"""

cur.execute(query)

datetimes = []
numwaits = []
avgmicros = []
for result in cur:
    datetimes.append(result[0])
    numwaits.append(result[1])
    avgmicros.append(result[2])
        
cur.close()
con.close()

title="db file sequential read waits"

fig = plt.figure(title)
ax = plt.axes()

plt.plot(datetimes,numwaits,'r')
plt.plot(datetimes,avgmicros,'b')

# Format X axis dates

fig.autofmt_xdate()
ax.fmt_xdata = mdates.DateFormatter('%m/%d/%Y %H:%M')
datetimefmt = mdates.DateFormatter("%m/%d/%Y")
ax.xaxis.set_major_formatter(datetimefmt)

# Title and axes labels

plt.title(title)
plt.xlabel("Date and time")
plt.ylabel("num waits and average wait time")

# Legend

plt.legend(["Number of waits","Average wait time in microseconds"],
loc='upper left')

plt.show()

The graph it produces is usable without a lot of time spent formatting it in a non-standard way:

It is a short 68 line script and you just need matplotlib and cx_Oracle to run it. I’ve tested this with Python 2.

Bobby

Categories: DBA Blogs

Rosetta Code

Sat, 2017-01-21 09:24

I have experimented with the Rosetta Code website as a way to learn more about computer technology. I have mentioned my exploration of the edX and OCW web sites in earlier posts so I thought I would mention Rosetta Code or RC as another way to learn.

The RC site displays code in a variety of programming languages so that you can compare the languages. They define certain tasks and people post code that performs the tasks. For example, the task could be to write a simple Hello World program that writes Hello World to the screen. The site shows how to do this in Java, Python, C, and others. At this moment there are 354 implementations of Hello World on the site.  I added this simple one for Oracle’s version of SQL: My Hello World

But, I can’t help wondering if this is just a fun game or is it really educational? I just finished a task this morning that was interesting to me. It is a draft task which means that people have not yet written enough example programs for the site managers to publish it as an official task. But anyone can see it. I’ve written the Python and PL/SQL examples. This 4 squares problem is just a puzzle or game but it was interesting to think about solving it in a declarative way with SQL and not a procedural way with Python or any other regular language. Maybe there is value in looking at these tasks and thinking about how SQL and relational database thinking could be applied?

Anyway, I just thought I would document what I have done with the RC site. Be careful because once you start working up example code for the site it can become addictive! I am still thinking about what the real value of the site is but it has helped me exercise my programming muscles and think a bit about SQL. Check it out if you think it has value.

Bobby

Categories: DBA Blogs

AZORA Meeting January 26th

Fri, 2017-01-06 15:40

The next Arizona Oracle User Group meeting is January 26th in Scottsdale. Signup on this meetup link.

Copied from invitation:

When:  January 26, 2017 (Thursday)
12:30 pm – 4:00 pm

Where:  Republic Services
1st Floor Training Rooms
14400 N 87th St (AZ101 & Raintree)
Scottsdale, AZ

Agenda:

12:30 – 1:00 Registration and Pizza

1:00-1:10  Welcome

1:10-2:10  Presentations

Room 1    Biju Thomas – OneNeck IT Solutions
(Oracle ACE Director)
“Oracle Database 12c New Features for 11gR2 DBA”

Room 2   Charles Kim – Viscosity North America
(Oracle ACE Director)
“Bullet Proof Your Data Guard Environment”

2:10-2:25  Break – Coffee & Cookies

2:25-3:25  Presentations

Room 1   Biju Thomas – OneNeck IT Solutions
(Oracle ACE Director)
“Introduction to Oracle Databases in the Cloud”

Room 2  Jerry Ward – Viscosity North America
“Building Faceted Search Navigation in APEX
with Oracle JET and  PL/SQL Pipelines”

3:25-3:30    Wrap Up and Closing

Categories: DBA Blogs

Improved VirtualBox Network

Fri, 2017-01-06 09:33

Before I left for vacation I noticed this blog post about setting up a network on VirtualBox: “CREATING A TEST LAB USING VIRTUALBOX / NAT NETWORKING”. Now that I am back in the office I thought I would try to apply some of the things that I learned from the blog post to my existing VirtualBox network. I’m pretty happy with the results so I thought I would document my experience here.

My situation differed slightly from the situation in the original post:

  1. I’m using VirtualBox 5.1.12 instead of 5.0.4
  2. I’m using Oracle Enterprise Linux 7.3 instead of CentOs 6
  3. I have 6 existing VMs instead of starting from scratch

I was cautious at first about trying the things recommended in the post because I didn’t want to mess up my existing VMs. These are all just test environments but it took some work to set them up. But, I wasn’t happy with the way the network was setup on my VMs so that motivated me to try something different. My biggest problem with my network was that I couldn’t SSH into my VMs when I worked from home using my work VPN connection.

After re-configuring my network I now have a static ip address for each VM within its own NAT network and I have port forwarding setup so that I can SSH into each one even when I’m working from home using VPN into my company’s network. I also have port forwarding so that I can login to an Oracle database on one of the VMs from my laptop even when using VPN.

The original blog post has most of the details but I thought that I would document a few minor differences that I came across to be helpful.

Default network name was NatNetwork instead of LocalNat.

In port forwarding I forwarded a port to port 1521 on the VM that has an Oracle database. I had to disable and stop the firewall on that VM so that I could connect to the Oracle database.

I went to /etc/sysconfig/network-scripts and looked at the configuration file and the format wasn’t the same as in the original post. This is probably because it is OEL 7.3 instead of CentOs 6. Instead of editing the file manually I ended up using the graphical network configuration app so that I knew I would edit the configuration correctly.

Later, after I wrote the first draft of this blog post I realized that I wanted to set up the network so that it automatically appends a domain name for our internal systems. I.e. if my standard domain is mycompany.com and I want to connect to mymachine.mycompany.com it would be nice to just connect to mymachine without fully qualifying the name with the domain. I ended up manually editing the file /etc/sysconfig/network-scripts/ifcfg-enp0s3 after googling around on the Internet to see how to add this. I added a DOMAIN line like this:

DOMAIN=”mydomain1.com mydomain2.com”

I created two text files to keep track of two things about my network configuration:

  1. The ports that VirtualBox forwards
  2. The ip address for each vm

I had to get the DNS server ip addresses from my laptop’s network settings.

Anyway, I don’t have much to add to the original post except just to point out these slight differences and my experience. It was super helpful to switch to this NAT network with port forwarding approach.

Bobby

P.S. After writing the first draft of this blog post I did some more testing. There is one thing about this configuration that I don’t like. It seems that anyone on my company’s network can SSH into one of my VMs if they use the forwarded port number and my laptop’s IP address.  I tried this from one of our Unix servers and it worked disturbingly well, even over the VPN. I think that the original blog post wanted this behavior but I was just trying to connect from my laptop to my VMs when I was using VPN. Still, it might come in handy to SSH into my VMs from other computers on our network. At least it isn’t opening up every port on my VM – only the ones I have set up with port forwarding. Also, I usually only bring these VMs up for short periods of time so they wont be available for people to hack into except for short unpredictable intervals and when I’m actively using them.

Categories: DBA Blogs

Delphix Users Panel Webinar

Wed, 2016-11-30 16:19

Delphix is sponsoring a user webinar on Wednesday from 10 to 11 am California time. I and a couple of other technical Delphix users will take part in a panel discussion. The webinar will give you a good chance to hear about other users’ experience with Delphix and a chance to ask questions. Like any good user meeting it will not be a non-technical sales pitch but it will instead focus on users sharing helpful technical information with other Delphix users.

Noted Oracle expert and Delphix employee Kellyn Pot’Vin-Gorman will also be there facilitating the discussion.

Here is the link to sign up for the free webinar: https://www.delphix.com/resources/webinar/delphix-users-panel

Be there or be square! 🙂

Bobby

Categories: DBA Blogs

Improving performance of top query

Wed, 2016-11-16 16:56

I’m on call this week. Here are the steps that I took to speed up a query today.

First I got an AWR report and found the top query. Also, someone from support told me to look at November 11 before the latest release and I found a similar top query.

I got a plan for both the new and old top queries – they both use the same plan which makes me think that the two queries are similar.

I looked at the top segments on the AWR report and found a particular table at the top of the logical reads. An index of that table was like number 5 on that list.

I looked at the columns of the table’s index to see how many distinct values there were. None of the three columns had more than 300 distinct values so they were not very selective. I noticed that there was a unique index on the table and the first column of that index had millions of distinct values.

I extracted some sample bind variable values for the query and find that the second bind variable was null or something like that. But, the index we were using included this second variable.

In looked at the bind variables and found that the first column from the unique index was part of the join conditions in the query. (The query had like 20 joins).

Then I extracted the query text and replaced the bind variables with literals to see how it would run. It used the unique index. I used hints to force the original index and compared to running with the unique index. It ran about 30 times faster with the unique index. I ran a few times to make sure it was all cached.

Then I tried to use SQLT’s coe_xfr_sql_profile.sql to force the plan that used the unique index but got an error. Had to download the latest version of SQLT to get it to work.

Now, on average, the query seems to run about 1000 times faster.

It is a delivered vendor package so it was nice to find the better plan and go behind the scenes to fix it. But, if another release comes out and changes this sql to a new sql_id we will have to create a new profile. It’s not perfect but its a good quick fix for my on call.

Bobby

Categories: DBA Blogs

Running SQL*Plus from a Python script

Fri, 2016-11-04 16:08

I needed to write a new script that was running on a Red Hat Linux 6 virtual machine and that would connect to databases using SQL*Plus. I was going to write a bash shell script but decided to use Python instead to see if I could do it using the Python that came with this version of Linux. I wont paste the entire script here but the key was to run SQL*Plus from Python instead of a shell script. Here is a simple example showing how I did it:

$ cat test.py
import subprocess

"""

Example of running a sqlplus script from python 2.6.6.

"""

def run_sqlplus(sqlplus_script):

    """

    Run a sql command or group of commands against
    a database using sqlplus.

    """

    p = subprocess.Popen(['sqlplus','/nolog'],stdin=subprocess.PIPE,
        stdout=subprocess.PIPE,stderr=subprocess.PIPE)
    (stdout,stderr) = p.communicate(sqlplus_script)
    stdout_lines = stdout.split("\n")

    return stdout_lines

sqlplus_script="""
connect test/test
select * from dual;
exit

"""

sqlplus_output = run_sqlplus(sqlplus_script)

for line in sqlplus_output:
    print line

Here is the output:

$ python test.py

SQL*Plus: Release 12.1.0.2.0 Production on Fri Nov 4 15:44:30 2016

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

SQL> SQL> Connected.
SQL>
D
-
X

SQL> Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

The function run_sqlplus takes a multi-line string as input. This is the text of a SQL*Plus script. It runs sqlplus /nolog to get a SQL*Plus prompt and then passes the strings in as the lines typed at the prompt. The function returns SQL*Plus’s output as a list of strings.

Anyway, this is just an example. I built a real script using these concepts. In this case we are using Python 2.6.6 without cx_Oracle installed so I couldn’t connect directly to an Oracle database. Instead I just ran SQL*Plus from Python.

Bobby

Categories: DBA Blogs

I put my SQL scripts on GitHub

Tue, 2016-10-25 10:45

I created a new GitHub public repository with my SQL scripts. Here is the URL:

https://github.com/bobbydurrett/OracleDatabaseTuningSQL

I’ve experimented with GitHub for my Python graphing scripts but wasn’t sure about putting the SQL out there. I don’t really have any comments in the SQL scripts. But, I have mentioned many of the scripts in blog posts so those posts form a type of documentation. Anyway, it is there so people can see it. Also, I get the benefit of using Git to version my scripts and GitHub serves as a backup of my repository.

Also, I have a pile of scripts in a directory on my laptop but I have my scripts mixed in with those that others have written. I’m pretty sure that the repository only has my stuff in it but if someone finds something that isn’t mine let me know and I’ll take it out. I don’t want to take credit for other people’s work. But, the point is to share the things that I have done with the community so that others can benefit just as I benefit from the Oracle community. I’m not selling anything and if there is someone else’s stuff in there it isn’t like I’m making money from it.

Like anything on the web use at your own risk. The repository contains scripts that I get a lot of benefits from but I make no guarantees. Try any script you get from the internet on some test system first and try to understand the script before you even run it there.

I hope that my new SQL repository helps people in their Oracle work.

Bobby

Categories: DBA Blogs

ASH script to show query run times

Mon, 2016-10-24 17:02

I ran into a situation last week where a developer complained that a query sometimes ran for 3 or more seconds but normally runs much less than 1 second. I had just been to a local AZORA user group meeting where Tim Gorman talked about using ASH to diagnose issues so Tim’s talk motivated me to find some clever way to use ASH. I had these three pairs of start and stop dates and times to work with. Each was about 3 to 4 seconds apart. I started looking at DBA_HIST_ACTIVE_SESS_HISTORY for the time period or even a large 11 second time period that bracketed the interval but I did not get any rows back for the first two intervals and only one row for the third. I knew that the V$ version of ASH sampled every 1 second so it might catch these 3 second queries but the queries in question had run the day before. But, something Tim said in the user group meeting made me think about using the V$ view. He said that on inactive development databases the in-memory V$ ASH data could hang around for a few days. Sure enough I was able to find some information in one of the given time periods. But, then I had to find the one slow execution of the query because there were multiple executions at the same time. I found that grouping by SQL_EXEC_ID would let me see each execution of the query by itself. So, I developed this query to show how long each execution ran:

select 
SQL_EXEC_ID,
to_char(SQL_EXEC_START,'YYYY-MM-DD HH24:MI:SS') sql_start,
to_char(min(sample_time),'YYYY-MM-DD HH24:MI:SS') first_sample,
to_char(max(sample_time),'YYYY-MM-DD HH24:MI:SS') last_sample,
max(sample_time)-min(sample_time) elapsed_seconds
from V$ACTIVE_SESSION_HISTORY a
where 
sample_time 
between 
to_date('20-OCT-2016 17:00:00','DD-MON-YYYY HH24:MI:SS')
and 
to_date('20-OCT-2016 17:30:00','DD-MON-YYYY HH24:MI:SS') and
sql_id='0gt3cjptk68vw'
group by SQL_EXEC_ID,SQL_EXEC_START
order by SQL_EXEC_START,SQL_EXEC_ID;

Here are a few rows from the output from around the time of the first interval that I was looking at:

SQL_EXEC_ID SQL_START           FIRST_SAMPLE        LAST_SAMPLE         ELAPSED_SECONDS
----------- ------------------- ------------------- ------------------- -----------------------
   16785284 2016-10-20 17:05:24 2016-10-20 17:05:25 2016-10-20 17:05:25 +000000000 00:00:00.000
   16785285 2016-10-20 17:05:25 2016-10-20 17:05:25 2016-10-20 17:05:25 +000000000 00:00:00.000
   16785380 2016-10-20 17:05:31 2016-10-20 17:05:31 2016-10-20 17:05:34 +000000000 00:00:03.000
   16785692 2016-10-20 17:05:51 2016-10-20 17:05:52 2016-10-20 17:05:53 +000000000 00:00:01.000
   16785772 2016-10-20 17:05:54 2016-10-20 17:05:55 2016-10-20 17:05:55 +000000000 00:00:00.000
   16785852 2016-10-20 17:05:59 2016-10-20 17:06:01 2016-10-20 17:06:01 +000000000 00:00:00.000
   16785940 2016-10-20 17:06:07 2016-10-20 17:06:08 2016-10-20 17:06:08 +000000000 00:00:00.000

The third row down lined up well with the interval in question. So, I was able to use ASH to show that the query ran for 3 seconds within the database. Also, each line was a wait on db file sequential read. This lead me to look at the execution plan and to check the index and partitioning to look for ways to improve the query’s performance.

Bobby

 

Categories: DBA Blogs

HugePages speeds up Oracle login process on Linux

Thu, 2016-10-20 13:28

We bumped a Linux 11.2.0.4 database up to a 12 gigabyte SGA and the login time went up to about 2.5 seconds. Then a Linux admin configured 12 gigabytes of HugePages to fit the SGA and login time went down to .13 seconds. Here is how I tested the login time. E.sql just has the exit command in it so this logs in as SYSDBA and immediately exits:

$ time sqlplus / as sysdba < e.sql

... edited out for space ...

real    0m0.137s
user    0m0.007s
sys     0m0.020s

So, then the question came up about our databases with 3 gig SGAs without HugePages. So I tested one of them:

real    0m0.822s
user    0m0.014s
sys     0m0.007s

Same version of Oracle/Linux/etc. Seems like even with a 3 gig SGA the page table creation is adding more than half a second to the login time. No wonder they came up with HugePages for Linux!

Bobby

Categories: DBA Blogs

Quickly built new Python graph SQL execution by plan

Wed, 2016-10-19 17:51

sql_id-c6m8w0rxsa92v-on-mydb-database-with-plans

I created a new graph in my PythonDBAGraphs to show how a plan change affected execution time. The legend in the upper left is plan hash value numbers. Normally I run the equivalent as a sqlplus script and just look for plans with higher execution times. I used it today for the SQL statement with SQL_ID c6m8w0rxsa92v. It has been running slow since 10/11/2016.

Since I just split up my Python graphs into multiple smaller scripts I decided to build this new Python script to see how easy it would be to show the execution time of the SQL statement for different plans graphically. It was not hard to build this. Here is the script (sqlstatwithplans.py):

import myplot
import util

def sqlstatwithplans(sql_id):
    q_string = """
select 
to_char(sn.END_INTERVAL_TIME,'MM-DD HH24:MI') DATE_TIME,
plan_hash_value,
ELAPSED_TIME_DELTA/(executions_delta*1000000) ELAPSED_AVG_SEC
from DBA_HIST_SQLSTAT ss,DBA_HIST_SNAPSHOT sn
where ss.sql_id = '""" 
    q_string += sql_id
    q_string += """'
and ss.snap_id=sn.snap_id
and executions_delta > 0
and ss.INSTANCE_NUMBER=sn.INSTANCE_NUMBER
order by ss.snap_id,ss.sql_id,plan_hash_value"""
    return q_string

database,dbconnection = 
util.script_startup('Graph execution time by plan')

# Get user input

sql_id=util.input_with_default('SQL_ID','acrg0q0qtx3gr')

mainquery = sqlstatwithplans(sql_id)

mainresults = dbconnection.run_return_flipped_results(mainquery)

util.exit_no_results(mainresults)

date_times = mainresults[0]
plan_hash_values = mainresults[1]
elapsed_times = mainresults[2]
num_rows = len(date_times)

# build list of distict plan hash values

distinct_plans = []
for phv in plan_hash_values:
    string_phv = str(phv)
    if string_phv not in distinct_plans:
        distinct_plans.append(string_phv)
        
# build a list of elapsed times by plan

# create list with num plans empty lists     
                        
elapsed_by_plan = []
for p in distinct_plans:
    elapsed_by_plan.append([])
    
# update an entry for every plan 
# None for ones that aren't
# in the row

for i in range(num_rows):
    plan_num = distinct_plans.index(str(plan_hash_values[i]))
    for p in range(len(distinct_plans)):
        if p == plan_num:
            elapsed_by_plan[p].append(elapsed_times[i])
        else:
            elapsed_by_plan[p].append(None)
            
# plot query
    
myplot.xlabels = date_times
myplot.ylists = elapsed_by_plan

myplot.title = "Sql_id "+sql_id+" on "+database+
" database with plans"
myplot.ylabel1 = "Averaged Elapsed Seconds"
    
myplot.ylistlabels=distinct_plans

myplot.line()

Having all of the Python code for this one graph in a single file made it much faster to put together a new graph. Pretty neat.

Bobby

Categories: DBA Blogs

Tim Gorman at AZORA meeting tomorrow in Scottsdale

Wed, 2016-10-19 10:34
#meetup_oembed .mu_clearfix:after { visibility: hidden; display: block; font-size: 0; content: " "; clear: both; height: 0; }* html #meetup_oembed .mu_clearfix, *:first-child+html #meetup_oembed .mu_clearfix { zoom: 1; }#meetup_oembed { background:#eee;border:1px solid #ccc;padding:10px;-moz-border-radius:3px;-webkit-border-radius:3px;border-radius:3px;margin:0; font-family: 'Helvetica Neue', Helvetica, Arial, sans-serif; font-size: 12px; }#meetup_oembed h3 { font-weight:normal; margin:0 0 10px; padding:0; line-height:26px; font-family:Georgia,Palatino,serif; font-size:24px }#meetup_oembed p { margin: 0 0 10px; padding:0; line-height:16px; }#meetup_oembed img { border:none; margin:0; padding:0; }#meetup_oembed a, #meetup_oembed a:visited, #meetup_oembed a:link { color: #1B76B3; text-decoration: none; cursor: hand; cursor: pointer; }#meetup_oembed a:hover { color: #1B76B3; text-decoration: underline; }#meetup_oembed a.mu_button { font-size:14px; -moz-border-radius:3px;-webkit-border-radius:3px;border-radius:3px;border:2px solid #A7241D;color:white!important;text-decoration:none;background-color: #CA3E47; background-image: -moz-linear-gradient(top, #ca3e47, #a8252e); background-image: -webkit-gradient(linear, left bottom, left top, color-stop(0, #a8252e), color-stop(1, #ca3e47));disvplay:inline-block;padding:5px 10px; }#meetup_oembed a.mu_button:hover { color: #fff!important; text-decoration: none; }#meetup_oembed .photo { width:50px; height:50px; overflow:hidden;background:#ccc;float:left;margin:0 5px 0 0;text-align:center;padding:1px; }#meetup_oembed .photo img { height:50px }#meetup_oembed .number { font-size:18px; }#meetup_oembed .thing { text-transform: uppercase; color: #555; }
Arizona Oracle User Group – October 20, 2016

Thursday, Oct 20, 2016, 12:30 PM

Republic Services – 3rd Floor Conference Room
14400 N 87th St (AZ101 & Raintree) Scottsdale, AZ

16 AZORAS Attending

Change In Plans -Tim Gorman comes to Phoenix! Stephen Andert had a sudden business commitment making it impossible for him to speak at Thursday’s meeting.Fortunately, Tim Gorman of Delphix will be coming from Denver to speak instead. Tim is an internationally-renowned speaker, performance specialist, member of the Oak Table, Oracle Ace Director, …

Check out this Meetup →

Phoenix area readers – I just found out that Oracle performance specialist and Delphix employee Tim Gorman will be speaking at the Arizona User Group meeting tomorrow in Scottsdale.  I am looking forward to it.

Bobby

Categories: DBA Blogs

Thinking about using Python scripts like SQL scripts

Fri, 2016-10-14 19:18

I’ve used Python to make graphs of Oracle database performance information. I put the scripts out on GitHub at https://github.com/bobbydurrett/PythonDBAGraphs. As a result I’m keeping my Python skills a little fresher and learning about git for version control and GitHub as a forum for sharing Open Source. Really, these Python scripts were an experiment. I don’t claim that I have done any great programming or that I will.

But, as I review what I have done so far it makes me think about how to change what I am doing so that Python would be more usable to me. I mainly use SQL scripts for Oracle database tuning. I run them through sqlplus on my laptop. I think I would like to make the way I’m using Python more like the way I use SQL scripts. My idea is that all the pieces would be in place so that I could write a new Python script as easily and quickly as I would a SQL script.

I started out with my PythonDBAGraphs project with a main script called dbgraphs.py that gives you several graphs to choose from. I also have a script called perfq.py that includes the code to build a select statement. To add a new graph I have added entries to both of these files. They are getting kind of long and unwieldy. I’m thinking of breaking up these to scripts into a separate script for each graph like ashcpu.py, onewait.py, etc.

You may wonder why I am talking about changes I might make to this simple set of scripts. I am thinking that my new approach is more in line with how businesses think about using Python. I have heard people say that business users could use Python and the same graphing library that I am using to build reports without having a developer work with them. Of course, people think the same about SQL and it is not always true. But, I think that my first approach to these Python scripts was to build it like a large standalone program. It is like I am building an app to sell or to publish like a compiler or new database system. But, instead I think it makes sense to build an environment where I can quickly write custom standalone scripts, just as I can quickly put together custom SQL scripts.

Anyway, this is my end of the week, end of the work day blogging thoughts. I’m thinking of changing my Python scripts from one big program to an environment that I can use to quickly build new smaller scripts.

Bobby

Categories: DBA Blogs

Need classes directory to run ENCRYPT_PASSWORD on PeopleTools 8.53

Tue, 2016-10-11 18:57

I had worked on creating a Delphix virtual copy of our production PeopleTools 8.53 database and wanted to use ENCRYPT_PASSWORD in Datamover to change a user’s password. But I got this ugly error:

Error: Process aborted. Possibly due to JVM is not available or missing java class or empty password.

What the heck! I have used Datamover to change passwords this way for 20 years and never seen this error. Evidently in PeopleTools 8.53 they increased the complexity of the encryption by adding a “salt” component. So, now when Datamover runs the ENCRYPT_PASSWORD command it calls Java for part of the calculation. For those of you who don’t know, Datamover is a Windows executable, psdmt.exe. But, now it is calling java.exe to run ENCRYPT_PASSWORD.

I looked at Oracle’s support site and tried the things the recommended but it didn’t resolve it. Here are a couple of the notes:

E-SEC: ENCRYPT_PASSWORD Error: Process aborted. Possibly due to JVM is not available or missing java class or empty password. (Doc ID 2001214.1)

E-UPG PT8.53, PT8.54: PeopleTools Only Upgrade – ENCRYPT_PASSWORD Error: Process aborted. Possibly due to JVM is not available or missing java class or empty password. (Doc ID 1532033.1)

They seemed to focus on a situation during an upgrade when you are trying to encrypt all the passwords and some have spaces in their passwords. But that wasn’t the case for me. I was just trying to change one user’s password and it wasn’t spaces.

Another recommendation was to put PS_HOME/jre/bin in the path. This totally made sense. I have a really stripped down PS_HOME and had the least number of directories that I need to do migrations and tax updates. I only have a 120 gig SSD C: drive on my laptop so I didn’t want a full multi-gigabyte PS_HOME. So, I copied the jre directory down from our windows batch server and tried several ways of putting the bin directory in my path and still got the same error.

Finally, I ran across an idea that the Oracle support documents did not address, probably because no one else is using partial PS_HOME directories like me. I realized that I needed to download the classes directory. I found a cool documentation page about the Java class search path for app servers in PeopleTools 8.53. It made me guess that psdmt.exe would search the PS_HOME/classes directory for the classes it needed to do the ENCRYPT_PASSWORD command. So, I copied classes down from the windows batch server and put the jre/bin directory back in the path and success!

Password hashed for TEST
Ended: Tue Oct 11 16:36:55 2016
Successful completion
Script Completed.

So, I thought I would pass this along in the unusual case that someone like myself needs to not only but the jre/bin directory in their path but is also missing the classes directory.

Bobby

Categories: DBA Blogs

JDBC executeBatch looks odd in AWR

Fri, 2016-10-07 19:18

A project team asked me to look at the performance of an Oracle database application that does a bunch of inserts into a table. But, when I started looking at the AWR data for the insert the data confused me.

The SQL by elapsed time section looked like this:

byelasped

So, 1514 executions of an insert with 1 second of elapsed time each, almost all of which was CPU. But then I looked at the SQL text:

sqltext

Hmm. It is a simple insert values statement. Usually this means it is inserting one row. But 1 second is a lot of CPU time to insert a row. So, I used my sqlstat.sql script to query DBA_HIST_SQLSTAT about this sql_id.

     >select ss.sql_id,
  2  ss.plan_hash_value,
  3  sn.END_INTERVAL_TIME,
  4  ss.executions_delta,
  5  ELAPSED_TIME_DELTA/(executions_delta*1000) "Elapsed Average ms",
  6  CPU_TIME_DELTA/(executions_delta*1000) "CPU Average ms",
  7  IOWAIT_DELTA/(executions_delta*1000) "IO Average ms",
  8  CLWAIT_DELTA/(executions_delta*1000) "Cluster Average ms",
  9  APWAIT_DELTA/(executions_delta*1000) "Application Average ms",
 10  CCWAIT_DELTA/(executions_delta*1000) "Concurrency Average ms",
 11  BUFFER_GETS_DELTA/executions_delta "Average buffer gets",
 12  DISK_READS_DELTA/executions_delta "Average disk reads",
 13  ROWS_PROCESSED_DELTA/executions_delta "Average rows processed"
 14  from DBA_HIST_SQLSTAT ss,DBA_HIST_SNAPSHOT sn
 15  where ss.sql_id = 'fxtt03b43z4vc'
 16  and ss.snap_id=sn.snap_id
 17  and executions_delta > 0
 18  and ss.INSTANCE_NUMBER=sn.INSTANCE_NUMBER
 19  order by ss.snap_id,ss.sql_id;

SQL_ID        PLAN_HASH_VALUE END_INTERVAL_TIME         EXECUTIONS_DELTA Elapsed Average ms CPU Average ms IO Average ms Cluster Average ms Application Average ms Concurrency Average ms Average buffer gets Average disk reads Average rows processed
------------- --------------- ------------------------- ---------------- ------------------ -------------- ------------- ------------------ ---------------------- ---------------------- ------------------- ------------------ ----------------------
fxtt03b43z4vc               0 29-SEP-16 07.00.34.682 PM              441         1100.68922     1093.06512     .32522449                  0                      0             .000492063           60930.449         .047619048             4992.20181
fxtt03b43z4vc               0 29-SEP-16 08.00.43.395 PM               91         1069.36489     1069.00231    .058494505                  0                      0                      0          56606.3846         .010989011                   5000
fxtt03b43z4vc               0 29-SEP-16 09.00.52.016 PM               75         1055.05561     1053.73324        .00172                  0                      0                      0          55667.1333                  0             4986.86667
fxtt03b43z4vc               0 29-SEP-16 10.00.01.885 PM              212         1048.44043     1047.14276    .073080189                  0                      0             .005287736          58434.6934         .004716981             4949.35377

Again it was about 1 second of cpu and elapsed time, but almost 5000 rows per execution. This seemed weird. How can a one row insert affect 5000 rows?

I found an entry in Oracle’s support site about AWR sometimes getting corrupt with inserts into tables with blobs so I thought that might be the case here. But then the dev team told me they were using some sort of app that did inserts in batches of 1000 rows each. I asked for the source code. Fortunately, and this was very cool, the app is open source and I was able to look at the Java code on GitHub. It was using executeBatch in JDBC to run a bunch of inserts at once. I guess you load up a bunch of bind variable values in a batch and execute them all at once. Makes sense, but it looked weird in the AWR.

Here is the Java test program that I hacked together to test this phenomenon:

import java.sql.*;
import oracle.jdbc.*;
import oracle.jdbc.pool.OracleDataSource;
import java.io.ByteArrayInputStream;
import java.io.IOException;
import java.util.*;

public class InsertMil5k
{
  public static void main (String args [])
       throws SQLException
  {
    OracleDataSource ods = new OracleDataSource();
    ods.setUser("MYUSER");
    ods.setPassword("MYPASSWORD");
    ods.setURL("jdbc:oracle:thin:@MYHOST:1521:MYSID");
    OracleConnection conn =
      (OracleConnection)(ods.getConnection ());
    conn.setAutoCommit(false);

    PreparedStatement stmt = conn.prepareStatement("insert into test values (:1,:2,:3,:4)");
    byte [] bytes = new byte[255];
    int k;
    for (k=0;k<255;k++)
      bytes[k]=(byte)k;

/* loop 200 times. Make sure i is unique */
    int i,j;
    for (j=0;j < 200; j++) {

/* load 5000 sets of bind variables */

      for (i=j*5000;i < (j*5000)+5000; i++) {
        stmt.setString(1, Integer.toString(i));
        stmt.setInt(2, 1);
        stmt.setBinaryStream(3, new ByteArrayInputStream(bytes), bytes.length);
        stmt.setLong(4, 1);
        stmt.addBatch();
      }

    stmt.executeBatch();
    conn.commit();
    }

    conn.close();
  }
}

I started with one of the Oracle JDBC samples and grabbed the batch features from the github site. I just made up some random data which wasn’t super realistic. It took me a while to realize that they were actually, at times, doing 5000 row batches. The other AWR entries had 1000 rows per execution so that finally makes sense with what the dev team told me.

I guess the lesson here is that the AWR records each call to executeBatch as an execution but the number of rows is the size of the batch. So, that explains why a simple one row insert values statement showed up as 5000 rows per execution.

Bobby

Categories: DBA Blogs

Pages