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

Last updated on AUGUST 25, 2017

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

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms