Oracle … as usual

Oracle by Laurent Leturgez

Category Archives: Administration

Get the min and max value of your In Memory Storage Indexes

Yesterday, I read a blog post from Maria Colgan (https://sqlmaria.com/2017/02/21/oracle-storage-index/) who described why you will not always see the benefits of In memory Storage Indexes.

I won’t re-write Maria’s post but to sum up, Oracle doesn’t sort the data to build IMCUs, as a result min and max values of the storage indexes are not very selective. I’ve explained this in my SIMD related presentation (available here: https://www.slideshare.net/lolo115/ukoug15-simd-outside-and-inside-oracle-12c-12102, See. Slides 22 and 23).

To go further, we can find a bunch of views, oops a bunch of undocumented views, related to IM segments, Compression units and SMUs.  (See doc bug in MOS: Bug 19361690 : SEVERAL V$ VIEWS FOR INMEMORY ARE NOT DOCUMENTED, Bug doesn’t seem to be fixed in 12.2)

If you have a look at these views, they contains a lot of very interesting things, and specially the min and max values for every IMCUs and columns inside.

In the below example, I took the same kind of example that Maria described.

First, I created two tables loaded in the IM store. Those tables are based on SH.SALES table, the first one is not sorted, the second is ordered by AMOUNT_SOLD :

SQL> create table s inmemory no memcompress priority critical as select * from sh.sales;

SQL> create table s2 inmemory no memcompress priority critical as select * from sh.sales order by amount_sold;

SQL> @IM_seg
Enter value for owner: LAURENT
Enter value for segment_name:

OWNER       SEGMENT_NAME    PARTITION_NAM TABLESPACE_NAME INMEMORY_SIZE      BYTES BYTES_NOT_POPULATED POPULATE_ INMEMORY INMEMORY_COMPRESS
----------- --------------- ------------- --------------- ------------- ---------- ------------------- --------- -------- -----------------
LAURENT     S                             USERS                28966912   37748736                   0 COMPLETED CRITICAL NO MEMCOMPRESS
LAURENT     S2                            USERS                28966912   37748736                   0 COMPLETED CRITICAL NO MEMCOMPRESS
                                                          -------------
sum                                                            57933824

Then, I used a script of mine based on one of these undocumented stuff, the V$IM_COL_CU view that gives us min and max values for each column in the IMCUs.

SQL> @IM_IMCU_stats
Enter value for tab_owner: LAURENT
Enter value for tab_name: S
Enter value for column_name: AMOUNT_SOLD

IMCU_ADDR                  OBJD ONAME                COLUMN_NAME                    DATA_TYPE  DICTIONARY_ENTRIES MIN_VAL         MAX_VAL
-------------------- ---------- -------------------- ------------------------------ ---------- ------------------ --------------- ---------------
00000000610FFF70          94467 S                    AMOUNT_SOLD                    NUMBER                      0 7.14            1520.39
00000000613FFF70          94467 S                    AMOUNT_SOLD                    NUMBER                      0 7.22            1533.38
00000000616FFF70          94467 S                    AMOUNT_SOLD                    NUMBER                      0 6.83            1566.01
00000000619FFF70          94467 S                    AMOUNT_SOLD                    NUMBER                      0 6.4             1598.63
0000000061CFFF70          94467 S                    AMOUNT_SOLD                    NUMBER                      0 6.54            1738.43
0000000076000000          94467 S                    AMOUNT_SOLD                    NUMBER                      0 6.54            1738.43
0000000076300000          94467 S                    AMOUNT_SOLD                    NUMBER                      0 6.54            1782.72
0000000076600000          94467 S                    AMOUNT_SOLD                    NUMBER                      0 7.13            1782.72
0000000076900000          94467 S                    AMOUNT_SOLD                    NUMBER                      0 7.13            1753.2

9 rows selected.

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

SQL> @IM_IMCU_stats
Enter value for tab_owner: LAURENT
Enter value for tab_name: S2
Enter value for column_name: AMOUNT_SOLD

IMCU_ADDR                  OBJD ONAME                COLUMN_NAME                    DATA_TYPE  DICTIONARY_ENTRIES MIN_VAL         MAX_VAL
-------------------- ---------- -------------------- ------------------------------ ---------- ------------------ --------------- ---------------
0000000071FFFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 481             1782.72
00000000721FFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 69.08           481
00000000724FFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 51.43           69.08
00000000727FFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 46.31           51.43
0000000072AFFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 32.35           46.31
0000000072DFFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 24.24           32.35
00000000730FFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 17.79           24.24
00000000733FFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 10.79           17.79
00000000736FFFE8          94469 S2                   AMOUNT_SOLD                    NUMBER                      0 6.4             10.79

9 rows selected.

We can clearly see that S2 table has been ordered by AMOUNT_SOLD, and if I count the number of lines with a value of AMOUNT_SOLD equal to 20, S table (unordered) will read all IMCUs (9), a query againt S2 will prune 8 of the 9 IMCUs.

SQL> @IM_sesstat

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
CPU used by this session                                                  3
IM scan CUs no memcompress                                                0
IM scan CUs memcompress for dml                                           0
IM scan CUs memcompress for query low                                     0
IM scan CUs memcompress for query high                                    0
IM scan CUs memcompress for capacity low                                  0
IM scan CUs memcompress for capacity high                                 0
IM scan CUs columns accessed                                              0
IM scan CUs columns decompressed                                          0
IM scan CUs columns theoretical max                                       0
IM scan rows                                                              0
IM scan rows valid                                                        0
IM scan rows optimized                                                    0
IM scan rows projected                                                    0
IM scan CUs split pieces                                                  0
IM scan CUs pruned                                                        0

16 rows selected.

SQL> select /*+ INMEMORY */ count(*) from s where amount_sold=20;

  COUNT(*)
----------
       140

1 row selected.

SQL> @IM_sesstat

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
CPU used by this session                                                 20
IM scan CUs no memcompress                                                9
IM scan CUs memcompress for dml                                           0
IM scan CUs memcompress for query low                                     0
IM scan CUs memcompress for query high                                    0
IM scan CUs memcompress for capacity low                                  0
IM scan CUs memcompress for capacity high                                 0
IM scan CUs columns accessed                                              9
IM scan CUs columns decompressed                                          0
IM scan CUs columns theoretical max                                      63
IM scan rows                                                         918843
IM scan rows valid                                                   918843
IM scan rows optimized                                                    0
IM scan rows projected                                                  140
IM scan CUs split pieces                                                  9
IM scan CUs pruned                                                        0

16 rows selected.

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

SQL> @IM_sesstat

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
CPU used by this session                                                  1
IM scan CUs no memcompress                                                0
IM scan CUs memcompress for dml                                           0
IM scan CUs memcompress for query low                                     0
IM scan CUs memcompress for query high                                    0
IM scan CUs memcompress for capacity low                                  0
IM scan CUs memcompress for capacity high                                 0
IM scan CUs columns accessed                                              0
IM scan CUs columns decompressed                                          0
IM scan CUs columns theoretical max                                       0
IM scan rows                                                              0
IM scan rows valid                                                        0
IM scan rows optimized                                                    0
IM scan rows projected                                                    0
IM scan CUs split pieces                                                  0
IM scan CUs pruned                                                        0

16 rows selected.

SQL> select /*+ INMEMORY */ count(*) from s2 where amount_sold=20;

  COUNT(*)
----------
       140

SQL> @IM_sesstat

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
CPU used by this session                                                  2
IM scan CUs no memcompress                                                9
IM scan CUs memcompress for dml                                           0
IM scan CUs memcompress for query low                                     0
IM scan CUs memcompress for query high                                    0
IM scan CUs memcompress for capacity low                                  0
IM scan CUs memcompress for capacity high                                 0
IM scan CUs columns accessed                                              1
IM scan CUs columns decompressed                                          0
IM scan CUs columns theoretical max                                      63
IM scan rows                                                         918843
IM scan rows valid                                                   103923
IM scan rows optimized                                               814920
IM scan rows projected                                                  140
IM scan CUs split pieces                                                  9
IM scan CUs pruned                                                        8

16 rows selected.

 

All the scripts I used in the post, including the one used to see storage indexes, are available here:

That’s all for today !! 🙂

 

Store your TNS entries in MS Active Directory (only for full Windows platforms)

When you manage a lot of Oracle clients, it can be difficult to manage as much tnsnames.ora files as you have Oracle clients.

In that case, it can be useful to configure solutions to centralize only one tnsnames.ora. Another solution is to use a Microsoft Active Directory to store your TNS Entries (This solution is for computers running on MS Windows).

The job is done in two steps :

  • First one is to configure Active Directory (AD) server
  • Second one is to configure your Oracle clients to query the AD server

In my lab, I have many boxes:

  • a MS Windows 2008 R2 Server (ok ok it’s an old box … but it works fine and I assume it will work fine on a 2012 R2 server). This server acts as a controller domain for the domain example.com. The server name is windows1.example.com. It hosts the Active Directory for the domain example.com and a DNS server.
  • a MS Windows where an Oracle Client is installed. (Don’t try to do this configuration on a linux box … it’s not working)

Configure AD to store Oracle TNS entries.

To do that, you first have to install an Oracle Client on the server. I won’t describe how to do that … you’re smart enough to do it yourself :). You just have to install the administrative Client.

Then, create a work directory, in my server I did that in C:\AD.  And copy all the files from $ORACLE_HOME/ldap/schema/ad to this work directory.

PS C:\> md AD
PS C:\> copy C:\app\product\11.2.0\dbhome_1\ldap\schema\ad\* C:\AD
PS C:\> dir C:\AD


    Directory: C:\AD


Mode                LastWriteTime     Length Name
----                -------------     ------ ----
-a---        09/11/2004     16:44        470 adContextCreate.lst
-a---        09/11/2004     16:44       2122 adContextCreateCommon.sbs
-a---        01/08/2001     04:16        591 adContextUpgradeFrom81600.lst
-a---        01/08/2001     04:17        407 adContextUpgradeFrom81600Common.sbs
-a---        23/05/2001     17:13        676 adDisplaySpecifiersCreate.lst
-a---        23/05/2001     17:13       5106 adDisplaySpecifiers_de.sbs
-a---        23/05/2001     17:13       5163 adDisplaySpecifiers_es.sbs
-a---        23/05/2001     17:13       5385 adDisplaySpecifiers_fr.sbs
-a---        23/05/2001     17:13       5092 adDisplaySpecifiers_it.sbs
-a---        23/05/2001     17:13       5562 adDisplaySpecifiers_ja.sbs
-a---        23/05/2001     17:13       5406 adDisplaySpecifiers_ko.sbs
-a---        23/05/2001     17:13      76035 adDisplaySpecifiers_other.sbs
-a---        23/05/2001     17:13       5453 adDisplaySpecifiers_pt_BR.sbs
-a---        23/05/2001     17:13       5069 adDisplaySpecifiers_us.sbs
-a---        23/05/2001     17:13       5225 adDisplaySpecifiers_zh_CN.sbs
-a---        01/08/2001     04:16        576 adSchemaCreate.lst
-a---        04/08/2003     17:51        219 adSchemaCreateAux.lst
-a---        13/11/2001     16:10        224 adSchemaCreateAux.sbs
-a---        09/11/2004     16:44       5445 adSchemaCreateBase.sbs
-a---        01/08/2001     04:17      11925 adSchemaCreateNet.sbs
-a---        01/08/2001     04:17       7462 adSchemaCreateRDBMS.sbs
-a---        01/08/2001     04:16        570 adSchemaUpgradeFrom81600.lst
-a---        01/08/2001     04:17        585 adSchemaUpgradeFrom81600Base.sbs
-a---        01/08/2001     04:17        509 adSchemaUpgradeFrom81600Net.sbs
-a---        01/08/2001     04:17        690 adSchemaUpgradeFrom81600RDBMS.sbs

 

Next, we will replace some values into some of these files. But before we need to note several DN (distinguished name).  :

  • DN of the root container. Usually this DN represents the domain where we will create what is called the “Oracle Context” (see below). In my case, my domain’s DN is : “DC=example,DC=com”.
  • DN of the Users branch in the AD container. In my case, it’s “CN=Users,DC=example,DC=com”.
  • DN of the user you are logged in. Basically, I will do that with the domain administrator, and its DN is: “CN=Administrator,CN=Users,DC=example,DC=com”
  • DN of the Oracle Context, in my case its DN is: “CN=OracleContext,DC=example,DC=com”. It’s in this Oracle Context that TNS Entries will be created.

I defined all these values in a set of PowerShell variables:

PS C:\> cd AD
PS C:\AD> $rootCont="DC=example,DC=com"
PS C:\AD> $usersBranch="CN=Users,DC=example,DC=com"
PS C:\AD> $userLogged="CN=Administrator,CN=Users,DC=example,DC=com"
PS C:\AD> $oracleContext="CN=OracleContext,DC=example,DC=com"

Then, all the files mentioned below will be “SEDed” to replace patterns with the correct values in new LDIF files (It has been done with Powershell, but you can do this with the tool you want: sed/cygwin, notepad etc).

PS C:\AD> cat adSchemaCreateBase.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adSchemaCreateBase.ldif -Encoding UTF8
PS C:\AD> cat adSchemaCreateNet.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adSchemaCreateNet.ldif -Encoding UTF8
PS C:\AD> cat adSchemaCreateRDBMS.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adSchemaCreateRDBMS.ldif -Encoding UTF8
PS C:\AD> cat adSchemaUpgradeFrom81600BASE.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adSchemaUpgradeFrom81600BASE.ldif -Encoding UTF8
PS C:\AD> cat adSchemaUpgradeFrom81600NET.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adSchemaUpgradeFrom81600NET.ldif -Encoding UTF8
PS C:\AD> cat adSchemaUpgradeFrom81600RDBMS.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adSchemaUpgradeFrom81600RDBMS.ldif -Encoding UTF8
PS C:\AD> cat adDisplaySpecifiers_us.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adDisplaySpecifiers_us.ldif -Encoding UTF8
PS C:\AD> cat adDisplaySpecifiers_other.sbs | %{$_ -replace “%s_AdDomainDN%",$rootCont} | Out-File adDisplaySpecifiers_other.ldif -Encoding UTF8

PS C:\AD> cat adContextCreateCommon.sbs | %{$_ -replace “%s_OracleContextDN%" ,$oracleContext} `
>> | %{$_ -replace “%s_AdUsersDomainDN%", $usersBranch} `
>> | %{$_ -replace “%s_CurrentUserDN%", $userLogged} | Out-File adContextCreateCommon.ldif -Encoding UTF8
>>
PS C:\AD>

PS C:\AD> cat adContextUpgradeFrom81600Common.sbs | %{$_ -replace “%s_OracleContextDN%",$oracleContext} | Out-File adContextUpgradeFrom81600Common.ldif -Encoding UTF8

Please note that if your AD is installed in another supported language, you have to modify the DisplaySpecifier file related to the installation language (for example,  adDisplaySpecifiers_fr.sbs if it’s installed in French).

After that, a simple bunch of ldapmodify commands, and the entries for OracleContext will be created in the AD:

PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adSchemaCreateBase.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adSchemaCreateNet.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adSchemaCreateRDBMS.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adSchemaUpgradeFrom81600BASE.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adSchemaUpgradeFrom81600NET.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adSchemaUpgradeFrom81600RDBMS.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adDisplaySpecifiers_us.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adDisplaySpecifiers_other.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adContextCreateCommon.ldif
PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\adContextUpgradeFrom81600Common.ldif

During execution, I had this kind off output … you can safely ignore this issue (probably due to powershell encoding which is made by default in UTF-8-BOM (original file used UTF-8 encoding):

ldapmodify.exe: no attributes to change or add (entry ´╗┐#)

Once done, you can check you have the correct number of objects in your directory. I did this check with a basic ldapsearch command:

PS C:\AD> ldapsearch -D "cn=Administrator,cn=users,dc=example,dc=com" -b "CN=Schema,CN=Configuration,dc=example,dc=com" -w "YOUR_PASSWORD" "(&(objectClass=attributeSchema)(CN=orcl*))" DN | Measure-Object -line

 Lines    Words    Characters    Property
 -----    -----    ----------    --------
    37    


PS C:\AD> ldapsearch -D "cn=Administrator,cn=users,dc=example,dc=com" -b "CN=Schema,CN=Configuration,dc=example,dc=com" -w "YOUR_PASSWORD" "(&(objectClass=classSchema)(CN=orcl*))" DN | Measure-Object -line

 Lines    Words    Characters    Property
 -----    -----    ----------    --------
    14    
          

If the AD MMC users and computers plugin, a new branch appeared: “OracleContext” and three groups related to security management of the Oracle Context:

users_ad

Then, If you want to add some entries, you have to create an ldap.ora file first, then create entries. TO finish this configuration steps, we have to grant permissions on specific branches to allow anonymous access on TNS entries. This is mandatory because Oracle client doesn’t bind the directory, and it doesn’t have to logon with a specific user to read the TNS Entry.

LDAP.ORA

This file has to be created in the $OH/network/admin. There must be 3 three parameters for the directory server name and port, the durectory server type, and the DN of the parent branch which contains the Oracle Context.
Here’s the content of my ldap.ora file (refer to Oracle documentation : Net Services Reference for more information).

DIRECTORY_SERVERS=windows1.example.com:389
DIRECTORY_SERVER_TYPE=AD
DEFAULT_ADMIN_CONTEXT="DC=example,DC=com"

CREATE TNS ENTRIES IN ACTIVE DIRECTORY

The easiest way to do that is to use Net Manager and add entry in the directory branch.

But, I prefer to import entries from a ldif file. To do that, you have to create a LDIF file which contains all the necessary properties for the TNS entry. Below, a sample of what it can contain:

PS C:\AD> cat orcl.ldif
dn: CN=orcl,CN=OracleContext,DC=example,DC=com
changetype: add
objectClass: top
objectClass: orclNetService
orclNetDescString: (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=windows1.example.com)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=orcl)))

dn: CN=coucou,CN=OracleContext,DC=example,DC=com
changetype: add
objectClass: top
objectClass: orclNetService
orclNetDescString:
 (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=192.168.99.15)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=orcl)))

And to finish, it’s easy to add them to the directory, the same way we import our ldif during AD configuration:

PS C:\AD> ldapmodify -c -D "cn=Administrator,cn=users,dc=example,dc=com" -w "YOUR_PASSWORD" -f C:\AD\orcl.ldif

adding new entry CN=orcl,CN=OracleContext,DC=example,DC=com

adding new entry CN=coucou,CN=OracleContext,DC=example,DC=com

SPECIFIC PERMISSIONS

Grant the permission “anonymous logon” on the entry we’ve created.

C:\> dsacls "CN=orcl,CN=OracleContext,DC=example,DC=com" /G "anonymous logon":GR
C:\> dsacls "CN=coucou,CN=OracleContext,DC=example,DC=com" /G "anonymous logon":GR

 

Client configuration

The client configuration is very easy, there’s only two lines to configure in SQLNET.ora file.

NAMES.DIRECTORY_PATH= (LDAP)
NAMES.LDAP_AUTHENTICATE_BIND=1

A call to tnsping will show you that trying to resolve the given alias will be done through your ldap configuration:

C:\>tnsping orcl

TNS Ping Utility for 64-bit Windows: Version 11.2.0.4.0 - Production on 12-JAN-2017 15:41:49

Copyright (c) 1997, 2013, Oracle.  All rights reserved.

Used parameter files:
C:\app\product\11.2.0\dbhome_1\network\admin\sqlnet.ora

Used LDAP adapter to resolve the alias
Attempting to contact (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=windows1.example.com)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=orcl
OK (0 msec)

Another way to verify it resolves the alias through LDAP is to enable SQLNET client tracing by addind these lines in the sqlnet.ora file:

TRACE_LEVEL_CLIENT=ADMIN
TRACE_UNIQUE_CLIENT=ON
TRACE_TIMESTAMP_CLIENT=ON
TRACE_DIRECTORY_CLIENT=c:\temp\client_trace
LOG_DIRECTORY_CLIENT=c:\temp\client_trace
DIAG_ADR_ENABLED=OFF

In the trace file, we see this information that prooves LDAP usage to resolve names:

[12-JAN-2017 15:45:21:752] nnflilc:  Opening sync conn to windows1.example.com:389
[12-JAN-2017 15:45:21:752] nnflalc: entry
[12-JAN-2017 15:45:21:752] nnflalc: native bind CN=Administrator,CN=Users,DC=example,DC=com returns 0
[12-JAN-2017 15:45:21:752] nnflalc: bind CN=Administrator,CN=Users,DC=example,DC=com returns 0x0
.../...
[12-JAN-2017 15:45:21:752] nnflrne1: Quering the directory for dn: cn=orcl,cn=OracleContext,DC=example,DC=com
[12-JAN-2017 15:45:21:752] nnflqbf: entry
[12-JAN-2017 15:45:21:752] nnflqbf: Search: Attrs[0]: objectclass
[12-JAN-2017 15:45:21:752] nnflqbf: Search:  Base: cn=orcl,cn=OracleContext,DC=example,DC=com; Scope: 0; filter: (objectclass=*) returns 0x0
[12-JAN-2017 15:45:21:752] nnflqbf: exit
[12-JAN-2017 15:45:21:752] nnflgne: entry
[12-JAN-2017 15:45:21:752] nnflgne:   DN : cn=orcl,cn=OracleContext,DC=example,DC=com
[12-JAN-2017 15:45:21:752] nnflgne: exit
.../...
[12-JAN-2017 15:45:21:752] nigtrm: Count in the NI global area is now 1
[12-JAN-2017 15:45:21:752] nigtrm: Count in the NL global area is now 1
[12-JAN-2017 15:45:21:752] nigini: entry
[12-JAN-2017 15:45:21:752] nigini: Count in the NL global area is now 2
[12-JAN-2017 15:45:21:752] nigini: Count in NI gbl area now: 2
[12-JAN-2017 15:45:21:752] nigini: exit
[12-JAN-2017 15:45:21:752] niqname: Hst is already an NVstring.
[12-JAN-2017 15:45:21:752] niqname: Inserting CID.
[12-JAN-2017 15:45:21:752] nigtrm: Count in the NI global area is now 1
[12-JAN-2017 15:45:21:752] nigtrm: Count in the NL global area is now 1
[12-JAN-2017 15:45:21:752] nigini: entry
[12-JAN-2017 15:45:21:752] nigini: Count in the NL global area is now 2
[12-JAN-2017 15:45:21:752] nigini: Count in NI gbl area now: 2
[12-JAN-2017 15:45:21:752] nigini: exit
[12-JAN-2017 15:45:21:752] niqname: Hst is already an NVstring.
[12-JAN-2017 15:45:21:752] niqname: Inserting CID.
[12-JAN-2017 15:45:21:752] niotns: entry
[12-JAN-2017 15:45:21:752] niotns: niotns: setting up interrupt handler...
[12-JAN-2017 15:45:21:752] niotns: Not trying to enable dead connection detection.
[12-JAN-2017 15:45:21:752] niotns: Calling address: (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=windows1.example.com)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=orcl)(CID=(PROGRAM=C:\app\product\11.2.0\dbhome_1\bin\sqlplus.exe)(HOST=clientWin)(USER=Administrator))))
[12-JAN-2017 15:45:21:752] nsgettrans_bystring: entry
[12-JAN-2017 15:45:21:752] nsgettrans_bystring: exit
[12-JAN-2017 15:45:21:752] nsmal: 280 bytes at 0x6baaf0
[12-JAN-2017 15:45:21:752] nscall: connecting...

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 :

 

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.

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.

 

 

 

Linux monitoring of oracle 12c multi-threaded instances

Oracle 12c comes with a new feature: multithreaded server. In summary, main processes like real time scheduled processes (vktm, lms), or main processes like pmon or dbwn continue to run as processes. For other ones (lgwr, mmon, server processes etc.), they run now in a thread.

This feature has been developed to optimize oracle to be run on new processors with many core and many threads per core (for example SPARC T Processors), but the DBA will have to change many methods he use to analyze problems in a multi-threaded server.

If for some problems, you usually analyze the OS side, top, ps, and other tools have to be used in a different way. Let’s see different tools that can be used to analyze processes and thread in linux (Tools mentioned here has been tested with Oracle Enterprise Linux 6).

For all example above, I used an orcl instance which run in a multi-threaded configuration

  • ps

If I run a simple ps under my config, there are only 6 processes:

[oracle@oel64-12c ~]$ ps -ef | grep [o]rcl
oracle    9871     1  0 21:02 ?        00:00:00 ora_pmon_orcl
oracle    9873     1  0 21:02 ?        00:00:00 ora_psp0_orcl
oracle    9878     1  5 21:02 ?        00:01:35 ora_vktm_orcl
oracle    9882     1  0 21:02 ?        00:00:02 ora_u004_orcl
oracle    9888     1  0 21:02 ?        00:00:11 ora_u005_orcl
oracle    9894     1  0 21:02 ?        00:00:00 ora_dbw0_orcl
 If I want to print all threads that run in these processes, I can run this command:
[oracle@oel64-12c ~]$ ps -eLo pid,pcpu,tid,user,comm,cmd | sed -n -e '1p' -e '/orcl/p'
  PID %CPU   TID USER     COMMAND         CMD
 9871  0.0  9871 oracle   ora_pmon_orcl   ora_pmon_orcl
 9873  0.0  9873 oracle   ora_psp0_orcl   ora_psp0_orcl
 9878  5.2  9878 oracle   ora_vktm_orcl   ora_vktm_orcl
 9882  0.0  9882 oracle   ora_scmn_orcl   ora_u004_orcl
 9882  0.0  9883 oracle   oracle          ora_u004_orcl
 9882  0.0  9884 oracle   ora_gen0_orcl   ora_u004_orcl
 9882  0.0  9885 oracle   ora_mman_orcl   ora_u004_orcl
 9882  0.0  9891 oracle   ora_dbrm_orcl   ora_u004_orcl
 9882  0.0  9895 oracle   ora_lgwr_orcl   ora_u004_orcl
 9882  0.0  9896 oracle   ora_ckpt_orcl   ora_u004_orcl
 9882  0.0  9897 oracle   ora_lg00_orcl   ora_u004_orcl
 9882  0.0  9898 oracle   ora_lg01_orcl   ora_u004_orcl
 9882  0.0  9899 oracle   ora_smon_orcl   ora_u004_orcl
 9882  0.0  9901 oracle   ora_lreg_orcl   ora_u004_orcl
 9888  0.0  9888 oracle   ora_scmn_orcl   ora_u005_orcl
 9888  0.0  9889 oracle   oracle          ora_u005_orcl
 9888  0.0  9890 oracle   ora_diag_orcl   ora_u005_orcl
 9888  0.0  9892 oracle   ora_dia0_orcl   ora_u005_orcl
 9888  0.0  9900 oracle   ora_reco_orcl   ora_u005_orcl
 9888  0.0  9902 oracle   ora_mmon_orcl   ora_u005_orcl
 9888  0.0  9903 oracle   ora_mmnl_orcl   ora_u005_orcl
 9888  0.0  9904 oracle   ora_d000_orcl   ora_u005_orcl
 9888  0.0  9905 oracle   ora_s000_orcl   ora_u005_orcl
 9888  0.0  9906 oracle   ora_n000_orcl   ora_u005_orcl
 9888  1.3  9931 oracle   oracle_9931_orc ora_u005_orcl
 9888  0.0  9932 oracle   ora_tmon_orcl   ora_u005_orcl
 9888  0.0  9933 oracle   ora_tt00_orcl   ora_u005_orcl
 9888  0.0  9934 oracle   ora_smco_orcl   ora_u005_orcl
 9888  0.0  9938 oracle   ora_fbda_orcl   ora_u005_orcl
 9888  0.0  9939 oracle   ora_aqpc_orcl   ora_u005_orcl
 9888  0.0  9944 oracle   ora_p000_orcl   ora_u005_orcl
 9888  0.0  9945 oracle   ora_p001_orcl   ora_u005_orcl
 9888  0.0  9946 oracle   ora_p002_orcl   ora_u005_orcl
 9888  0.0  9947 oracle   ora_p003_orcl   ora_u005_orcl
 9888  0.0  9948 oracle   ora_p004_orcl   ora_u005_orcl
 9888  0.0  9949 oracle   ora_p005_orcl   ora_u005_orcl
 9888  0.0  9950 oracle   ora_p006_orcl   ora_u005_orcl
 9888  0.0  9951 oracle   ora_p007_orcl   ora_u005_orcl
 9888  0.0  9952 oracle   ora_cjq0_orcl   ora_u005_orcl
 9888  0.0  9996 oracle   ora_qm02_orcl   ora_u005_orcl
 9888  0.0  9998 oracle   ora_q002_orcl   ora_u005_orcl
 9888  0.0  9999 oracle   ora_q003_orcl   ora_u005_orcl
 9888  0.0 16009 oracle   ora_w000_orcl   ora_u005_orcl
 9894  0.0  9894 oracle   ora_dbw0_orcl   ora_dbw0_orcl
16414  0.0 16414 oracle   sed             sed -n -e 1p -e /orcl/p
 First column is the PID, second column is the CPU percent burn by the thread, third column is the thread Id, next column is the thread owner, the second last column is the oracle thread name and the last is the process name.
With ps, you can have a static view and possibly identify problematic processes
  • top

With top, you can see you processes or threads in a more dynamic fashion. Top option used to see threads is -H, but you have to mention which processes you want to analyze with -p parameter followed by pids. The main drawback of this command is that -p is limited to 20 pids but for a mid size multi-threaded instance, it’s ok.

[oracle@oel64-12c ~]$ top -p $(pgrep -d',' orcl$) -H
top - 21:55:37 up 1 day,  2:03,  6 users,  load average: 1.10, 1.04, 1.13
Tasks:  43 total,   0 running,  43 sleeping,   0 stopped,   0 zombie
Cpu0  : 25.8%us, 46.5%sy,  0.0%ni, 14.5%id, 10.3%wa,  0.0%hi,  3.0%si,  0.0%st
Cpu1  : 16.3%us, 46.8%sy,  0.0%ni, 28.9%id,  7.8%wa,  0.0%hi,  0.3%si,  0.0%st
Mem:   4055296k total,  3052640k used,  1002656k free,    20360k buffers
Swap:  8388604k total,  1475216k used,  6913388k free,  2302200k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 9878 oracle    -2   0 1489m  17m  15m S  6.7  0.4   3:03.07 ora_vktm_orcl
 9892 oracle    20   0 3457m 340m 252m S  0.5  8.6   0:01.27 ora_dia0_orcl
 9902 oracle    20   0 3457m 340m 252m S  0.5  8.6   0:02.00 ora_mmon_orcl
 9871 oracle    20   0 1489m  21m  19m S  0.0  0.5   0:00.33 ora_pmon_orcl
 9873 oracle    20   0 1489m  17m  15m S  0.0  0.4   0:01.17 ora_psp0_orcl
 9882 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.07 ora_scmn_orcl
 9883 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.00 oracle
 9884 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.25 ora_gen0_orcl
 9885 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.25 ora_mman_orcl
 9891 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.24 ora_dbrm_orcl
 9895 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.33 ora_lgwr_orcl
 9896 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:01.08 ora_ckpt_orcl
 9897 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.12 ora_lg00_orcl
 9898 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.03 ora_lg01_orcl
 9899 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.07 ora_smon_orcl
 9901 oracle    20   0 2594m 1.2g 1.2g S  0.0 31.2   0:00.13 ora_lreg_orcl
 9888 oracle    20   0 3457m 340m 252m S  0.0  8.6   0:00.40 ora_scmn_orcl
 9889 oracle    20   0 3457m 340m 252m S  0.0  8.6   0:00.01 oracle
  • pidstat

pidstat is a command which appears in OEL6. It runs like a vmstat or mpstat with an interval and a counter, but it gives information of how evolve cpu, io, memory consumption for a specific process.

For example, to see cpu consumption every second for the process with pid 9888

[oracle@oel64-12c ~]$ pidstat -p 9888 -u 1
Linux 2.6.39-400.17.1.el6uek.x86_64 (oel64-12c.localdomain)     01/14/2014      _x86_64_        (2 CPU)

10:03:14 PM       PID    %usr %system  %guest    %CPU   CPU  Command
10:03:15 PM      9888    0.00    0.00    0.00    0.00     0  ora_scmn_orcl
10:03:16 PM      9888    1.00    0.00    0.00    1.00     1  ora_scmn_orcl
10:03:17 PM      9888    0.00    0.00    0.00    0.00     1  ora_scmn_orcl
10:03:18 PM      9888    1.00    1.00    0.00    2.00     1  ora_scmn_orcl
Please note that the process name is ora_u005_orcl but it’s printed with the command name which is, in fact, the thread name.

So if you want to see every thread in this process, you need to use -t option:

[oracle@oel64-12c ~]$ pidstat -p 9888 -u -t 1
Linux 2.6.39-400.17.1.el6uek.x86_64 (oel64-12c.localdomain)     01/14/2014      _x86_64_        (2 CPU)

10:08:42 PM      TGID       TID    %usr %system  %guest    %CPU   CPU  Command
10:08:43 PM      9888         -    0.00    0.00    0.00    0.00     1  ora_scmn_orcl
10:08:43 PM         -      9888    0.00    0.00    0.00    0.00     1  |__ora_scmn_orcl
10:08:43 PM         -      9889    0.00    0.00    0.00    0.00     1  |__oracle
10:08:43 PM         -      9890    0.00    0.00    0.00    0.00     0  |__ora_diag_orcl
10:08:43 PM         -      9892    0.00    0.00    0.00    0.00     0  |__ora_dia0_orcl
10:08:43 PM         -      9900    0.00    0.00    0.00    0.00     0  |__ora_reco_orcl
10:08:43 PM         -      9902    0.00    0.00    0.00    0.00     1  |__ora_mmon_orcl
10:08:43 PM         -      9903    0.00    0.00    0.00    0.00     0  |__ora_mmnl_orcl
10:08:43 PM         -      9904    0.00    0.00    0.00    0.00     0  |__ora_d000_orcl
10:08:43 PM         -      9905    0.00    0.00    0.00    0.00     0  |__ora_s000_orcl
10:08:43 PM         -      9906    0.00    0.00    0.00    0.00     0  |__ora_n000_orcl
10:08:43 PM         -      9932    0.00    0.00    0.00    0.00     0  |__ora_tmon_orcl
10:08:43 PM         -      9933    0.00    0.00    0.00    0.00     0  |__ora_tt00_orcl
10:08:43 PM         -      9934    0.00    0.00    0.00    0.00     1  |__ora_smco_orcl
10:08:43 PM         -      9938    0.00    0.00    0.00    0.00     1  |__ora_fbda_orcl
10:08:43 PM         -      9939    0.00    0.00    0.00    0.00     1  |__ora_aqpc_orcl
10:08:43 PM         -      9944    0.00    0.00    0.00    0.00     0  |__ora_p000_orcl
10:08:43 PM         -      9945    0.00    0.00    0.00    0.00     0  |__ora_p001_orcl
10:08:43 PM         -      9946    0.00    0.00    0.00    0.00     1  |__ora_p002_orcl
10:08:43 PM         -      9947    0.00    0.00    0.00    0.00     0  |__ora_p003_orcl
10:08:43 PM         -      9948    0.00    0.00    0.00    0.00     0  |__ora_p004_orcl
10:08:43 PM         -      9949    0.00    0.00    0.00    0.00     1  |__ora_p005_orcl
10:08:43 PM         -      9950    0.00    0.00    0.00    0.00     1  |__ora_p006_orcl
10:08:43 PM         -      9951    0.00    0.00    0.00    0.00     1  |__ora_p007_orcl
10:08:43 PM         -      9952    0.00    0.00    0.00    0.00     1  |__ora_cjq0_orcl
10:08:43 PM         -      9996    0.00    0.00    0.00    0.00     0  |__ora_qm02_orcl
10:08:43 PM         -      9998    0.00    0.00    0.00    0.00     1  |__ora_q002_orcl
10:08:43 PM         -      9999    0.00    0.00    0.00    0.00     0  |__ora_q003_orcl
10:08:43 PM         -     16009    0.00    0.00    0.00    0.00     1  |__ora_w000_orcl
10:08:43 PM         -     21462    0.00    1.00    0.00    1.00     1  |__ora_vkrm_orcl
10:08:43 PM         -     22117    0.00    0.00    0.00    0.00     1  |__ora_w001_orcl
10:08:43 PM         -     22128    0.00    0.00    0.00    0.00     0  |__ora_w002_orcl
10:08:43 PM         -     22689    0.00    0.00    0.00    0.00     1  |__ora_w003_orcl
10:08:43 PM         -     22703    0.00    0.00    0.00    0.00     0  |__ora_w004_orcl
10:08:43 PM         -     22713    0.00    0.00    0.00    0.00     0  |__ora_w005_orcl
There are other interesting options to monitor IO (-d), page faults and memory (-r), CPU utilization seen above (-u), switching activities (-w).
For example:
[oracle@oel64-12c ~]$ pidstat -p 9888 -w -t 1
Linux 2.6.39-400.17.1.el6uek.x86_64 (oel64-12c.localdomain)     01/14/2014      _x86_64_        (2 CPU)

10:57:54 PM      TGID       TID   cswch/s nvcswch/s  Command
10:57:55 PM      9888         -      1.00      1.00  ora_scmn_orcl
10:57:55 PM         -      9888      1.00      1.00  |__ora_scmn_orcl
10:57:55 PM         -      9889      0.00      0.00  |__oracle
10:57:55 PM         -      9890      1.00      0.00  |__ora_diag_orcl
10:57:55 PM         -      9892      1.00      0.00  |__ora_dia0_orcl
10:57:55 PM         -      9900      1.00      0.00  |__ora_reco_orcl
10:57:55 PM         -      9902      1.00      0.00  |__ora_mmon_orcl
10:57:55 PM         -      9903      1.00      1.00  |__ora_mmnl_orcl
10:57:55 PM         -      9904      1.00      0.00  |__ora_d000_orcl
10:57:55 PM         -      9905      1.00      0.00  |__ora_s000_orcl
10:57:55 PM         -      9906      1.00      0.00  |__ora_n000_orcl
10:57:55 PM         -      9932      1.00      0.00  |__ora_tmon_orcl
10:57:55 PM         -      9933      1.00      0.00  |__ora_tt00_orcl
10:57:55 PM         -      9934      1.00      1.00  |__ora_smco_orcl
10:57:55 PM         -      9938      1.00      0.00  |__ora_fbda_orcl
10:57:55 PM         -      9939      1.00      0.00  |__ora_aqpc_orcl
10:57:55 PM         -      9944      0.00      0.00  |__ora_p000_orcl
10:57:55 PM         -      9945      0.00      0.00  |__ora_p001_orcl
10:57:55 PM         -      9946      0.00      0.00  |__ora_p002_orcl
10:57:55 PM         -      9947      0.00      0.00  |__ora_p003_orcl
10:57:55 PM         -      9948      0.00      0.00  |__ora_p004_orcl
10:57:55 PM         -      9949      0.00      0.00  |__ora_p005_orcl
10:57:55 PM         -      9950      0.00      0.00  |__ora_p006_orcl
10:57:55 PM         -      9951      0.00      0.00  |__ora_p007_orcl
10:57:55 PM         -      9952      1.00      0.00  |__ora_cjq0_orcl
10:57:55 PM         -      9996      0.00      0.00  |__ora_qm02_orcl
10:57:55 PM         -      9998      0.00      0.00  |__ora_q002_orcl
10:57:55 PM         -      9999      1.00      0.00  |__ora_q003_orcl
10:57:55 PM         -     21462     96.00      3.00  |__ora_vkrm_orcl
10:57:55 PM         -     22713      1.00      0.00  |__ora_w005_orcl
10:57:55 PM         -     29708      0.00      0.00  |__ora_q001_orcl
10:57:55 PM         -     29709      0.00      0.00  |__oracle_29709_or
10:57:55 PM         -     26975      1.00      0.00  |__ora_w004_orcl
  • gdb (for debug)

If you want to trace system calls made by threads, you can use linux debugger (gdb). I don’t have a deep knowledge of gdb, but you can attach gdb to a process with the -p option.

[oracle@oel64-12c ~]$ gdb -p 9888
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-60.el6)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 9888

.../...
After this, you have a command which prints threads information (LWP (for Light Weight Process ???) indicates the Thread Id:
(gdb) info threads
  31 Thread 0x7f5a89ff6700 (LWP 29709)  0x0000003abe00e75d in read () from /lib64/libpthread.so.0  <<< my session is located here and is waiting for a command (read syscall)
  30 Thread 0x7f5a81ff2700 (LWP 29708)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  29 Thread 0x7f5b10beb700 (LWP 9889)  0x0000003abdcdf343 in poll () from /lib64/libc.so.6
  28 Thread 0x7f5b0ea2a700 (LWP 9890)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  27 Thread 0x7f5b07fff700 (LWP 9892)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  26 Thread 0x7f5afbfff700 (LWP 9900)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  25 Thread 0x7f5af3fff700 (LWP 9902)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  24 Thread 0x7f5aebfff700 (LWP 9903)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  23 Thread 0x7f5ae3fff700 (LWP 9904)  0x0000003abdce9163 in epoll_wait () from /lib64/libc.so.6
  22 Thread 0x7f5adbfff700 (LWP 9905)  0x0000003abdce9163 in epoll_wait () from /lib64/libc.so.6
  21 Thread 0x7f5ad3fff700 (LWP 9906)  0x0000003abdce9163 in epoll_wait () from /lib64/libc.so.6
  20 Thread 0x7f5acbfff700 (LWP 9932)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  19 Thread 0x7f5ac3fff700 (LWP 9933)  0x0000003abe00ef3d in nanosleep () from /lib64/libpthread.so.0
  18 Thread 0x7f5ab3fff700 (LWP 9934)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  17 Thread 0x7f5aabfff700 (LWP 9938)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  16 Thread 0x7f5aa3fff700 (LWP 9939)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  15 Thread 0x7f5a99ffe700 (LWP 9944)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  14 Thread 0x7f5a97ffd700 (LWP 9945)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  13 Thread 0x7f5a95ffc700 (LWP 9946)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  12 Thread 0x7f5a93ffb700 (LWP 9947)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  11 Thread 0x7f5a91ffa700 (LWP 9948)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  10 Thread 0x7f5a8fff9700 (LWP 9949)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  9 Thread 0x7f5a8dff8700 (LWP 9950)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  8 Thread 0x7f5a8bff7700 (LWP 9951)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  7 Thread 0x7f5a9bfff700 (LWP 9952)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  6 Thread 0x7f5a83ff3700 (LWP 9996)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  5 Thread 0x7f5a87ff5700 (LWP 9998)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  4 Thread 0x7f5a85ff4700 (LWP 9999)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  3 Thread 0x7f5abbfff700 (LWP 21462)  0x0000003abe00ef3d in nanosleep () from /lib64/libpthread.so.0
  2 Thread 0x7f5a79fee700 (LWP 22713)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
* 1 Thread 0x7f5b10f2a9e0 (LWP 9888)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
 Next, you can select a specific thread with the gdb “thread” command:
(gdb) thread 31
[Switching to thread 31 (Thread 0x7f5a89ff6700 (LWP 29709))]#0  0x0000003abe00e75d in read () from /lib64/libpthread.so.0
(gdb) info threads
* 31 Thread 0x7f5a89ff6700 (LWP 29709)  0x0000003abe00e75d in read () from /lib64/libpthread.so.0
  30 Thread 0x7f5a81ff2700 (LWP 29708)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  29 Thread 0x7f5b10beb700 (LWP 9889)  0x0000003abdcdf343 in poll () from /lib64/libc.so.6
  28 Thread 0x7f5b0ea2a700 (LWP 9890)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  27 Thread 0x7f5b07fff700 (LWP 9892)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
  26 Thread 0x7f5afbfff700 (LWP 9900)  0x0000003abdceb22a in semtimedop () from /lib64/libc.so.6
 .../...
Next, you can use breakpoints, watchpoint etc. to debug oracle calls etc.
If you are interested by tracing oracle system calls with gdb, Frits Hoogland have written many articles on this subject: