Unexpected Performance Issue with Unified Audit and OEM

Oracle 19C. January 2023.

EM Event: Critical: database-server.domain - Disk Device sda is 98.01% busy.
Photo of flat tyre on a car

A customer was experiencing excessive I/O against the operating disk (sda), which indicated problems with /u01 or /u03.

There was nothing obviously writing a lot of data to any “sda” mounted filesystems (and no swapping), so process tracing was initiated to review I/O against processes (pidstat), a process identified and linked to a query via GV$PROCESS and GV$SESSION, and this query against the audit trail was identified as a primary culprit.

(warning: pidstat can be very resource hungry – please use with caution!)

Bad SQL - sql_id=3wybn83gkuc4k

SELECT TO_CHAR(current_timestamp AT TIME ZONE 'GMT','YYYY-MM-DD HH24:MI:SS TZD') AS curr_timestamp
      ,SUM(failed_count) AS failed_count
      ,TO_CHAR(MIN(first_occur_time),'yyyy-mm-dd hh24:mi:ss') AS first_occur_time
      ,TO_CHAR(MAX(last_occur_time),'yyyy-mm-dd hh24:mi:ss') AS last_occur_time
FROM
(
SELECT COUNT(db_user) AS failed_count
      ,MIN(extended_timestamp) AS first_occur_time
      ,MAX(extended_timestamp) AS last_occur_time
  FROM sys.dba_common_audit_trail
 WHERE action BETWEEN 100 AND 102
   AND returncode != 0
   AND statement_type = 'LOGON'
   AND extended_timestamp >= current_timestamp - to_dsinterval('0 0:30:00')
UNION
SELECT COUNT(dbusername) AS failed_count
      ,MIN(event_timestamp) AS first_occur_time
      ,MAX(event_timestamp) AS last_occur_time
  FROM unified_audit_trail
 WHERE action_name = 'LOGON'
   AND return_code <> 0
   AND event_timestamp >= current_timestamp - to_dsinterval('0 0:30:00')
)

The problem presented itself a couple months after the implementation of Unified Audit (with a long retention).
The unified audit table AUDSYS.AUD$UNIFIED is partitioned by EVENT_TIMESTAMP, which is one of the predicates, and the code is only looking at the last 30 minutes of the data.

BUT, we aren’t looking just at the partitioned audit table. If the database cannot write to the audit table (e.g. if it is a physical standby), there is an overflow location of $ORACLE_BASE/audit/$instance_name. This contains “.bin” files which are processed and read by the view UNIFIED_AUDIT_TRAIL, and joined to AUDSYS.AUD$UNIFIED.

As the “.bin” files cannot be indexed, every file for each instance is translated and read every time the code is invoked.
Which is every 30 minutes.

pwd
/u01/app/oracle/audit/<instance_name>

ls -1 
ora_audit_1127534399_3323516267.bin
ora_audit_1127554851_1290166488.bin
ora_audit_1127556228_1457226874.bin
ora_audit_1127570671_3180208504.bin
etc... 

many many files, each up to 10MB in size

But where is this SQL coming from?

There is a metric within Oracle Enterprise Manager (OEM) called “Failed Login Count”. This runs every 30 minutes. Coincidence? Nope.

How does this metric work to determine the amount of failed logins (not) connecting to the database every 30 minutes? It queries your audit. To do this, it uses a pre-processor PERL program to determine what sort of auditing you are doing (unified/OS/DB/XML/etc) and runs the relevant query against the database to pull the audit records. Remember, unless you explicitly have disabled it, if you are on Oracle 12.1 or above you are auditing failed logons by default. Handy.

The preprocessor for this code is called “failLogin.pl” – I discovered this in MOS 1265699.1 (which is about a related problem from Oracle 12.1, when Unified Audit didn’t work properly and had significant performance issues.)

You can find failLogin.pl in the $AGENT_HOME/*/scripts/ (I’m being deliberately vague here as it seems to have moved around in different versions!)

$ cd $AGENT_HOME (you can find this by looking at the background process with: ps -ef | grep agent )
$ find . -name failLogin.pl -print

Fixing This

So, what’s the solution to this excessive disk usage, processing all of those .bin files every 30 minutes?

  1. Switch off the metric in OEM (but this is a really useful metric and can highlight hacking attempts, password problems, and deployment failure)
  2. Create a nice new segregated and very very fast mount point for the .bin files
  3. Keep the “.bin” audit directory really tidy. This means losing audit records of course, which you may not want.
  4. Load the “.bin” records into the database using DBMS_AUDIT_MGMT.LOAD_UNIFIED_AUDIT_FILES, and remove them (which may not be possible if this is a Physical Standby open for READ)
  5. Copy the failLogin.pl to a safe place, and amend the SQL to only read the table and not the .bin files. We can do this by accessing via the table directly, and not via the view UNIFIED_AUDIT_TRAIL (see amended SQL below)
  6. I’m sure you can think of something else
SELECT TO_CHAR(current_timestamp AT TIME ZONE 'GMT','YYYY-MM-DD HH24:MI:SS TZD') AS curr_timestamp
      ,SUM(failed_count) AS failed_count
      ,TO_CHAR(MIN(first_occur_time),'yyyy-mm-dd hh24:mi:ss') AS first_occur_time
      ,TO_CHAR(MAX(last_occur_time),'yyyy-mm-dd hh24:mi:ss') AS last_occur_time
FROM (
    SELECT COUNT(db_user) AS failed_count
          ,MIN(extended_timestamp) AS first_occur_time
          ,MAX(extended_timestamp) AS last_occur_time
     FROM sys.dba_common_audit_trail
    WHERE action BETWEEN 100 AND 102
          AND returncode != 0
          AND statement_type = 'LOGON'
          AND extended_timestamp >= current_timestamp - to_dsinterval('0 0:30:00')
    UNION
    SELECT COUNT(dbid) AS failed_count
          ,MIN(event_timestamp) AS first_occur_time
          ,MAX(event_timestamp) AS last_occur_time
     FROM audsys.aud$unified
    WHERE action = 100
      AND return_code <> 0
      AND event_timestamp >= current_timestamp - to_dsinterval('0 0:30:00')
);

NOTE: This code ran in a couple of seconds, rather than the many minutes of the version accessing the .bin files. Of course, you are missing reading all of the audit making the metric fairly useless on a READ-ONLY Physical Standby.

Of course, if you change the code there’s a very good chance it will get overwritten the next time you patch, or use a different SQL if you change how you are auditing, and you will have to remember to keep the code maintained manually. Not ideal!

Advertisement

Turning rows into columns

Penshaw Monument
Turning Moo’s into Columns?

It’s odd how some things pass you by in new Oracle releases. Today I discovered “sys.odcinumberlist” and “sys.odcivarchar2list“.

I was wanting to generate a pre-defined list for a join to ensure each value was represented, and came up with the new in Oracle 12 function “sys.odcinumberlist”, so not new! Well, there’s 2 straightforward functions: “sys.odcinumberlist” and “sys.odcivarchar2list”.

How are they used?

SELECT column_value AS number_list
FROM sys.odcinumberlist(1,2,5,7,9,5,2,-34,5,43,2,0)
ORDER BY number_list;

NUMBER_LIST
-----------
        -34
          0
          1
          2
          2
          2
          5
          5
          5
          7
          9
         43

12 rows selected.

Note how I have had to alias the "column value" virtual column to allow mne to sort the list
SELECT column_value AS char_list FROM sys.odcivarchar2list('A','V','DD');

CHAR_LIST
---------
A
V
DD

Nice, simple, with a limit of 32768 items in the list. So how was I using it? I was checking to see which profiles existed in a database (the list was somewhat longer than this, as was the SQL, but this is good for a demo) so I generated my full list of known profiles to join to the existing profiles in each database.

WITH my_profiles AS (
    SELECT
        column_value AS profile_name
    FROM
        sys.odcivarchar2list(
            'DEFAULT'
          , 'SOME_OTHER_PROFILE' --etc etc etc 
        )
)
SELECT
    mp.profile_name
  , nvl( profile , '<does-not-exist>') AS profile
  , resource_name
  , limit
FROM
    my_profiles  mp
    LEFT OUTER JOIN dba_profiles dp ON ( mp.profile_name = dp.profile )
ORDER BY
    profile
  , resource_name;

PROFILE_NAME         PROFILE              RESOURCE_NAME                  LIMIT
-------------------- -------------------- ------------------------------ -----------
SOME_OTHER_PROFILE   <does-not-exist>
DEFAULT              DEFAULT              COMPOSITE_LIMIT                UNLIMITED
DEFAULT              DEFAULT              CONNECT_TIME                   UNLIMITED
DEFAULT              DEFAULT              CPU_PER_CALL                   UNLIMITED
DEFAULT              DEFAULT              CPU_PER_SESSION                UNLIMITED
DEFAULT              DEFAULT              FAILED_LOGIN_ATTEMPTS          10
DEFAULT              DEFAULT              IDLE_TIME                      UNLIMITED
DEFAULT              DEFAULT              INACTIVE_ACCOUNT_TIME          UNLIMITED
DEFAULT              DEFAULT              LOGICAL_READS_PER_CALL         UNLIMITED
DEFAULT              DEFAULT              LOGICAL_READS_PER_SESSION      UNLIMITED
DEFAULT              DEFAULT              PASSWORD_GRACE_TIME            7
DEFAULT              DEFAULT              PASSWORD_LIFE_TIME             180
DEFAULT              DEFAULT              PASSWORD_LOCK_TIME             1
DEFAULT              DEFAULT              PASSWORD_REUSE_MAX             UNLIMITED
DEFAULT              DEFAULT              PASSWORD_REUSE_TIME            UNLIMITED
DEFAULT              DEFAULT              PASSWORD_ROLLOVER_TIME         -1
DEFAULT              DEFAULT              PASSWORD_VERIFY_FUNCTION       NULL
DEFAULT              DEFAULT              PRIVATE_SGA                    UNLIMITED
DEFAULT              DEFAULT              SESSIONS_PER_USER              UNLIMITED

There’s a number of other ways to do this, including using the UNPIVOT function, creating your own table type, etc, but this was the nice and simple option I was looking for.

Huge Pages on Exadata

Quick note to myself: Oracle has deprecated the initialisation parameter use_large_pages=”true” on Exadata as of 19.13 (OK – could be 19.12, I’ve not checked)

If you started your database in 19.11, and had this set, you got yourself a warning in the alert log (if you have a look):
“WARNING: use_large_pages=TRUE is not a recommended setting for database on Exadata”

from 19.13, this has changed to

“ERROR: use_large_pages = TRUE is not a supported setting for database on Exadata”
” : suggested values are AUTO_ONLY or ONLY”

So what’s the difference?

use_large_pages = TRUE – allocate memory out of huge pages. If there aren’t enough huge pages, allocate the rest out of standard pages. This can result in performance degradation and increased transaction lookaside buffer allocation to manage the standard pages (taking even more memory).

use_large_pages = ONLY – allocate memory out of large pages. If there aren’t enough large pages, fail to start the database.

use_large_pages = AUTO_ONLY – allocate memory out of large pages. If there aren’t enough large pages configured, configure some more by increasing the kernel parameter vm.nr_hugepages. If that fails (e.g. if it can’t get enough contiguous memory to deallocate from standard pages and allocate the new huge pages) fail to start the database. This does result in an “up-only” scenario for huge page allocation as there is no mechanism to automatically deallocate the hugepages once they have been allocated, but the changes are not written permanently to the kernel config so a reboot would take care of it.

So what should you do?

Well, the idea behind AUTO_ONLY is seems to be Oracle ongoing “death of the DBA”, whereby the DBA doesn’t need to understand huge pages and automatically gets the memory and performance benefits associated with using huge pages.

No huge pages allocated:
$ cat /proc/meminfo | grep -i huge
AnonHugePages: 0 kB
ShmemHugePages: 0 kB
FileHugePages: 0 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Hugepagesize: 2048 kB
Hugetlb: 0 kB

------------------------------------------------------------------------

SQL> ALTER system SET use_large_pages='AUTO_ONLY' sid='*' scope=spfile;
 
System altered.

SQL> shutdown immediate 
ORACLE instance shut down.

SQL> startup nomount
ORACLE instance started.

Total System Global Area 3154114080 bytes
Fixed Size                  9139744 bytes
Variable Size            1207959552 bytes
Database Buffers         1929379840 bytes
Redo Buffers                7634944 bytes

(note: "startup nomount" is enough to allocate memory, so the huge_pages are generated at this point)

------------------------------------------------------------------------
And they have magically appeared! (note: total allocation will vary by a page or two)

$ cat /proc/meminfo | grep -i huge
AnonHugePages:         0 kB
ShmemHugePages:        0 kB
FileHugePages:         0 kB
HugePages_Total:    1506
HugePages_Free:        3
HugePages_Rsvd:        3
HugePages_Surp:        0
Hugepagesize:       2048 kB
Hugetlb:         3082240 kB

$ sysctl vm.nr_hugepages
vm.nr_hugepages = 1506
Oracle must be changing the setting and performing a "sysctl" to allocate the pages. If anyone knows what their algorithm is to decide if the pages should be allocated to SGA (and "stolen" from potential PGA and O/S utilisation), and at what percentage will Oracle stop taking from the PGA and O/S? 

An 8G (7972M available) server is allowed an SGA of 6,906M (86% of available memory). Not a lot left for PGA there.

set it too large and you could hit 
"ORA-27104: system-defined limits for shared memory was misconfigured"
which might result in
"ORA-00700: soft internal error, arguments: [sms physmem limit], [6828326912]... "
or
"ORA-00700: soft internal error, arguments: [pga physmem limit], [1048576000]..."

due to being unable to allocate PGA/SGA. I'm talking:

"WARNING: pga_aggregate_limit value is too high for the
amount of physical memory on the system


I'd upped the SGA_MAX_SIZE to 6516M, started the DB, lowered it to 3000M and restarted the DB without a server reboot and...

Total System Global Area 3154114080 bytes
Fixed Size                  9139744 bytes
Variable Size             637534208 bytes
Database Buffers         2499805184 bytes
Redo Buffers                7634944 bytes
Database mounted.
Database opened.

SQL > !cat /proc/meminfo | grep -i huge
AnonHugePages:         0 kB
ShmemHugePages:        0 kB
FileHugePages:         0 kB
HugePages_Total:    3258 <- that's a lot of 2M pages (6516M)
HugePages_Free:     1752 <- we've only allocated 3000M. No cleanup without a reboot
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
Hugetlb:         6672384 kB


Happy huge pages everyone and keep checking that alert log.

Oracle Optimizer System Statistics

System Statistics Are a Little Complex


Oh System statistics! Should we gather them? Should we not?
What do they mean? What are they doing to the optimizer?

[tl;dr – in almost all cases, DON’T GATHER SYSTEM STATISTICS. DON’T SET MBRC. LET THEM DEFAULT!]

First you need to be armed with a piece of information. When Oracle optimizes your SQL, it produces a COST to compare each SQL execution plan. Exactly what is this COST? It’s not seconds. It’s not quite the amount of I/O required. It’s not an arbitrary figure either. Oracle Optimizer Cost is the cost of getting your data in terms of SINGLE BLOCK READS. Remember this for later.

Lets have a look at the system stats defaults :

SELECT sname,pname,pval1 FROM SYS.AUX_STATS$ ORDER BY 1,2;
SNAME                PNAME                               PVAL1
-------------------- ------------------------------ ----------
SYSSTATS_INFO        DSTART
SYSSTATS_INFO        DSTOP
SYSSTATS_INFO        FLAGS                                   0
SYSSTATS_INFO        STATUS
SYSSTATS_MAIN        CPUSPEED
SYSSTATS_MAIN        CPUSPEEDNW                           2911 (this will vary)
SYSSTATS_MAIN        IOSEEKTIM                              10
SYSSTATS_MAIN        IOTFRSPEED                           4096
SYSSTATS_MAIN        MAXTHR
SYSSTATS_MAIN        MBRC
SYSSTATS_MAIN        MREADTIM
SYSSTATS_MAIN        SLAVETHR
SYSSTATS_MAIN        SREADTIM

What we are looking for here is the the 3 metrics highlighted in colour. As we can see, the are not set. By default, we need to calculate those, or know where to find the defaults for those values to get to them. Once we have those 3 metrics, we can calculate the RATIO used by the optimizer to convert MULTIBLOCK READ into a cost metric of SINGLE BLOCK READS.

The CPU speed is used to calculate the COST of the query in terms of CPU required. This is small percentage of the query cost but it may help decide which plan is chosen. This is also converted from CPU cost into a cost metric of SINGLE BLOCK READS.

Lets get the values for MBRC, MREADTIM and SREADTIM.

MBRC is easy. If it is not explicitly set, it uses the init.ora parameter “db_file_multiblock_read_count” and uses that. However, by default (and also my recommendation) this should not be set, meaning Oracle will use the hidden parameter “_db_file_optimizer_read_count” to cost your queries. This defaults to 8. [note: this is not the value used in execution. Oracle attempts to do 1MB reads, and uses the value in “_db_file_exec_read_count” to control the multiblock reads at execution time. For an 8K block size, this is set to 128.

SREADTIM and MREADTIM are calculations based upon information we now have:
SREADTIM = IOSEEKTIM + db_block_size        / IOTFRSPEED = 10+(8192 /4096) = 12
MREADTIM = IOSEEKTIM + db_block_size * MBRC / IOTFRSPEED = 10+(8192*8/4096) = 26

Right! Now we have more information and can calculate a ratio. The multi block cost-per-block. This will allow us to take the number of blocks in (for example) a table scan [DBA_TAB_STATISTICS.BLOCKS statistic] and covert it to the cost metric os SINGLE BLOCK READS, meaning we can compare (for example) a FULL TABLE SCAN’s I/O directly with the I/O required for an Index Range Scan and Table Lookup.

multi-block cost-per-block = 1/MBRC * MREADTIM/SREADTIM = 1/8 * 26/12 = 0.270833

If we pull some data from a 10053 trace, where I have a table scan of a table containing 1,000,000 blocks, we should see the 1,000,000 blocks being converted to 270,833 “single block read blocks” for COST purposes.

[10053] SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for COST_CHECK[COST_CHECK]
  SPD: Return code in qosdDSDirSetup: NOCTX, estType = TABLE
  Table: COST_CHECK  Alias: COST_CHECK
    Card: Original: 1000000.000000  Rounded: 1000000  Computed: 1000000.000000  Non Adjusted:1000000.000000
  Scan IO  Cost (Disk) =   270835.000000
  Scan CPU Cost (Disk) =   7411440000.000001
  Total Scan IO  Cost  =   270835.000000 (scan (Disk))
                       =   270835.000000
  Total Scan CPU  Cost =   7411440000.000001 (scan (Disk))
                       =   7411440000.000001
  Access Path: TableScan
    Cost:  271041.492812  Resp: 271041.492812  Degree: 0
      Cost_io: 270835.000000  Cost_cpu: 7411440000
      Resp_io: 270835.000000  Resp_cpu: 7411440000
  Best:: AccessPath: TableScan
         Cost: 271041.492812  Degree: 1  Resp: 271041.492812  Card: 1000000.000000  Bytes: 0.000000

Well we were close! There’s a fudge factor in play here, but 270,835 is pretty much 270,833 🙂

We can also work out the CPU element of the COST.
Scan IO  Cost (Disk) =   270835.000000
Cost: 271041.492812
so CPU cost must be 271041.492812 – 270835.000000 = 206.492812

Scan CPU Cost (Disk)=7411440000.000001 so doing the maths to convert to units of “single block read time”…

CPUSPEEDNW = 2,991 (Mhz, but we convert 2,991,000 Khz)

= 7,411,440,000 / 2,991,000 / SREADTIM
=  ‭2,477.913741223671013039 / 12
‭= 206.49281176863925108659311267135‬ cost of CPU in units of SREADTIM

So now you can see how your system statistics can fundamentally change the optimizer by changing the ratio of multiblock-reads to single block reads.

You want to play yourself and see what happens? Of course you do…

Here’s an excel spreadsheet where you can plug in your numbers and see what happens to the ratio between single and multi block reads to see how system stats influence the optimizer. By plugging in different numbers, you will see how complex the interactions are – so what’s the ideal numbers? Use the DEFAULTS in almost all cases** [WARNING – don’t go changing your system stats based on this statement. You might experience a significant amount of plan changes, some of which may be very very bad!]:


Also, this is my version of a script by Franck Pachot, and also based on work by Chris Antognini, which you can run against your system:

select pname,pval1,calculated,formula from sys.aux_stats$ where sname='SYSSTATS_MAIN'
model
reference sga on (
select 'Database Buffers' name,sum(bytes) value from v$sgastat where name in ('shared_io_pool','buffer_cache')
) dimension by (name) measures(value)
reference parameter on (
select name,decode(type,3,to_number(value)) value from v$parameter where name='db_file_multiblock_read_count' and ismodified!='FALSE'
union all
select name,decode(type,3,to_number(value)) value from v$parameter where name='sessions'
union all
select name,decode(type,3,to_number(value)) value from v$parameter where name='db_block_size'
union all
SELECT a.ksppinm name, to_number(b.ksppstvl) value FROM x$ksppi a, x$ksppsv b WHERE a.indx=b.indx AND ksppinm like '_db_file_optimizer_read_count'
)
dimension by (name) measures(value)
partition by (sname) dimension by (pname) measures (pval1,pval2,cast(null as number) as calculated,cast(null as varchar2(120)) as formula) rules(
calculated['MBRC']=coalesce(pval1['MBRC'],parameter.value['db_file_multiblock_read_count'],parameter.value['_db_file_optimizer_read_count'],8),
calculated['MREADTIM']=coalesce(pval1['MREADTIM'],pval1['IOSEEKTIM'] + (parameter.value['db_block_size'] * calculated['MBRC'] ) / pval1['IOTFRSPEED']),
calculated['SREADTIM']=coalesce(pval1['SREADTIM'],pval1['IOSEEKTIM'] + parameter.value['db_block_size'] / pval1['IOTFRSPEED']),
calculated['_multi block Cost per block']=round(1/calculated['MBRC']*calculated['MREADTIM']/calculated['SREADTIM'],4),
calculated['_single block Cost per block']=1,
formula['MBRC']=case when pval1['MBRC'] is not null then 'MBRC' when parameter.value['db_file_multiblock_read_count'] is not null then 'db_file_multiblock_read_count' when parameter.value['_db_file_optimizer_read_count'] is not null then '_db_file_optimizer_read_count (db_file_multiblock_read_count not set, which is good!)' else '= not sure so used 8' end,
formula['MREADTIM']=case when pval1['MREADTIM'] is null then '= IOSEEKTIM + db_block_size * MBRC / IOTFRSPEED' end||' = '||pval1['IOSEEKTIM']||'+('||parameter.value['db_block_size']||'*'||calculated['MBRC']||'/'||pval1['IOTFRSPEED']||')',
formula['SREADTIM']=case when pval1['SREADTIM'] is null then '= IOSEEKTIM + db_block_size / IOTFRSPEED' end||' = '||pval1['IOSEEKTIM']||'+('||parameter.value['db_block_size']||'/'||pval1['IOTFRSPEED']||')',
formula['_multi block Cost per block']='= 1/MBRC * MREADTIM/SREADTIM = 1/'||calculated['MBRC']||' * '||calculated['MREADTIM']||'/'||calculated['SREADTIM'],
calculated['_maximum mbrc']=sga.value['Database Buffers']/(parameter.value['db_block_size']*parameter.value['sessions']),
formula['_maximum mbrc']='= buffer cache blocks/sessions (small cache limiter) = ' || sga.value['Database Buffers']/parameter.value['db_block_size']||'/'||parameter.value['sessions'],
formula['_single block Cost per block']='relative to the multi blovk cost per block. Always 1!',
formula['CPUSPEED']='overrides CPUSPEEDNW when set',
formula['CPUSPEEDNW']='CPU speed Mhz - non workload',
formula['IOSEEKTIM']='IO seek time in ms',
formula['IOTFRSPEED']='IO transfer speed in KB/s',
formula['MAXTHR']='Maximum IO system throughput',
formula['SLAVETHR']='average parallel slave IO throughput'
) order by 1;

** there is a case for gathering ‘exadata’ system stats. Increasing the IOTRFSPEED to 200,000 and changing the MBRC to (probably) 128 or 64 will *really* change the ratios, forcing a lot of full table scans down onto the storage cells, instead of using mediocre indexes. This should be considered (and thoroughly tested) if you have a DW on a dedicated Exadata. From a little more on exadata stats, check this blog post

Goldengate Install Error

Sometimes you waste much more time than you can believe because the instrumentation of the system isn’t great. If you don’t know what a system is doing, you can’t easily fix it. Time should be take to instrument your code, and ensure that any outputs from that instrumentation are readily understandable by others.

Here’s a mild frustration from this week that I encountered. I was installing Goldengate…

./runInstaller -silent -waitforcompletion -responseFile /u01/migrate/gg/software/fbo_ggs_Linux_x64_shiphome/Disk1/install_source.rsp
Starting Oracle Universal Installer...

Checking Temp space: must be greater than 120 MB. Actual 21571 MB Passed
Checking swap space: must be greater than 150 MB. Actual 24575 MB Passed
Preparing to launch Oracle Universal Installer from /tmp/OraInstall2020-07-30_08-03-36PM. Please wait ...
[WARNING] [INS-08109] Unexpected error occurred while validating inputs at state 'installOptions'.
CAUSE: No additional information available.
ACTION: Contact Oracle Support Services or refer to the software manual.
SUMMARY:
- java.lang.NullPointerException

Oh my word! ACTION: Contact Oracle Support Services! java.lang.NullPointerException! Something is terribly wrong!

I’d better re-read this error message carefully… Unexpected error occurred while validating inputs at state ‘installOptions’. What? Validating inputs? Lets have a look at the inputs from the response file:

install_source.rsp

################################################################################
## ##
## Oracle GoldenGate installation option and details ##
## ##
################################################################################

#-------------------------------------------------------------------------------
# Specify the installation option.
# Specify ORA19c for installing Oracle GoldenGate for Oracle Database 19c or
# ORA18c for installing Oracle GoldenGate for Oracle Database 18c or
# ORA12c for installing Oracle GoldenGate for Oracle Database 12c or
# ORA11g for installing Oracle GoldenGate for Oracle Database 11g
#-------------------------------------------------------------------------------
INSTALL_OPTION=ORA11G

#-------------------------------------------------------------------------------
# Specify a location to install Oracle GoldenGate
#-------------------------------------------------------------------------------
SOFTWARE_LOCATION=/u01/gg

START_MANAGER=
MANAGER_PORT=
DATABASE_LOCATION=
INVENTORY_LOCATION=
UNIX_GROUP_NAME=

 

I only have 2 inputs; the INSTALL_OPTION and the SOFTWARE_LOCATION… and the INSTALL_OPTION is wrong! This field is case sensitive. ORA11G does not match ORA11g, so I get a dramatic null pointer exception and a failure. It would have been a much quicker remediation if the Oracle error had been curated a little better and the programmer a little more sympathetic to users of their code.

How about:
Installation parameter INSTALL_OPTION invalid,
rather than
Unexpected error occurred while validating inputs at state ‘installOptions’

UKOUG Techfest19

I’ve just returned from Techfest19 – the UKOUG Flagship Oracle Tech conference – and it was simply excellent.

79374309_10158533454103840_8801012542173347840_o

Amazing Sunset from the Grand

It was held at The Grand Hotel in Brighton, and it was grand. If you missed it, you really missed out. 250 mostly amazing  presentations.

I did 2 main ones about Oracle Statistics, and also MC’d the Jonathan Lewis Optimizer Panel, alongside Martin Widlake. The highlight of my conference was asking a left-field question of an Oracle Architect about Full Table Scans, which has resulted in the potential for a change to the code to make them (possibly slightly) more efficient. Thank you for listening Roger!

78256648_10158533454068840_8935776057437454336_o

Oracle ACE Dinner

 

 

 

 


If you missed my 2 sessions on Database Statistics, you can find a webinar and a Blair-Witch style video of each of them here on my website:


78372397_10158533455058840_55580213999828992_o

UKOUG Guest Speaker, before the party

Oracle Tech Conferences

It’s mid-November 2019. The leaves have mostly fallen and the nights are drawing in. That can only mean… it’s time for Europes 2 biggest Independent Oracle User Groups to have their conferences.

The first, starting Tuesday 18th November, is DOAG – the German Oracle User Group – in Nuremberg.nuremberg I’m flying out there a couple of days beforehand as I have meetings, and it’s nice to travel and chill out too. This year I’m speaking about Oracle Database Statistics at both conferences, but I only have time for the “basics” talk at DOAG so I’ll try to get some Unconference time to talk about when it gets harder.

Then, from the 1st to the 4th December, it’s the UKOUG Techfest 2019. This is slightly different this year as we have split the main conference, comprising Tech, Business Apps and JDE into 3 separate components at different times of the year. The Tech-only conference has stayed in the December slot (with Business Apps moving to June).

We have also moved the conference to Brighton. New location, Great town.

I’ll be talking about  Oracle Database Statistics, but this time in 2 slots, Database Stats #1. Doing it Right, the Easy Way (Monday 2nd December 09:00), then in a bit more depth I’ll do Database Stats #2. Doing it Right, When it’s Harder (Wednesday 4th December 11:00)

For a UKOUG “conference survival guide”, I recommendbrighton-autumn UKOUG Techfest Survival Guide 2019. All you need to know about getting the most out of 3.5 days of Tech shenanigans. Turn up, learn, but also try to meet people and have fun! I hope to see you at one of both of these conferences, maybe have a coffee or somethings stronger – easy on the stalking though (read Martins Survival Guide first)

If you have not registered for Techfest 2019, you can do that here: UKOUG TechFest 2019!

There a full agenda of around 250 Oracle-related Tech talks. The problem isn’t trying to work out if there’s enough to see, but trying to work out how to prioritise all of them!

See you there!

techfest19_2000x400_techfest

Parallel Madness

usain-bolt-1I’ve noticed at a few clients with data warehouses recently that the Developers and, upon occasion, Business Users have a real fondness for hinting the SQL they are producing with one particular hint. PARALLEL.

As any fule kno, this IS the magic go-faster hint. PARALLEL(2) is obviously twice as fast as serial execution. PARALLEL(4) is amazing and PARALLEL(64) like Usain Bolt on Red Bull.

The problem is that, like all database features, parallel query comes with a cost.

When you specify /*+ PARALLEL(n) */ you are telling the optimizer that it has a lot more resources to use to complete this particular query. Not a single thread but many. PARALLEL(10) will use 21 processes to complete its execution – 20 Parallel Execution Server (10 producers, 10 consumers) and a coordinator (which is your connections shadow process) which will deal with any aspects of the parallel plan which cannot be parallelised.

Allowed free reign to use PARALLEL, devs and users will quickly consume all of the resources available on a given server, causing contentions which will inevitably slow down the overall execution of every piece of code executing on there. To illustrate this, I’d like to use an example I came across a while ago to show how excess PARALLEL of a single statement can be problematic itself.

Lets say I have a single server with 16 cores, lots of memory and a decent SSD array so the problem will centre around the CPU. Inevitably your 16 cores will be hyperthreaded. This then looks to Oracle like you have 32 cores. Whilst Oracle knows you have 16 hyperthreaded cores, you get CPU_COUNT=32

NOTE: 16 cores hyperthreaded DO NOT have the power of 32 cores, especially when dealing with databases. Some database workloads are actually WORSE with hyperthreading enabled (e.g. Data Warehouse systems on SQL Server). Inevitably the server admins will have enabled it unless you can provide cast-iron evidence to have it disabled.

I have a statement which the users are complaining about. It starts with the  following code: SELECT /*+ PARALLEL */ (complex multi-table join)

So what does this unrestricted (and therefore DEFAULT!) degree of parallelism (DOP) do in this case?
The default DOP is defined as PARALLEL_THREADS_PER_CPU x CPU_COUNT=2 x 32 = PARALLEL(64)
On RAC it is PARALLEL_THREADS_PER_CPU x CPU_COUNT x INSTANCE_COUNT!

Lets have a look at the ACTIVITY of this PARALLEL(64) query:

parallel_64_activity

You can see from the screenshot that Oracle knows there are 16 cores but it has gone PARALLEL(64), using 128 parallel exection slaves and fully expecting to have the available resources to run PARALLEL(64) efficiently. The execution plan is calculated around this assumption. There are 64 parallel execution slaves attempting to work on this at the same time. It’s worth looking at the metrics associated with this query.

Peaks of 2GB/s disk, 140GB of TEMP and 32 CPU’s.

parallel_64_metrics

The query took 36.9 minutes to complete.

I had the query changed to inject a modicum of realism into the available resources at the time of the run, and restricted the DOP to PARALLEL(8).

parallel_8_activity

Oracle is restricted to the limited amount of resource, which is availble. The execution plan is different, to reflect the lower amount of available resources. Looking at the metrics:

Peaks of 1GB/s, 3GB of TEMP and 12 CPU’s.

parallel_8_metrics

The query took 10.3 minutes to complete. 3 times quicker!

It is worth noting that testing the query in isolation with PARALLEL(16) took 7 minutes to complete, but that DOP would have resource-starved the server as a whole causing everything else currently executing to slow down, and was discounted as an option.

With PARALLEL, less can be better.
Using PARALLEL for everything can be counter-productive.
Co-ordinating PARALLEL across multiple RAC nodes can be disasterous without careful design to take advantage of this feature (using PARALLEL_LOCAL_FORCE=TRUE will restrict parallel processing to a single node). Oracle recommend you don’t do this. Other opinions are available and I generally recommend setting this to TRUE.

We have a limited amount of resources on our servers. Working within those resource limitations will provide substantial benefits.

Before using Parallel processing, I’d recommend thoroughly reading the VLDB and Partitioning Guide appropriate to your database release!

If you use PARALLEL:

  • Use Resource Manager to restrict DOP appropriately for different groups of users.
  • Consider setting PARALLEL_LOCAL_FORCE=TRUE
  • Consider setting PARALLEL_THREAD_PER_CPU=1, especially where you have hyperthreading enabled.
  • Consider your overall workload, not just the SQL you are working with right now.

 

Where’s my Oracle SQL Plan Baseline?

saeed-mhmdi-130222-unsplashNo so long ago I was having fun creating SQL Plan Baselines in a old 11.2.0.3 database due to be decomissioned but which needs to keep running for a while (no doubt several years) – so minimal time/money to be expended on it. Then, one day, I couldn’t create a baseline and needed to figure out why…

We get the occasional painful plan change, so pinning down an acceptable historic plan using a Baseline is becoming a regular occurrence. The standard route for this is:

1. Notice plan isn’t good and that we have been running with a good plan historically
2. Identify an plan hash value which is acceptable
3. Load it from the library cache if that plan is in there (unlikely)

[ Kerry Osborne has a useful blog post/script for this so I won’t reproduce here: http://kerryosborne.oracle-guy.com/2012/03/displaying-sql-baseline-plans/ ]

4. If not, create a SQL Tuning Set from AWR with that specific plan and convert the SQL Tuning Set into a Baseline. You will need the begin-and-end snap id’s containing the plan, the sql_id and the plan_hash_value for the specific plan you want to baseline:

Please ensure you have suitable licensing before running any of the following code!

declare
 baseline_ref_cur DBMS_SQLTUNE.SQLSET_CURSOR;
begin
 DBMS_SQLTUNE.CREATE_SQLSET('NEIL');
 open baseline_ref_cur for
 select VALUE(p) from table(
 DBMS_SQLTUNE.SELECT_WORKLOAD_REPOSITORY(&begin_snap_id, &end_snap_id,'sql_id='||CHR(39)||'4jcxvz3adqbs2'||CHR(39)||'and plan_hash_value=1905606778',NULL,NULL,NULL,NULL,NULL,NULL,'ALL')) p;
 DBMS_SQLTUNE.LOAD_SQLSET('NEIL', baseline_ref_cur);
end;
/

Did we get it?

select * from dba_sqlset_statements where sqlset_name = 'NEIL';

SQLSET_NAME, SQLSET_OWNER, SQLSET_ID, SQL_ID,       FORCE_MATCHING_SIGNATURE, SQL_TEXT,                                   PARSING_SCHEMA_NAME, PLAN_HASH_VALUE ...
----------------------------------------------------------------------------------------------------------------------------------------------------------
NEIL         NEIL_DBA             35  4jcxvz3adqbs2 6134983393191283611       INSERT WHEN CNT = 1 THEN INTO SOME_TABLE...  APP                  1905606778      ...

Cool! I have captured the SQL. Lets create the baseline using: dbms_spm.load_plans_from_sqlset

declare
cnt number;
begin
 cnt := dbms_spm.load_plans_from_sqlset(sqlset_name=>'NEIL',SQLSET_OWNER=>'NEIL_DBA');
 dbms_output.put_line('Plans Loaded : '||to_char(cnt));
end;
/
... and I get ...

Plans Loaded : 0

Zero plans? So what plans are in there? Has my plan actually appeared?

select SQL_HANDLE,PLAN_NAME,CREATOR,ORIGIN,PARSING_SCHEMA_NAME, ENABLED,ACCEPTED,REPRODUCED,CREATED
  from dba_sql_plan_baselines where origin like 'MANUAL-LOAD%' order by created desc;

SQL_HANDLE           PLAN_NAME                      CREATOR   ORIGIN      PARSING_SCHEMA_NAME  ENABLED  ACCEPTED  REPRODUCED  CREATED
-----------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_23829f7bf3712438 SQL_PLAN_270nzggtr291s1a6ce30c NEIL_DBA  MANUAL-LOAD APP                  YES      YES       YES         2018-12-31 00.00.00.000000000

No! But how do I prove that? Baselines don’t have the SQL ID associated with them?

Here’s some code from [blog post here: http://oracleprof.blogspot.com/2011/07/how-to-find-sqlid-and-planhashvalue-in.html ] which will take the SQL_Handle and display the SQL ID and Plan Hash Value (you may need an explicit grant to use DBMS_CRYPTO in your PDB for this to work):

For SQL Handle: SQL_23829f7bf3712438 

declare
v_sqlid VARCHAR2(13);
v_num number;
BEGIN
 dbms_output.put_line('SQL_ID '||' '|| 'PLAN_HASH_VALUE' || ' ' || 'SQL_HANDLE ' || ' ' || 'PLAN_NAME');
 dbms_output.put_line('-------------'||' '|| '---------------' || ' ' || '------------------------------' || ' ' || '--------------------------------');
 for a in (select sql_handle, plan_name, trim(substr(g.PLAN_TABLE_OUTPUT,instr(g.PLAN_TABLE_OUTPUT,':')+1)) plan_hash_value, sql_text
from (select t.*, c.sql_handle, c.plan_name, c.sql_text from dba_sql_plan_baselines c, table(dbms_xplan.DISPLAY_SQL_PLAN_BASELINE(c.sql_handle, c.plan_name)) t
where c.sql_handle = '&sql_handle') g
where PLAN_TABLE_OUTPUT like 'Plan hash value%') loop
  v_num := to_number(sys.UTL_RAW.reverse(sys.UTL_RAW.SUBSTR(dbms_crypto.hash(src => UTL_I18N.string_to_raw(a.sql_text || chr(0),'AL32UTF8'), typ => 2),9,4)) || sys.UTL_RAW.reverse(sys.UTL_RAW.SUBSTR(dbms_crypto.hash(src => UTL_I18N.string_to_raw(a.sql_text || chr(0),'AL32UTF8'), typ => 2),13,4)),RPAD('x', 16, 'x'));
  v_sqlid := '';
  FOR i IN 0 .. FLOOR(LN(v_num) / LN(32))
  LOOP
   v_sqlid := SUBSTR('0123456789abcdfghjkmnpqrstuvwxyz',FLOOR(MOD(v_num / POWER(32, i), 32)) + 1,1) || v_sqlid;
  END LOOP;
 dbms_output.put_line(v_sqlid ||' ' || rpad(a.plan_hash_value,15) || ' ' || rpad(a.sql_handle,30) || ' ' || rpad(a.plan_name,30));
end loop;
end;
/

SQL_ID        PLAN_HASH_VALUE SQL_HANDLE                     PLAN_NAME
------------- --------------- ------------------------------ --------------------------------
7f4n59twq8mrj 3036703685      SQL_23829f7bf3712438           SQL_PLAN_270nzggtr291s1a6ce30c 

 

That baseline is definitely not mine. It’s for the wrong SQL ID!
The “Plans Loaded” message was correct when it said “0“!

Why? There was no error message, no output other than the number of plans loaded. That sucks dbms_spm!

I need to trace it. Do that by using dbms_spm.configure

(thank you Timur Akhmadeev for helping me! It’s not easy to google/MOS how to do this, hence this post so I don’t forget again!)

declare
cnt number;
begin
 dbms_spm.configure('spm_tracing',1);
 cnt := dbms_spm.load_plans_from_sqlset(sqlset_name=>'NEIL',SQLSET_OWNER=>'NEIL_DBA');
 dbms_output.put_line('Plans Loaded : '||to_char(cnt));
 dbms_spm.configure('spm_tracing',0);
end;
/

Looking in the trace file, it tells you what went wrong:

*** 2019-01-01 12:00:00.007
load sts: STS=NEIL, owner=NEIL_DBA
load sts: cursor opened
load sts: sql_id=4jcxvz3adqbs2 phv=1905606778
load sts: plan has empty outline, skipping it
load sts: plans total=0 plans loaded=0

So why does my plan have an empty outline?

The SQL_TEXT began “INSERT WHEN CNT = 1 THEN INTO SOME_TABLE… “.

It’s a multi-table insert, inserting into different tables depending upon a condition.
Baselines for Multi-table Inserts are NOT supported by SPM.

https://docs.oracle.com/cd/E11882_01/server.112/e41084/statements_9014.htm#SQLRF01604

I hope this helps you with your baseline creation troubleshooting!

Having baseline creation problems, you should check MOS article 789520.1

 

Proactive Oracle Support?

You may not be aware but Oracle have been talking about their new ProActive support with user groups like the UKOUG. It’s basically trying to show you best practices you should be implementing before stuff goes wrong, and many other useful bits of information.

It covers a lot of areas and is really worth a look, whether you’re using Oracle Database, Linux, MySQL, EBS, JDEdwards or indeed most Oracle products.

The open URL for headline information is: https://www.oracle.com/GetProactive

The place to look is at MOS document: 432.1
However, I do have to wonder just how up to date some of the content is given the “Trending” topic in the Oracle Database area is about planning your move to Oracle 12.1. Really Oracle? Really? You might want to dedicate a bit of time to getting this changed to 18 or 19?

 

This slideshow requires JavaScript.