## I put my SQL scripts on GitHub

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

## ASH script to show query run times

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

Posted in Uncategorized | 6 Comments

## HugePages speeds up Oracle login process on Linux

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

## Quickly built new Python graph SQL execution by plan

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

Posted in Uncategorized | 2 Comments

## Tim Gorman at AZORA meeting tomorrow in Scottsdale

### 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, …

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

## Thinking about using Python scripts like SQL scripts

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

P.S. It took less time than I thought to split this up. Pushed out the new version with dbgraphs.py and perfq.py split up across each script for each graph. I did keep one class in a file by itself, signatures.py,  because several graphs use it. I guess I won’t really know if splitting these large scripts up is better until I need to build a new graph. But it seems less overwhelming to just build a new script instead of editing some large existing scripts.

## Need classes directory to run ENCRYPT_PASSWORD on PeopleTools 8.53

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 they 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!

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 put the jre/bin directory in their path but is also missing the classes directory.

Bobby

## JDBC executeBatch looks odd in AWR

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:

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:

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",
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.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.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

P.S. The other thing that I didn’t mention when I wrote this blog post of Friday was my confusion over the number of buffer gets. If you look at the sqlstat output above you will see around 60,000 buffer gets per execution. This really puzzled me before I realized that it was really inserting 5000 rows. How can a single row insert get 60,000 buffers? It almost seemed like it was scanning the indexes or that there was something weird with the inline blob column. The top segments part of the AWR report pointed to the three indexes on this table and not to the blob segment so my guess was that somehow the index lookup had degraded into an index scan. But, when I finally realized that it was 5000 rows per execution then I divided the 60,000 buffer gets by 5000 rows to get 12 gets per inserted row. Given three indexes this didn’t seem crazy.

Posted in Uncategorized | 3 Comments

I was googling for things related to NOLOGGING operations and found this useful post on the Ask Tom web site: url

There is a nice table in the post that shows when insert operations generate redo log activity. But it isn’t formatted very well so I thought I would format the table here so it lines up better.

Table Mode    Insert Mode     ArchiveLog           mode result
-----------   -------------   -----------------    -----------
LOGGING       APPEND          ARCHIVE LOG          redo generated
NOLOGGING     APPEND          ARCHIVE LOG          no redo
LOGGING       no append       ""                   redo generated
NOLOGGING     no append       ""                   redo generated
LOGGING       APPEND          noarchive log mode   no redo
NOLOGGING     APPEND          noarchive log mode   no redo
LOGGING       no append       noarchive log mode   redo generated
NOLOGGING     no append       noarchive log mode   redo generated


All of this is from Ask Tom. My contribution here is just the formatting.

I ran a couple of tests whose results agree with this table. I ran insert append on a database that was not in archivelog mode and the insert ran for the same amount of time with the table set for LOGGING as it did with the table set for NOLOGGING. I ran the same test on a database that is in archivelog mode and saw a big difference in run time between LOGGING and NOLOGGING. I didn’t prove it but I assume that the redo generation caused the difference in run time.

No archivelog and logging:

insert /*+append*/ into target select * from source;

64000 rows created.

Elapsed: 00:00:00.36


No archivelog and nologging:

insert /*+append*/ into target select * from source;

64000 rows created.

Elapsed: 00:00:00.38


Archivelog and logging:

insert /*+append*/ into target select * from source;

64000 rows created.

Elapsed: 00:00:00.84


Archivelog and nologging:

insert /*+append*/ into target select * from source;

64000 rows created.

Elapsed: 00:00:00.53


I haven’t tested all the table options but I thought it was worth formatting for my reference and for others who find it useful.

Bobby