By William Sescu

The default configuration which is shipped with OUD is not meant to be ready for enterprise usage. The default settings of OUD are targeted at evaluators and developers who run equipment with limited resources, and so it is quite likely that you run into performance issues if you don’t change anything, before going into production. The OUD performance depends on a lot of things like

  • Network configuration/routing/firewalls/bonding
  • OUD version and configuration (Replication, TLS)
  • Java version and Java runtime memory configuration
  • DNS Lookup times
  • Name Service Cache Daemon
  • And many more …

However, it is not always the servers fault. Sometimes the client is causing the issue. But how do I know, if it is the client or the server. In the following example it takes about 10 seconds to resolve the connect string DBIT122_LDAP. That is enormous. Far too long from being acceptable. Where is the tnsping spending so much time?

oracle@dbidg02:/u01/app/oracle/network/admin/ [DBIT122] time tnsping DBIT122_LDAP

TNS Ping Utility for Linux: Version 12.2.0.1.0 - Production on 04-APR-2017 08:43:06

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

Used parameter files:
/u01/app/oracle/network/admin/sqlnet.ora

Used LDAP adapter to resolve the alias
Attempting to contact (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=dbidg01)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=DBIT122)))
OK (10 msec)

real    0m10.177s
user    0m0.017s
sys     0m0.018s

To exclude, that it is the servers fault, just check the OUD access log where you can see any ldap request against the OUD.

[dbafmw@dbidg01 logs]$ tail -50f /u01/app/oracle/product/Middleware/11.1.2.3/asinst_1/OUD/logs/access
...
...
[04/Apr/2017:08:43:39 +0200] CONNECT conn=5 from=192.168.56.202:30826 to=192.168.56.201:1389 protocol=LDAP
[04/Apr/2017:08:43:39 +0200] BIND REQ conn=5 op=0 msgID=1 type=SIMPLE dn="" version=3
[04/Apr/2017:08:43:39 +0200] BIND RES conn=5 op=0 msgID=1 result=0 authDN="" etime=0
[04/Apr/2017:08:43:39 +0200] SEARCH REQ conn=5 op=1 msgID=2 base="cn=DBIT122_LDAP,cn=OracleContext,dc=dbi,dc=com" scope=base filter="(objectclass=*)" attrs="objectclass,orclNetDescString,orclNetDescName,orclVersion"
[04/Apr/2017:08:43:39 +0200] SEARCH RES conn=5 op=1 msgID=2 result=0 nentries=1 etime=2
[04/Apr/2017:08:43:39 +0200] UNBIND REQ conn=5 op=2 msgID=3
[04/Apr/2017:08:43:39 +0200] DISCONNECT conn=5 reason="Client Disconnect"
...
...

The important entry to look for is the etime after the search request. The etime filed is the elapsed time in milliseconds which the server spent processing the request. In the above case, it is 2 milliseconds, so quite fast. If you would see here large elapsed times here, then this would be a good indicator for issues on the server side.

Now, that we know that the server is ok, let’s move to client side. The first thing I am trying to do, is to see how fast the ldapsearch is. I am using the ldapsearch which comes with 12cR2 and I will use the same search criteria which tnsping is using to search for the connect string. The ldapsearch syntax from the OUD binaries differs a little bit with ldapsearch syntax which is shipped with 12cR2. Why should Oracle make them the same, it would be too easy. 😉 Ok, let’s check the ldapsearch.

oracle@dbidg02:/u01/app/oracle/network/admin/ [DBIT122] time ldapsearch -v -h dbidg01 -p 1389 -b "cn=DBIT122_LDAP,cn=OracleContext,dc=dbi,dc=com" 
-s base "(objectclass=*)" "objectclass,orclNetDescString,orclNetDescName,orclVersion"

ldap_open( dbidg01, 1389 )
filter pattern: (objectclass=*)
returning: objectclass,orclNetDescString,orclNetDescName,orclVersion
filter is: ((objectclass=*))
cn=dbit122_ldap,cn=OracleContext,dc=dbi,dc=com
1 matches

real    0m0.020s
user    0m0.005s
sys     0m0.004s

I don’t see any issues here. My ldapsearch came back in a blink of an eye. So .. where are the other 10 seconds? We need more information. We can either use strace or we can activate tracing on the client side. Something less known in the Oracle world is the tnsping tracing, which can be activated too. My tnsping is slow, and so I want only the tnsping to be traced and nothing else. To do so, we need to specify two parameters in the sqlnet.ora file. The TNSPING.TRACE_DIRECTORY and the TNSPING.TRACE_LEVEL. The tnsping trace level can have 4 different values like the sqlnet tracing.

  • 0 or OFF – No Trace output
  • 4 or USER – User trace information
  • 10 or ADMIN – Administration trace information
  • 16 or SUPPORT – Worldwide Customer Support trace information

Because I want to have the full trace output, I go for level 16 which is the support tracing.

oracle@dbidg02:/u01/app/oracle/network/admin/ [DBIT122] cat sqlnet.ora | grep TNSPING

TNSPING.TRACE_DIRECTORY = /u01/app/oracle/network/trc
TNSPING.TRACE_LEVEL = SUPPORT

Ok. Let’s do it again and see the outcome.

oracle@dbidg02:/u01/app/oracle/network/admin/ [DBIT122] time tnsping DBIT122_LDAP

TNS Ping Utility for Linux: Version 12.2.0.1.0 - Production on 04-APR-2017 09:44:44

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

Used parameter files:
/u01/app/oracle/network/admin/sqlnet.ora

Used LDAP adapter to resolve the alias
Attempting to contact (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=dbidg01)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=DBIT122)))
OK (10 msec)

real    0m10.191s
user    0m0.013s
sys     0m0.016s
oracle@dbidg02:/u01/app/oracle/network/admin/ [DBIT122]

If we look at the trace file, we see that Oracle found 3 directory paths in the following order, TNSNAMES, EZCONNECT and LDAP.

[04-APR-2017 09:44:44:569] nnfgsrsp: Obtaining path parameter from names.directory_path or native_names.directory_path
[04-APR-2017 09:44:44:569] nnfgsrdp: entry
[04-APR-2017 09:44:44:569] nnfgsrdp: Setting path:
[04-APR-2017 09:44:44:569] nnfgsrdp: checking element TNSNAMES
[04-APR-2017 09:44:44:569] nnfgsrdp: checking element EZCONNECT
[04-APR-2017 09:44:44:569] nnfgsrdp: checking element LDAP

Switching to the TNSNAMES adapter is very fast and Oracle see’s it immediately that the query is unsuccessful, and so it is switching to the next adapter.

[04-APR-2017 09:44:44:569] nnfgrne: Switching to TNSNAMES adapter
[04-APR-2017 09:44:44:569] nnftboot: entry
[04-APR-2017 09:44:44:569] nlpaxini: entry
[04-APR-2017 09:44:44:569] nlpaxini: exit
[04-APR-2017 09:44:44:569] nnftmlf_make_local_addrfile: entry
[04-APR-2017 09:44:44:569] nnftmlf_make_local_addrfile: construction of local names file failed
[04-APR-2017 09:44:44:569] nnftmlf_make_local_addrfile: exit
[04-APR-2017 09:44:44:569] nlpaxini: entry
[04-APR-2017 09:44:44:569] nlpaxini: exit
[04-APR-2017 09:44:44:569] nnftmlf_make_system_addrfile: entry
[04-APR-2017 09:44:44:569] nnftmlf_make_system_addrfile: system names file is /u01/app/oracle/network/admin/tnsnames.ora
[04-APR-2017 09:44:44:569] nnftmlf_make_system_addrfile: exit
[04-APR-2017 09:44:44:569] nnftboot: exit
[04-APR-2017 09:44:44:569] nnftrne: entry
[04-APR-2017 09:44:44:569] nnftrne: Original name: DBIT122_LDAP
[04-APR-2017 09:44:44:569] nnfttran: entry
[04-APR-2017 09:44:44:569] nnfttran: Error querying DBIT122_LDAP of attribute A.SMD errcode 408
[04-APR-2017 09:44:44:569] nnfgrne: Query unsuccessful, skipping to next adapter

Now, Oracle is switching to the EZCONNECT adapter.

[04-APR-2017 09:44:44:569] nnfgrne: Switching to EZCONNECT adapter
[04-APR-2017 09:44:44:569] nnfhboot: entry
[04-APR-2017 09:44:44:569] nnfhboot: exit
[04-APR-2017 09:44:44:569] snlinGetAddrInfo: entry
[04-APR-2017 09:44:54:664] snlinGetAddrInfo: getaddrinfo() failed with error -2
[04-APR-2017 09:44:54:664] snlinGetAddrInfo: exit
[04-APR-2017 09:44:54:665] snlinGetAddrInfo: entry
[04-APR-2017 09:44:54:727] snlinGetAddrInfo: getaddrinfo() failed with error -2
[04-APR-2017 09:44:54:727] snlinGetAddrInfo: exit
[04-APR-2017 09:44:54:727] nnfhrne: Error forming address for DBIT122_LDAP, errcode 406
[04-APR-2017 09:44:54:727] nnfgrne: Query unsuccessful, skipping to next adapter

Ok. Here we go. Between “snlinGetAddrInfo: entry” and “snlinGetAddrInfo: getaddrinfo() failed with error -2”  10 seconds have been gone. Oracle thinks that the DBIT122_LDAP is an easy connect string, and tries to resolve the name, which fails.

So I need to switch the entries in the directory path in the sqlnet.ora file, to NAMES.DIRECTORY_PATH= (TNSNAMES,LDAP,EZCONNECT). After I have done that, the tnsping comes back successfully and very fast.

oracle@dbidg02:/u01/app/oracle/network/admin/ [DBIT122] time tnsping DBIT122_LDAP

TNS Ping Utility for Linux: Version 12.2.0.1.0 - Production on 04-APR-2017 10:25:39

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

Used parameter files:
/u01/app/oracle/network/admin/sqlnet.ora

Used LDAP adapter to resolve the alias
Attempting to contact (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=dbidg01)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=DBIT122)))
OK (0 msec)

real    0m0.018s
user    0m0.007s
sys     0m0.006s

Conclusion

It is not always the OUD servers fault when you hit performance issues. I might be on the client as well and it can have a severe impact.

Post Views: 476
Thumbnail [60x60]
by
Oracle Team