Oracle … as usual

Oracle by Laurent Leturgez

Tracing Oracle binaries and tools

Oracle is well known for its instrumentation: wait interface, log files and tracing capabilities.

Usually, lots of them are documented but the way you can trace binaries and tools are usually not. More, reading trace files is not an easy thing to do but some times you can find clues about the problem you face.

In this post, I will talk about how to enable tracing when you use some binaries.

RMAN

RMAN is the Oracle utility used to backup and recover your databases. To enable tracing is RMAN, you have to switch rman is “debug” mode.

This mode can be enabled directly in rman:

 


[oracle@oel7 ~]$ rman target /

Recovery Manager: Release 12.1.0.2.0 - Production on Wed Feb 24 15:45:13 2016

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

connected to target database: ORCL (DBID=1413029491)

RMAN> debug on

RMAN-03036: Debugging set to level=9[MEDIUM], types=ALL

DBGSQL: TARGET> begin dbms_rcvman.setDebugOn; dbms_rcvman.dumpPkgState('Debug On'); end;
DBGSQL: sqlcode = 0
DBGRCVMAN: ENTERING dumpPkgState Debug On

.../...

Or (much better) it can be enabled with the debug option in the rman command, and by specifying a trace file :


[oracle@oel7 ~]$ rman target / debug trace=tracefile.trc

Recovery Manager: Release 12.1.0.2.0 - Production on Wed Feb 24 15:22:10 2016

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

RMAN-06005: connected to target database: ORCL (DBID=1413029491)

RMAN> disconnect

All the debug stuff is then located in your “tracefile.trc” file.

You can enable tracing on specific component in rman :

  • SQL: for tracing SQL queries generated by rman
  • RESTORE: for tracing restore operation only
  • RECOVER: for tracing recovery operation only
  • RESYNC: for tracing synchronization operation only
  • DUPLICATE: for tracing duplicate operation only

And for each or all of these component, you can set a verbosity level from 1 (lowest) to 10 (highest). 9 is the default verbosity level. Sometimes, you can change the verbosity level without any change in your tracefile.

Here are some examples (point that many components can be traced at the same time):


[oracle@oel7 ~]$ rman target / debug recover level=10 trace=tracefile.trc

[oracle@oel7 ~]$ rman target / debug sql level=1 trace=tracefile.trc

RMAN> debug restore,sql level=10

DGMGRL

DGMGRL is the tool used to control dataguard broker and operates some changes in your dataguard configuration: add config, initiate a switchover or a failover etc.

Dgmgrl can be switched to debug mode to get more information about a failed command.


[oracle@dg1 ~]$ dgmgrl -debug sys/oracle@prod_lille
DGMGRL for Linux: Version 11.2.0.4.0 - 64bit Production

Copyright (c) 2000, 2009, Oracle. All rights reserved.

Welcome to DGMGRL, type "help" for information.
[W000 02/24 16:14:15.62] Connecting to database using prod_lille.
[W000 02/24 16:14:15.65] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:14:15.65] Broker version is '11.2.0.4.0'
Connected.

This option can be very useful specially when you perform a switchover operation, all operations are logged and you can follow every connection, disconnection, tns errors, instance startup etc.

Below is an example of a successful switchover in debug mode:


DGMGRL> switchover to prod_arras;
Performing switchover NOW, please wait...
Operation requires a connection to instance "prod" on database "prod_arras"
Connecting to instance "prod"...
[W000 02/24 16:31:42.31] Connecting to database using (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=dg2.localdomain)(PORT=1521))(ADDRESS=(PROTOCOL=TCP)(HOST=dg1.localdomain)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=prod_arras_DGB)(INSTANCE_NAME=prod))).
[W000 02/24 16:31:42.33] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:31:42.33] Broker version is '11.2.0.4.0'
Connected.
New primary database "prod_arras" is opening...
Operation requires startup of instance "prod" on database "prod_lille"
Starting instance "prod"...
[W000 02/24 16:31:50.20] Connecting to database using (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=dg1.localdomain)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=prod_lille_DGMGRL)(INSTANCE_NAME=prod)(SERVER=DEDICATED))).
[W000 02/24 16:31:50.21] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
ORA-01034: ORACLE not available
Process ID: 0
Session ID: 0 Serial number: 0

ORACLE instance started.
[W000 02/24 16:31:51.52] Connecting to database using (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=dg1.localdomain)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=prod_lille_DGMGRL)(INSTANCE_NAME=prod)(SERVER=DEDICATED))).
[W000 02/24 16:31:51.54] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:31:51.55] Broker version is '11.2.0.4.0'
alter database mount

Database mounted.
[W000 02/24 16:31:59.85] Connecting to database using (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=dg1.localdomain)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=prod_lille_DGMGRL)(INSTANCE_NAME=prod)(SERVER=DEDICATED))).
[W000 02/24 16:31:59.87] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:31:59.87] Broker version is '11.2.0.4.0'
Switchover succeeded, new primary is "prod_arras"

EXPDP / IMPDP

Datapump export and import operation can be traced too. But for these tools, Oracle published a note on how to enable tracing a datapump operation. The MOS note is “Export/Import DataPump Parameter TRACE – How to Diagnose Oracle Data Pump (Doc ID 286496.1)”.

To trace a datapump process, you can do it at different levels, client process (expdp/impdp), master process (DM), worker process (DW) and you can trace different services. That’s why Oracle used a TRACE parameter. This one in coded with a hexadecimal value that code for a type of services you want to trace, and this service will generate trace in different processes (DM, DW, etc.).

The Trace value depends on which service you want to trace:


-- Summary of Data Pump trace levels:
-- ==================================

  Trace   DM   DW  ORA  Lines
  level  trc  trc  trc     in
  (hex) file file file  trace                                         Purpose
------- ---- ---- ---- ------ -----------------------------------------------
  10300    x    x    x  SHDW: To trace the Shadow process (API) (expdp/impdp)
  20300    x    x    x  KUPV: To trace Fixed table
  40300    x    x    x  'div' To trace Process services
  80300    x            KUPM: To trace Master Control Process (MCP)      (DM)
 100300    x    x       KUPF: To trace File Manager
 200300    x    x    x  KUPC: To trace Queue services
 400300         x       KUPW: To trace Worker process(es)                (DW)
 800300         x       KUPD: To trace Data Package
1000300         x       META: To trace Metadata Package
------- 'Bit AND'
1FF0300    x    x    x  'all' To trace all components          (full tracing)

Here’s an example with full tracing:


[oracle@oel7 ~]$ expdp system/oracle directory=dpdir dumpfile=test.dmp logfile=test.log tables=HR.REGIONS REUSE_DUMPFILES=YES trace=FFF0300

In the trace files generated, you will find lots of very interesting stuff (for example below, the trace file of the expdp process)


*** 2016-02-24 18:25:33.740
*** SESSION ID:(135.7145) 2016-02-24 18:25:33.740
*** CLIENT ID:() 2016-02-24 18:25:33.740
*** SERVICE NAME:(SYS$USERS) 2016-02-24 18:25:33.740
*** MODULE NAME:(ude@oel7.localdomain (TNS V1-V3)) 2016-02-24 18:25:33.740
*** CLIENT DRIVER:() 2016-02-24 18:25:33.740
*** ACTION NAME:() 2016-02-24 18:25:33.740

SHDW: *** GET_STATUS_VERSION call ***
SHDW: Version = 9999
KUPP:18:25:33.741: Input trace/debug flags: 0FFF0300 = 268370688
KUPP:18:25:33.741: Current trace/debug flags: 0FFF0300 = 268370688
SHDW:18:25:33.741: Current user = SYSTEM
SHDW:18:25:33.741: Current schema = SYSTEM
SHDW:18:25:33.741: Current language = AMERICAN_AMERICA.AL32UTF8
SHDW:18:25:33.742: Current session address = 00000001B7D050F8
SHDW:18:25:33.742: *** OPEN call ***
SHDW:18:25:33.742: operation = EXPORT
SHDW:18:25:33.742: job_mode = table
SHDW:18:25:33.742: remote_link =
SHDW:18:25:33.742: job_name =
SHDW:18:25:33.742: version =
SHDW:18:25:33.742: compression = 2
KUPV:18:25:33.743: Open request for job: SYSTEM.SYS_EXPORT_TABLE_01
KUPV:18:25:33.745: Master Table create statement: CREATE TABLE "SYSTEM"."SYS_EXPORT_TABLE_01" (abort_step NUMBER,ancestor_process_order NUMBER,base_object_name VARCHAR2(30),base_object_schema VARCHAR2(30),base_object_type VARCHAR2(30),base_process_order NUMBER,block_size NUMBER,cluster_ok NUMBER,completed_bytes NUMBER,completed_rows NUMBER,completion_time DATE,control_queue VARCHAR2(30),creation_level NUMBER,cumulative_time NUMBER,data_buffer_size NUMBER,data_io NUMBER,dataobj_num NUMBER,db_version VARCHAR2(60),degree NUMBER,domain_process_order NUMBER,dump_allocation NUMBER,dump_fileid NUMBER,dump_length NUMBER,dump_orig_length NUMBER,dump_position NUMBER,duplicate NUMBER,elapsed_time NUMBER,error_count NUMBER,extend_size NUMBER,file_max_size NUMBER,file_name VARCHAR2(4000),file_type NUMBER,flags NUMBER,grantor VARCHAR2(30),granules NUMBER,guid RAW(16),in_progress CHAR(1),instance VARCHAR2(60),instance_id NUMBER,is_default NUMBER,job_mode VARCHAR2(21),job_version VARCHAR2(60),last_file NUMBER,last_update DA
TE,load_method NUMBER,metadata_buffer_size NUMBER,metadata_io NUMBER,name VARCHAR2(30),object_int_oid VARCHAR2(32),object_long_name VARCHAR2(4000),object_name VARCHAR2(200),object_number NUMBER,object_path_seqno NUMBER,object_row NUMBER,object_schema VARCHAR2(30),object_tablespace VARCHAR2(30),object_type VARCHAR2(30),object_type_path VARCHAR2(200),old_value VARCHAR2(4000),operation VARCHAR2(8),option_tag VARCHAR2(30),orig_base_object_schema VARCHAR2(30),original_object_name VARCHAR2(128),original_object_schema VARCHAR2(30),packet_number NUMBER,parallelization NUMBER,parent_process_order NUMBER,partition_name VARCHAR2(30),phase NUMBER,platform VARCHAR2(101),process_name VARCHAR2(30),process_order NUMBER,processing_state CHAR(1),processing_status CHAR(1),property NUMBER,queue_tabnum NUMBER,remote_link VARCHAR2(128),scn NUMBER,seed NUMBER,service_name VARCHAR2(64),size_estimate NUMBER,start_time DATE,state VARCHAR2(12),status_queue VARCHAR2(30),subpartition_name VARCHAR2(30),target_xml_clob CLOB,tde_rewrapped_
key RAW(2000),template_table VARCHAR2(30),timezone VARCHAR2(64),total_bytes NUMBER,trigflag NUMBER,unload_method NUMBER,user_directory VARCHAR2(4000),user_file_name VARCHAR2(4000),user_name VARCHAR2(30),value_n NUMBER,value_t VARCHAR2(4000),version NUMBER,work_item VARCHAR2(21),xml_clob CLOB) SEGMENT CREATION IMMEDIATE INITRANS 10
KUPV:18:25:33.780: (Re)Creating job: SYSTEM.SYS_EXPORT_TABLE_01

.../...

SRVCTL

srvctl is the program that control clusterware resources. You can use it in a RAC configuration, or with Oracle Restart.

If, for example, a ressource doesn’t start in your cluster, or you would like to have more information about the process. You can set a specific environment variable named SRVM_TRACE to the value you want and then run your command. srvctl just look if the variable is defined and then it traces. The debug information is written in the standard output.

See demonstration below:


[oracle@rac1 ~]$ env|grep SRVM
[oracle@rac1 ~]$ srvctl status database -db cdb
Instance cdb1 is running on node rac1
Instance cdb2 is not running on node rac2
[oracle@rac1 ~]$ export SRVM_TRACE=laurent
[oracle@rac1 ~]$ srvctl status database -db cdb
[main] [ 2016-02-24 18:43:08.601 CET ] [OPSCTLDriver.setInternalDebugLevel:325] tracing is true at level 2 to file null
[main] [ 2016-02-24 18:43:08.607 CET ] [OPSCTLDriver.main:162] SRVCTL arguments : args[0]=status args[1]=database args[2]=-db args[3]=cdb
[main] [ 2016-02-24 18:43:08.608 CET ] [SRVMContext.init:114] Performing SRVM Context init. Init Counter=1
[main] [ 2016-02-24 18:43:08.622 CET ] [Library.load:194] library.load
[main] [ 2016-02-24 18:43:08.623 CET ] [sPlatform.isHybrid:66] osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2016-02-24 18:43:08.624 CET ] [sPlatform.isHybrid:66] osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2016-02-24 18:43:08.624 CET ] [Library.load:271] Loading library /u01/app/oracle/product/12.1.0/dbhome_1/lib/libsrvmhas12.so
[main] [ 2016-02-24 18:43:08.635 CET ] [SRVMContext.init:131] SRVM Context init-ed
[main] [ 2016-02-24 18:43:08.648 CET ] [Version.isPre:610] version to be checked 12.1.0.2.0 major version to check against 10
[main] [ 2016-02-24 18:43:08.648 CET ] [Version.isPre:621] isPre.java: Returning FALSE
[main] [ 2016-02-24 18:43:08.651 CET ] [OCR.loadLibrary:328]
Inside constructor of OCR
[main] [ 2016-02-24 18:43:08.652 CET ] [OCR.loadLibrary:336] Going to load the ocr library

.../...

[oracle@rac1 ~]$ unset SRVM_TRACE
[oracle@rac1 ~]$ srvctl status database -db cdb
Instance cdb1 is running on node rac1
Instance cdb2 is not running on node rac2

OPATCH

Opatch can be traced with an environment variable positioned like srvctl. This variable is OPATCH_DEBUG and it has to be set to TRUE. As for srvctl, information is written to standard output:


[oracle@rac1 ~]$ export OPATCH_DEBUG=TRUE
[oracle@rac1 ~]$ $ORACLE_HOME/OPatch/opatch lsinv
OPatch was not able to set FMW_COMPONENT_HOME by itself.
Machine Info: Linux rac1.localdomain 3.8.13-44.1.1.el6uek.x86_64 #2 SMP Wed Sep 10 06:10:25 PDT 2014 x86_64 x86_64 x86_64 GNU/Linux
_osArch is amd64
_javaVMSpecVersion is 1.0
_javaVMSpecVendor is Sun Microsystems Inc.
_javaVMSpecName is Java Virtual Machine Specification
_javaVMVendor is Sun Microsystems Inc.
_javaJRESpecVersion is 1.6
_javaJRESpecVendor is Sun Microsystems Inc.
_javaJRESpecName is Java Platform API Specification
_javaSupportedClassVersion is 50.0
OPatch compiled with major version: 50, minor version: 0
_osArch (from OCM API) is
/u01/app/oracle/product/12.1.0/dbhome_1/jdk/bin/java -Xms150m -Xmx256m -XX:MaxPermSize=128M -cp /u01/app/oracle/product/12.1.0/dbhome_1/OPatch/ocm/lib/emocmclnt.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/OraInstaller.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/OraPrereq.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/OraCheckPoint.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/share.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/orai18n-mapping.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/xmlparserv2.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/emCfg.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/ojmisc.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/jlib/opatch.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/jlib/opatchsdk.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/automation.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/apache-commons/commons-cli-1.0.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/jlib/oracle.opatch.classpath.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/activation.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/jaxb-api.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/jaxb-impl.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/jsr173_1.0_api.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/OsysModel.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/osysmodel-utils.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/CRSProductDriver.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/oracle.oplan.classpath.jar -DOPatch.ORACLE_HOME=/u01/app/oracle/product/12.1.0/dbhome_1 -DOPatch.DEBUG=true -DOPatch.RUNNING_DIR=/u01/app/oracle/product/12.1.0/dbhome_1/OPatch -DOPatch.MW_HOME= -DOPatch.WL_HOME= -DOPatch.COMMON_COMPONENTS_HOME= -DOPatch.OUI_LOCATION= -DOPatch.FMW_COMPONENT_HOME= -DOPatch.OPATCH_CLASSPATH= -DOPatch.WEBLOGIC_CLASSPATH= oracle/opatch/OPatch lsinv -invPtrLoc /u01/app/oracle/product/12.1.0/dbhome_1/oraInst.loc
Oracle Interim Patch Installer version 12.1.0.1.3
Copyright (c) 2016, Oracle Corporation. All rights reserved.

OPatchSession::parse() on "lsinv","-invPtrLoc","/u01/app/oracle/product/12.1.0/dbhome_1/oraInst.loc",

Argument is "lsinv"
Add commands for Help
add command "apply"

.../...

Oracle Kernel Tracing

Oracle Kernel tracing can be done by enabling some events.

Event is a number between 10000 and 10999. It’s very similar to an error code … but it’s not a real one.

The most popular events are 10046 (SQL Trace) and 10053 (CBO debug trace) …but there are plenty of other ones and you can find details in oraus.msg file (or you can plan with oerr utility).

Events can be positioned by many ways :

  • With an ALTER SESSION (It’s not recommended to use ALTER SYSTEM when you enable events)
SQL> alter session set events '10046 trace name context forever, level 12';
SQL> alter session set events '10046 trace name context off';
  • With an oradebug command. This method offers the possibility to set an event in another session

For example, if you want to enable 10053 event in the session that have the OS PID 5683 (You can use SETMYPID for debugging your own session, or SETORAPID to target a session with a specific Oracle PID)


SQL> oradebug setospid 5683; 
SQL> oradebug event 10053 trace name context forever, level 1;
SQL> oradebug event 10053 trace name context off;
  • With DBMS_SYSTEM.SET_EV. Like ORADEBUG, you can set an event in another session

 


SQL> -- Enable SQL Trace in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10046, le=>12, nm=>'');
SQL> -- Disable SQL Trace in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10046, le=>0, nm=>'');

SQL> -- Enable CBO debug in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10053, le=>1, nm=>'');
SQL> -- Disable CBO debug in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10046, le=>0, nm=>'');

For all of these commands, the trace file will be available in the folder referenced by user_dump_dest.

Starting with Oracle 11.2, Oracle come with a new way to trace its components. This is named UTS (Unified Tracing System).

UTS offers the possibility to trace some components (like with events) but you can combine it with filters (for example, trace CBO computation when a specific SQL_ID is parsed etc.)

Note: Events are still available and they have’nt been replaced by UTS … UTS completes them.

The component list can be get with “oradebug doc component” command.

I will not write some detailed stuff about UTS because very interesting guys in the community have already written blog posts and articles on this.

You can visit them by following these URLs :

  • Tanel Pöder: http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc
  • Miladin Modrakovic: https://oraclue.files.wordpress.com/2011/03/oracle_diagnostic_events_in_11g1.pdf

 

Last but not least, tracing everything without knowing what you are doing can be dangerous (Filesystem full filling, database hangs and/or crash), so it’s recommended to use tracing very carefully.

 

Thanks to my friend Pierre Labrousse who helped me for parts of this post.

I’m now an Oracle ACE :)

Last week, I received an email from Oracle that announced I was accepted in the Oracle ACE Program. And yes, I’m very proud of this.🙂

For those who don’t know what is the Oracle ACE program, it’s an award you receive when the community recognizes your expertise in a specific domain.

How does it works ? You have to be nominated by someone in the community. This person fills in a nomination form which gives details about your expertise and how you “show” it to the community (Blogs, Social networking, conferences, book authoring etc etc).

In my case, I’ve been nominated by Mohamed Houri (@MohamedHouri) and my nomination has been supported by lots of people who are very well known in the community (Tanel Pöder, Kellyn Pot’vin Gorman, Deiby Gomez, Ludovico Caldara and Franck Pachot). I would like to warmly thank them for their support.

Now I will continue being active in the community: Writing on Oracle forums, presenting at Oracle conferences (I would like to present at two conferences at least this year), blogging and social networking (mainly on twitter: @lleturgez).

My Oracle ACE profile is now available at this URL : https://apex.oracle.com/pls/apex/f?p=19297:4:::NO:4:P4_ID:15320 .

Thank you Oracle ACE (@oracleace).

 

When an Oracle 12c common user transforms himself as a local user … but keeps his username.

In Oracle 12c new architecture, you have two kinds of users. Users who are declared in the root container, and users who are declared in a pluggable database.

The first ones are named common user, and the others are name local user. The particularity of those common user is that they are synchronised with the pluggable database(s) to be known in each of them.

Oracle make the distinction between common user and local user by their name. Common usernames have a constraint, they have to start with “C## “(or the value of the parameter “COMMON_USER_PREFIX”). For example, C##LAURENT is a common username whereas LAURENT is a local username.

Oracle controls that, because if you create a common user in a PDB, you will throw an “ORA-65094: invalid local user or role name”. At the opposite, you will throw an “ORA-65096: invalid common user or role name” if you try to create a local user in the CDB$ROOT container.

A weird behaviour happened when you plug a PDB which contained synced definition of a common user.

Below, I paste a demo of what I’m saying (this example has been taken in a SE2 database so … with only one PDB, but I reproduced the problem with a PDB which was unplugged from one container and plugged into another one).

  • In the pluggable database, common user creation

SQL> show con_name

CON_NAME
------------------------------
CDB$ROOT

SQL> show pdbs

    CON_ID CON_NAME                       OPEN MODE  RESTRICTED
---------- ------------------------------ ---------- ----------
         2 PDB$SEED                       READ ONLY  NO
         3 PDB1                           READ WRITE NO

SQL> create user c##laurent identified by laurent container=ALL;

User created.

SQL> grant connect to c##laurent container=ALL;

Grant succeeded.

  • In the PDB the common user is synced

SQL> conn sys/oracle@pdb1 as sysdba
Connected.

SQL> select username,common from dba_users where username like 'C##%';

USERNAME                   COM
-------------------------- ---
C##LAURENT                 YES

 

  • Now I unplug my PDB and drop it from the container

SQL> show con_name

CON_NAME
------------------------------
CDB$ROOT

SQL> alter pluggable database pdb1 close immediate;

Pluggable database altered.

SQL> alter pluggable database pdb1 unplug into '/home/oracle/laurent.xml';

Pluggable database altered.

SQL> drop pluggable database pdb1;

Pluggable database dropped.

  • Now, let’s drop the common user in the root container to simulate a new and fresh container database
SQL> select con_id,username,common from cdb_users where username like 'C##%';

    CON_ID USERNAME      COM
---------- ------------- ---
	     1 C##LAURENT    YES

SQL> drop user c##laurent cascade;

User dropped.
  • Finally I plug my PDB in the container, open it, and query CDB_USERS to see what happened to my common user c##LAURENT
SQL> create pluggable database newone
  2  using '/home/oracle/laurent.xml'
  3  nocopy tempfile reuse;

Pluggable database created.

SQL> alter pluggable database newone open;

Pluggable database altered.

SQL> select con_id,username,common from cdb_users where username like 'C##%';

    CON_ID USERNAME       COM
---------- -------------- ---
         3 C##LAURENT     YES

SQL> conn c##laurent/laurent@oel6:1521/NEWONE
ERROR:
ORA-28000: the account is locked

Well if you have a closer look to the CON_ID, my “common user” has been affected as a local user (because defined in the PDB). So, if I’m ok with the definition of  local user … it’s a local user, but with a common username … oh dear !!!

Following this URL in the documentation (https://docs.oracle.com/database/121/SQLRF/statements_8003.htm#SQLRF54735), Oracle recommends to set a value for COMMON_USER_PREFIX even with this particular behaviour.

UPDATE : A friend of mine and a fellow Oracle consultant, Pierre Labrousse, gave me a clue In the Oracle MOS Note 1511619.1, Oracle says that if you face a common user who is locked in a newly plugged PDB to do one of the following:

  • Leave the user account locked and use the objects of its schema.
  • Use Oracle Data Pump to copy these objects to another schema, and then drop the locked user account.
  • Close the PDB, connect to the root, and then create a common user with the same name as the locked account. When you re-open the PDB, Oracle Database resolves the differences in the roles and privileges that were commonly granted to the locked user. Afterward, you can unlock this user account in the PDB. Privileges and roles that were locally granted to the user will remain unchanged.

 

 

 

Oracle 11g, frequency histograms, and character columns …

Recently I worked on a performance issue on two Oracle 11g instances (11.2.0.3 and 11.2.0.4) and I hit a bug concerning histograms and character columns. Oracle 11g is now about 7 years old but it’s a version that is still used in lots of systems .. that’s why I decided to write this blog post.

Well, in Oracle 11g, you have two kind of histograms :

  • Frequency histograms: they are calculated when the number of distinct values (NDV) in a column is lower than the number of buckets in the histogram. Frequency histograms are the most accurate histogram, because they count the exact number of occurrences for each value.
  • Height balanced histograms: they are calculated when the NDV is greater than the number of buckets in the histogram. Height balanced histograms are less accurate but they give some precious information to the optimizer on data distribution.

Histograms help the cost optimizer to take the good decision when the CBO have to choose for an access path or a join. (You can find very interesting papers on this topic by Jonathan Lewis or Mohamed Houri)

The problem I met was related to frequency histograms on character columns (CHAR, VARCHAR2 and NVARCHAR2).

In the dictionary, there are two views that give interesting information about how data is distributed:

  • DBA_TAB_COL_STATISTICS: this view gives information about column statistics (density, NDV, sample_size etc.) and if there’s an histogram on the column.
  • DBA_HISTOGRAMS: this view gives information on column histograms and how data values are distributed

Let’s took an example:

LAURENT @ orcl >; create table foo (id number);

Table created.

LAURENT @ orcl > begin
 2 for i in 1..10
 3 loop
 4 insert into foo select i from dual connect by level <=i; 5 end loop; 6 end; 7 / PL/SQL procedure successfully completed. LAURENT @ orcl > commit;

Commit complete.

LAURENT @ orcl > select id,count(*) from foo group by id order by 1;

	ID   COUNT(*)
---------- ----------
	 1	    1
	 2	    2
	 3	    3
	 4	    4
	 5	    5
	 6	    6
	 7	    7
	 8	    8
	 9	    9
	10	   10

10 rows selected.

Now, we gather statistics with a frequency histogram (that’s why I chose 11 buckets):

LAURENT @ orcl > exec dbms_stats.gather_table_stats(ownname=>USER, tabname=>'FOO', method_opt=>'FOR COLUMNS ID SIZE 11', estimate_percent=>100);

PL/SQL procedure successfully completed.

LAURENT @ orcl > select table_name,column_name,num_distinct,density,num_nulls,sample_size,histogram
 2 from user_tab_col_statistics
 3 where table_name='FOO';

TABLE_NAME COLUMN_NAM NUM_DISTINCT    DENSITY  NUM_NULLS SAMPLE_SIZE HISTOGRAM
---------- ---------- ------------ ---------- ---------- ----------- ---------------
FOO        ID                   10 .009090909          0          55 FREQUENCY

Now let’s have a look to the DBA_HISTOGRAMS view (or USER or ALL depending on the context)


LAURENT @ orcl > select table_name,column_name,
  2  endpoint_number,endpoint_value,
  3  endpoint_actual_value
  4  from user_histograms
  5  where table_name='FOO';

TABLE_NAME COLUMN_NAM ENDPOINT_NUMBER ENDPOINT_VALUE ENDPOINT_A
---------- ---------- --------------- -------------- ----------
FOO        ID                       1              1
FOO        ID                       3              2
FOO        ID                       6              3
FOO        ID                      10              4
FOO        ID                      15              5
FOO        ID                      21              6
FOO        ID                      28              7
FOO        ID                      36              8
FOO        ID                      45              9
FOO        ID                      55             10

The ENDPOINT_VALUE represents the column value, for example, and because it’s a frequency histogram, if we’d like to know how many values of 7 there is in the table, we have to take the endpoint_number for this value: 28 and to substract the endpoint_number of the preceding endpoint-value (6) … So there are 28-21=7 lines with the value 7.

Now, you’ve understood this basic … let’s take another example:


LAURENT @ orcl > begin
  2  for i in 1..10000
  3  loop
  4  case mod(i,10)
  5    when 0 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'01'));
  6    when 1 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'02'));
  7    when 2 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'03'));
  8    when 3 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'04'));
  9    when 4 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'05'));
 10    when 5 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'06'));
 11    when 6 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'07'));
 12    when 7 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'08'));
 13    when 8 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'09'));
 14    when 9 then insert into t values(mod(i,10), concat(lpad('X',30,'X'),'10'));
 15  end case;
 16  end loop;
 17  commit;
 18  end;
 19  /

PL/SQL procedure successfully completed.

LAURENT @ orcl > insert into t select 10,'XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX' from dual connect by level <=100000; 

100000 rows created. 

LAURENT @ orcl > commit;

Commit complete.

LAURENT @ orcl > exec dbms_stats.gather_table_stats(ownname=>USER, tabname=>'T', method_opt=>'for all columns size 12', estimate_percent=>100);

PL/SQL procedure successfully completed.

LAURENT @ orcl > select table_name,column_name,density,histogram,sample_size from user_tab_col_statistics where table_name='T';

TABLE_NAME COLUMN_NAM    DENSITY HISTOGRAM       SAMPLE_SIZE
---------- ---------- ---------- --------------- -----------
T          ID         4.5455E-06 FREQUENCY            110000
T          V          4.5455E-06 FREQUENCY            110000

And if we have a look to the data distribution of the column V, no problem …


LAURENT @ orcl > select table_name,column_name,
  2  endpoint_number,endpoint_value,
  3  endpoint_actual_value
  4  from user_histograms
  5  where table_name='T' and column_name='V'
  6  order by ENDPOINT_ACTUAL_VALUE;

TABLE_NAME COLUMN_NAM ENDPOINT_NUMBER ENDPOINT_VALUE ENDPOINT_ACTUAL_VALUE
---------- ---------- --------------- -------------- --------------------------------
T          V                     1000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX01
T          V                     2000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX02
T          V                     3000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX03
T          V                     4000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX04
T          V                     5000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX05
T          V                     6000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX06
T          V                     7000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX07
T          V                     8000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX08
T          V                     9000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX09
T          V                    10000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX10
T          V                   110000     4.5871E+35 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

11 rows selected.

The problem comes when the size of the character column exceeds 32 bytes:


LAURENT @ orcl > drop table t purge;

Table dropped.

LAURENT @ orcl > create table t (id number, v varchar2(64));

Table created.

LAURENT @ orcl > begin
for i in 1..10000
loop
case mod(i,10)
  when 0 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'01'));
  when 1 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'02'));
  when 2 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'03'));
  when 3 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'04'));
  when 4 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'05'));
  when 5 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'06'));
  when 6 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'07'));
  when 7 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'08'));
  when 8 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'09'));
  when 9 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'10'));
end case;
end loop;
commit;
end;
/

LAURENT @ orcl > insert into t select 10,'XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX' from dual connect by level <=100000; 100000 rows created. LAURENT @ orcl > commit;

Commit complete.

LAURENT @ orcl > exec dbms_stats.gather_table_stats(ownname=>USER, tabname=>'T', method_opt=>'for all columns size 12', estimate_percent=>100);

PL/SQL procedure successfully completed.

LAURENT @ orcl > select table_name,column_name,density,histogram,sample_size from user_tab_col_statistics where table_name='T';

TABLE_NAME COLUMN_NAM    DENSITY HISTOGRAM       SAMPLE_SIZE
---------- ---------- ---------- --------------- -----------
T          ID         4.5455E-06 FREQUENCY            110000
T          V          4.5455E-06 FREQUENCY            110000

But … if we have a look to the DBA_HISTOGRAMS view …


LAURENT @ orcl > select table_name,column_name,
  2  endpoint_number,endpoint_value,
  3  endpoint_actual_value
  4  from user_histograms
  5  where table_name='T'
  6  order by COLUMN_NAME,ENDPOINT_ACTUAL_VALUE;

TABLE_NAME COLUMN_NAM ENDPOINT_NUMBER ENDPOINT_VALUE ENDPOINT_ACTUAL_VALUE
---------- ---------- --------------- -------------- --------------------------------
T          ID                    1000              0
T          ID                    2000              1
T          ID                    3000              2
T          ID                    4000              3
T          ID                    5000              4
T          ID                    6000              5
T          ID                    7000              6
T          ID                    8000              7
T          ID                    9000              8
T          ID                   10000              9
T          ID                  110000             10
T          V                   110000     4.5871E+35

LAURENT @ orcl > select count(*) from t where v=lpad('X',32,'X')||'05';

  COUNT(*)
----------
      1000

LAURENT @ orcl > select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS'));

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------
SQL_ID  aass8rg64h38b, child number 0
-------------------------------------
select count(*) from t where v=lpad('X',32,'X')||'05'

Plan hash value: 2966233522

-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      2 |        |      2 |00:00:00.01 |    1416 |
|   1 |  SORT AGGREGATE    |      |      2 |      1 |      2 |00:00:00.01 |    1416 |
|*  2 |   TABLE ACCESS FULL| T    |      2 |   110K |   2000 |00:00:00.01 |    1416 |
-------------------------------------------------------------------------------------

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

   2 - filter("V"='XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX05')

19 rows selected.

LAURENT @ orcl > select count(*) from t where v='XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX';

  COUNT(*)
----------
    100000

LAURENT @ orcl > select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS'));

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------
SQL_ID  adnfzsc6buqa3, child number 0
-------------------------------------
select count(*) from t where v='XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX'

Plan hash value: 2966233522

-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |      1 |00:00:00.01 |     708 |
|   1 |  SORT AGGREGATE    |      |      1 |      1 |      1 |00:00:00.01 |     708 |
|*  2 |   TABLE ACCESS FULL| T    |      1 |   110K |   100K |00:00:00.01 |     708 |
-------------------------------------------------------------------------------------

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

   2 - filter("V"='XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX')

19 rows selected.

So, with this kind of difference between E-rows and A-rows, you can easily face performance problems, specially if this column has been indexed. So we have a frequency histogram and it doesn’t help us to determine the cardinality in the character column…

This behaviour has been reported in the Bug 18377553 : POOR CARDINALITY ESTIMATE WITH HISTOGRAMS AND VALUES > 32 BYTES.

In my case, the problem occurred with NVARCHAR2 columns (national character set was AL16UTF16), so when the column was containing more that 16 characters, performance problems occurred.

Hopefully, Oracle has published a one-off patch for this bug (available for 11.2.0.3 and 11.2.0.4 on linux x86-64), or as a workaround, you can remove histogram on these kind of columns (with the method_opt: FOR COLUMNS … SIZE 1)

In 12.1, the problem occurs only when the size of the character column exceeds 64 bits (32 characters under AL16UTF16 character set)


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 Linux: Version 12.1.0.2.0 - Production                                            0
NLSRTL Version 12.1.0.2.0 - Production                                                    0

SQL> create table t (id number, v nvarchar2(64));

Table created.

SQL> begin
for i in 1..10000
loop
case mod(i,10)
  when 0 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'01'));
  when 1 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'02'));
  when 2 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'03'));
  when 3 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'04'));
  when 4 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'05'));
  when 5 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'06'));
  when 6 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'07'));
  when 7 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'08'));
  when 8 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'09'));
  when 9 then insert into t values(mod(i,10), concat(lpad('X',32,'X'),'10'));
end case;
end loop;
commit;
end;
/

PL/SQL procedure successfully completed.

SQL> insert into t select 10,'XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX' from dual connect by level <=100000; 100000 rows created. SQL> commit;

Commit complete.

SQL> exec dbms_stats.gather_table_stats(ownname=>USER, tabname=>'T', method_opt=>'for all columns size 12', estimate_percent=>100);

PL/SQL procedure successfully completed.

SQL> select table_name,column_name,density,histogram,sample_size from user_tab_col_statistics where table_name='T';

TABLE_NAME COLUMN_NAM    DENSITY HISTOGRAM       SAMPLE_SIZE
---------- ---------- ---------- --------------- -----------
T          ID         4.5455E-06 FREQUENCY            110000
T          V          4.5455E-06 FREQUENCY            110000

SQL> select table_name,column_name,
  2  endpoint_number,endpoint_value,
  3  endpoint_actual_value
  4  from user_histograms
  5  where table_name='T'
  6  order by COLUMN_NAME,ENDPOINT_NUMBER;

TABLE_NAME COLUMN_NAM ENDPOINT_NUMBER ENDPOINT_VALUE ENDPOINT_ACTUAL_VALUE
---------- ---------- --------------- -------------- ----------------------------------
T          ID                    1000              0 0
T          ID                    2000              1 1
T          ID                    3000              2 2
T          ID                    4000              3 3
T          ID                    5000              4 4
T          ID                    6000              5 5
T          ID                    7000              6 6
T          ID                    8000              7 7
T          ID                    9000              8 8
T          ID                   10000              9 9
T          ID                  110000             10 10
T          V                   110000     1.7849E+33  X X X X X X X X X X X X X X X X X
                                                      X X X X X X X X X X X X X X X

12 rows selected.

Problem with 12.1 databases, the one-off patch has not been released yet and It will be fixed in 12.2.

Slides of my presentation at UKOUG TECH15 conference

The conference was last December, but I was a little bit busy this month …

So here are the slides of my presentation about SIMD extensions inside and outside Oracle 12c during the Super Sunday at UKOUG TECH15 conference.

It was my pleasure to have some great attendees in the audience: Frits Hoogland (ACE Director and Oak Table Member), Ludovico Caldara (Oracle Ace), Luca Canali (Oak Table Member), Mark Fielding (Oracle ACE), Bertrand Drouvot (Oracle Ace), Franck Pachot (Oracle Ace) and all the French guys who were at the conference!

Follow

Get every new post delivered to your Inbox.

Join 462 other followers