Interesting Change in Database Listener Behaviour at 11g

There is a small yet significant improvement in the implementation of TNSLSNR at 11g around the way it writes to the listener log files, both “log.xml” and “listener.log”. First though I’ll describe some 10g listener behaviour that anyone who’s written their own script for recycling the log file will have noticed. I should also mention this is all Unix based – I’m not aware if the same issues exist in a Windows environment.

Below I check the listener log file and then rename it “listener.log.old”.

$ cd /u01/app/oracle/product/10.2.0/db_1/network/log
$ ls -l listener*
-rw-r----- 1 oracle oinstall 3715 Jun 19 22:33 listener.log
$ mv listener.log listener.log.old

Next I connect to a database via the listener and check for files starting with “listener” in the log location.

$ sqlplus a/a@orcl
SQL> exit

$ ls -l listener*
-rw-r----- 1 oracle oinstall 3964 Jun 19 22:34 listener.log.old

$ tail -1 listener.log.old
19-JUN-2011 22:34:48 * (CONNECT_DATA=(SERVICE_NAME=orcl)(CID=(PROGRAM=sqlplus)(HOST=vb-centos-10.2-a)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.105)(PORT=24980)) * establish * orcl * 0

There is no new “listener.log” and my recent connection was logged in the “listener.log.old” file.

I can go one step further and remove the file while the listener is running and while I am “tailing” the file.

### session 1
$ tail -f listener.log.old

### session 2
$ rm listener.log.old
$ sqlplus a/a@orcl

### session 1
19-JUN-2011 22:38:12 * (CONNECT_DATA=(SERVICE_NAME=orcl)(CID=(PROGRAM=sqlplus)(HOST=vb-centos-10.2-a)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.105)(PORT=25010)) * establish * orcl * 0

Log entries are still going to the old log file even though the file is not visible from the operating system.

$ ls -l listener*
ls: listener*: No such file or directory

If I left it like this I could end up with a huge listener.log file that is essentially invisible. If ever you have “du” and “df” output that disagree by a huge amount in an Oracle home filesystem then this may be why. You should never see it in the ADR though as that would imply 11g. Before we go on to that we’ll restart the listener logging so the correct file is used (there are many ways to do this by the way).

$ lsnrctl

LSNRCTL for Linux: Version 10.2.0.4.0 - Production on 19-JUN-2011 22:44:43

Copyright (c) 1991, 2007, Oracle.  All rights reserved.

Welcome to LSNRCTL, type "help" for information.

LSNRCTL> set current_listener listener
Current Listener is listener
LSNRCTL> set log_status off
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=vb-centos-10.2-a)(PORT=1521)))
listener parameter "log_status" set to OFF
The command completed successfully
LSNRCTL> set log_status on
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=vb-centos-10.2-a)(PORT=1521)))
listener parameter "log_status" set to ON
The command completed successfully

Now let’s demonstrate what happens if we repeat this test at 11g (11.2 in my case but the behaviour is the same at 11.1).

$ cd /u01/app/oracle/diag/tnslsnr/vb-centos-11/listener/trace
$ ls -l listener*
-rw-r----- 1 oracle oinstall 31486 Jun 16 18:36 listener.log
$ mv listener.log listener.log.old

$ sqlplus  a/a@orcl
SQL> exit

$ ls -l listener*
-rw-r----- 1 oracle oinstall 243 Jun 16 18:36 listener.log
-rw-r----- 1 oracle oinstall 31486 Jun 16 18:36 listener.log.old

$ cat listener.log
Thu Jun 16 18:36:56 2011
16-JUN-2011 18:36:56 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl)(CID=(PROGRAM=sqlplus)(HOST=vb-centos-11.2-a)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.102)(PORT=49695)) * establish * orcl * 0

So this time the listener has recreated “listener.log” file and not continued to write to the renamed log file. If we use the strace utility we can see why. An extract from the 11g output is below. Notice the “open” commands for the “log.xml” and “listener.log” files.

lstat64("/u01/app/oracle/diag/tnslsnr/vb-centos-11/listener/alert/log.xml", {st_mode=S_IFREG|0640, st_size=90949, ...}) = 0
open("/u01/app/oracle/diag/tnslsnr/vb-centos-11/listener/alert/log.xml", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0660) = 15
fcntl64(15, F_SETFD, FD_CLOEXEC)        = 0
write(15, "<msg time='2011-06-16T18:12:17.1"..., 236) = 236
close(15)                               = 0
stat64("/u01/app/oracle/diag/tnslsnr/vb-centos-11/listener/alert/log.xml", {st_mode=S_IFREG|0640, st_size=91185, ...}) = 0
times({tms_utime=118, tms_stime=1077, tms_cutime=0, tms_cstime=0}) = 434969334
lstat64("/u01/app/oracle/diag/tnslsnr/vb-centos-11/listener/trace/listener.log", {st_mode=S_IFREG|0640, st_size=1021, ...}) = 0
open("/u01/app/oracle/diag/tnslsnr/vb-centos-11/listener/trace/listener.log", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0660) = 15
fcntl64(15, F_SETFD, FD_CLOEXEC)        = 0
write(15, "Thu Jun 16 18:12:17 2011\n", 25) = 25

And below an extract from tracing a 10g listener.

_llseek(3, 0, [4511], SEEK_CUR)         = 0
write(3, "19-JUN-2011 22:41:01 * service_u"..., 49) = 49

This time we do not get an open for each write – we only see the file reopened if we restart logging.

open("/u01/app/oracle/product/10.2.0/db_1/network/log/listener.log", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0666) = 3

Let’s hope the next improvement is to take the cycling of the trace “listener.log” file (not xml version) into the code.

About these ads

One thought on “Interesting Change in Database Listener Behaviour at 11g

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s