Tracing Listener Connections

Como podemos hacer un seguimiento a las conexiones del Listener:

1. Enable tracing for the appropriate period of time needed to capture enough data.

LSNRCTL> set trc_level ADMIN

2. Disable tracing.

LSNRCTL> set trc_level OFF

3. View trace file (optional) - the trace file can be viewed although it is very cryptic. The file can be located by using the show command along with trc_directory and again with trc_file. The following is an example of the raw trace file.

LSNRCTL> set trc_level ADMIN

Con este comando activamos el trace al listener, este genera un archivo en la ruta que le demos al 

parametro trc_file

En este caso lo dejaermos por default:

/u01/app/oracle/product/11.2.0/dbhome_1/network/admin

Por otra parte Oracle posee un herramienta para hacer debugg del trace al igual que tkprof, este es trcasst.

-bash-4.1$ trcasst svr_8875.trc


Trace File Statistics:
----------------------
Start Timestamp : 16-JUN-2016 12:02:25:596
End Timestamp   : 16-JUN-2016 13:30:09:296
Total number of Sessions: 1

DATABASE:
  Operation Count:    9 OPENS,   129 PARSES,   131 EXECUTES,    46 FETCHES
    Parse Counts:
      72 PL/SQL,    47 SELECT,      0 INSERT,     0 UPDATE,     0 DELETE,
       0 LOCK,       0 TRANSACT,    2 DEFINE,     0 SECURE,     8 OTHER
    Execute counts with SQL data:
      72 PL/SQL,    44 SELECT,      0 INSERT,     0 UPDATE,     0 DELETE,
       0 LOCK,       0 TRANSACT,    2 DEFINE,     0 SECURE,     0 OTHER

    Operation Ratio: 14.333333333333334 PARSES per OPEN,  1.0155038759689923 EXECUTES per PARSE

  Packet Ratio: 1.3129770992366412 packets sent per operation
  Currently opened Cursors: 0
  Maximum opened Cursors  : 9

 ORACLE NET SERVICES:
  Total Calls  :       172 sent,        172 received,         275 oci
  Total Bytes  :     52407 sent,      93168 received
    Average Bytes:       304 sent per packet,        541 received per packet
    Maximum Bytes:      2969 sent,       5297 received

 Grand Total Packets:    172  sent,     172 received

ORA-609

ORA-609 opiodr aborting process unknown ospid tips

Para remover este error  ORA-609 , debemos incrementar el valor para INBOUND_CONNECT_TIMEOUT en listener.ora  del servidor y sqlnet.ora.

- sqlnet.ora: SQLNET.INBOUND_CONNECT_TIMEOUT=180

- listener.ora: INBOUND_CONNECT_TIMEOUT_listener_name=120

Para obtener información adicional para este error ORA-609 , mira  MOSC note 1121357.1


Troubleshooting Guide ORA-609 : Opiodr aborting process unknown ospid (Doc ID 1121357.1)

Este error se presenta para las siguientes versiones de Oracle:
Oracle Net Services - Version 11.1.0.7 to 12.1.0.2 [Release 11.1 to 12.1]
Information in this document applies to any platform.


Revisamos el alert.log de nuestra base:

ORA-609 is being reported in the alert log.  The error is intermittent and may not occur for days at a time. 

Fatal NI connect error 12547, connecting to:

 (LOCAL=NO)

  VERSION INFORMATION:

        TNS for Linux: Version 11.2.0.3.0 - Production

        Oracle Bequeath NT Protocol Adapter for Linux: Version 11.2.0.3.0 - Production

        TCP/IP NT Protocol Adapter for Linux: Version 11.2.0.3.0 - Production

  Time: 16-JUN-2016 09:04:12

  Tracing not turned on.

  Tns error struct:

    ns main err code: 12547

TNS-12547: TNS:lost contact

    ns secondary err code: 12560

    nt main err code: 0

    nt secondary err code: 0

    nt OS err code: 0

opiodr aborting process unknown ospid (8064) as a result of ORA-609

Listener log shows the connection was established with no apparent errors.  This is because the connection
 failed AFTER the listener has handed off the connection to the server process.

12-OCT-2009 10:03:39 * (CONNECT_DATA=(SID=ORCL)) * (ADDRESS=(PROTOCOL=tcp)(HOST=123.456.1.123)(PORT=3158)) * establish * ORCL * 0

12-OCT-2009 10:03:39 * (CONNECT_DATA=(SID=ORCL)) * (ADDRESS=(PROTOCOL=tcp)(HOST=123.456.1.123)(PORT=3159)) * establish * ORCL * 0

Notice in this example Oracle Net Server trace, filename "svr_7464.trc"

Here the problem is seen when receiving the connection packet from client.  Note that the ORA-609 does not appear in the Oracle Net trace.  The ORA-609 is represented by the accompanying ns=12537 in this trace snippet.

[000001 12-OCT-2009 10:03:39:116] nscon: doing connect handshake...

[000001 12-OCT-2009 10:03:39:116] nscon: recving a packet

[000001 12-OCT-2009 10:03:39:116] nsprecv: entry

[000001 12-OCT-2009 10:03:39:116] nsprecv: reading from transport...

[000001 12-OCT-2009 10:03:39:116] nttrd: entry

[000001 12-OCT-2009 10:03:39:163] nttrd: exit

[000001 12-OCT-2009 10:03:39:163] ntt2err: entry

[000001 12-OCT-2009 10:03:39:163] ntt2err: Read unexpected EOF ERROR on 7104

[000001 12-OCT-2009 10:03:39:163] ntt2err: exit

[000001 12-OCT-2009 10:03:39:163] nsprecv: error exit

[000001 12-OCT-2009 10:03:39:163] nserror: entry

[000001 12-OCT-2009 10:03:39:163] nserror: nsres: id=0, op=68, ns=12537, ns2=12560; 

[000001 12-OCT-2009 10:03:39:163] nscon: error exit

[000001 12-OCT-2009 10:03:39:163] nsdo: nsctxrnk=0

[000001 12-OCT-2009 10:03:39:163] nsdo: error exit

[000001 12-OCT-2009 10:03:39:163] nsinh_hoff: error recving request

Other times tracking ORA-609 via Alert and Oracle Net server traces, shows issue further on during handshake.

Alert.log except here:

Mon Dec 21 15:52:15 2009

ORA-609 : opiodr aborting process unknown ospid (21631120_1)

[21-DEC-2009 15:52:15:025] nscon: sending NSPTAC packet

[21-DEC-2009 15:52:15:025] nspsend: entry

[21-DEC-2009 15:52:15:031] ntt2err: Read unexpected EOF ERROR on 14

[21-DEC-2009 15:52:15:031] ntt2err: exit

[21-DEC-2009 15:52:15:031] nsprecv: error exit

[21-DEC-2009 15:52:15:031] nserror: entry

[21-DEC-2009 15:52:15:031] nserror: nsres: id=0, op=68, ns=12537, ns2=12560; 

[21-DEC-2009 15:52:15:031] nsrdr: error exit

[21-DEC-2009 15:52:15:031] nsdo: nsctxrnk=0

[21-DEC-2009 15:52:15:031] nsdo: error exit

[21-DEC-2009 15:52:15:031] nsnareceive: error exit

[21-DEC-2009 15:52:15:031] nserror: entry

[21-DEC-2009 15:52:15:031] nserror: nsres: id=0, op=68, ns=12537, ns2=12532; 

[21-DEC-2009 15:52:15:031] nacomrc: failed with error 12637

[21-DEC-2009 15:52:15:031] nacomrc: exit

[21-DEC-2009 15:52:15:031] na_receive_packet: failed with error 12637

[21-DEC-2009 15:52:15:031] na_receive_packet: exit

[21-DEC-2009 15:52:15:031] na_server: failed with error 12637

It is common to find corresponding errors in the sqlnet.log file that is local to the instance.

Fatal NI connect error 12537, connecting to:

(LOCAL=NO)

VERSION INFORMATION:

TNS for Solaris: Version 11.2.0.2.0 - Production

Oracle Bequeath NT Protocol Adapter for Solaris: Version 11.2.0.2.0 - Production

TCP/IP NT Protocol Adapter for Solaris: Version 11.2.0.2.0 - Production

Time: 21-DEC-2009 15:52:15

Tracing not turned on.

Tns error struct:

ns main err code: 12537 

TNS-12537: TNS:connection closed

ns secondary err code: 12560

nt main err code: 0

nt secondary err code: 0

nt OS err code: 0

Matched to an event in the Oracle Net Server Trace

TROUBLESHOOTING STEPS

1. Find the incoming client(s) making the connections from the listener.log.
Alert log will show an ORA-609 error similar to following :

Mon Oct 05 12:41:49 2009

ORA-609 : opiodr aborting process unknown ospid (21131406_1)

Go to the listener.log and find the entry for this connection.  The entry in the listener.log should look similar to the following:

05-OCT-2009 12:41:49 * (CONNECT_DATA=(SID=orcl)) *

(ADDRESS=(PROTOCOL=tcp)(HOST=sample.com)(PORT=1234)) * establish * orcl * 0

Notice the client address in our example is "sample.com".   One option is to locate several clients and enable client tracing at those sites.  You might inspect the log file (ORACLE_HOME/network/log) at the client(s) and check specifically for timeout errors that might have occurred at the same timestamp.

2.

DIAG_ADR_ENABLED=off                  # Disable ADR if version 11g

TRACE_LEVEL_SERVER = 16               # Enable level 16 trace

TRACE_TIMESTAMP_SERVER = ON           # Set timestamp in the trace files

TRACE_DIRECTORY_SERVER = <DIRECTORY>  # Control trace file location

TRACE_FILELEN_SERVER =<n>   #Control size of trace set in kilobytes eg 20480

TRACE_FILENO_SERVER =<n>       #Control number of trace files per process

Cyclic tracing will allow you to control the size of and number of trace files that are produced.

The TRACE_FILELEN parameter is for the size of a trace file.
The TRACE_FILENO parameter is the number of traces per process.

Important Notes:

The SQLNET.ORA file is only read once on creation of a process. RDBMS Background process and shared server dispatchers will need to be restarted for parameter changes in the SQLNET.ORA to be picked up. Once a process has started to be traced, tracing will not stop until that the process stops.

In an environment where both GRID and RDBMS homes are installed, instance would reference a sqlnet.ora file in RDBMS_HOME/network/admin by default.  (Whereas the listener would refer to GRID_HOME/network/admin for its .ora files)

Please note, that enabling Oracle Net server tracing can produce large amounts of trace, in a very short time frame. Even with cyclic tracing, each process will have the TRACE_FILENO_SERVER value amount of traces produced. Optimal tracing workflow should be to enable tracing, reproduce problem and then disable tracing. Thus limiting amount of time tracing is enabled.

Setting TRACE_FILENO_SERVER to 1 and TRACE_FILELEN_SERVER = 20480, could be a solution to lowering the amount of trace generated per process. Remember the trace file will be overwritten and you could lose the important data covering the failure.

4. Errorstack: Setup errorstack to capture failure. This can be particular useful when capturing an Oracle Net client trace is not feasible.

SQL> alter session set events '609 errorstack(3)';

SQL> alter session set events '609 off';

Once you get a failure:

• Review the SQLNET.LOG file on server.

• Find the matching entry in the ALERT. LOG, compare via timestamp.

• From the entry in the SQLNET.LOG file, you will have the Oracle Net server trace name, from the line "Tracing to file". 

• Open the server trace and grep / search for the Connection ID value.

• Then search the clients trace client directory for the same Connection ID value.

Log File Sync

Puede ser descrito como el tiempo que la sesión de usuario tarda esperando para que la información de redo se guarde para hacer el cambio permanente. (latencia del COMMIT). El evento "log file sync" también se presenta durante las operaciones de ROLLBACK debido a que este tipo de operación también implica actualizar la información de redo en la Base de Datos.

A continuación se presentan algunos Tips de afinamiento para ayudar a reducir los eventos waits "log file sync"

ü  Afinar el proceso LGWR para buscar obtener un mejor rendimiento en el disco. Por ejemplo: No colocar los online Redo Logs en RAID 5.

ü  Detectar si existen muchas transacciones de corta duración para ver si es posible juntarlas en un solo proceso de tipo BATCH para reducir el número de operaciones de COMMIT.

ü  Analizar si alguna transacción puede utilizar la opción COMMIT NOWAIT

ü  Analizar si alguna operación se puede ejecutar seguramente usando las opciones NOLOGGING / UNRECOVERABLE.

ü  Aumentar el tamaño de los redologs buscando que la operaciones de redo log switch se realicen entre 15 a 20 minutos.

Complementar por medio del uso de la nota técnica de Oracle Support

WAITEVENT: "log file sync" Reference Note [ID 34592.1]

High Waits on log file sync Note# 125269.1

Tuning the Redolog Buffer Cache and Resolving Redo Latch Contention

Note# 147471.1

catalogo rman

En esta nota explico paso a paso como configurar un catalogo de RMAN.

1. Create a new standard database.  RCAT

2. create a tablespace for RMAN repository user:

 export ORACLE_SID=RCAT

SQL>create tablespace rcat datafile '+DATA/rcat/datafile/rcat.dbf' size 200M autoextend on;

3. create RMAN repository catalog user:

SQL> CREATE USER rcat IDENTIFIED BY "rcat" DEFAULT TABLESPACE RCAT QUOTA UNLIMITED ON rcat;

SQL> prompt grant recovery catalog owner to rcat catalog owner

SQL> GRANT recovery_catalog_owner TO rcat;

4. Create RMAN catalog inside this user. To create the catalog, connect to RMAN database through RMAN:

Before entering RMAN utility set some OS environment variables: 
-format RMAN time format output (this will output the date inside RMAN to "01-MAR-2010 18:34:23"):

$> export NLS_DATE_FORMAT="DD-MON-YYYY HH24:MI:SS"

rman catalog rcat/rcat

recovery catalog database Password:

connected to recovery catalog database

RMAN> CREATE CATALOG;

recovery catalog created

5. Register a database to the catalog, now that we have a RMAN Repository Catalog. So, on a database that you need to register connect to RMAN and register the database to RMAN catalog:

1.   Creación de un nuevo espacio de tabla mediante el comando SQL*Plus: 

*  create tablespace <espaciodetabla del catálogo del RMAN> datafile <nombre del archivodedatos> size <tamaño del archivodedatos> m;

       

2.   Creación del usuario propietario del catálogo RMAN introduciendo este comando: * create user <propietario del catálogo RMAN> identified by <contraseña> default tablespace <espaciodetabla del catálogo RMAN> quota unlimited on <espaciodetabla del catálogo de RMAN>;                

3.   Asignación de los privilegios correctos a dicho usuario mediante el siguiente comando: * grant recovery_catalog_owner to <propietario del catálogo RMAN>;

                 

4.   Para establecer la conexión con la base de datos del catálogo de RMAN, abra un nuevo símbolo del sistema y ejecute el siguiente comando: rman catalog <propietario del catálogo RMAN>/<contraseña del catálogo RMAN>@rmandb

                
donde rmandb es el nombre TNS de la base de datos de catálogo de RMAN.

5.   Cree un catálogo mediante este comando: create catalog;

            

6.  Conéctese a la base de datos del catálogo y a la base de datos de destino de RMAN. *rman target <usuario(sys) con privilegios sysdba>/< contraseña para usuario(sys)>@targetdb catalog <propietario del catálogo de RMAN>/<contraseña del catálogo RMAN>@rmandb

            
donde rmandb es el nombre TNS de la base de datos de catálogo de RMAN y targetdb es el nombre TNS de la base de datos de destino.

7.  Ejecute el siguiente comando. register database;

$ rman catalog rman/rman

connected to recovery catalog database

RMAN> connect target sys/CLORINOSBEFX@CLORINOSBEFX

connected to target database: CLORINOS (DBID=1732973088)

RMAN> register database;

database registered in recovery catalog

starting full resync of recovery catalog

full resync complete

SQL> connect rman/rman

Connected.

SQL>  select * from rc_database;

    DB_KEY  DBINC_KEY                 DBID               NAME               RESETLOGS_CHANGE# RESETLOG

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

         2               4                         1732973088      CLORINOS        

rman target / catalog rcat@RCAT

 RMAN.DBMS_RCVCAT version 11.02.00.01 in RCVCAT database is not current

RMAN> upgrade catalog;

recovery catalog owner is RMAN

enter UPGRADE CATALOG command again to confirm catalog upgrade

RMAN> UPGRADE CATALOG

recovery catalog upgraded to version 11.02.00.03

DBMS_RCVMAN package upgraded to version 11.02.00.03

DBMS_RCVCAT package upgraded to version 11.02.00.03

SQL> connect rcat/rcat

Connected.

SQL>

SQL>

SQL> select * from rc_database;

    DB_KEY  DBINC_KEY             DBID NAME      RESETLOGS_CHANGE# RESETLOG

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

         2            4 1732973088 CLORINOS            57437604 22/10/13

       927       928 3376507379 DEXPLOG2       298481158 28/10/13

###############################

create tablespace TOOLS  datafile '+DATA/catdb/datafile/tools.dbf'  size 200M;

CREATE USER rman IDENTIFIED BY cat

  TEMPORARY TABLESPACE temp

  DEFAULT TABLESPACE tools

  QUOTA UNLIMITED ON tools;

GRANT CONNECT, RESOURCE, RECOVERY_CATALOG_OWNER TO rman;

GRANT RECOVERY_CATALOG_OWNER TO rman;

GRANT create session TO rman;

% rman

RMAN> CONNECT CATALOG rman/cat@catdb

ORACLE:

OK=  uid=500(oracle) gid=500(oinstall) groups=500(oinstall),501(asmadmin),502(dba),503(oper),504(asmdba)

MAL uid=500(oracle) gid=503(oinstall) groups=501(asmadmin),503(oinstall),504(dba),505(oper),507(asmdba)

GRID:

OK=  uid=501(grid) gid=503(oinstall) grupos=500(asmadmin),501(asmdba),502(asmoper),503(oinstall),504(dba)

MAIL uid=501(grid) gid=503(oinstall) groups=501(asmadmin),502(asmoper),503(oinstall),504(dba),507(asmdba)

BIEN:

asmadmin:x:500:oracle,grid   asmadmin:x:501:grid,oracle

asmdba:x:501:grid,oracle    asmdba:x:507:oracle,grid

asmoper:x:502:grid                asmoper:x:502:grid

oinstall:x:503:                         oinstall:x:503:oracle,grid 

dba:x:504:oracle,grid                dba:x:504:grid,oracle

oper:x:505:oracle                 oper:x:505:oracle

MAL:

oracle:x:500:

  oracleasm createdisk DISK01 /dev/sdc1

  oracleasm createdisk DISK02 /dev/sdd1

  oracleasm createdisk DISK03 /dev/sde1

export ORACLE_SID=CLPRTR01

CREATE USER clprtr01 IDENTIFIED BY "clprtr01" DEFAULT TABLESPACE RCAT QUOTA UNLIMITED ON rcat;