TNS-12518, TNS-12540, TNS-12582 and TNS-12615 Errors Reported in 11g Listener Log Under Heavy Load (Doc ID 1399677.1)

In this Document

Symptoms

Changes

Cause

Solution

References

---

APPLIES TO:

Oracle Database - Enterprise Edition - Version 11.1.0.7 and later
Oracle Net Services - Version 11.1.0.7 and later
Information in this document applies to any platform.
checked for currency on 23-jul-2014

SYMPTOMS

High workload reported on system. 

Large number of connections simultaneously arriving to be serviced (in this case over 400). Following error is frequently reported in the listener log :

09-DEC-2011 13:27:18 * establish * 12540
TNS-12540: TNS:internal limit restriction exceeded

And reported in the alert log is:

ORA-609 : opiodr aborting process unknown ospid

Performance testing (login storm) to the TNS listener resulted in intermittent connection failures with listener.log showing

09-DEC-2011 13:26:56 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ntvrec11)(CID=(PROGRAM=sqlplus)(HOST=myhostname)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=XX.XX.XX.XXX)(PORT=60875)) * establish * ntvrec11 * 12518
TNS-12518: TNS:listener could not hand off client connection
TNS-12540: TNS:internal limit restriction exceeded

09-DEC-2011 13:27:13 * 12582
TNS-12582: TNS:invalid operation
TNS-12615: TNS:preempt error

Level 16 Listener trace shows internal limit being reached. This is the amount of connections waiting to be serviced:

nsevwait: waiting for transport event (1 thru 1023)...
nsevwait: waiting for transport event (1 thru 1023)...
nsevwait: waiting for transport event (1 thru 1023)...

Oracle Net Server tracing of connections, shows a delay in shadow process initialization:

[000001 09-DEC-2011 13:27:35:797] nauss_set_state: exit
[000001 09-DEC-2011 13:27:35:798] nau_gslf: exit
[000001 09-DEC-2011 13:27:35:798] nau_gparams: exit
[000001 09-DEC-2011 13:27:35:799] nau_gin: exit
[000001 09-DEC-2011 13:27:35:799] nagblini: exit
[000001 09-DEC-2011 13:27:48:647] nigini: entry << --Approx 12-second delay in shadow server process initialization
[000001 09-DEC-2011 13:27:48:648] nigini: Count in the NL global area is now 3
[000001 09-DEC-2011 13:27:48:649] nigini: Count in NI gbl area now: 1
[000001 09-DEC-2011 13:27:48:649] nrigbi: entry
[000001 09-DEC-2011 13:27:48:650] nrigbni: entry
[000001 09-DEC-2011 13:27:48:652] nrigbni: Unable to get data from navigation file tnsnav.ora

Reviewing Truss output of the listener process and checking on the matching PID section in the Oracle net server trace(in this case PID 16982) , show big delays with commands around ADR functionality :
 

16982 13:27:35.826386 mkdir("/app/oracle/diag/rdbms/ntvrec11", 0775 <unfinished ...>
16982 13:27:36.143307 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:36.143378 stat("/app/oracle/diag/rdbms/ntvrec11", <unfinished ...>
16982 13:27:36.305298 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:36.305385 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11", 0775 <unfinished ...>
16982 13:27:36.510242 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:36.510314 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11", <unfinished ...>
16982 13:27:36.907213 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:36.907405 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/trace", 0775 <unfinished ...>
16982 13:27:37.316572 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:37.316617 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/trace", <unfinished ...>
16982 13:27:37.333905 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=212992, ...}) = 0
16982 13:27:37.333979 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/alert", 0775 <unfinished ...>
16982 13:27:37.361174 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:37.361250 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/alert", <unfinished ...>
16982 13:27:37.788804 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:37.788871 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/incident", 0775 <unfinished ...>
16982 13:27:38.224029 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:38.224077 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/incident", <unfinished ...>
16982 13:27:38.419055 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:38.419118 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/metadata", 0775 <unfinished ...>
16982 13:27:38.614831 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:38.614924 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/metadata", <unfinished ...>
16982 13:27:38.985487 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:38.985549 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/hm", 0775 <unfinished ...>
16982 13:27:38.994554 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:38.994598 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/hm", <unfinished ...>
16982 13:27:39.946417 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:39.946660 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/ir", 0775 <unfinished ...>
16982 13:27:39.957608 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:39.957661 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/ir", <unfinished ...>
16982 13:27:41.099211 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:41.099307 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/incpkg", 0775 <unfinished ...>
16982 13:27:41.888733 <... mkdir resumed> ) = -1 EEXIST (File exists)
16982 13:27:41.888804 stat("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/incpkg", <unfinished ...>
16982 13:27:42.490940 <... stat resumed> {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
16982 13:27:42.491028 mkdir("/app/oracle/diag/rdbms/ntvrec11/ntvrec11/sweep", 0775 <unfinished ...>

CHANGES

Recent upgrade to 11gR1 database.

CAUSE

The issue is related to load and overhead related to Automatic Diagnostic Repository (ADR) functionality and IO issues on the database server.  The combination of these results in slowness in spawning the database shadow processes, causing number of connection requests to be queued by the TNS Listener and internal limits restrictions to be reached.

Each new shadow process that is spawned tries to create the ADR directories, even if they already exist.

This is due to Unpublished Bug:9700115 CHECK ADR DIRECTORIES EXISTENCE AND ATTRIBUTES FIRST BEFORE CREATING THEM

SOLUTION

As a workaround, set the following initialization parameter for the 11g Database instance(s) to disable the Automatic Diagnostic Repository (ADR) mechanism.

_diag_adr_enabled=FALSE

and/or:

Apply Patch:9700115 to change the behavior of the ADR to check if the subdirectories exists before it tries to create them.

REFERENCES

NOTE:9700115.8 - Bug 9700115 - Each process attempts to create ADR directories