HASH GROUP BY not used when using more that 354 aggregate functions

Monday, November 13, 2017 2 comments
Few days ago we had performance problem with one of our main application views. This was complex view that used a lot of aggregate function. Functions were used to transpose rows into columns.

When developer added few more aggregate functions for a new columns, query performance changed significantly and we had performance problem.

After quick analysis I have noticed one change in the execution plan.

HASH GROUP BY aggregation was replaced with less performant SORT GROUP BY. I have tried to force HASH GROUP BY using hints but nothing helped.


We tried to reproduce problem using dummy tables and then colleague found what was triggering plan change.

In this example I have query with 354 unique aggregate functions which is using HASH GROUP BY.

SELECT
          *
      FROM (SELECT LEVEL ID
             FROM DUAL CONNECT BY LEVEL < 1000) VANJSKI,
          (  SELECT
                    123 UNUTARNJI_ID,
                     sum(1) kolona0,
                     sum(1) kolona1,
                     sum(2) kolona2,
...
...
...
                     sum(350) kolona350    ,
                     sum(351) kolona351    ,
                     sum(352) kolona352    ,
                     sum(353) kolona353    ,
                     sum(354) kolona354
               FROM DUAL
           GROUP BY 123) UNUTARNJI
    WHERE     VANJSKI.ID = UNUTARNJI.UNUTARNJI_ID(+);

Plan hash value: 2294628051
---------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| A-Rows |   A-Time   |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |      |      1 |        |       |     5 (100)|    999 |00:00:00.01 |       |       |          |
|*  1 |  HASH JOIN OUTER               |      |      1 |      1 |  4631 |     5  (20)|    999 |00:00:00.01 |  2293K|  2293K| 1549K (0)|
|   2 |   VIEW                         |      |      1 |      1 |    13 |     2   (0)|    999 |00:00:00.01 |       |       |          |
|   3 |    CONNECT BY WITHOUT FILTERING|      |      1 |        |       |            |    999 |00:00:00.01 |       |       |          |
|   4 |     FAST DUAL                  |      |      1 |      1 |       |     2   (0)|      1 |00:00:00.01 |       |       |          |
|   5 |   VIEW                         |      |      1 |      1 |  4618 |     2   (0)|      1 |00:00:00.01 |       |       |          |
|   6 |    HASH GROUP BY               |      |      1 |      1 |       |     2   (0)|      1 |00:00:00.01 |   677K|   677K|  723K (0)|
|   7 |     FAST DUAL                  |      |      1 |      1 |       |     2   (0)|      1 |00:00:00.01 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------

Notice what will happen if I change "sum(1) kolona0" function and add one more unique function.

SELECT
          *
      FROM (SELECT LEVEL ID
             FROM DUAL CONNECT BY LEVEL < 1000) VANJSKI,
          (  SELECT
                    123 UNUTARNJI_ID,
                     sum(355) kolona0,
                     sum(1) kolona1,
                     sum(2) kolona2,
...
...
...
                     sum(350) kolona350    ,
                     sum(351) kolona351    ,
                     sum(352) kolona352    ,
                     sum(353) kolona353    ,
                     sum(354) kolona354
               FROM DUAL
           GROUP BY 123) UNUTARNJI
    WHERE     VANJSKI.ID = UNUTARNJI.UNUTARNJI_ID(+);

Plan hash value: 2326946862
---------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| A-Rows |   A-Time   |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |      |      1 |        |       |     5 (100)|    999 |00:00:00.01 |       |       |          |
|*  1 |  HASH JOIN OUTER               |      |      1 |      1 |  4631 |     5  (20)|    999 |00:00:00.01 |  2293K|  2293K| 1645K (0)|
|   2 |   VIEW                         |      |      1 |      1 |    13 |     2   (0)|    999 |00:00:00.01 |       |       |          |
|   3 |    CONNECT BY WITHOUT FILTERING|      |      1 |        |       |            |    999 |00:00:00.01 |       |       |          |
|   4 |     FAST DUAL                  |      |      1 |      1 |       |     2   (0)|      1 |00:00:00.01 |       |       |          |
|   5 |   VIEW                         |      |      1 |      1 |  4618 |     2   (0)|      1 |00:00:00.01 |       |       |          |
|   6 |    SORT GROUP BY               |      |      1 |      1 |       |     2   (0)|      1 |00:00:00.01 | 20480 | 20480 |18432  (0)|
|   7 |     FAST DUAL                  |      |      1 |      1 |       |     2   (0)|      1 |00:00:00.01 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------

Query execution plan changed - HASH GROUP BY was replaced with SORT GROUP BY.


This was obviously limitation for HASH GROUP BY but I couldn't find more information using Oracle docs or Google so I have asked Oracle support for a confirmation.

From Oracle support I have received answer that similar case was bug closed as not bug, without workaround. Using default DB_BLOCK_SIZE, the limitation is set to 354 aggregate functions.

To solve performance problem we have changed view to avoid HASH GROUP BY limitation.

Testing environment - Oracle Database 12c Enterprise Edition Release 12.1.0.2.0



Read More...

Beware of intensive slow query logging when using - log_queries_not_using_indexes

Saturday, October 21, 2017 0 comments
MySQL slow query log is great for identifying slow queries that are good candidates for optimisation. Slow query logging is disabled by default, but it is activated by DBA's or developers on most environments.

You can use slow query log to record all the traffic but be careful with this action as logging all traffic could be very I/O intensive and could have negative impact on general performance. It is recommended to record all traffic only for specific time periods.

This is why slow query logging is controlled with long_query_time parameter to log only slow queries.
But there is another parameter to think about - log_queries_not_using_indexes.

By default log_queries_not_using_indexes is disabled. If you have this parameter turned on you will log queries that don’t use an index, or that perform a full index scan where the index doesn't limit the number of rows - regardless of time taken.

If you have long_query_time configured to reasonable time, and still notice that queries are intensively logged in slow query log file, then you probably have enabled log_queries_not_using_indexes.

Enabling this parameter you’re practically saying that full scans are "evil" and should be considered for optimisation. But full scan doesn’t always mean that query is slow. In some situations query optimizer chooses full table scan as better option than index or you are probably querying very small table.


For instance, on several occasions I've noticed slow query logs flooded with queries like this:

# Time: 171021 17:51:45
# User@Host: monitor[monitor] @ localhost []
# Thread_id: 1492974  Schema:   QC_hit: No
# Query_time: 0.000321  Lock_time: 0.000072  Rows_sent: 0  Rows_examined: 1
# Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: No
# Filesort: No  Filesort_on_disk: No  Merge_passes: 0  Priority_queue: No
SET timestamp=1508608305;
SELECT
      SCHEMA_NAME
    FROM information_schema.schemata
    WHERE SCHEMA_NAME NOT IN ('mysql', 'performance_schema', 'information_schema');

+------+-------------+----------+------+---------------+------+---------+------+------+-------------+
| id   | select_type | table    | type | possible_keys | key  | key_len | ref  | rows | Extra       |
+------+-------------+----------+------+---------------+------+---------+------+------+-------------+
|    1 | SIMPLE      | schemata | ALL  | NULL          | NULL | NULL    | NULL | NULL | Using where |
+------+-------------+----------+------+---------------+------+---------+------+------+-------------+
Notice, Query_time: 0.000321.

Should I optimize query that is running 0.000321 secs with adding indexes. Probably not. But anyway, my log is flooded with this or similar queries.

I don’t see that parameter very useful and I would leave it on default value to avoid possible problems with intensive query logging.


Read More...

Enable SSL-encryption for MariaDB Galera Cluster

Tuesday, October 17, 2017 0 comments
Imagine you have MariaDB Galera cluster with nodes running in different data centers. Data centers are not connected via secured VPN tunnel.
As database security is very important you must ensure that traffic between nodes is fully secured.

Galera Cluster supports encrypted connections between nodes using SSL protocol and in this post I want to show how to encrypt all cluster communication using SSL encryption.


Check current SSL configuration.
MariaDB [(none)]> SHOW VARIABLES LIKE 'have_ssl';
+---------------+----------+
| Variable_name | Value    |
+---------------+----------+
| have_ssl      | DISABLED |  ###==> SSL Disabled
+---------------+----------+
1 row in set (0.01 sec)

MariaDB [(none)]> status
--------------
mysql  Ver 15.1 Distrib 10.0.29-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

Connection id:          56
Current database:
Current user:           marko@localhost
SSL:                    Not in use   ###==> SSL is not used
Current pager:          stdout
Using outfile:          ''
Using delimiter:        ;
Server:                 MariaDB
Server version:         10.0.17-MariaDB-1~trusty-wsrep-log mariadb.org binary distribution, wsrep_25.10.r4144
Protocol version:       10
Connection:             Localhost via UNIX socket
Server characterset:    utf8
Db     characterset:    utf8
Client characterset:    utf8
Conn.  characterset:    utf8
UNIX socket:            /var/run/mysqld/mysqld.sock
Uptime:                 7 days 42 min 29 sec

Threads: 52  Questions: 10  Slow queries: 0  Opens: 0  Flush tables: 1  Open tables: 63  Queries per second avg: 0.000
--------------
SSL is currently disabled.

To fully secure all cluster communication we must SSL-encrypt replication traffic within Galera Cluster, State Snapshot Transfer and traffic between database server and client.

We will create SSL Certificates and Keys using openssl.

# Create new folder for certificates
mkdir -p /etc/mysql/ssl
cd /etc/mysql/ssl

# Create CA certificate
# Generate CA key
openssl genrsa 2048 > ca-key.pem

# Using the CA key, generate the CA certificate
openssl req -new -x509 -nodes -days 3600 \
> -key ca-key.pem -out ca-cert.pem
-----
Country Name (2 letter code) [AU]:HR
State or Province Name (full name) [Some-State]:Zagreb
Locality Name (eg, city) []:Zagreb
Organization Name (eg, company) [Internet Widgits Pty Ltd]:Dummycorp
Organizational Unit Name (eg, section) []:IT
Common Name (e.g. server FQDN or YOUR name) []:myu1.localdomain
Email Address []:marko@dummycorp.com


# Create server certificate, remove passphrase, and sign it
# Create the server key
openssl req -newkey rsa:2048 -days 3600 \
>         -nodes -keyout server-key.pem -out server-req.pem
-----
Country Name (2 letter code) [AU]:HR
State or Province Name (full name) [Some-State]:Zagreb
Locality Name (eg, city) []:Zagreb
Organization Name (eg, company) [Internet Widgits Pty Ltd]:Dummycorp
Organizational Unit Name (eg, section) []:IT
##==> Use the ".localdomain" only on the first certificate.
Common Name (e.g. server FQDN or YOUR name) []:myu1
Email Address []:marko@dummycorp.com

Please enter the following 'extra' attributes
to be sent with your certificate request
A challenge password []:secretpassword
An optional company name []:

# Process the server RSA key
openssl rsa -in server-key.pem -out server-key.pem

# Sign the server certificate
openssl x509 -req -in server-req.pem -days 3600 \
>         -CA ca-cert.pem -CAkey ca-key.pem -set_serial 01 -out server-cert.pem


# Create client certificate, remove passphrase, and sign it
# Create the client key
openssl req -newkey rsa:2048 -days 3600 \
>         -nodes -keyout client-key.pem -out client-req.pem
-----
Country Name (2 letter code) [AU]:HR
State or Province Name (full name) [Some-State]:Zagreb
Locality Name (eg, city) []:Zagreb
Organization Name (eg, company) [Internet Widgits Pty Ltd]:Dummycorp
Organizational Unit Name (eg, section) []:IT
Common Name (e.g. server FQDN or YOUR name) []:myu1
Email Address []:marko@dummycorp.com

Please enter the following 'extra' attributes
to be sent with your certificate request
A challenge password []:secretpassword
An optional company name []:

# Process client RSA key
openssl rsa -in client-key.pem -out client-key.pem

# Sign the client certificate
openssl x509 -req -in client-req.pem -days 3600 \
>         -CA ca-cert.pem -CAkey ca-key.pem -set_serial 01 -out client-cert.pem


# Verify certificates

openssl verify -CAfile ca-cert.pem server-cert.pem client-cert.pem

server-cert.pem: OK
client-cert.pem: OK

If verification succeeds copy certificates to all nodes in the cluster.
Set mysql as owner of the files.

# Copy
scp -r /etc/mysql/ssl node1:/etc/mysql
scp -r /etc/mysql/ssl node2:/etc/mysql
scp -r /etc/mysql/ssl node3:/etc/mysql

# Change owner
node1: chown -R mysql:mysql /etc/mysql/ssl
node2: chown -R mysql:mysql /etc/mysql/ssl
node3: chown -R mysql:mysql /etc/mysql/ssl


Secure database and client connections.

Add following lines in my.cnf configuration file.
# MySQL Server
[mysqld]
ssl-ca=/etc/mysql/ssl/ca-cert.pem
ssl-cert=/etc/mysql/ssl/server-cert.pem
ssl-key=/etc/mysql/ssl/server-key.pem

# MySQL Client
[client]
ssl-ca=/etc/mysql/ssl/ca-cert.pem
ssl-cert=/etc/mysql/ssl/client-cert.pem
ssl-key=/etc/mysql/ssl/client-key.pem


Secure replication traffic.

Define paths to the key, certificate and certificate authority files. Galera Cluster will use this files for encrypting and decrypting replication traffic.

wsrep_provider_options="socket.ssl_key=/etc/mysql/ssl/server-key.pem;socket.ssl_cert=/etc/mysql/ssl/server-cert.pem;socket.ssl_ca=/etc/mysql/ssl/ca-cert.pem"


Enable SSL for mysqldump and Xtrabackup.

Create user which requires SSL for connection.

MariaDB [(none)]> CREATE USER 'sstssl'@'localhost' IDENTIFIED BY 'sstssl';
Query OK, 0 rows affected (0.03 sec)

MariaDB [(none)]> GRANT PROCESS, RELOAD, LOCK TABLES, REPLICATION CLIENT ON *.* TO 'sstssl'@'localhost' REQUIRE ssl;
Query OK, 0 rows affected (0.02 sec)

MariaDB [(none)]> FLUSH PRIVILEGES;
Query OK, 0 rows affected (0.00 sec)

I will use this user for replication.
Change wsrep_sst_auth in my.cnf configuration file.

wsrep_sst_auth="sstssl:sstssl"


Now we must recreate whole cluster.
If I restart only one node, while others are running, node won't join to existing cluster.
You can notice this errors in mysql error log.

171017  3:20:29 [ERROR] WSREP: handshake with remote endpoint ssl://192.168.56.22:4567 failed: asio.ssl:336031996: 'unknown protocol' ( 336031996: 'error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol')
171017  3:20:29 [ERROR] WSREP: handshake with remote endpoint ssl://192.168.56.23:4567 failed: asio.ssl:336031996: 'unknown protocol' ( 336031996: 'error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol')
Shutdown the cluster and bootstrap it.


Check.
MariaDB [(none)]> status
--------------
mysql  Ver 15.1 Distrib 10.0.29-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

Connection id:          87
Current database:
Current user:           marko@localhost
SSL:                    Cipher in use is DHE-RSA-AES256-SHA  ###==> SSL is used
Current pager:          stdout
Using outfile:          ''
Using delimiter:        ;
Server:                 MariaDB
Server version:         10.0.17-MariaDB-1~trusty-wsrep-log mariadb.org binary distribution, wsrep_25.10.r4144
Protocol version:       10
Connection:             Localhost via UNIX socket
Server characterset:    utf8
Db     characterset:    utf8
Client characterset:    utf8
Conn.  characterset:    utf8
UNIX socket:            /var/run/mysqld/mysqld.sock
Uptime:                 1 min 4 sec

Threads: 52  Questions: 676  Slow queries: 16  Opens: 167  Flush tables: 1  Open tables: 31  Queries per second avg: 10.562
--------------


MariaDB [(none)]> SHOW VARIABLES LIKE 'have_ssl';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| have_ssl      | YES   |
+---------------+-------+
1 row in set (0.01 sec)



REFERENCES
6.4.3.2 Creating SSL Certificates and Keys Using openssl
MySQL : Configure SSL Connections

Read More...

Delete large amounts of data on Galera Cluster using pt-archiver

Thursday, September 28, 2017 0 comments
Galera Cluster is excellent virtually synchronous multi-master database cluster. It has many benefits which you can check on GaleraCluster.
But beside benefits it has some limitations and one of them is handling large transactions.

Large replication data sets could degrade performance of whole cluster causing cluster freezing, increased memory consumption, crashing nodes, etc. To avoid this issues it is recommended to split large transactions into smaller chunks.

In this post I want to show you how to safely delete large amounts of data on Galera Cluster. You can perform this task using several tools or writing custom procedures to split large transaction into chunks. In this example I will use pt-archiver tool from Percona.


Imagine you have received task to perform data cleanup in devices table for several schemas.
It looks like very simple task - delete rows from devices table where device_cookie is 0.
delete from devices where device_cookie = 0

But, although statement looks simple it could potentially freeze whole cluster so before executing delete statement count how many rows you need to delete.

In my case I have to delete few millions of rows which is too much for one transaction so I need to split transaction into smaller chunks.

mysql> select count(*) from devices;
+----------+
| count(*) |
+----------+
|  2788504 |
+----------+

mysql> select count(*) - (select count(*) from devices where device_cookie = 0) 
       from devices;
+----------+
| count(*) |
+----------+
|      208 |
+----------+

I have to delete around 2.7 millions of rows.

This is command I will use:
pt-archiver --source h=localhost,u=marko,p="passwd",D=sch_testdb,t=devices \
--purge --where "device_cookie = 0" --sleep-coef 1.0 --txn-size 1000

--purge - delete rows.
--where "device_cookie = 0" - filter rows you want to delete.
--sleep-coef 1.0 - throttle delete process to avoid pause signals from cluster.
--txn-size 1000 - this is chunk size for every transaction.

# time pt-archiver --source h=localhost,u=marko,p="passwd",D=sch_testdb,t=devices \
--purge --where "device_cookie = 0" --sleep-coef 1.0 --txn-size 1000

real 3m32.532s
user 0m17.268s
sys 0m2.460s

Check after delete finished.
mysql> select count(*) from devices;
+----------+
| count(*) |
+----------+
|      208 |
+----------+
1 row in set (0.00 sec)

As I have to perform delete for several schemas, I have created simple shell script which iterates through schema list and executes pt-archiver command.

# cat delete_rows.sh
#!/bin/bash

LOGFILE=/opt/skripte/schema/table_delete_rows.log
SCHEMA_LIST=/opt/skripte/schema/schema_list.conf

# Get schema list and populate conf file
mysql -B -u marko -ppasswd --disable-column-names --execute "select schema_name from information_schema.schemata where schema_name like 'sch_%' and schema_name <> 'sch_sys'" > $SCHEMA_LIST

while IFS= read -r schema; do

  START=`date +%s`

  echo "`date`=> Deleting rows from table in schema: $schema"

  pt-archiver --source h=localhost,u=marko,p="passwd",D=$schema,t=devices --purge --where "device_cookie = 0" --sleep-coef 1.0 --txn-size 500

  SPENT=$(((`date +%s` - $START) / 60))

  echo "`date`=> Finished deleting in schema - spent: $SPENT mins"
  echo "*************************************************************************"

done <$SCHEMA_LIST >> $LOGFILE

exit 0



Read More...

Beware of ORA-19721 on 12c using Transportable Tablespace (Oracle changed behavior)

Saturday, September 16, 2017 0 comments
Almost every big database has it's hot data which is used often, and cold data which is rarely touched. From version 9i I have used transportable tablespace feature to exclude cold (archive) data from database and keep it on cheap storage or tapes.

If someone needs to query some of archive tables it was very easy to plug in tablespace for a few days and after archive data is not needed anymore tablespace could be easily dropped. So I was plugging the same tablespaces more than once.

But when I tried the same process on 12c database I was unpleasantly surprised that Oracle changed behaviour and I could not reattach tablespace.

Let’s demonstrate this in simple demo case.

Create tablespace and set it to be read only.
create tablespace ARCHIVE01 datafile '/oradata1/data/ora12c/archive01.dbf' size 50M;
Tablespace created.

create table archtab tablespace ARCHIVE01 as select * from dba_objects;
Table created.

alter tablespace ARCHIVE01 read only;
Tablespace altered.

create directory export_tts as '/oradata1/export';
Directory created.

Export tablespace metadata.
$ expdp '" / as sysdba "' directory=EXPORT_TTS dumpfile=exp_archive01.dmp logfile=exp_archive01.log transport_tablespaces=ARCHIVE01 transport_full_check=Y

Export: Release 12.1.0.2.0 - Production on Sat Sep 16 18:07:27 2017

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

Connected to: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

WARNING: Oracle Data Pump operations are not typically needed when connected to the root or seed of a container database.

Starting "SYS"."SYS_EXPORT_TRANSPORTABLE_01":  "/******** AS SYSDBA" directory=EXPORT_TTS dumpfile=exp_archive01.dmp logfile=exp_archive01.log transport_tablespaces=ARCHIVE01 transport_full_check=Y
Processing object type TRANSPORTABLE_EXPORT/PLUGTS_BLK
Processing object type TRANSPORTABLE_EXPORT/TABLE
Processing object type TRANSPORTABLE_EXPORT/TABLE_STATISTICS
Processing object type TRANSPORTABLE_EXPORT/STATISTICS/MARKER
Processing object type TRANSPORTABLE_EXPORT/POST_INSTANCE/PLUGTS_BLK
Master table "SYS"."SYS_EXPORT_TRANSPORTABLE_01" successfully loaded/unloaded
******************************************************************************
Dump file set for SYS.SYS_EXPORT_TRANSPORTABLE_01 is:
  /oradata1/export/exp_archive01.dmp
******************************************************************************
Datafiles required for transportable tablespace ARCHIVE01:
  /oradata1/data/ora12c/archive01.dbf
Job "SYS"."SYS_EXPORT_TRANSPORTABLE_01" successfully completed at Sat Sep 16 18:08:06 2017 elapsed 0 00:00:3

Drop tablespace but keep datafile.
SQL> drop tablespace ARCHIVE01 including contents keep datafiles;
Tablespace dropped.

Let’s plug in tablespace.
$ impdp '" /as sysdba "' directory=EXPORT_TTS dumpfile=exp_archive01.dmp logfile=imp_archive01.log transport_datafiles='/oradata1/data/ora12c/archive01.dbf'

Import: Release 12.1.0.2.0 - Production on Sat Sep 16 18:11:32 2017

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

Connected to: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

WARNING: Oracle Data Pump operations are not typically needed when connected to the root or seed of a container database.

Master table "SYS"."SYS_IMPORT_TRANSPORTABLE_01" successfully loaded/unloaded
Starting "SYS"."SYS_IMPORT_TRANSPORTABLE_01":  "/******** AS SYSDBA" directory=EXPORT_TTS dumpfile=exp_archive01.dmp logfile=imp_archive01.log transport_datafiles=/oradata1/data/ora12c/archive01.dbf
Processing object type TRANSPORTABLE_EXPORT/PLUGTS_BLK
Processing object type TRANSPORTABLE_EXPORT/TABLE
Processing object type TRANSPORTABLE_EXPORT/TABLE_STATISTICS
Processing object type TRANSPORTABLE_EXPORT/STATISTICS/MARKER
Processing object type TRANSPORTABLE_EXPORT/POST_INSTANCE/PLUGTS_BLK
Job "SYS"."SYS_IMPORT_TRANSPORTABLE_01" successfully completed at Sat Sep 16 18:11:51 2017 elapsed 0 00:00:18
Check alert log.
Plug in tablespace ARCHIVE01 with datafile
  '/oradata1/data/ora12c/archive01.dbf'
TABLE SYS.WRI$_OPTSTAT_HISTHEAD_HISTORY: ADDED INTERVAL PARTITION SYS_P451 (42993) VALUES LESS THAN (TO_DATE(' 2017-09-17 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
ALTER TABLESPACE "ARCHIVE01" READ WRITE
Completed: ALTER TABLESPACE "ARCHIVE01" READ WRITE
ALTER TABLESPACE "ARCHIVE01" READ ONLY
Sat Sep 16 18:11:51 2017
 Converting block 0 to version 10 format
Completed: ALTER TABLESPACE "ARCHIVE01" READ ONLY

Notice that Oracle is altering tablespace (datafile headers) to READ WRITE - Completed: ALTER TABLESPACE "ARCHIVE01" READ WRITE.

Quote from Oracle Support site:
Oracle Development declared it as "Expected Behavior" Starting from 12.1, during the TTS import operation, the tablespaces (datafile headers) are put into read-write mode intermittently in order to fix up TSTZ table columns and clean up unused segments in the datafiles. This functionality was implemented on many customer's request basis. And, hence, this cannot be reversed. Note that, it intermittently only changes the status to "read-write" and the final status will still be "read-only" only.

Now if I drop tablespace and try to reattach it again.

Create tablespace.
SQL> drop tablespace ARCHIVE01 including contents keep datafiles;
Tablespace dropped.
Import tablespace metadata.
$ impdp '" /as sysdba "' directory=EXPORT_TTS dumpfile=exp_archive01.dmp logfile=imp_archive01.log transport_datafiles='/oradata1/data/ora12c/archive01.dbf'

Import: Release 12.1.0.2.0 - Production on Sat Sep 16 18:13:51 2017

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

Connected to: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

WARNING: Oracle Data Pump operations are not typically needed when connected to the root or seed of a container database.

Master table "SYS"."SYS_IMPORT_TRANSPORTABLE_01" successfully loaded/unloaded
Starting "SYS"."SYS_IMPORT_TRANSPORTABLE_01":  "/******** AS SYSDBA" directory=EXPORT_TTS dumpfile=exp_archive01.dmp logfile=imp_archive01.log transport_datafiles=/oradata1/data/ora12c/archive01.dbf
Processing object type TRANSPORTABLE_EXPORT/PLUGTS_BLK
ORA-39123: Data Pump transportable tablespace job aborted
ORA-19721: Cannot find datafile with absolute file number 14 in tablespace ARCHIVE01

Job "SYS"."SYS_IMPORT_TRANSPORTABLE_01" stopped due to fatal error at Sat Sep 16 18:13:55 2017 elapsed 0 00:00:02

I have received error and failed to plug in tablespace.


Workaround for this "expected" behaviour is to change datafile permissions in OS level to be read only.
There is also workaround if you are using ASM so check on Oracle supprot site.

Let’s repeat steps from demo but now using workaround.


Create tablespace.
SQL> create tablespace ARCHIVE02 datafile '/oradata1/data/ora12c/archive02.dbf' size 50M;
Tablespace created.

SQL> create table archtab tablespace ARCHIVE02 as select * from dba_objects;
Table created.

SQL> alter tablespace ARCHIVE02 read only;
Tablespace altered.

Export tablespace metadata.
$ expdp '" / as sysdba "' directory=EXPORT_TTS dumpfile=exp_archive02.dmp logfile=exp_archive02.log transport_tablespaces=ARCHIVE02 transport_full_check=Y

Export: Release 12.1.0.2.0 - Production on Sat Sep 16 18:18:25 2017

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

Connected to: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

WARNING: Oracle Data Pump operations are not typically needed when connected to the root or seed of a container database.

Starting "SYS"."SYS_EXPORT_TRANSPORTABLE_01":  "/******** AS SYSDBA" directory=EXPORT_TTS dumpfile=exp_archive02.dmp logfile=exp_archive02.log transport_tablespaces=ARCHIVE02 transport_full_check=Y
Processing object type TRANSPORTABLE_EXPORT/PLUGTS_BLK
Processing object type TRANSPORTABLE_EXPORT/TABLE
Processing object type TRANSPORTABLE_EXPORT/TABLE_STATISTICS
Processing object type TRANSPORTABLE_EXPORT/STATISTICS/MARKER
Processing object type TRANSPORTABLE_EXPORT/POST_INSTANCE/PLUGTS_BLK
Master table "SYS"."SYS_EXPORT_TRANSPORTABLE_01" successfully loaded/unloaded
******************************************************************************
Dump file set for SYS.SYS_EXPORT_TRANSPORTABLE_01 is:
  /oradata1/export/exp_archive02.dmp
******************************************************************************
Datafiles required for transportable tablespace ARCHIVE02:
  /oradata1/data/ora12c/archive02.dbf
Job "SYS"."SYS_EXPORT_TRANSPORTABLE_01" successfully completed at Sat Sep 16 18:18:44 2017 elapsed 0 00:00:18

Drop tablespace and keep datafile.
SQL> drop tablespace ARCHIVE02 including contents keep datafiles;
Tablespace dropped.


Change permissions for datafile to be read only.
$ chmod 0440 /oradata1/data/ora12c/archive02.dbf
$ ls -l /oradata1/data/ora12c/archive02.dbf
-r--r-----. 1 oracle oinstall 52436992 Sep 16 18:17 /oradata1/data/ora12c/archive02.dbf

Import tablespace metadata.
$ impdp '" /as sysdba "' directory=EXPORT_TTS dumpfile=exp_archive02.dmp logfile=imp_archive02.log transport_datafiles='/oradata1/data/ora12c/archive02.dbf'

Import: Release 12.1.0.2.0 - Production on Sat Sep 16 18:20:23 2017

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

Connected to: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

WARNING: Oracle Data Pump operations are not typically needed when connected to the root or seed of a container database.

Master table "SYS"."SYS_IMPORT_TRANSPORTABLE_01" successfully loaded/unloaded
Starting "SYS"."SYS_IMPORT_TRANSPORTABLE_01":  "/******** AS SYSDBA" directory=EXPORT_TTS dumpfile=exp_archive02.dmp logfile=imp_archive02.log transport_datafiles=/oradata1/data/ora12c/archive02.dbf
Processing object type TRANSPORTABLE_EXPORT/PLUGTS_BLK
Processing object type TRANSPORTABLE_EXPORT/TABLE
Processing object type TRANSPORTABLE_EXPORT/TABLE_STATISTICS
Processing object type TRANSPORTABLE_EXPORT/STATISTICS/MARKER
Processing object type TRANSPORTABLE_EXPORT/POST_INSTANCE/PLUGTS_BLK
Job "SYS"."SYS_IMPORT_TRANSPORTABLE_01" successfully completed at Sat Sep 16 18:20:28 2017 elapsed 0 00:00:03

In alert log you can notice ORA-1114 IO errors because Oracle cannot modify datafile.
Plug in tablespace ARCHIVE02 with datafile
  '/oradata1/data/ora12c/archive02.dbf'
ALTER TABLESPACE "ARCHIVE02" READ WRITE
ORA-1114 signalled during: ALTER TABLESPACE "ARCHIVE02" READ WRITE...

Drop tablespace and reattach it again.
SQL> drop tablespace ARCHIVE02 including contents keep datafiles;
Tablespace dropped.

Plug in tablespace.
$ impdp '" /as sysdba "' directory=EXPORT_TTS dumpfile=exp_archive02.dmp logfile=imp_archive02.log transport_datafiles='/oradata1/data/ora12c/archive02.dbf'

Import: Release 12.1.0.2.0 - Production on Sat Sep 16 18:22:01 2017

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

Connected to: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

WARNING: Oracle Data Pump operations are not typically needed when connected to the root or seed of a container database.

Master table "SYS"."SYS_IMPORT_TRANSPORTABLE_01" successfully loaded/unloaded
Starting "SYS"."SYS_IMPORT_TRANSPORTABLE_01":  "/******** AS SYSDBA" directory=EXPORT_TTS dumpfile=exp_archive02.dmp logfile=imp_archive02.log transport_datafiles=/oradata1/data/ora12c/archive02.dbf
Processing object type TRANSPORTABLE_EXPORT/PLUGTS_BLK
Processing object type TRANSPORTABLE_EXPORT/TABLE
Processing object type TRANSPORTABLE_EXPORT/TABLE_STATISTICS
Processing object type TRANSPORTABLE_EXPORT/STATISTICS/MARKER
Processing object type TRANSPORTABLE_EXPORT/POST_INSTANCE/PLUGTS_BLK
Job "SYS"."SYS_IMPORT_TRANSPORTABLE_01" successfully completed at Sat Sep 16 18:22:05 2017 elapsed 0 00:00:03

Now I didn’t received error and I was able to plug in tablespace.
I have to remind myself to change datafile permissions before plugging tablespaces from 12c version.



REFERENCES
Doc ID 2094476.1


Read More...

Using In-Memory Option with SQL Plan Baselines, SQL Profiles and SQL Hints

Monday, March 6, 2017 0 comments
Oracle database In-Memory option was introduced in 12.1.0.2 patchset. It is great feature to improve performance of analytic queries. For mixed workload OLTP environments In-Memory option could improve performance of analytic queries without significant negative affect on quick OLTP queries or DML operations.

So you have decided that In-Memory option could be great for you and now you want to implement this option for your critical production database.

But in your code you have many SQL hints hard-coded, SQL Profiles implemented or SQL Plan baselines created to solve problems with unstable query performance. What will happen with execution plans if you populate In-Memory column store with critical tables in the database.

Example:
Version : Oracle 12.1.0.2

For test I will use query with fixed plan using both SQL profile and SQL plan baseline.

select object_type, count(*)
from admin.big_table
group by object_type;

OBJECT_TYPE               COUNT(*)
----------------------- ----------
PACKAGE                      14858
PACKAGE BODY                 13724
PROCEDURE                     2254
PROGRAM                        110


SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID  8g28yt7c1nacr, child number 0
-------------------------------------
select object_type, count(*) from admin.big_table group by object_type

Plan hash value: 1753714399

--------------------------------------------------------------------------------
| Id  | Operation          | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |       |       |  4819 (100)|          |
|   1 |  HASH GROUP BY     |           |    39 |   351 |  4819   (1)| 00:00:01 |
|   2 |   TABLE ACCESS FULL| BIG_TABLE |  1000K|  8789K|  4795   (1)| 00:00:01 |
--------------------------------------------------------------------------------

DECLARE
my_plans pls_integer;
BEGIN
  my_plans := DBMS_SPM.LOAD_PLANS_FROM_CURSOR_CACHE(
    sql_id => '8g28yt7c1nacr');
END;
/

@coe_xfr_sql_profile 8g28yt7c1nacr 1753714399
@coe_xfr_sql_profile_8g28yt7c1nacr_1753714399.sql


select object_type, count(*)
from admin.big_table
group by object_type;


SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));


SQL_ID  8g28yt7c1nacr, child number 0
-------------------------------------
select object_type, count(*) from admin.big_table group by object_type

Plan hash value: 1753714399

--------------------------------------------------------------------------------
| Id  | Operation          | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |       |       |  4819 (100)|          |
|   1 |  HASH GROUP BY     |           |    39 |   351 |  4819   (1)| 00:00:01 |
|   2 |   TABLE ACCESS FULL| BIG_TABLE |  1000K|  8789K|  4795   (1)| 00:00:01 |
--------------------------------------------------------------------------------

Note
-----
   - SQL profile coe_8g28yt7c1nacr_1753714399 used for this statement
   - SQL plan baseline SQL_PLAN_1wn92bz7gqvxx73be0962 used for this statement

Note section in execution plan output says that I’m using both SQL profile and SQL plan baseline for this query.

I have previously enabled In-Memory Column Store and now I will populate table data into the in-memory column store.

alter table admin.big_table inmemory priority critical;

col segment_name for a15
select segment_name, 
       inmemory_size/1024/1024 im_size_mb,
       bytes/1024/1024 size_mb,
       bytes_not_populated,
       inmemory_compression
from v$im_segments;

SEGMENT_NAME    IM_SIZE_MB    SIZE_MB BYTES_NOT_POPULATED INMEMORY_COMPRESS
--------------- ---------- ---------- ------------------- -----------------
BIG_TABLE          27.1875        144                   0 FOR QUERY LOW

1 row selected.

Run query again.

select object_type, count(*)
from admin.big_table
group by object_type;

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID  8g28yt7c1nacr, child number 0
-------------------------------------
select object_type, count(*) from admin.big_table group by object_type

Plan hash value: 1753714399

--------------------------------------------------------------------------------------
|Id | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time    |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT            |           |       |       |   257 (100)|         |
| 1 |  HASH GROUP BY              |           |    39 |   351 |   257  (13)| 00:00:01|
| 2 |   TABLE ACCESS INMEMORY FULL| BIG_TABLE |  1000K|  8789K|   233   (4)| 00:00:01|
--------------------------------------------------------------------------------------

Note
-----
   - SQL profile coe_8g28yt7c1nacr_1753714399 used for this statement
   - SQL plan baseline SQL_PLAN_1wn92bz7gqvxx73be0962 used for this statement

Notice "TABLE ACCESS INMEMORY FULL" operation is used instead of "TABLE ACCESS FULL" and both SQL profile and SQL plan baselines are used for this query.

In this case Oracle used in-memory column store to read data without any intervention on SQL profile or SQL plan baseline. Plan hash value remained the same in both cases.


But what if we have index operations involved in execution plan.

-- Temporary disable IM column store to optimise queries
SQL> alter system set inmemory_query=DISABLE;

-- Force Oracle to use index
SQL> alter session set optimizer_index_caching=100;
SQL> alter session set optimizer_index_cost_adj=1;


select object_type, count(*)
from admin.big_table
where object_type > 'C'
group by object_type;



SQL_ID  8xvfvz3axf5ct, child number 0
-------------------------------------
select object_type, count(*) from admin.big_table where object_type >
'C' group by object_type

Plan hash value: 3149057435

-------------------------------------------------------------------------------------
| Id  | Operation            | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |              |       |       |    28 (100)|          |
|   1 |  SORT GROUP BY NOSORT|              |    39 |   351 |    28   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN   | IDX_OBJ_TYPE |  1000K|  8789K|    28   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("OBJECT_TYPE">'C')


-- Create SQL plan baseline 

DECLARE
my_plans pls_integer;
BEGIN
  my_plans := DBMS_SPM.LOAD_PLANS_FROM_CURSOR_CACHE(
    sql_id => '8xvfvz3axf5ct');
END;
/

-- Create SQL profile

SQL>@coe_xfr_sql_profile 8xvfvz3axf5ct 3149057435
SQL>@coe_xfr_sql_profile_8xvfvz3axf5ct_3149057435.sql


I have slightly different query with "INDEX RANGE SCAN" operation in execution plan. SQL plan baseline and SQL profile are both created for this query.


In Note section you can see that SQL profile and SQL plan baseline are both used.

select object_type, count(*)
from admin.big_table
where object_type > 'C'
group by object_type;


SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID  8xvfvz3axf5ct, child number 0
-------------------------------------
select object_type, count(*) from admin.big_table where object_type >
'C' group by object_type

Plan hash value: 3149057435

-------------------------------------------------------------------------------------
| Id  | Operation            | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |              |       |       |    28 (100)|          |
|   1 |  SORT GROUP BY NOSORT|              |    39 |   351 |    28   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN   | IDX_OBJ_TYPE |  1000K|  8789K|    28   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("OBJECT_TYPE">'C')

Note
-----
   - SQL profile coe_8xvfvz3axf5ct_3149057435 used for this statement
   - SQL plan baseline SQL_PLAN_76jwvc1sug4k44391ca35 used for this statement


Enable IM column store to optimise queries.

SQL> alter system set inmemory_query=ENABLE;

System altered.


select object_type, count(*)
from admin.big_table
where object_type > 'C'
group by object_type;

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID  8xvfvz3axf5ct, child number 1
-------------------------------------
select object_type, count(*) from admin.big_table where object_type >
'C' group by object_type

Plan hash value: 3149057435

-------------------------------------------------------------------------------------
| Id  | Operation            | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |              |       |       |    28 (100)|          |
|   1 |  SORT GROUP BY NOSORT|              |    39 |   351 |    28   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN   | IDX_OBJ_TYPE |  1000K|  8789K|    28   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("OBJECT_TYPE">'C')

Note
-----
   - SQL profile coe_8xvfvz3axf5ct_3149057435 used for this statement
   - SQL plan baseline SQL_PLAN_76jwvc1sug4k44391ca35 used for this statement

This time in-memory option is not used to improve performance of the query.

Let’s drop SQL profile and leave SQL plan baseline enabled.

exec dbms_sqltune.drop_sql_profile('coe_8xvfvz3axf5ct_3149057435');


elect object_type, count(*)
from admin.big_table
where object_type > 'C'
group by object_type;


Plan hash value: 1753714399

--------------------------------------------------------------------------------------
| Id| Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time    |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT            |           |    39 |   351 |   255  (12)| 00:00:01|
| 1 |  HASH GROUP BY              |           |    39 |   351 |   255  (12)| 00:00:01|
|*2 |   TABLE ACCESS INMEMORY FULL| BIG_TABLE |  1000K|  8789K|   231   (3)| 00:00:01|
--------------------------------------------------------------------------------------


Predicate Information (identified by operation id):
---------------------------------------------------

   2 - inmemory("OBJECT_TYPE">'C')
       filter("OBJECT_TYPE">'C')

Note
-----
   - SQL plan baseline "SQL_PLAN_76jwvc1sug4k473be0962" used for this statement

Note section says that SQL plan baseline is used for this statement, but different than before.
I have "TABLE ACCESS INMEMORY FULL" operation and plan has changed automatically.

In Oracle 12cR1 Adaptive SQL Plan Management is enabled by default. Oracle calculated more efficient plan using in-memory column store and automatically accepted new SQL execution plan for this query. As new SQL plan is added and accepted Oracle was able to change execution plan.

set lines 200
set pages 999
col plan_name for a30
col sql_text for a50 wrap

select plan_name, sql_text, enabled, accepted
from dba_sql_plan_baselines
where sql_text like '%object_type > %';


PLAN_NAME                      SQL_TEXT                                ENA ACC
------------------------------ --------------------------------------- --- ---
SQL_PLAN_76jwvc1sug4k4ebe5b30f select object_type, count(*)            YES NO
                               from admin.big_table
                               where object_type > 'C'
                               group by object_type

SQL_PLAN_76jwvc1sug4k473be0962 select object_type, count(*)            YES YES
                               from admin.big_table
                               where object_type > 'C'
                               group by object_type

SQL_PLAN_76jwvc1sug4k44391ca35 select object_type, count(*)            YES YES
                               from admin.big_table
                               where object_type > 'C'
                               group by object_type

What if I disable adaptive sql plan management to forbid automatically evolving existing baselines.

-- Disable automatic evolving
BEGIN
  DBMS_SPM.set_evolve_task_parameter(
    task_name => 'SYS_AUTO_SPM_EVOLVE_TASK',
    parameter => 'ACCEPT_PLANS',
    value     => 'FALSE');
END;
/

-- Drop SQL plan baseline used for in-memory full scan
DECLARE
  l_plans_dropped  PLS_INTEGER;
BEGIN
  l_plans_dropped := DBMS_SPM.drop_sql_plan_baseline (
    sql_handle => NULL,
    plan_name  => 'SQL_PLAN_76jwvc1sug4k473be0962');
END;
/

In-memory full scan is not used as index range scan operation was specified in existing baseline which is used for query.

select object_type, count(*)
from admin.big_table
where object_type > 'C'
group by object_type;

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID 8xvfvz3axf5ct, child number 1
-------------------------------------
select object_type, count(*) from admin.big_table where object_type >
'C' group by object_type

Plan hash value: 3149057435

-------------------------------------------------------------------------------------
| Id  | Operation      | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |     |     |  28 (100)|     |
|   1 |  SORT GROUP BY NOSORT|      |  39 | 351 |  28   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN   | IDX_OBJ_TYPE |  1000K|  8789K|  28   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("OBJECT_TYPE">'C')

Note
-----
   - SQL plan baseline SQL_PLAN_76jwvc1sug4k44391ca35 used for this statement

New plan was added but this time it is not accepted automatically and taken in consideration by the optimizer. We have to manually validate and accept new plan to use it for query executions.

set lines 200
set pages 999
col plan_name for a30
col sql_text for a50 wrap

select plan_name, sql_text, enabled, accepted
from dba_sql_plan_baselines
where sql_text like '%object_type > %';

PLAN_NAME                      SQL_TEXT                                 ENA ACC
------------------------------ ---------------------------------------- --- ---
SQL_PLAN_76jwvc1sug4k4ebe5b30f select object_type, count(*)             YES NO
                               from admin.big_table
                               where object_type > 'C'
                               group by object_type

SQL_PLAN_76jwvc1sug4k473be0962 select object_type, count(*)             YES NO
                               from admin.big_table
                               where object_type > 'C'
                               group by object_type

SQL_PLAN_76jwvc1sug4k44391ca35 select object_type, count(*)             YES YES
                               from admin.big_table
                               where object_type > 'C'
                               group by object_type


What will happen if I have query with hint.

select /*+index(t IDX_OBJ_TYPE)*/  
       object_type, count(*)
from admin.big_table t
where object_type > 'C'
group by object_type;


SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID  8k7fykgphx8ra, child number 0
-------------------------------------
select /*+index(t IDX_OBJ_TYPE)*/        object_type, count(*) from
admin.big_table t where object_type > 'C' group by object_type

Plan hash value: 3149057435

-------------------------------------------------------------------------------------
| Id  | Operation            | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |              |       |       |  2770 (100)|          |
|   1 |  SORT GROUP BY NOSORT|              |    39 |   351 |  2770   (1)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN   | IDX_OBJ_TYPE |  1000K|  8789K|  2770   (1)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("OBJECT_TYPE">'C')

In-memory data access is ignored as we have hint forcing usage of the index.

select /*+full(t)*/
       object_type, count(*)
from admin.big_table t
where object_type > 'C'
group by object_type;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

Plan hash value: 1753714399

--------------------------------------------------------------------------------------
|Id | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time    |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT            |           |    39 |   351 |   255  (12)| 00:00:01|
| 1 |  HASH GROUP BY              |           |    39 |   351 |   255  (12)| 00:00:01|
|*2 |   TABLE ACCESS INMEMORY FULL| BIG_TABLE |  1000K|  8789K|   231   (3)| 00:00:01|
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - inmemory("OBJECT_TYPE">'C')
       filter("OBJECT_TYPE">'C')

In case we have hint forcing full scan, query will read data from in-memory column store as "TABLE ACCESS INMEMORY FULL" and "TABLE ACCESS FULL" are the same full table scan operations for the optimizer.


Conclusion
If your production application is heavily dependent on SQL profiles and SQL hints it would be hard to use full potential of in-memory column store option in a short time.
With SQL plan baselines it is slightly easier because you could use Adaptive SQL Plan Management to alter plans.

But you must dedicate some time for proper testing, because changing plans and dropping indexes blindly could cause many performance problems.



Read More...

Reduce Hard Parse time using SQL Profile

Thursday, November 3, 2016 2 comments
Few days ago we had concurrency problem with "cursor: pin S wait on X" wait event. This wait event is mostly associated with parsing in some form.

After quick diagnosis I’ve found problematic query. It was fairly complex query which was executed very often with average 0.20 seconds of execution time. As this query was using bind variables, Oracle reused existing plan and problems with "cursor: pin S wait on X" wait events weren’t appearing.

But when hard parse occurred we experienced problems with specified mutex waits. Query execution with hard parsing jumped from 0.20 seconds to over 2,1 seconds.

One session would hold mutex pin in exclusive mode while other sessions were waiting to get a mutex pin in share mode - waiting with "Cursor: pin S wait on X" wait event.

Rewriting query would solve this issue but we needed some solution quickly.


I have decided to perform few tests using SQL plan baselines and SQL profiles and measure effect on hard parse. Tested query is intentionally excluded from the post.

Version : Oracle 12.1.0.2

Query execution statistics:
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      1.15       2.09          0         10          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.01          0        177          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.16       2.11          0        187          0           1

Statistics
----------------------------------------------------------
       1691  recursive calls
          0  db block gets
       1594  consistent gets
          0  physical reads
          0  redo size
       7266  bytes sent via SQL*Net to client
       8393  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         60  sorts (memory)
          0  sorts (disk)
          1  rows processed

Total query execution is 2.11 seconds where parsing took 2.09 seconds which is practically whole query execution time.


What will happen if we create fixed baseline for the query:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      1.15       2.09          0          7          0           0
Execute      1      0.00       0.00          0          0          1           0
Fetch        2      0.00       0.01          0        177          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.16       2.11          0        184          1           1

Note
-----
   - SQL plan baseline "SQL_PLAN_6q3anxq5dfsj4e57c1833" used for this statement

Statistics
----------------------------------------------------------
       1691  recursive calls
          0  db block gets
       1594  consistent gets
          0  physical reads
          0  redo size
       7287  bytes sent via SQL*Net to client
       8393  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         60  sorts (memory)
          0  sorts (disk)
          1  rows processed

I have practically the same results which means that SQL plan baseline had no effect on parse time.


But, what will happen if I create SQL profile instead of baseline:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.65       1.21          6         21          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.01       0.01          0        177          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.66       1.23          6        198          0           1

Note
-----
   - SQL profile "PROFILE_09vf7nstqk7n2" used for this statement

Statistics
----------------------------------------------------------
        654  recursive calls
          0  db block gets
       1300  consistent gets
          6  physical reads
          0  redo size
       7284  bytes sent via SQL*Net to client
       8393  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         60  sorts (memory)
          0  sorts (disk)
          1  rows processed

This is big improvement.
Notice elapsed time for parse - from 2.09 secs to 1.21 secs.
Check query statistics - almost three times less recursive calls.


But why?
This is my explanation and I might be wrong so please leave comment below if this is the case.

When we’re using SQL baselines for plan management first step is always generating execution plans from optimizer. Cost based optimizer produces several plans and then compares plans with plans in the SQL plan baseline. Many different plans will be probed as a part of optimizer calculations. SQL plan baseline has no effect on number of calculations.

With SQL profiles we will feed optimizer with estimations and hints before calculation starts. Future plan will be influenced by the SQL profile. Basically we will point optimizer "in the right direction" and optimizer will not perform the same amount of calculations like before. As a result we have less recursive calls and less time spent on hard parsing.


After "fixing" plan with SQL profile, I’ve tried to reproduce mutex concurrency intentionally forcing hard parse but now Oracle managed to perform hard parse without affecting many sessions. Maybe I’ve solved problem temporarily and bought some time for developers to rewrite problematic query.



Read More...

Using Adaptive Cursors Sharing with SQL Plan Baselines

Tuesday, June 28, 2016 1 comments
We have several databases where automatic capturing of sql plan baselines is enabled for a few schemas.

Execution of some queries deeply depend on variables where is not always the best to reuse same execution plan for all executions. For those queries I want to avoid using literals and inefficient execution plans. Also, I want to use SQL plan baselines as I have automatic capturing enabled.

Question is, can I make Adaptive Cursor Sharing to work with SQL Plan Baselines without changing query?
Activate bind awareness for every execution to avoid inefficient execution plans?

I want to avoid even one inefficient execution or wait for ACS kick in automatically, because this one lousy execution could be potentially big problem.


For demo case I’m using 1000000 rows table with skewed data:

SQL> select * from v$version;

BANNER                                                                               CON_ID
-------------------------------------------------------------------------------- ----------
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production              0
PL/SQL Release 12.1.0.2.0 - Production                                                    0
CORE    12.1.0.2.0      Production                                                        0
TNS for IBM/AIX RISC System/6000: Version 12.1.0.2.0 - Production                         0
NLSRTL Version 12.1.0.2.0 - Production                                                    0


select owner, count(*)
from big_table
group by owner;

OWNER        COUNT(*)
---------- ----------
MDSYS               1
PUBLIC         499999
SYS            499999
ORDSYS              1


create index IDX_OWNER on BIG_TABLE(owner);

begin
  dbms_stats.gather_table_stats(ownname=>'MSUTIC',tabname=>'BIG_TABLE',cascade=>TRUE, estimate_percent=>100, method_opt=>'for columns size 4 owner');
end;
/


This is my test query.

SQL> var own varchar2(10);
SQL> exec :own := 'SYS';

select owner, sum(object_id)
from big_table
where owner = :own
group by owner;


SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));


SQL_ID  5cdba9s9mkag7, child number 0
-------------------------------------
select owner, sum(object_id) from big_table where owner = :own group by
owner

Plan hash value: 2943376087

----------------------------------------------------------------------------------
| Id  | Operation            | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |           |       |       |  3552 (100)|          |
|   1 |  SORT GROUP BY NOSORT|           |   499K|  9277K|  3552   (1)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL  | BIG_TABLE |   499K|  9277K|  3552   (1)| 00:00:01 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("OWNER"=:OWN)

For a first execution bind sensitivity is enabled because I have gathered statistics with histogram.

select     sql_id
    ,      is_bind_aware 
    ,      is_bind_sensitive
    ,      is_shareable
    ,      plan_hash_value
    from   v$sql  
    where  sql_id = '5cdba9s9mkag7';
 
SQL_ID        I I I PLAN_HASH_VALUE
------------- - - - ---------------
5cdba9s9mkag7 N Y Y      2943376087


To enable bind awareness I want to insert BIND_AWARE hint without changing query.

I will use SQL Patch for this:

SQL> begin
  sys.dbms_sqldiag_internal.i_create_patch(
     sql_text => 'select owner, sum(object_id)
                  from big_table
                  where owner = :own
                  group by owner',
     hint_text => 'BIND_AWARE',
     name      => 'bind_aware_patch');
end;
/  2    3    4    5    6    7    8    9   10

PL/SQL procedure successfully completed.

Now let’s check execution and bind awareness for the query.

SQL> var own varchar2(10);
SQL> exec :own := 'SYS';

select owner, sum(object_id)
from big_table
where owner = :own
group by owner;


SQL_ID  5cdba9s9mkag7, child number 0
-------------------------------------
select owner, sum(object_id) from big_table where owner = :own group by
owner

Plan hash value: 2943376087

----------------------------------------------------------------------------------
| Id  | Operation            | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |           |       |       |  3552 (100)|          |
|   1 |  SORT GROUP BY NOSORT|           |   499K|  9277K|  3552   (1)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL  | BIG_TABLE |   499K|  9277K|  3552   (1)| 00:00:01 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("OWNER"=:OWN)

Note
-----
   - SQL patch "bind_aware_patch" used for this statement
   
   
select     sql_id
    ,      is_bind_aware 
    ,      is_bind_sensitive
    ,      is_shareable
    ,      plan_hash_value
    from   v$sql  
    where  sql_id = '5cdba9s9mkag7';
 
 
SQL_ID        I I I PLAN_HASH_VALUE
------------- - - - ---------------
5cdba9s9mkag7 Y Y Y      2943376087


We have note that SQL patch is used and we have bind awareness enabled. For every query execution, during hard parse, Oracle will peak variable and calculate efficient execution plan accordingly. At least, I would expect this.


Let’s try with another variable - will Oracle alter execution plan.
SQL> var own varchar2(10);
SQL> exec :own := 'MDSYS';
   
   
select owner, sum(object_id)
from big_table
where owner = :own
group by owner;
   

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));   


SQL_ID  5cdba9s9mkag7, child number 1
-------------------------------------
select owner, sum(object_id) from big_table where owner = :own group by
owner

Plan hash value: 1772680857

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |     4 (100)|          |
|   1 |  SORT GROUP BY NOSORT        |           |     1 |    19 |     4   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| BIG_TABLE |     1 |    19 |     4   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | IDX_OWNER |     1 |       |     3   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("OWNER"=:OWN)

Note
-----
   - SQL patch "bind_aware_patch" used for this statement


   
select     sql_id
    ,      is_bind_aware 
    ,      is_bind_sensitive
    ,      is_shareable
    ,      plan_hash_value
    from   v$sql  
    where  sql_id = '5cdba9s9mkag7';
   
   
SQL_ID        I I I PLAN_HASH_VALUE
------------- - - - ---------------
5cdba9s9mkag7 Y Y Y      2943376087
5cdba9s9mkag7 Y Y Y      1772680857

Notice how Oracle changed execution plan and now we have two plans for specified sql text.


Capture SQL plans from cursor cache to create baseline.

DECLARE
my_plans pls_integer;
BEGIN
  my_plans := DBMS_SPM.LOAD_PLANS_FROM_CURSOR_CACHE(
    sql_id => '5cdba9s9mkag7');
END;
/

We have two ACCEPTED plans saved for this query which Oracle will consider during execution, and SQL patch forcing bind awareness.

set lines 200
col sql_handle for a25
col plan_name  for a35
select sql_handle, plan_name, enabled, accepted, fixed 
from dba_sql_plan_baselines
where sql_handle='SQL_f02626d2f3cad6cc';

SQL_HANDLE                PLAN_NAME                           ENA ACC FIX
------------------------- ----------------------------------- --- --- ---
SQL_f02626d2f3cad6cc      SQL_PLAN_g09j6ubtwppqc69a8f699      YES YES NO 
SQL_f02626d2f3cad6cc      SQL_PLAN_g09j6ubtwppqcaf705ad7      YES YES NO 


Now we will perform test to check will Oracle alter execution plan on variable value.

SQL> var own varchar2(10);
SQL> exec :own := 'SYS';

select owner, sum(object_id)
from big_table
where owner = :own
group by owner;

OWNER                            SUM(OBJECT_ID)
-------------------------------- --------------
SYS                                  7.5387E+10

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID  5cdba9s9mkag7, child number 0
-------------------------------------
select owner, sum(object_id) from big_table where owner = :own group by
owner

Plan hash value: 2943376087

----------------------------------------------------------------------------------
| Id  | Operation            | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |           |       |       |  3552 (100)|          |
|   1 |  SORT GROUP BY NOSORT|           |   499K|  9277K|  3552   (1)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL  | BIG_TABLE |   499K|  9277K|  3552   (1)| 00:00:01 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("OWNER"=:OWN)

Note
-----
   - SQL patch "bind_aware_patch" used for this statement
   - SQL plan baseline SQL_PLAN_g09j6ubtwppqcaf705ad7 used for this statement

Oracle used SQL patch and SQL plan baseline.

What if I change variable value.

SQL> var own varchar2(10);
SQL> exec :own := 'MDSYS';

select owner, sum(object_id)
from big_table
where owner = :own
group by owner;

OWNER                            SUM(OBJECT_ID)
-------------------------------- --------------
MDSYS                                    182924

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(format => 'TYPICAL'));

SQL_ID  5cdba9s9mkag7, child number 1
-------------------------------------
select owner, sum(object_id) from big_table where owner = :own group by
owner

Plan hash value: 1772680857

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |     4 (100)|          |
|   1 |  SORT GROUP BY NOSORT        |           |     1 |    19 |     4   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| BIG_TABLE |     1 |    19 |     4   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | IDX_OWNER |     1 |       |     3   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("OWNER"=:OWN)

Note
-----
   - SQL patch "bind_aware_patch" used for this statement
   - SQL plan baseline SQL_PLAN_g09j6ubtwppqc69a8f699 used for this statement

Oracle immediately changed execution plan and used different SQL plan baseline.


At the end I have original query with bind variables, I have SQL plan baselines captured, and I’m using powerful ACS feature to have efficient plans for different variables.

Read More...

Slow full table scan due to row chaining

Wednesday, February 24, 2016 4 comments
Few days ago I’ve received complaint that simple count on 2 million rows table is running forever.

This was the statement:
select count(1)
from CLIENT k
where k.expires is null;

I've used fake names for table name and columns.
Database version: 11.2.0.4.0

Indeed, query was running longer than I would expect. Oracle was using FULL SCAN of the table with "db file sequential read" wait events. This was little odd to me as I would expect "direct path reads" or "db file scattered reads".


It was partitioned table with 4 partitions and 294 columns.

select count(*) from dba_tab_columns where table_name = 'CLIENT';
 
 COUNT(*)
----------
      294

select owner, segment_name, partition_name, bytes, blocks
from dba_segments
where segment_name in ('CLIENT');
 
OWNER      SEGMENT_NAME    PARTITION_NAME            BYTES     BLOCKS
---------- --------------- -------------------- ---------- ----------
SCOTT       CLIENT         CLIENT_OTHER          8388608        1024
SCOTT       CLIENT         CLIENT_CITY           1643118592     200576
SCOTT       CLIENT         CLIENT_CNTR           591396864      72192
SCOTT       CLIENT         CLIENT_STRNG          52428800       6400


select table_name, partition_name, NUM_ROWS, AVG_ROW_LEN
from dba_tab_partitions
where table_name='CLIENT';

TABLE_NAME                     PARTITION_NAME           NUM_ROWS    AVG_ROW_LEN
------------------------------ ----------------------- ----------- ---------------
CLIENT                          CLIENT_OTHER             0            0
CLIENT                          CLIENT_CITY              1469420      572
CLIENT                          CLIENT_CNTR              592056       495
CLIENT                          CLIENT_STRNG             48977        565


select table_name, data_type, count(*)
from dba_tab_cols
where table_name='CLIENT'
group by table_name, data_type
order by 3 desc;
 
TABLE_NAME DATA_TYPE                                  COUNT(*)
---------- ---------------------------------------- ----------
CLIENT   NUMBER                                          191
CLIENT   VARCHAR2                                         70
CLIENT   DATE                                             32
CLIENT   TIMESTAMP(6)                                      3
CLIENT   RAW                                               2
CLIENT   CL_UTR                                            1
CLIENT   O_TIP_KAR                                         1
CLIENT   O_ZA_NA                                           1
CLIENT   O_PO_OSO                                          1

Some of the columns were collections.

select type_name, typecode
from dba_types
where type_name in (select data_type
                   from dba_tab_cols
                   where table_name='CLIENT'
                   and data_type not in ('NUMBER','VARCHAR2',
                   'DATE','TIMESTAMP(6)','RAW'));
 
TYPE_NAME                      TYPECODE                     
------------------------------ ------------------------------
CL_UTR                         COLLECTION                    
O_TIP_KAR                      COLLECTION                    
O_ZA_NA                        COLLECTION                    
O_PO_OSO                       COLLECTION                    

These were varrays used to store multivalued attributes.


In trace I've seen lots disk reads and elapsed time over 2400 seconds.

select count(1)
  from CLIENT k
where k.expires is null

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2    203.96    2450.19    5455717    8240323          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4    203.97    2450.20    5455717    8240323          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 369  (MSUTIC)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=8240323 pr=5455717 pw=0 time=1349733885 us)
   1905617    1905617    1905617   PARTITION LIST ALL PARTITION: 1 4 (cr=8240323 pr=5455717 pw=0 time=2449532855 us cost=164110 size=3801914 card=1900957)
   1905617    1905617    1905617    TABLE ACCESS FULL CLIENT PARTITION: 1 4 (cr=8240323 pr=5455717 pw=0 time=2448530798 us cost=164110 size=3801914 card=1900957)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   SORT (AGGREGATE)
1905617    PARTITION LIST (ALL) PARTITION: START=1 STOP=4
1905617     TABLE ACCESS   MODE: ANALYZED (FULL) OF 'CLIENT' (TABLE) 
                PARTITION: START=1 STOP=4

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to CLIENT                       2        0.00          0.00
  Disk file operations I/O                       29        0.00          0.00
  direct path read                             2048        0.19          9.78
  db file sequential read                   5178860        0.23       2241.08
  resmgr:internal state change                    2        0.11          0.21
  SQL*Net message from CLIENT                     1        0.00          0.00

Object statistics were telling me that all reads were from table partitions.

Session Objects Statistics
Object/Event % Time Seconds Calls - Time per Call -
Avg Min Max
Obj#(299564)
    db file sequential read 78.1% 1,757.0600s 3,677,752 0.0005s 0.0001s 0.2333s
    direct path read 0.4% 8.8314s 1,706 0.0052s 0.0004s 0.1953s
    resmgr:internal state change 0.0% 0.2162s 2 0.1081s 0.1000s 0.1162s
    Disk file operations I/O 0.0% 0.0014s 23 0.0001s 0.0000s 0.0002s
Obj#(299565)
    db file sequential read 20.5% 462.5006s 1,416,370 0.0003s 0.0001s 0.1794s
    direct path read 0.0% 0.8966s 304 0.0029s 0.0001s 0.0479s
    Disk file operations I/O 0.0% 0.0003s 6 0.0000s 0.0000s 0.0000s
Obj#(299566)
    db file sequential read 1.0% 21.5203s 84,738 0.0003s 0.0001s 0.0552s
    direct path read 0.0% 0.0587s 38 0.0015s 0.0000s 0.0206s


Hm… why am I having so many db file sequential reads with direct path reads happening also?
This is a table with lots of columns so I might have problems with chained or migrated rows.
Oracle is probably using individual block reads to fetch pieces of each row.

As I had table with more than 255 columns I would expect intra-block chaining, but this shouldn't cause sequential reads. Only if row doesn’t fit in the block I would have regular row chaining.
I’m probably having problems with row migrations.

Chained row is a row that is too large to fit into a block and if this is the root cause of the problem there isn't much I can do to improve performance. If it’s too big to fit into a block, it would be too big after rebuilding table also.

Migration of an row occurs when row is updated in a block and amount of free space in the block is not adequate to store all the row’s data. Row is migrated to another physical block.
This usually happens when you have PCTFREE set to low.

What is important for migrated rows - you can improve performance reorganizing table/partition or simply deleting/inserting chained rows.

Tanel wrote blog post on the subject "Detect chained and migrated rows in Oracle – Part 1” and I’ve decided to use his great tool Snapper to get some diagnostic info.

SQL> @sn 60 6596
@snapper all 60 1 "6596"
Sampling SID 6596 with interval 60 seconds, taking 1 snapshots...
 
-- Session Snapper v4.06 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)
 
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  6596, MSUTIC    , STAT, session logical reads                                     ,        283813,      4.74k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, user I/O wait time                                        ,          5719,      95.46,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, non-idle wait time                                        ,          5719,      95.46,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, non-idle wait count                                       ,        193388,      3.23k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, session pga memory                                        ,         -8400,    -140.21,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, enqueue requests                                          ,             2,        .03,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, enqueue releases                                          ,             2,        .03,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, physical read total IO requests                           ,        193740,      3.23k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, physical read total multi block requests                  ,           353,       5.89,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, physical read total bytes                                 ,    1630494720,     27.21M,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, cell physical IO interconnect bytes                       ,    1630494720,     27.21M,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, consistent gets                                           ,        283812,      4.74k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, consistent gets direct                                    ,        283810,      4.74k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, physical reads                                            ,        199034,      3.32k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, physical reads direct                                     ,        199034,      3.32k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, physical read IO requests                                 ,        193739,      3.23k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, physical read bytes                                       ,    1630486528,     27.21M,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, file io wait time                                         ,      57195780,    954.66k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, Number of read IOs issued                                 ,           353,       5.89,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, no work - consistent read gets                            ,        283808,      4.74k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, table scan rows gotten                                    ,       2881106,     48.09k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, table scan blocks gotten                                  ,         83578,       1.4k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, table fetch continued row                                 ,        200188,      3.34k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , STAT, buffer is not pinned count                                ,        200226,      3.34k,         ,             ,          ,           ,          ~ per execution
  6596, MSUTIC    , TIME, DB CPU                                                    ,       5620720,    93.82ms,     9.4%, [@         ],          ,           ,
  6596, MSUTIC    , TIME, sql execute elapsed time                                  ,      60270147,      1.01s,   100.6%, [##########],          ,           ,
  6596, MSUTIC    , TIME, DB time                                                   ,      60270147,      1.01s,   100.6%, [##########],          ,           ,          ~ unaccounted time
  6596, MSUTIC    , WAIT, Disk file operations I/O                                  ,           123,     2.05us,      .0%, [          ],         2,        .03,     61.5us average wait
  6596, MSUTIC    , WAIT, db file sequential read                                   ,      57234629,   955.31ms,    95.5%, [WWWWWWWWWW],    192888,      3.22k,   296.72us average wait
 
--  End of Stats snap 1, end=2016-02-23 13:23:19, seconds=59.9
 
----------------------------------------------------------------------------------------------------
Active% | INST | SQL_ID          | SQL_CHILD | EVENT                               | WAIT_CLASS
----------------------------------------------------------------------------------------------------
   97% |    1 | 2q92xdvxjj712   | 0         | db file sequential read             | User I/O
    3% |    1 | 2q92xdvxjj712   | 0         | ON CPU                              | ON CPU
 
--  End of ASH snap 1, end=2016-02-23 13:23:19, seconds=60, samples_taken=99
 
PL/SQL procedure successfully completed.

Notice "table fetch continued row" statistic. Tanel wrote that this counter is usually increasing when rows are accessed with index access paths.
In my case I have full scan that is increasing the value. This count is number of chained pieces Oracle had to go through in order to find the individual pieces of the rows.
I won’t go any further in detail - just check Tanel’s blog post.


Let’s identify chained rows running ANALYZE command with the LIST CHAINED ROWS option. This command will collect information about each migrated or chained row.

SQL> analyze table SCOTT.CLIENT list chained rows;
 
Table analyzed.
 
SQL> select count(*) from chained_rows;
 
 COUNT(*)
----------
  2007045

SQL> select partition_name, count(*) from chained_rows group by partition_name;
 
PARTITION_NAME                   COUNT(*)
------------------------------ ----------
CLIENT_CITY                       1411813
CLIENT_CNTR                       552873
CLIENT_STRNG                      42359

Table with 2097647 rows has 2007045 chained/migrated rows. This was causing so many reads for simple full scan of the small table.


I have decided to rebuild table partitions without changing PCTFREE parameter to fit migrated rows into a single block.


After rebuild number of chained rows decreased.

SQL> analyze table SCOTT.CLIENT list chained rows;
 
Table analyzed.
 
SQL> select count(*) from chained_rows;
 
 COUNT(*)
----------
    37883

Now query finished in 14 secs without sequential reads happening.
select  count(1)
  from CLIENT k
  where k.expires is null

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      2.34      13.96     185802     185809          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      2.34      13.96     185802     185809          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 369  (MSUTIC)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=185809 pr=185802 pw=0 time=13965941 us)
   1905617    1905617    1905617   PARTITION LIST ALL PARTITION: 1 4 (cr=185809 pr=185802 pw=0 time=13560379 us cost=109526 size=3811234 card=1905617)
   1905617    1905617    1905617    TABLE ACCESS FULL CLIENT PARTITION: 1 4 (cr=185809 pr=185802 pw=0 time=12848619 us cost=109526 size=3811234 card=1905617)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   SORT (AGGREGATE)
1905617    PARTITION LIST (ALL) PARTITION: START=1 STOP=4
1905617     TABLE ACCESS   MODE: ANALYZED (FULL) OF 'CLIENT' (TABLE) 
                PARTITION: START=1 STOP=4

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to CLIENT                       2        0.00          0.00
  direct path read                             3569        0.11          8.99
  SQL*Net message from CLIENT                     2        0.00          0.01


Snapper also showed that I don’t have problem with row chaining.
SQL> @sn 15 6601
@snapper all 15 1 "6601"
Sampling SID 6601 with interval 15 seconds, taking 1 snapshots...
 
-- Session Snapper v4.06 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)
 
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 SID, USERNAME  , TYPE, STATISTIC                                                 ,      DELTA, HDELTA/SEC, %TIME, GRAPH    , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   6601, MSUTIC , STAT, Requests to/from CLIENT                                ,          1,     .07,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, user calls                                                ,          1,        .07,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, pinned cursors current                                 ,         -1,    -.07,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, session logical reads                                  ,     149590,    9.9k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, CPU used when call started                             ,        227,   15.02,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, CPU used by this session                               ,        227,   15.02,      ,             ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, DB time                                                   ,       1047,   69.29,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, user I/O wait time                                     ,        424,   28.06,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, non-idle wait time                                     ,        424,   28.06,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, non-idle wait count                                    ,       3216,  212.84,      ,          ,       ,           ,       ~ per execution
   6601, MSUTIC , STAT, session uga memory                                     ,     135248,   8.95k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, physical read total IO requests                        ,       9354,  619.07,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, physical read total multi block requests               ,       9333,  617.68,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, physical read total bytes                              , 1225228288,  81.09M,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, cell physical IO interconnect bytes                    , 1225228288,  81.09M,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, consistent gets                                        ,     149578,    9.9k,      ,             ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, consistent gets from cache                             ,          5,     .33,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, consistent gets from cache (fastpath)                  ,          5,     .33,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, consistent gets direct                                 ,     149572,    9.9k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, logical read bytes from cache                          ,      40960,   2.71k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, physical reads                                            ,     149548,    9.9k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, physical reads direct                                  ,     149548,    9.9k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, physical read IO requests                              ,       9353,  619.01,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, physical read bytes                                    , 1225097216,  81.08M,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, calls to kcmgcs                                           ,          5,     .33,      ,          ,          ,        ,       ~ per execution
   6601, MSUTIC , STAT, file io wait time                                      ,        304,   20.12,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, total number of slots                                  ,         -2,    -.13,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, Effective IO time                                      ,    4239980, 280.61k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, Number of read IOs issued                              ,       9354,  619.07,      ,          ,       ,        ,          ~ per execution
   6601, MSUTIC , STAT, no work - consistent read gets                         ,     149564,    9.9k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, Cached Commit SCN referenced                           ,     149132,   9.87k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, table scans (cache partitions)                         ,          3,      .2,         ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, table scans (direct read)                              ,          3,      .2,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, table scan rows gotten                                 ,    3518684, 232.88k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, table scan blocks gotten                               ,     149559,    9.9k,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, bytes sent via SQL*Net to CLIENT                       ,        211,   13.96,      ,          ,       ,           ,   105.5 bytes per roundtrip
   6601, MSUTIC , STAT, bytes received via SQL*Net from CLIENT                 ,          8,     .53,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , STAT, SQL*Net roundtrips to/from CLIENT                      ,          2,     .13,      ,          ,       ,        ,       ~ per execution
   6601, MSUTIC , TIME, DB CPU                                                    ,    2000964,   132.43ms, 13.2%, [@@     ],       ,        ,
   6601, MSUTIC , TIME, sql execute elapsed time                               ,    8500210,   562.57ms,    56.3%, [###### ],       ,        ,
   6601, MSUTIC , TIME, DB time                                                   ,    8500269,   562.57ms,    56.3%, [###### ],       ,        ,     14.62s unaccounted time
   6601, MSUTIC , WAIT, direct path read                                          ,    4059380,   268.66ms, 26.9%, [WWW    ],      3064,  202.78,  1.32ms average wait
   6601, MSUTIC , WAIT, SQL*Net message to CLIENT                              ,          4,   .26us,   .0%, [       ],      1,     .07,        4us average wait
   6601, MSUTIC , WAIT, SQL*Net message from CLIENT                            ,    8006127,   529.87ms,    53.0%, [WWWWWW ],      1,     .07,   8.01s average wait
 
--  End of Stats snap 1, end=2016-02-24 08:23:59, seconds=15.1
 
 
----------------------------------------------------------------------------------------------------
Active% | INST | SQL_ID       | SQL_CHILD | EVENT                               | WAIT_CLASS
----------------------------------------------------------------------------------------------------
 29% | 1 | gg54c4j6b9jb0   | 0         | direct path read                    | User I/O
 21% | 1 | gg54c4j6b9jb0   | 0         | ON CPU                           | ON CPU
 
--  End of ASH snap 1, end=2016-02-24 08:23:59, seconds=15, samples_taken=96


Reorganizing table solved my problem. Finally full scans on the table were running much faster.

There is interesting support note "Doc ID 238519.1" which states that trailing NULLs do not take space in the rowpiece: initially row fits in one rowpiece.
If column beyond 255 is then populated, then all the NULL columns between last populated and this new column now takes up space.
Row has to be split into two rowpieces and the new rowpiece is migrated to a new block - row becomes chained.

In our table we have trailing NULL columns so this probably caused such migration.


Unfortunately I don’t have time to perform detailed investigation.




REFERENCES
http://blog.tanelpoder.com/2009/11/04/detect-chained-and-migrated-rows-in-oracle/
Updating a Row with More Than 255 Columns Causes Row Chaining (Doc ID 238519.1)

Read More...