DBA Blogs

FOR IMMEDIATE RELEASE San Francisco (April 1, 2013) – In a dramatic move calculated to give fresh life to the moribund relational database movement, the latest version of Oracle Corporation’s flagship database has eliminated the famous “join penalty” by making it possible to store rows from multiple relational tables in the same database block. There […]

Building a secure Hadoop cluster requires protecting a number of services which comprise Hadoop infrastructure. If you are using CDH distribution, then Cloudera Manager (CM) is one of the components that needs to be secured. CM consists of Server, Agents running on all cluster machines and web UI. CM provides you with 3 levels of securing (good/better/best) it’s communication:

• Transport Layer Security (TLS) Encryption for Cloudera Manager
• TLS Authentication of Server to Agent and Users
• TLS Authentication of Agents to Server

There is a good step by step guide in CM documentation, and it’s easy to follow for one server, but what when you have hundreds of them? There are different approaches to the problem of managing server’s configuration at scale, but I’d like to focus on Ansible which is a neat framework for parallel commands execution and complex rollouts. And it’s written in Python! Ansible is easy to install and requires only a couple of Python libraries on a “master” node and nothing else that python2.6 on “slaves”. You don’t have to setup ssh-keys and configures passwordless access across all machines, which is important if we are talking about security. To give you and idea of how Ansible command looks like, here is how you can restart CM Agents on all Hadoop data nodes:

ansible hadoop_data_nodes -m service\ 
 -a "name=cloudera-scm-agent state=restarted"  -k --sudo 

This command will read a list of hosts from your /etc/ansible/hosts file or any other file specified by ANSIBLE_HOSTS environment variable. It will find a section [hadoop_data_nodes] in the hosts file (which has ini-like structure) it and will execute given command for all servers in this section. Ansible will ask you for both ssh and sudo passwords only once and will use them to execute command on target servers. Ansible relies on modules (specified by -m option) to perform specific tasks like restarting services, executing shell commands or manipulating text files. Full list of modules can be found here. You can write your own, of course, if you need.

Below is the step by step guide on configuring all 3 levels of TLS for CM. In some aspects it repeats steps from CM documentation guide, but there are some important nuances that I have discovered. This guide is also scalable: you can apply it with very little modifications to clusters of any size.

Level I. TLS Encryption for Cloudera Manager

Following steps assume that you have installed Ansible on the same server as your CM Server and properly configured it to access all nodes in your cluster.

1. Create a directory for CM keystore:

   mkdir /etc/cloudera-scm-server/keystore

2. Generate a certificate for CM. You will be prompted for new Keystore password. Also make sure CN field that you will be asked to specify matches CM Server hostname. It’s not *your* name!

   keytool -validity 1095 -keystore\
    /etc/cloudera-scm-server/keystore/scm-keystore -alias jetty\
     -genkeypair -keyalg RSA

   note -validity option, new certificate will be valid for 3 years in this case

3. Restrict permissions to the Keystore:

   chown -R cloudera-scm:cloudera-scm /etc/cloudera-scm-server/keystore/
   chmod o-r /etc/cloudera-scm-server/keystore/scm-keystore

4. Enable TLS Encryptions for Agents, provide path and password to the Keystore in CM web UI. You can refer to CM documentation on how to do this.
5. Next, we need to update CM Agent configuration files to set use_tls=1 option. For this Ansible lineinfile module can be used:

   ansible hadoop -m lineinfile -a\
     "dest=/etc/cloudera-scm-agent/config.ini state=present regexp='use_tls.*'\
        line='use_tls=1'" -k -K

   There are several assumptions made here. First of all, your Ansible host list has a [hadoop] section in it, which covers all Hadoop cluster nodes, or it hase sections like [hadoop_namenodes], [hadoop_datanodes], etc. Ansible can recognise patterns. Second, your template for CM Agnet config.ini files has all security related options in it, but they are commented out. Maintaining a template for all configuration files is a good idea and Ansible can help you here as well, but it’s beyond the scope of this guide.

6. Restart CM Server (again, I assume that you run Ansible commands from the same machine):

   sudo /etc/init.d/cloudera-scm-agent restart

7. Restart CM Agents and check their health:

   ansible hadoop -m service -a\
     'name=cloudera-scm-agent state=restarted' -k -K;
   ansible hadoop -m shell -a\
     "tail /var/log/cloudera-scm-agent/cloudera-scm-agent.log" -k -K

   You have already seen an example with service Ansible module. New module used here is shell. It allows you to run arbitrary shell commands. It’s a good idea to verify that all agents started fine, so you can check the log files on all servers.

If all is fine, at this point you have encrypted communication between CM Server and CM Agents.

Level II. TLS Authentication of Server to Agent and Users

At this level you will force CM Agents to check a certificate for CM Server to make sure they are talking to the right machine.

1. Export CM Server Certificate from Keystore and converting it to .der format:

   keytool -exportcert -keystore\
     /etc/cloudera-scm-server/keystore/scm-keystore -alias jetty\
     -file scm-server.der
   openssl x509 -out scm-server.pem -in scm-server.der -inform der

2. Create new cert dirs on all agent servers:

   ansible hadoop -m shell -a "mkdir /etc/cloudera-scm-agent/cert" -k -K

3. Copy server cert to agents:

   ansible hadoop -m copy -a "src=/tmp/scm-server.pem
         dest=/etc/cloudera-scm-agent/cert/ owner=root group=root" -k -K

4. Change very_cert_file option in agent’s config.ini:

   ansible hadoop -m lineinfile -a "dest=/etc/cloudera-scm-agent/config.ini 
     state=present regexp='verify_cert_file' 
     line='verify_cert_file=/etc/cloudera-scm-agent/cert/scm-server.pem'" -k -K

5. Enabled Use TLS Encryption for Admin Console in CM Web UI
6. Restart CM server and Agents. See Steps 6-7 in Level I section.

Level III. TLS Authentication of Agents to Server

This is similar to previous level, but requires certificates to be generated for all agents, so they can authenticate to CM Server. Here I describe an approach with self-signed certificates which is fine for development or POC clusters. For production clusters you may need to comply with your organisation’s standards and obtain properly signed certificates.

1. Generated password for Agent keys and copied it to all agents machines:

ansible hadoop -m shell -a\
 'echo PASSWORD > /etc/cloudera-scm-agent/cert/agent_cert.pwd' -k -K
ansible hadoop -m shell -a\
  'chmod o-rx /etc/cloudera-scm-agent/cert/agent_cert.pwd' -k -K

1. Next step is to generate private key and certificate for each CM Agent. To automate this task I wrote a quick script — https://github.com/dazbur/morecerts. It takes list of hosts in a plain text file and produces private key and certificate for each host. Resulting files will have agent_HOSTNAME.key and agent_HOSTNAME.pem format. It also takes care of providing Distinguished Name options for keys-generating commands:
   • Create a text file with list of Agent’s IP adress. You can just copy it from Ansible hosts lists
   • Create agent key password and put it into a text file
   • Generate keys:

     ./morecerts.py -f agentiplist.file -p agent.pass.file gencerts

   • Add keys to CM Server keystore:

     sudo ./morecerts.py -f agentiplist.file -p agent.pass.file -k\
      /etc/cloudera-scm-server/keystore/scm-keystore\
         -w KEYSTORE_PASSOWORD addtokeystore

2. Copy keys and certs to agent machines (assuming you have generated keys in your home directory):

   ansible hadoop -m copy -a "src=~/agent_$inventory_hostname.key
    dest=/etc/cloudera-scm-agent/cert/agent.key owner=root group=root"  -k -K
   ansible hadoop -m copy -a "src=~/agent_$inventory_hostname.pem
    dest=/etc/cloudera-scm-agent/cert/agent.pem owner=root group=root"  -k -K

   Here you can see another nice trick Ansible can do: $inventory_hostname variable corresponds to the server on which command will be executed. This allows me to copy specific files to specific servers.

3. Update agent config.ini files to set client_key_file, client_keypw_file and client_cert_file options:

   ansible hadoop -m lineinfile -a "dest=/etc/cloudera-scm-agent/config.ini 
    state=present regexp='client_key_file.*' 
     line='client_key_file=/etc/cloudera-scm-agent/cert/agent.key'" -k -K
   
   ansible hadoop -m lineinfile -a "dest=/etc/cloudera-scm-agent/config.ini 
     state=present regexp='client_keypw_file.*' 
     line='client_keypw_file=/etc/cloudera-scm-agent/cert/agent_cert.pwd'" -k -K
   
   ansible hadoop -m lineinfile -a "dest=/etc/cloudera-scm-agent/config.ini 
     state=present regexp='client_cert_file.*' 
     line='client_cert_file=/etc/cloudera-scm-agent/cert/agent.pem'" -k -K

4. Update CM configurtion via Web UI to set Use TLS Authentication of Agents to Server, Path to Truststore and Truststore Password. Truststore in our case is the same as Keystore.
5. Restart CM Server and Agents

You are done now! Ansible can also wrap individual playbooks, so you can execute them on demand later. In general, I found Ansible to be a great tool to manage and execute commands on many servers and it is definitely worth exploring.

Link to the latest version of my Exadata talk slides: zip

Here are the details of my presentation time and place if you are going to Collaborate 13 in Denver:

Session title: Exadata Distinctives
Room: Mile High Ballroom 1C
Date and Time: 1:15PM-2:15PM

I look forward to seeing you there!

- Bobby

PS. Minor revision today 04/04/2013.  Got to practice with a few coworkers listening.  Feel like this is it for the slides.

This is a very short blog post to share a good news I  learned last week at the great New Zealand Oracle User Group 2013 conference. During a keynote Tom Kyte mentioned that Oracle is  going to introduce a Temporary Undo.

Most of us know that for years Oracle temporary tables weren’t true temporary tables from technical perspective. As any change would generate UNDO data and UNDO would generate corresponding REDO. Therefore changes on temporary tables generated a REDO. Depending on an application a REDO stream generated from temporary tables could be significant. REDO volumes have a direct impact on database recovery. Database must apply all REDO data in case of recovery (including temporary tables REDO). This going to change soon.

Yury

BTW: I really enjoyed the conference. This was one of the very best if not the best conferences I have attended in the region. If you will have a chance to be part of it in the future then don’t think twice. Go for it :)

The answers to the questions like whether to patch now or wait a little? What quirks are there in that stunning new features? What are the limitations of that fancy index type, any working examples of a particular add-on, are best found in the blogs. This Log Buffer Edition provides you a window to those blogs out there.

Oracle:

Scott Wesley is dishing out the reasons you should upgrade your APEX environment.

In case you haven’t already noticed, PeopleTools 9.2 is out and available for download!

Since two thirds of sensitive data in most organizations resides in databases, consolidation onto private clouds represent an opportunity to improve information security and compliance.

BITeamwork has been out since Oracle Open World 2012 but since its involvement with several customers the product has evolved into a really amazing software offering.

Andrew Reid is giving simple example, tested on Oracle 11.2, shows how to use V$SQL_BIND_CAPTURE to see the value of bind variables used in a WHERE clause.

SQL Server:

Steve Bolton is sharing a rickety stairway to SQL Server Data Mining.

What to Do When You Can’t Wipe an Infected System? Brian Kelley answers.

Policy Based Management has 4 evaluation modes and if you are not already familiar with them you can go here to get more information.

James had someone asked him the other day if they are using SSIS 2012 Project Versions, is there any benefit to using TFS?

Did you know that when you deploy projects to the SSIS catalog in SSIS 2012, the previous version of the project is kept in the server?

MySQL:

Here is how to run your own Web SMS Portal with PointSMS.

Sven is blogging about flexible Fail-over policies using MySQL and Global Transaction Identifiers.

Daniel van Eeden is running Percona XtraDB cluster in a sandbox on Ubuntu.

What other pluggable authentication plugins would you like in MariaDB? Colin Charles asks.

Why MySQL Performance at Low Concurrency is Important? Peter Zaitsev questions.

This is the second article in a series about internals and performance of concurrent managers. In this post, we’ll take a look at three important settings that affect the performance of the concurrent managers: number of processes, “sleep seconds”, and “cache size”.  This article might be a bit on the theoretical side, but it should provide a good understanding of how these settings actually affect the behavior and performance of concurrent managers. Most of the statements in this article build off of information from my previous post:  The Internal Workflow of e-Business Suite Concurrent Manager Process. It may be helpful to take a look at it before continuing with this one.

Life cycle of a Concurrent Request

The interesting thing about tuning concurrent managers is the fact that we don’t tune a particular query or a running process, but we actually tune the pending time of concurrent requests. The goal of the tuning is to make sure concurrent requests start executing soon enough after the time they have been scheduled for. Let’s take a look at the life cycle of a concurrent request:

The Life cycle of a Concurrent Request (CR)

Based on the diagram above, the pending time of the request is the interval between the time the request was scheduled to start and the time it actually started. This time can be split in two parts:

1. Pending for Conflict Resolution Manager (CRM) – Here the CRM checks the incompatibility rules effective for the pending concurrent request against other running requests. The CRM allows the request to execute only when all incompatible requests have completed.
2. Pending for Concurrent Manager (CM) – This is the time spent waiting for an available concurrent manager process. It also includes the time the CM process takes to fetch the request from FND_CONCURRENT_REQUESTS table and to start executing it. “Pending for CM” is the interval that can be tuned by altering the number of manager processes, “sleep seconds” and the “cache size” settings.

Requirements

Understanding the requirements is a mandatory step for any tuning attempt. Otherwise, it’s hard to know when to stop tuning as can become unclear if the performance is sufficient or not. When you’re tuning concurrent managers the requirements can be defined by answering a simple question: How long is the request allowed to stay pending after the scheduled start? You should also keep in mind the following items while thinking about the answer:

• Be realistic – “Requests should start immediately” is not a valid answer. It’s simply not possible because of how concurrent managers work. If there is anything you have to run immediately – concurrent programs are not the correct way of doing it.
• Think of groups of concurrent programs – If you have a similar requirements for a group of requests (i.e. a program printing invoices while the customer is waiting on-site should start executing in 10 seconds after it’s submitted), a dedicated concurrent manager should be implemented for them.
• Unsure of requirements? – If the requirements are not known, ask the end users if they have experienced situations when requests stay in the queue for too long. Was it because the managers couldn’t cope with the amount of incoming requests? If so, the settings might be too low.
• Work Shifts - If the requirements differ at different times of the day, concurrent manager Work Shifts can be used to define different settings depending on the time of the day.

Settings

The settings related to concurrent managers are explained in the documentation: Oracle E-Business Suite System Administrator’s Guide – Configuration. But I find the explanations are too often unclear to effectively tune the concurrent managers. In this chapter I’ll reveal the basic principles behind each of the three main settings and will describe how I utilize them to control the performance of concurrent managers.

Number of Processes

From the Documentation: “The number of operating system processes you want your work shift to run simultaneously. Each process can run a concurrent request.”

• It’s important to add that there is no coordination between processes of a concurrent manager. If all concurrent processes fetched from the FND_CONCURRENT_REQUESTS table at exactly the same time – they all would read exactly the same information about pending requests. A simple mechanism of row locking is utilized later to allow execution of a concurrent request on a single manager process.
• Choosing the correct number of concurrent processes is not easy as the workloads are not constant and the number of pending requests can vary. Here are some clues you should consider (I’m also planning a future blog post about measuring the actual utilization levels of concurrent managers):
  • Don’t configure too many processes! Your hardware is limited. If you configure too many processes you’ll exhaust the server resources. For example, if you run lots of big Oracle Reports (CPU-intensive workload) and you have 4 CPUs on your only web/forms/concurrent node, configuring 8 processes for the concurrent manager is risky. If 8 reports where to be generated at the same time, the users could experience web/forms slowness. The same applies to the database tier. Additionally, if too many processes are configured they can use a significant amount of resources even when they are idle. This is especially important for RAC configurations. (This too will be explained in one of my upcoming blog posts)
  • Don’t configure too few processes! If the number of processes is insufficient, the requests will start queuing. If that becomes an issue, increase the number of processes slightly. Consider defining a Work Shift with a different number of processes at different times of the day to accommodate your requirements.
  • Don’t be afraid of queuing! Queuing is normal, especially if all requests still manage to start as expected based on the requirements. If you see recurring queuing at particular times, check with the users if that is going to be a problem.
  • Start low! If you’re unsure of what setting should be used, start with a low number of processes. Check if any queueing occurs and if the users start complaining.

Sleep Seconds

From the Documentation: ”The sleep time for your manager during this work shift. Sleep time is the number of seconds your manager waits between checking the list of pending concurrent requests (concurrent requests waiting to be started)”

• The documentation is inaccurate – It should clearly state that it’s effective for each manager process – i.e. if you have 5 concurrent manager processes for the Standard Manager and the “Sleep Seconds” setting is set to 30, then the average time between checks for pending requests (if all managers are idle) is 30 / 5 = 6 seconds.
• A manager process sleeps only when there are no pending requests - The manager process checks the requests queue immediately after it has processed the last request it fetched. A common misconception is that if the rate of incoming requests is very high, the “Sleep Seconds” should be low to process all of them quickly. Not true! If the rate of incoming requests is high, there is a good chance some requests will be executing at any given time. So, when they complete, the requests queue will be checked immediately and the new requests will be started.
• What value to use? - Calculate it! Three parameters are important to estimate the “Sleep Seconds” (S) setting: the number of manager processes (N), the average utilization level (U) of concurrent managers (this setting will be explained later), and the average time of how long the request is allowed to be pending (T). As “Sleep Seconds” are effective only for the idle processes, it can be calculated using the following: S = N * (1 – U) * T.
  • Example 1: if N = 5 processes, U= 20%, T=20 seconds – let’s calculate the “Sleep Seconds” setting: S = 5 * (1 – 0.2) * 20 = 5 * 0.8 * 20 = 80 seconds. It seems high, but think about it – if the average utilization of 5 processes is 20%, then there are 4 idle processes at any given time. Each of these will have a sleep interval of 80 seconds, so on average the requests queue will be checked every 20 seconds.
  • Example 2: if N = 3 processes, U= 90%, T=20 seconds: S = 3 * (1 – 0.9) * 20 = 3 * 0.1 * 20 = 6 seconds.  This example reveals a problem as the calculated “Sleep Seconds” are lower than the requirement we have set – this means the requirement can’t be reached with the number of running processes. Think about it – we have 3 processes each utilized 90% of time, it’s impossible to meet the 20 seconds goal because most of the time all managers are busy. There simply aren’t enough processes to execute the incoming requests. The defined requirements can be reached only if at least one manager process is idle – This scenario also describes a “perfect world”, where all but one manager is busy, so all new requests are picked up in time and the processing overhead of the idle manager processes is minimal.
    

Cache Size

From the Documentation: “The number of requests your manager remembers each time it reads which requests to run”

• Almost useless setting - Unless you have a manager with only one running process. If multiple manager processes are running, there is a good chance that most of the cached requests will be processed (remember, the processes don’t coordinate the work – they compete the work) by other manager processes while the first request is running.
  • Example, there are 10 manager processes and 10 requests are submitted. One of the manager processes starts executing the 1st request, the other managers start running the remaining requests. So, by the time the request completes all the cached requests will be obsolete, but the manager process will try to lock the corresponding rows in FND_CONCURRENT_REQUESTS table anyway, and will fail for all 9 requests. It will then immediately query the queue to check if more requests are pending.
  • I think it’s best to set “Cache Size” setting to 1 so the hardware resources aren’t spent on trying to lock the processed requests, but rather on checking the requests queue.
• Request priorities are cached too - If you have a cache size greater than 1, keep in mind the request priorities are cached too. If the priority is changed for a cached request, the manager process will not notice it.

Summary

I have to admit this article turned out to be much more complicated to write than I expected, even if there are just a few settings to describe. The problem is that the concurrent processing environment is changing all the time. At one moment it’s completely idle, and then suddenly there is a spike of incoming requests. It makes it impossible to tune for all situations.  There will always be instances when any configuration works better and others when it makes things worse, but I hope I was able to outline the significance of each configurable parameter so the overall picture is clearer.

As I promised, two other articles are lined up for the future – one to describe the actual utilization levels of concurrent managers and the other to look into overhead of an idle concurrent processing environment. Stay tuned!

My OLTP system just cutover from 11.1.0.7.x to 11.2.0.3.5 and a bunch of my custom monitoring stuff now looks a whole lot different.

I had some custom slicing and dicing of the contents of sgastat ( I query it once an hour ) so I can keep an eye on stuff.  Not a big believer in Oracle changing stuff so everything is fixed size and my 11.2 shared pool is a fair amount larger than my 11.1.

To guard against 4031's my system monitors free memory and will force shared pool flush when running low.  No one at least on medium sized systems should be absolutely petrified of a flush of the shared pool ... no you don't want to do it often.

Anyways there are so many different things now showing up in my 11.2 sgastat areas ... what the heck is KGLHD and KGLH0?  Why are KGLHD and KGLH0 so large?

Where is my PCursor and CCursor?  11.1 "sql area" not appears to be renamed to "SQLA".

Lots of things to learn here about what has changed in 11.2!

Information below is just showing things that were larger than 50 meg ...

*** 11.1.0.7.12
SUBPOOL                   NAME                       MB                                    
shared pool (0 - Unused): free memory                224                                   
shared pool (1):          free memory                757.25                                
shared pool (1):          sql area                   602.08                                
shared pool (1):          CCursor                    208.43                                
shared pool (1):          private strands            78.58                                 
shared pool (1):          event statistics per sess  59.98                                 
shared pool (1):          PCursor                    59.56                                 

*** 11.2.0.3.5 ...
SUBPOOL                   NAME                       MB                                    
shared pool (0 - Unused): free memory                512                                   
shared pool (1):          KGLHD                      972.88                                
shared pool (1):          SQLA                       893.1                                 
shared pool (1):          free memory                591.51                                
shared pool (1):          KGLH0                      505.61                                
shared pool (1):          kkslLoadParentOnLock:lite  289.42                                
shared pool (1):          db_block_hash_buckets      178                                   
shared pool (1):          private strands            107.41                                
shared pool (1):          event statistics per sess  93.91                                 
shared pool (1):          ksunfy : SSO free list     87.54                                 
shared pool (1):          kglhdusr                   81.57                                 
shared pool (1):          dbktb: trace buffer        78.13                                 
shared pool (1):          kkslBind_value             60.77                                 
shared pool (1):          FileOpenBlock              55.83                                 
shared pool (1):          KTI-UNDO                   55.55                                 
shared pool (1):          KGLS                       53.61                                 
shared pool (1):          KKSSP                      51.18                                 

Sorry for anyone that may have seen this already via Oracle L ... some volleying back and forth on this item ( and thanks to Jonathan Lewis ).

This is the same approximate workload ( one week in between ) on an 11.1 system and now running on 11.2.

Just some of the top things from the AWR report here.

Looks like Oracle counts parses different in 11.2 ( does not count as a parse a hit in the session_cached_cursors area ) and also fixed reporting the W/A MB processed number.  In 11.1 it should have been divided by ( 1024 * 1024 ) to give megabytes correctly.

11.1.0.7.12 ...
Load Profile              Per Second    Per Transaction   Per Exec   Per Call
~~~~~~~~~~~~         ---------------    --------------- ---------- ----------
      DB Time(s):                1.4                0.0       0.00       0.00
       DB CPU(s):                0.7                0.0       0.00       0.00
       Redo size:          109,808.0            2,749.8
   Logical reads:           13,060.0              327.0
   Block changes:              725.7               18.2
  Physical reads:              593.6               14.9
 Physical writes:               44.2                1.1
      User calls:            4,492.2              112.5
          Parses:            1,813.0               45.4
     Hard parses:                2.0                0.1
W/A MB processed:        1,089,100.0           27,272.6
          Logons:                1.7                0.0
        Executes:            1,871.9               46.9
       Rollbacks:                0.2                0.0
    Transactions:               39.9
   
11.2.0.3.5 ...
Load Profile              Per Second    Per Transaction   Per Exec   Per Call
~~~~~~~~~~~~         ---------------    --------------- ---------- ----------
      DB Time(s):                0.7                0.0       0.00       0.00
       DB CPU(s):                0.6                0.0       0.00       0.00
       Redo size:           98,996.9            2,831.7
   Logical reads:           11,926.5              341.2
   Block changes:              618.0               17.7
  Physical reads:              310.8                8.9
 Physical writes:               46.6                1.3
      User calls:            4,770.8              136.5
          Parses:               98.2                2.8
     Hard parses:                2.0                0.1
W/A MB processed:                1.0                0.0
          Logons:                1.7                0.1
        Executes:            1,998.8               57.2
       Rollbacks:                0.1                0.0
    Transactions:               35.0

Friends,

I want to remind you, to let us know if you would like to come for the dinner at Pedro’s on Tuesday April, 23.

Actually ALL of you should come !

Pedro’s is asking us to have a better idea of the number of participants, so please go to this page “MySQL Community Dinner at Pedro’s 2013”

and subscribe.

We want to have all of you enjoy the evening with us, subscribe & come!

The central point of my Exadata presentation is that data flows from the disks and into and out of memory caches in a different way on Exadata when using a Smart Scan than in non-Exadata Oracle databases.  An interesting consequence of the way data is cached in Smart Scans is that it is cached in flash memory which is slower than regular RAM.  Non-Smart Scan table accesses may use the faster block buffer cache in the database server’s RAM.  I have on my presentation that it takes about 1 millisecond to read from flash memory versus 10 nanoseconds on regular RAM.  I got those numbers from an Exadata class put on by Oracle and from memory statistics published on the internet.  But, I couldn’t remember if I had verified the 1 millisecond number for flash cache access experimentally so I did a simple test that came back with about .4 milliseconds to read 32K from the flash cache.  This is still much slower than RAM but faster than I thought.

Here are my test scripts, logs, and a spreadsheet calculating the result: zip

I slightly modified the script from my previous post to set autotrace on and timing on.

SQL> select sum(BLOCKS) from test;

SUM(BLOCKS)
-----------
 1983309312

Elapsed: 00:00:00.73

The query ran in .73 seconds.

NAME                                 VALUE
------------------------------- ----------
physical read total IO requests       1841
cell flash cache read hits            1837

Almost every IO was cached in flash memory so I’ll do the calculation as if all the execution time for the query is accounted for by the flash cache reads.

.73 seconds X 1000 milliseconds per second = 730 ms

730 ms/1837 flash cache reads = .4 milliseconds/flash cache read (rounded up from .397)

So, this isn’t perfect but it is one piece of evidence that the flash cache reads are about .4 milliseconds on the Exadata V2 system this was tested on.

- Bobby

PS.  I determined that the flash cache reads were 32 K using the following information:

Statistics
----------------------------------------------------------
  7239  physical reads

NAME                                MB
--------------------------- ----------
physical read total bytes   56.5546875

NAME                                 VALUE
------------------------------- ----------
physical read total IO requests       1841

56 megabytes read/1841 physical IOs is about 32K.  Also, 7239 physical blocks read/1841 physical IOs is about 4 8K blocks per read = 32 K.  So, these tests appear to show that 32K flash cache reads take about .4 milliseconds.

 

MongoDB is document-oriented database management system and supported by 10gen. Anyway, I was writing about a book, that's MongoDB Applied Design Patterns Practical Use Cases with the Leading NoSQL Database By Rick Copeland.

A book will guide you how to do the connection between MongoDB and the business problem it's designed to solve. Learn how to apply MongoDB design patterns with some Cases such as e-commerce, content management ans etc. You will see demonstrates from this book, that's very useful for readers. I believe this book is useful for someone who are interested in learning practical patterns for solving problems and designing applications using MongoDB.

This book has 2 parts: Part I introduces the reader to some generally applicable design patterns in MongoDB and Part II: Use Cases. This is good part. It covers a particular problem domain and the techniques and patterns used to address the problem:

• Operational intelligence: Perform real-time analytics of business data

• Ecommerce: Use MongoDB as a product catalog master or inventory management system

• Content management: Learn methods for storing content nodes, binary assets, and discussions

• Online advertising networks: Apply techniques for frequency capping ad impressions, and keyword targeting and bidding

• Social networking: Learn how to store a complex social graph, modeled after Google+

• Online gaming: Provide concurrent access to character and world data for a multiplayer role-playing game

Written By: Surachart Opun http://surachartopun.com

Q: Are Oracle SQL CPU times reliable?
During performance analysis, it's usually important to collect the CPU consumption for specific SQL statements for opportunity and comparison analysis. There are multiple SQL CPU consumption data sources. I'm the type of person who asks, "Are they to be trusted? Is one method more accurate then the other?" This posting will compare four different sources of SQL CPU consumption: v$sess_time_model, v$sqlstats, Statspack report, and the OS Linux command procstat.

You download the analysis pack containing all related scripts and data HERE.

My Real Motivation (and fear)
My initial motivation for this investigation occurred when a student of mine noticed something very strange in this below Statspack report (source: http://filebank.orapub.com/perf_stats/SP_PDXPROD.txt ) :

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
latch: cache buffers chains                     53,712      31,764    591   49.8
CPU time                                                    16,758          26.2
Backup: sbtwrite2                                8,909      11,126   1249   17.4
latch free                                       3,198       1,851    579    2.9
latch: cache buffer handles                      1,967         931    473    1.5
          -------------------------------------------------------------
. . .
SQL ordered by CPU  DB/Inst: PDXPROD/PDXPROD  Snaps: 2625-2635
. . .
    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
  14456.36        7,000       2.07   86.3  497518.80   1,182,585,272  314328380
SELECT DISTINCT CM_NODE.NODE_ID, CM_NODE.CM_MODIFIED_DATE FROM C

The snapshot interval is about 150 minutes. (I don't know why 150 minutes was chosen.) Looking at the "Top 5 Timed Events", the top wait event is clearly "latch: cache buffer chains" with all sessions in the snapshot interval waiting nearly 32K seconds. The other wait times are not even close. Now focus on the "SQL ordered by CPU" section, where I show the clear top SQL CPU consumer. The next SQL statement consumes only 6.9% of the CPU compared to the above 86.3%.

Important to know: An Oracle session is either consuming CPU or waiting for something. The wait may be idle, but it is still waiting. When running a SQL statement the elapsed time is all the CPU plus all the wait time. For example, if a statement takes 30 seconds to run, 10 seconds may be associated with CPU consumption and the other 20 seconds associated with wait time. It follows that if the CPU consumption is 10 seconds and the elapsed time is 30 seconds, the wait time must be 20 seconds. ...not rocket science.

If you look closely at the above top CPU SQL statement it's elapsed time is 497518.90 seconds and its CPU consumption is 14456.36. It follows the wait time must be 483062.54 that is around 480K seconds. Now look at the top wait event's time. It's around 32K.

The problem:
How is it possible that the clear top wait event time is 32K seconds while a single SQL statement has 480K of wait time? Obviously something is wrong, very very wrong.
There are a number of possible reasons for this discrepancy and I may never the truth. The issue could be incorrect CPU time collection, faulty Statspack data collection or reporting, a bug in Oracle's wait interface, or perhaps something else. Because my entire Oracle performance career is based on quantitative Oracle performance analysis, I can't ignore this. Plus it's a good reason to take the time to compare various data collection sources reporting the same thing, like CPU consumption.

My first step in this quest is drilling into CPU consumption. (Which is something that should be done regardless of this situation.) Then I'll look into the wait time and finally the elapsed time. And of course I may need to dig into Statspack data collection; especially when a system is seriously bottlenecked (on this system there is a massive CPU bottleneck); Data collection can take a while and numbers tend is be tweaked... but not (I suspect) like what we are seeing above (I hope anyways).

Let's press on to check SQL statement CPU consumption!

What To Test?
It's not possible to test every scenario. So I pick the ones that, based on my experience, will likely be questioned. And of course I need to be able to develop a good test, that is an experiment.

My initial thought was the issue was with sub-second SQL that gets executed multiple times a seconds. However, if the above Statspack total execution and total elapsed time values are correct, the SQL shown above has an execution rate of 0.8 execs/second with the average elapsed time around 71 seconds. So the issue here is not sub-second elapsed time SQL and not simultaneous executions.

This makes my experimental setup much simpler. It's very difficult to collect accurate timing information from multiple sources with sub second SQL. For my experiment I had the SQL run for around 85 seconds. The longer the SQL elapsed time, the less impact performance statistics data collection has on the analysis. For example, if my data collection takes 1 second and the SQL elapsed time is 1 second, I've got a big problem. However, if my data collection takes 1 second and the SQL elapsed time is 60 seconds, I can deal with that. Especially if all the performance data sources show the same performance picture. In my experiment to simplify the situation, there was only one session executing the SQL.

The above SQL is a select statement, so decided not to test DML.

Below is the SQL decided to use in this experiment (snippet from quick.sql).

while ( execs_total_v < &exec_todo )
loop
        select count(object_id), sum(object_id)
        into   bogus1_v, bogus2_v
        from   customers;

        execs_total_v  := execs_total_v + 1 ;
end loop;

The exec_todo variable gives me control over the elapsed time. In the experiment I set exec_todo to  200. The quick.sql script is called by main experiment driver script, startExpr.sh.

As detailed in the Data Gathering Specifics section below, I varied the load five times.

CPU SQL Data Sources
There are a number of sources to get CPU consumption for a specific SQL statement. Most DBAs have a slightly irrational love and hate relationship for the various sources. Here are the sources I used in this experiment.

v$sess_time_model. The "DB CPU" statistics is server process CPU consumption in microseconds. Since I queried from the "sess" and not the "sys" _time_model view, I should only get the server process CPU consumption for a specific session. If I surround the SQL statement with a "DB CPU" query and subtract the ending value from the initial value, the result should be just the SQL statement CPU consumption.

v$sqlstats. The "cpu_time" statistic is CPU time in microseconds. Gathering from v$sqlstats is tricky because as the SQL statement is running additional rows related to your statement are inserted. So it's not a simple, "ending time minus beginning time" thing. You have to very careful to look at the correct v$sqlstats rows. You can see how I did by examining getsidcpu.sh and startExpr.sh, both of which are contained in the analysis pack (link at top of posting).

Statspack (v$sql). My source is the "CPU Time (s)" column in the SQL listing area. Regardless of how Statspack gathers the data, I need to have confidence in what Statspack stores and reports. In my experiments I pull the CPU consumption from the stats$sql_summary table's "cpu_time" column.

As you and I are both wondering, "Where does Statspack get its SQL CPU time?", in SQL*Plus I ran a simple SQL trace just before I executed the Statspack collection procedure ( exec perfstat.statspack.snap(i_snap_level=>10); ). Looking closely at the raw trace file, it appears Statspack is gathering SQL CPU consumption from v$sql not v$sqlstats. In the trace file, look for the statement, "INSERT INTO STATS$SQL_SUMMARY" and you will see column cpu_time is populated from v$sql. I am running Oracle 11.2 on Linux.

Operating System. In my mind, the OS is the "truth" in CPU consumption. So I needed to find a way to collect CPU consumption for a specific OS process. It took me a while to find a tool that provided good time granularity. I stumbled upon a tool called procstat. It compiled fine on my Linux box. Here is a link to the code.

Now the trick is to gather all this data without significantly impacting what I'm observing and skewing the collection data. Read on...

Data Collection Specifics
The general collection idea is simple: gather initial session CPU time, run the SQL, gather final session CPU time, calculate the CPU time delta (i.e., difference), and store the results. But alas, it was not that simple. For two main reasons:

Querying from v$ views is not read consistent. And, if you remember back to my posts about when v$sysstat and v$sqlstats get updated, the various statistics are updated for different reasons and at different times. My solution was to sleep three seconds after the SQL completes using dbms_lock.sleep(3), thus giving Oracle time to update the statistics while at the same time, consuming virtually no CPU. This appears to have worked wonderfully.

When/where to collect the data. My goal is always to collect performance data just before and just after the thing under observation. But the various collection methods (e.g., OS tool, v$) can make this troublesome. With this objective in mind, I had to move some of the collection away from the "thing under observation" or insert a delay until I was confident the data was being collected correctly. ...and yes, this does take some time... you're welcome!

The main experiment script is "startExpr.sh" which calls the "quick.sql" and "getsidcpu.sh" scripts. Looking at these you'll see exactly how I gathered the data. It's kind of complicated because of the issues mentioned above and because I'm gathering data from four difference sources.

The load on the system is an important factor when gathering performance data. So I altered the load five times; starting with a reasonably active but not out-of-control system and then increased the CPU load until the OS CPU run queue would hit more than twice the number of CPU cores... a massive CPU bottleneck. I did not run this experiment on an IO bottleneck system. Perhaps later if I need to.

At each load level and for each data collection source, 31 samples where collected. (People tend to complain when there are less than 30 samples collected (for reasons they can't explain), so I typically gather at least 31.

Data Analysis
To analyze the data I used the free "R" statistics package. It is free, runs on Windows/Linux/Mac OS X, easy to use and especially so with basic statistical analysis, and you can script your analysis in a text file. Here's the link to the R script I used in this analysis. Usually I use Mathematica (which I love) but I want to start incorporating R into my One Day Performance Seminar, so this is a good opportunity to develop some courseware as well. I have a very short and simple step-by-step R tutorial for Oracle DBAs here. That link may become stale as I add more specific R tutorials.

Here is a link to the experimental results data in a SQL*Plus like format.

I used the pulldata.sh script to format the data into an easily usable format for R. All the data files (end in .dat") are available in the main experiment pack (see top of posting for link).

The entire experiment can be summed up in the below "smoothed" histograms. Below are the results for each of the five different system loads. The load increases left to right, top to bottom. So the lightest load is the upper left image and the most intensive load is the bottom center image.





While difficult to see, all the above histograms contain all 31 samples for each of the four data collection methods. For example, the green line represents the SQL CPU consumption based on v$sess_time_model's "DB CPU" statistic. The lines are plotted in this order: red, blue, black, and green. If you don't see the color you are looking for, it's because another data source essentially had the same results and graphically covers it up. For example, if you look at the bottom center image (the most intensive load) all you can see are the green and blue lines. Where are the read and black lines? If you think about it, the red line is being covered up with either the blue or green line.

Does this "covering up" make a difference to the analysis? No. In fact, it is just I wanted to see! Because all four data sources and their associated lines are essentially the same, resulting in a single line, this means all four data sources show the same CPU consumption for the SQL statement!

To get more statistical: While the lines are overlapping because their results look to be the same, looks can be deceiving. Therefore, I did some significant testing. I suspect the most controversial data is be between v$sess_time_model's "DB CPU" statistic (highly trusted) and Statspack SQL CPU time (not as much trusted). And also between the operating system (highly trusted) and Statspack (not as much trusted).

While all the statistical analysis data is in the "R" output text file (cpu_r.txt), I will only comment on the upper right image (experimentally, this is load 3) where three lines can be visually seen. Since the sample sets are not normally distributed (their sample normality test p-values < 0.05), I used the Wilcox location test. If the Wilcox p-value is greater than 0.05 then any difference in our sample sets is likely caused by unfortunately picking just the wrong samples for our test (i.e., random selection) or perhaps something else (e.g., sun spots).

The p-value for "DB CPU" and Statspack is an amazingly high 0.9885. The p-value for the operating system and Statspack test is also an amazingly high 0.9103. This is the statistical way of saying, there is not a real difference in the sample sets values.

What Does This Mean?
I need to be careful how I write this. My experiment (Linux Oracle Enterprise Edition 11.2) showed that on my CPU bound system with a reasonably long duration SQL statement (~85 seconds), all four data collection methods returned the "same" values. So either, all are incorrect (which we all hope is not the case) or they are all correct (which I'm thankful for).

But to address my fundamental and motivating question of, "How is it possible that the clear top wait event time is 32K seconds while a single SQL statement has 480K of wait time? Obviously something is wrong, very very wrong." It appears the issue is not CPU consumption collection and Statspack reporting.

More practically and to the point, when I look at CPU time in a Statspack report I will trust it... unless I have a really good reason not to.

But that still leaves wait time, elapsed time, and Statspack collection and reporting as possible problems. I guess this means you'll be seeing some related postings in the near future!

Thanks for reading!

Craig.

If you enjoy my blog, I suspect you'll get a lot out of my courses; Oracle Performance Firefighting,  Advanced Oracle Performance Analysis, and my one-day Oracle Performance Research Seminar. I teach these classes around the world multiple times each year. For the latest schedule, go to www.orapub.com . I also offer on-site training and consulting services.

P.S. If you want me to respond to a comment or you have a question, please feel free to email me directly at craig@orapub .com. Another option is to send an email to OraPub's general email address, which is currently orapub.general@comcast .net.

There are no rules for blogging. There cannot be any, because you cannot trap the wind in your hands. It’s innovation, it’s creativity, and it’s right out of the core of the technology from the bleeding edge. This Log Buffer drips into that, and brings you some of the finest posts.

Oracle:

Yes its not a fad. Big Data is the commercial supercomputing in the age of Datafication.

Tanel Poder is listing Exadata storage cells and their configuration info from V$CELL_CONFIG.

How well do you know your hints? When Jonathan asks, it stays asked.

Rather than just describing the contents of the trace file, Dough thought it might be a good idea to tie the various sections into how they might help you solve Real WorldTM problems.

Timur Akhmadeev produces yet another gem of a blog post.

SQL Server:

Michelle Ufford is blogging about conversion issues upgrading to PowerShell 3.0.

Mark Broadbent is figuring out as just how to upload SQL Server 2012 Enterprise/ Developer Edition installation files to his Windows Azure Virtual Machine.

Chris Shaw needs the opinion regarding the sessions for the PASS summit.

Chris Webb writes about UK/US Date Format Bug in PowerPivot and SSAS Tabular.

Thomas LaRock is having a SQL Server Query Performance Tuning: A 12 Step Program.

MySQL:

Among many others, here is yet another live post from Percona 2013.

Petri Virsunen opines about Zero-Downtime MySQL Maintenance And Schema Operations.

ip.access Relies on MySQL to Support Mobile Traffic Growth.

Wanted: Evaluators to Try MongoDB with Fractal Tree Indexing

Zmanda Recovery Manager for MySQL – What’s New in Version 3.5

Concurrent processing is one of the key elements of any e-Business Suite system. It provides scheduling and queueing functionality for background jobs and it’s used by most of the applications modules. As many things depend on concurrent processing it’s important to make sure the configuration is tuned for your requirements and hardware specification.

This is the first article in a series about performance of concurrent processing. We’ll take a closer look at the internals of concurrent managers, the settings that affect their performance and the ways of diagnosing performance and configuration issues. Today we’ll start with an overview of the internal workflow of a concurrent manager process. Enjoy the reading!

There are few things that need to be clear before we start:

1. This is only about how the concurrent processing framework (the concurrent managers) works and it’s not about the concurrent requests executed in the framework.
2. There are multiple types of concurrent managers in eBS – internal manager, conflict resolution manager, workflow agent listener service, standard manager, etc. Their roles are different and in this post I’ll discuss only managers that pick up scheduled concurrent requests from the “queue” and execute them – or specifically all managers that have type of “Concurrent Manager” set in Concurrent managers’ definition form. Typical examples of these managers are “Standard Manager”, “Inventory Manager” and probably your own custom concurrent managers created for processing specific types of concurrent requests.

“Concurrent Managers” Form

It is important to understand the internal workflow of a concurrent manager because otherwise it’s hard to realize how a configuration change actually affects the system. Several years ago I had to implement an online change of a specialization rule and it triggered a bounce of all Standard Manager processes – that’s when I realized I had to understand how it worked and since then I have spent lots of hours looking into internals of concurrent managers. I’m not saying everything is 100% clear for me now – there are too many little things that matter in certain situations. This series of posts will be more about concepts and I hope you’ll find it useful.

So how does a concurrent manager process work? Here is a diagram I created to explain it:

Internal workflow of a concurrent manager process

I’ve numbered each step of the diagram to provide a bit more details about them:

0. This is where the story begins. There is no EXIT state in the diagram as the managers normally process requests in an infinite loop. Obviously, there is a way for a concurrent manager process to receive the command to quit when the managers need to be shut down, but that’s not included here for simplicity.
1. Internal Concurrent Manager (ICM) requests the Service Manager (FNDSM) to start up the Concurrent Manager process. For the Standard Manager processes the binary executable FNDLIBR is started, for the Inventory Manager it’s  INVLIBR, and there are others too.
2. The manager process connects to the database and reads the settings (e.g profile options, sleep seconds, cache size).
3. The process saves information about itself in FND_CONCURRENT_PROCESSES table (os process id, database name, instance name, DB session identifiers, logfile path and name and others). It also updates FND_CONCURRENT_QUEUES by increasing the value of RUNNING_PROCESSES.
4. The concurrent manager process collects information from the database to build the SQL for querying the FND_CONCURRENT_REQUESTS table. The query will be used every time the manager process will look for scheduled concurrent requests.  This is the only time the manager process reads the Specialization Rules (which programs it is allowed to execute and which not) from the database. Keep in mind, if the specialization rules are changed while the managers are running, they are bounced without warning as that is the only way to update the specialization rules cached by the manager process.
5. The SQL (from step 4) is executed to collect information about pending concurrent requests from FND_CONCURRENT_REQUESTS table.
6. The results are checked to verify if any requests are pending for execution.
7. If no requests are pending for execution the manager process sleeps and then goes to step 5. The “Sleep Seconds” parameter of the  ”Work Shifts” settings of the concurrent manager determines how long the process sleeps before FND_CONCURRENT_REQUESTS table is queried again. This is the only time the “sleep seconds” setting is used.
8. If there is at least one concurrent request pending for execution the concurrent manager process caches rowids for the FND_CONCURRENT_REQUESTS rows of pending concurrent requests. The “Cache Size” setting of the concurrent manager specifies how many rowids to cache.
9. The cached list of rowids is checked to verify if there are any unprocessed concurrent requests (rows in FND_CONCURRENT_REQUESTS table) left .If none are left – the processing returns to step 5 and the FND_CONCURRENT_REQUESTS table is queried again.
10. The next unprocessed rowid is picked from the process cache and the processing starts.
11. Concurrent manager process executes a SELECT-for-UPDATE statement to lock the STATUS_CODE in FND_CONCURRENT_PROCESSES for the request it’s about to process. This is the mechanism to ensure that each concurrent request is executed only once and only by one manager process even if many processes are running simultaneously. The SELECT-for-UPDATE statement can complete with “ORA-00054: resource busy and acquire with NOWAIT specified” or “0 rows updated” if another manager process has started processing the request already.
12. If the STATUS_CODE of the request was locked successfully the concurrent manager executes the concurrent request. The processing moves to step 9 where the cached list of concurrent requests (rowids) is being checked again.

The workflow is not very complex, but it’s important to remember there are normally multiple concurrent manager processes running at the same time and they are competing for the requests to run. This competition introduces another dimension of tuning for settings, like number of concurrent manager processes, sleep seconds or cache size. Stay tuned for the next post in the series to find out more!

I encountered an unusual situation recently where Oracle was writing trace files into the user directory instead of the usual oracle diagnostic destinations. Our monitoring software indicated that the “/home” directory was filling up. When I checked the space, I saw it had become 85% full.

$ df /home
Filesystem 1K-blocks Used Available Use% Mounted on
/dev/mapper/home 20642428 16503552 3090300 85% /home

In digging further, I found the pythian user was using a large amount of space. This is very unusual as the monitoring software we use has a very small footprint and the log files rotate so as not to use a lot of disk space.

$ cd home
$ du -sh *
392K bturner
16K lost+found
....
4.5G pythian
...

Digging further, I found an unfamiliar directory “oradig_pythian” had been created. I had never seen this directory before and it is not related to our monitoring software.

$ cd pythian
$ du -sh *
2.4M avail
11M logs
4.3G oradiag_pythian
...

Drilling down the “oradiag_pythian”, there was an usually named directory “host_1460457767_80″ which was full of subdirectories that are similar in name to the oracle diagnostic directories.

$ pwd
/home/pythian/oradiag_pythian/diag/clients/user_pythian/host_1460457767_80
$ du -sh *
2.9G alert
4.0K cdump
4.0K incident
4.0K incpkg
4.0K lck
276K metadata
4.0K metadata_dgif
4.0K metadata_pv
4.0K stage
4.0K sweep
1.4G trace

The only file in the “trace” directory was a sqlnet.log file. This 1.4GB file was being written to many times per minute complaining of a missing oracle diagnostic directory.

$ ls -ltr trace | tail -3
total 1466924
-rw-rw---- 1 pythian pythian 1500659093 Mar 13 09:36 sqlnet.log
$ cd trace
[pythian@bsn-s-ora11g-1 trace]$ tail -10 sqlnet.log
Wed Mar 13 09:42:04 2013
Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]
Wed Mar 13 09:42:04 2013
Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]
Wed Mar 13 09:42:05 2013
Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]
Wed Mar 13 09:42:05 2013
Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]
Wed Mar 13 09:42:05 2013
Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

In addition, the “alert” directory was full of “log.xml” files.

$ ls -ltr alert | tail -3
-rw-r—– 1 pythian pythian 10485849 Mar 10 14:43 log_293.xml
-rw-r—– 1 pythian pythian 10485849 Mar 12 19:05 log_294.xml
-rw-r—– 1 pythian pythian 2915094 Mar 13 09:36 log.xml
$ ls -lt alert | tail -3
-rw-r—– 1 pythian pythian 10485849 Jul 16 2012 log_3.xml
-rw-r—– 1 pythian pythian 10485849 Jul 15 2012 log_2.xml
-rw-rw—- 1 pythian pythian 10485895 Jul 14 2012 log_1.xml

In checking the contents of the most recent log.xml file, it also shows that log files are being written to and being filled up with messages of the missing directory.

$ tail -40 log.xml
host_addr='10.20.30.40'>
Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log] [/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

In checking for directory, the first directory “/u01/app/oracle/product/11.2.0/db_1/log” did exist. The second directory “/u01/app/oracle/product/11.2.0/db_1/log/diag/clients” did not exist.

$ ls -l /u01/app/oracle/product/11.2.0/db_1/log
total 8
drwxr-xr-t 3 oracle oinstall 4096 May 10 2012 client_hostname
drwxrwxr-x 3 oracle oinstall 4096 May 10 2012 diag

$ ls -l /u01/app/oracle/product/11.2.0/db_1/log/diag/clients
ls: /u01/app/oracle/product/11.2.0/db_1/log/diag/clients: No such file or directory

$ cd /u01/app/oracle/product/11.2.0/db_1/log/diag
$ ls -l
total 8
-rw-r—– 1 oracle oinstall 16 Mar 6 14:32 adrci_dir.mif
drwxr-x— 2 oracle oinstall 4096 Nov 18 22:21 rdbms

I decided to create the directory and see what happens. Nothing happened. And by “nothing”, I mean “nothing” in a good way. Oracle stopped writing to the sqlnet.log file and the log.xml files to indicate the directory was missing.
At the same time, nothing was created in the new clients directory.

$ cd /u01/app/oracle/product/11.2.0/db_1/log/diag
$ mkdir clients
$ cd clients
$ ls

Seems like it was spending a lot of time complaining about a missing directory that it did not need to use. So why did Oracle create the “oradiag_pythian” directory and start complaining about the missing “client” directory ?

I was not able to find anything on metalink that would explain this behaviour. Thankfully I still had the FIRST log.xml file that was created and there was some clue there as to why these files were created.

$ head -40 log_1.xml

Create Relation ADR_CONTROL

Create Relation ADR_INVALIDATION

Create Relation INC_METER_IMPT_DEF

Create Relation INC_METER_PK_IMPTS

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log]
[/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

Directory does not exist for read/write [/u01/app/oracle/product/11.2.0/db_1/log]
[/u01/app/oracle/product/11.2.0/db_1/log/diag/clients]

<msg org_id=’oracle’ /=” time=’2012-06-18T13:41:01.773-04:00′
type=’UNKNOWN’ level=’16′ host_id=’10.20.30.40′

Using the information in this first log file, I was able to find a similar incident that had occurred for someone else and they had been able to track it down to Oracle bug 58917 ( which I could not access on Metalink ).

In the related incident ( https://savannah.cern.ch/bugs/?58917 ), they noted that this was occured following an ORA-24550, and that

For the record: the Oracle signal handler producing these ORA-24550 can probably be completed disabled (e.g. if one wants to use the ROOT signal handler) by setting DIAG_SIGHANDLER_ENABLED=FALSE

When reviewing the performance of some queries, it is sometimes useful to review the sessions statistics for each execution of the query. These session statistics complement the wait events found in ASH and trace files. The wait events do not show this information. Many of these session level statistics can be quite revealing. They can show some execution differences that are otherwise difficult, if not impossible for some, to see with trace files and ASH data.

I had a situation that required to look at these stats so I could see why one query would run fast and sometimes much slower. ASH data was not exposing this issue clearly. In order to facilitate the comparison of the data from run to run, I wrote a simple wrapper ksh shell script for the query. It saves the session statistics in a table before and after the execution of the query and then prints out the statistics in a pivot report. This turned out to be very handy to me and therefore I chose to share it with the world :)

Below is a sample output of the report. It prints only statistics that have changed and it shows all execution stats in separate columns. The executions are labeled like “run#-HH:MI:SS.ssss”. Those labels show the query’s execution sequence and elapsed time.

NAME                                  '1-00:00:00.0107' '2-00:00:00.0085' '3-00:00:00.0050' '4-00:00:00.0051' '5-00:00:00.0053'
------------------------------------- ----------------- ----------------- ----------------- ----------------- -----------------
CPU used by this session                              1                                   2                 1                 1
calls to get snapshot scn: kcmgss                     2                 3                 2                 2                 2
calls to kcmgcs                                                         4
consistent gets                                                        17
consistent gets from cache                                             17
consistent gets from cache (fastpath)                                  17
cursor authentications                                                                    1
enqueue releases                                      1                 1
enqueue requests                                      1                 1
execute count                                         2                 3                 2                 2                 2
global enqueue gets sync                              2                 2                 2
global enqueue releases                               2                 2                 2
logical read bytes from cache                                      139264
no work - consistent read gets                                         13
non-idle wait count                                   1
opened cursors cumulative                             2                 3                 2                 2                 2
opened cursors current                                1                 1                 1                 1                 1
parse count (hard)                                    1                 1
parse count (total)                                   2                 2                 2                 2                 2
pinned cursors current                                1                 1                 1                 1                 1
recursive calls                                       6                 9                 5                 5                 5
recursive cpu usage                                   1                                   2                 1                 1
session cursor cache hits                                               1
session logical reads                                                  17
session pga memory                                65536            196608            196608            196608            131072
session pga memory max                            65536            196608            196608            196608            131072
session uga memory                                                  65488             65488             65488             65488
session uga memory max                           123512            123512            123512            123512            123512
table scan blocks gotten                                               13
table scan rows gotten                                               1276
table scans (short tables)                                              1
workarea executions - optimal                         1                 1                 1                 1                 1
workarea memory allocated                                              50                37                37                37

Note that the execution time in the labels is the elaspe time difference between the capture of the before and after session stats. Not the real query execution elapse. The difference should be very low, like less than 0.01s as you can see from the above durations. Also, note that the PLSQL block that runs the query does not fetch the data. It only opens the cursor, which executes the query. This shows you how long the query takes to get the resultset ready and removes the network and application related overhead.

Here is the code:

#!/bin/sh

export v_sql_text=$(cat sql_runstat_source_query.sql)

echo 'Enter username:';read username
echo 'Please enter your password: ';stty -echo;read passwd;stty echo

sqlplus -S /nolog<
prompt connecting...
connect $username/$passwd

set echo off feed off verify off
set serveroutput on size 2000
col name for a50

prompt verifying the existence of the table query_stats...
declare
 table_exists number;
begin
 select count(*) into table_exists from dba_tables where owner = user and table_name='QUERY_STATS';
 if table_exists = 0 then
    execute immediate 'CREATE TABLE '||user||'.query_stats AS SELECT systimestamp as timestamp, '' '' before, 0 run, name, value FROM v\$statname NATURAL JOIN v\$mystat where 1=2';
    dbms_output.put_line('Table '||user||'.query_stats created.');
 else
    dbms_output.put_line('Warning! Table '||user||'.query_stats exists already. Appending...');
 end if;
end;
/
drop type query_stats_table_type;
create or replace type query_stats_type
as object
(TIMESTAMP TIMESTAMP(6) WITH TIME ZONE,
 BEFORE    CHAR(1),
 RUN       NUMBER,
 NAME      VARCHAR2(64),
 VALUE     NUMBER
);
/
create or replace type query_stats_table_type
as table of query_stats_type;
/
prompt executing the query and saving pre and post session stats...
declare
  next_run     number;
  stats_before query_stats_table_type;
  stats_after  query_stats_table_type;
  type cur_type is ref cursor;
  c            cur_type;
begin
  -- capturing pre-stats
  select nvl(max(run),-1)+1 into next_run from query_stats;
  SELECT query_stats_type(systimestamp, 'Y', next_run, name, value) bulk collect into stats_before FROM v\$statname NATURAL JOIN v\$mystat;
  -- executing the query from the var v_sql_text, which is loaded from file sql_runstat_source_query.sql
  open c for $v_sql_text;
  -- capturing post-stats
  next_run := next_run + 1;
  SELECT query_stats_type(systimestamp, 'N', next_run, name, value) bulk collect into stats_after FROM v\$statname NATURAL JOIN v\$mystat;
  -- saving stats
  insert into query_stats 
  select * from table(cast(stats_before as query_stats_table_type))
  union all
  select * from table(cast(stats_after as query_stats_table_type))
  ;
  commit;
end;
/

prompt getting the run id list...
col max_run new_value run noprint
select max(run) max_run from query_stats;

-- get the run ids and their durations and join them as CSVs to pass to the pivot query
col runlist new_value runs noprint
select listagg(run,',') within group (order by run) runlist
  from
       (select ''''||ceil(run/2)||'-'||duration_H_M_S||'''' run
          from ( SELECT distinct run,
                        to_char(extract(HOUR   FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
                        to_char(extract(MINUTE FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
                        to_char(extract(SECOND FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00.0000') AS duration_H_M_S
                   FROM query_stats
               )
         where duration_H_M_S is not null
           and mod(run,2)<>0
         order by 1
       )
;

prompt pivoting the run statistics where there is a value difference...
set linesize 200 trim on
select *
  from (
   select ceil(run/2)||'-'||duration_H_M_S as run,
          name,
          value_diff
     from (
           SELECT run,
                  name,
                  value,
                  value-lag(value) OVER (partition by name ORDER BY name, run) as value_diff,
                  to_char(extract(HOUR   FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
                  to_char(extract(MINUTE FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00')||':'||
                  to_char(extract(SECOND FROM timestamp-lag(timestamp) OVER (ORDER BY name, run)),'FM00.0000') AS duration_H_M_S
             FROM query_stats
           )
   where mod(run,2)<>0
     and value_diff > 0
   )
pivot (sum(value_diff) for run in (&runs))
order by name
;
prompt done!
exit
EOF

Some notes about it:

1- The ksh script runs an anonymous plsql block that gets dynamically modified to incorporate the statement you want to test.

2- The statement you want to test needs to be stored in a file called “sql_runstat_source_query.sql” located in the same folder as the ksh script.

3- Do not add a semi-colon at the end of your statement in the sql_runstat_source_query.sql file.

4- The query_stats table contains all the session statistics before and after each executions, not just those that changed and get printed by the pivot table. It also has the timestamp of the captures. You can therefore get more information from this data if needed. For example, you could tailor the column label to show you the full timestamp, or write your own analytics query to suite your needs.

5- The run numbers in the query_stats table are actually a serial number for the statistics capture, starting at 0. 0=first “before” capture, 1=first “after” capture, 2=second “before capture, and so on.

6- The script will create the query_stats table if it is missing, else it appends to it. Two user TYPEs are also created. None of these get dropped after execution so it’s up to you to remove them if you don’t want to keep them in your schema.

7- Remember to either truncate, rename or drop the query_stats table before testing a different statement.

8- You may need to alter the script to set your ORACLE environment variables.

Enjoy!
Marc

For only $299 you can access Virtual IOUG Collaborate 13 individually or setup a conference room at your company for the whole team. There will be two tracks broadcasted so if you have demand for both tracks, it make sense to purchase two access passes and setup two tracks broadcasted in parallel in your office so that members of your team can choose individually what to attend. I think that’s a steal even if you want to purchase this package individually.

Virtual attendance doen’t completely replace the physical presence but if you can’t come to Denver in April, this is the next best thing. Relationships that you gain from meeting your peers and speakers face to face are extremely valuable and you will cary them throughout your whole career. I’ve been just recently discussing with Rene Antunez (who’s just joined Pythian) how social media and twitter revolutionized our professional networking, and we agreed that things like Twitter alone won’t cut it for many of us. While some folks only know most of their peers online, the real relationships are established face to face — discussing a presentation with the speaker during lunch, sharing a drink at the reception or having a heated discussion in a pub near the convention center. With such relationships, social media becomes a natural extended communication channel.

But I digress… so those of you who can’t come to Denver for one reason or another, do consider taking Virtual IOUG Collaborate 2013 Pass and enjoy the session in tracks “High Availability, Disaster Recovery, Manageability” and “Performance, Scalability and Internals”. Here are some of the speakers you would have a chance to see over 4 days of sessions broadcasting:

• Kuassi Mensah, Oracle
• John Beresniewicz, Oracle
• Michael Abbey, Pythian
• Yury Velikanov, Pythian
• Craig Shallahamer, OraPub
• Karl Arao, Enkitec
• Carlos Sierra, Oracle
• Mark W Farnham, Rightsizing
• Guy Harrison, Dell
• Frits Hoogland, VX Company
• Tim Gorman, Evergreen Database Technologies
• Kyle Hailey, Delphix
• Gwen Shapira, Pythian

My favorite virtual track is Performance, Scalability and Internals but I will be at the conference physically so I will also be attending lots of sessions on Big Data and Data Science. By the way, as virtual attendee, you will get access to the recordings as well so even if you miss certain session live, you can watch it later at your convenience.

If your team is dispersed geographically, the members would need a pass each to watch broadcast live but, again, I still think it’s a steal at $299!

Looking forward to see some of you in Denver and some of you on Twitter talking about what you saw at the virtual conference. If you don’t come to Denver and not going to be virtual attendee — tell me why and what else can we do to plug you into Collaborate — I will relay your message to the IOUG Board of Directors and the Conference Committee.

http://youtu.be/j_XcIpglExE