Out of Space Error while still Have Space

Recently I worked on a large database on a X-4 full rack Exadata for a few months. I am using sqlplus command every day on this database without any issue. Then suddenly, I got the following error on db node 1 when trying to run sqlplus.

$ sqlplus / as sysdba
ORA-09925: Unable to create audit trail file
Linux-x86_64 Error: 28: No space left on device
Additional information: 9925
ORA-09925: Unable to create audit trail file
Linux-x86_64 Error: 28: No space left on device
Additional information: 9925

I know this is the issue at OS level, not at database level. The audit trail directory should be under /u01. Run the df command. Interesting, I see it still have about 12G available on /u01, just like the parking space image below.

$ df -kh /u01
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/VGExaDb-LVDbOra1
                       99G   82G   12G  88% /u01

space_issue_201410
I know /u01 takes some space, but 82G out of 99G seem too much. Check out the same /u01 on db node 2. Yes, it has only 22G used. Try sqlplus there without any issue. At this moment I roughly know the cause of the issue. I saw similar space issue in another client in the past and the database there had serious performance issue. The cause of the issue was millions of audit files under the audit directory.

When we run df or du command, majority of time we are only interested in how much space we use and how much space is available. This is the space limit in the file system. There is another limit: inode limit. Inode is the metadata of a file, containing information like file size, owner, group, file access/modify/change time and much more. When a file is created, the metadata of the file is stored in an inode (or inode number). Each file has a unique inode number that is used internally by the file system. When accessing a file, the system first seraches inode table for the unique inode number. With the information from the inode, the file can be found and accessed.

We usually don’t see the inode reach to its limit quite often. Use df -i command can help to identify inode limit issue. Here is the result after running df -i command.

$ df -h -i /u01
Filesystem            Inodes   IUsed   IFree IUse% Mounted on
/dev/mapper/VGExaDb-LVDbOra1
                         13M     13M       0  100% /u01

Obviously we used up 100% of all 13M inodes in /u01 file system.

At this moment, I know where Oracle database can generate many files. It’s audit directory. Run the following command to find out space usage for audit folder and run for almost 6 minutes without the result back. Had to kill the process.

Then use another way to find out the top 10 usage. As expected, audit directory took a lot of space there with over 50G.

$ cd /u01/app/oracle/product/11.2.0.4/dbhome_1
$ du -a . | sort -n -r | head -n 10
57566392        .
52851540        ./rdbms
52722128        ./rdbms/audit
788268  ./lib
768116  ./bin
559916  ./owb
335520  ./oc4j
309500  ./assistants
303920  ./assistants/dbca
303596  ./ctx

There is another way to find out whether the directory is big. Run ls command from parent directory.

$ cd /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms
$ ls -l
total 1039920
drwxr-xr-x 2 oracle oinstall      49152 Aug 22 10:33 admin
drwxr-xr-x 2 oracle oinstall 1063747584 Oct 20 19:20 audit
drwxr-xr-x 2 oracle oinstall       4096 Jun 27 14:47 demo
drwxr-xr-x 2 oracle oinstall       4096 Jun 27 14:47 doc
drwxr-xr-x 5 oracle oinstall       4096 Jun 27 14:48 install
drwxr-xr-x 2 oracle oinstall       4096 Jun 27 14:47 jlib
drwxr-xr-x 2 oracle oinstall       4096 Jul 31 11:45 lib
drwxr-xr-x 2 oracle oinstall       4096 Aug 22 18:30 log
drwxr-xr-x 2 oracle oinstall       4096 Jun 27 14:47 mesg
drwxr-xr-x 2 oracle oinstall       4096 Jun 27 14:47 public
drwxr-xr-x 5 oracle oinstall       4096 Jun 27 14:46 xml

So the solution seems easy. Just remove aud file under the audit directory. Then I run rm command. It runs for a few minutes and finally gave an error message below.

$ rm *.aud
-bash: /bin/rm: Argument list too long

It seems having a lot of files in this directories and I would like to find out the total number of files in the directory. Tried to run ls -l | wc -l to get file count. It had never finished and taken forever to run. The reason why ls -l is so slow is that by default, ls command sorts the file alphabetically. So if you’re interested in listing some files quickly, you could use ls -f | head -100 command to get a list of files.

At this moment, I had to use rm -rf from its parent directory and it worked. Even with this method, it took more than 8 hours to completed.

In the middle of this delete process, I stopped the delete process after the free inode reached to 1%. As I have some free inodes available for other processes and don’t worry about this space issue in a short time, I would like to find out how long it take to calculate the space usage under audit directory and how many audit files under the same directory.

Here are the results:

$ cd /u01/app/oracle/product/11.2.0.3/dbhome_1/rdbms
$ df -i /u01
Filesystem            Inodes   IUsed   IFree IUse% Mounted on
/dev/mapper/VGExaDb-LVDbOra1
                     13107200 12955396  151804   99% /u01

$ time du -khs /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/audit
50G     /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/audit

real    26m6.220s
user    0m5.299s
sys     2m25.058s

$ time ls -l | wc -l
12839426

real    29m16.458s
user    2m47.544s
sys     2m9.860s

The above result shows it took 29 minutes to find out 12.8 million files in the directory and 26 minutes to get the space usage for the audit directory. So basically forget about the idea to use ls -l command when there are millions of files in a directory.

There are a few other useful command to find out inode information.

$ ls -i
4653873 admin  4949095 demo  4653875 install  4653881 lib  4653883 mesg    4653885 xml
4734977 audit  4653874 doc   4653880 jlib     4653882 log  4653884 public

$ stat audit
  File: `audit'
  Size: 1063747584      Blocks: 2079672    IO Block: 4096   directory
Device: fc03h/64515d    Inode: 4734977     Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 4085/  oracle)   Gid: ( 1140/oinstall)
Access: 2014-10-21 14:39:39.000000000 -0400
Modify: 2014-10-21 17:30:32.000000000 -0400
Change: 2014-10-21 17:30:32.000000000 -0400

As ls -l command is painfully slow to list files in a directory with millions of files, there are other ways to retrieve the files faster.

find . -type f -printf ‘%T+ %p\n’ | sort -r | head -100
This commands finds all files in the current directory, lists them from newest to oldest, then prints only the first 100 files.

find . -type f -mtime -3 -printf ‘%T+ %p\n’ | sort -r | head -100
This commands finds only files created in the last day (-mtime -3), and sorts only these files.

find . -type f -mmin -20 -printf ‘%T+ %p\n’ | sort -r | head -100
For finer control, this command selects only files created/modified less than 20 minutes ago.

Different Results from Data Guard’s Show Configuration Command

cat_lion_mirror
Recently I built a Data Guard environment on two Exadatas with three RAC databases and did a lot of tests. The Show Configuration is probably the most frequent command I used in DG Broker.

When running show configuration from dgmgrl, we usually see the same result no matter where the command is executed, primary or any standby databases. During one switchover test, I run into a weird situation. The show configuration command can return me three different results from one primary database and two standby databases, just like above the image above (cat changes into a lion from the mirror). Here are the result:

Primary Database (wzxdb)

DGMGRL> show configuration
Configuration - DG_Config

  Protection Mode: MaxPerformance
  Databases:
	wzxdb - Primary database
	wzsdb - Physical standby database
	  Error: ORA-16664: unable to receive the result from a database

	wzpdb - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:
ERROR 

Checked the DG Broker log at /u01/app/oracle/diag/rdbms/wzxdb/wzkdb1/trace/drcwzkdb1.log, it has something below

07/16/2014 09:30:20
Site wzsdb returned ORA-16664.
Data Guard Broker Status Summary:
  Type                        Name              Severity  Status
  Configuration               DG_Config         Warning  ORA-16607
  Primary Database            wzxdb             Success  ORA-00000
  Physical Standby Database   wzsdb               Error  ORA-16664
  Physical Standby Database   wzpdb             Success  ORA-00000

Let’s continue to check status for the standby databases.
1st Standby Database, wzpdb

DGMGRL> show configuration
Configuration - DG_Config

  Protection Mode: MaxPerformance
  Databases:
	wzxdb - Primary database
	wzsdb - Physical standby database
	wzpdb - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:
SUCCESS

2nd Standby Database, wzsdb

DGMGRL> show configuration
Configuration - DG_Config

  Protection Mode: MaxPerformance
  Databases:
	wzxdb - Primary database
	wzsdb - Physical standby database
	wzpdb - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:
ORA-16501: the Data Guard broker operation failed
ORA-16625: cannot reach database "wzxdb"
DGM-17017: unable to determine configuration status	

The first thing I checked whether Data Guard replication was still working or not. Did a few switch logfile from primary and can see the logs were replicated to two standby databases. Verified data guard related parameters, tnsnames and listener entries in all databases. Found no issue there. At this moment, I narrowed down the issue to DG Broker and suspect it could relate to DG Broker configuration. After a few tries, I found a solution to fix this issue.
1. On primary db (wzxdb), remove the database wzsdb from DG Broker configuration, then add it back.
2. On standby db (wzsdb), bounce the database.

Here are the detail steps:

Primary Database (wzxdb)
DGMGRL> remove database wzsdb
Removed database "wzsdb" from the configuration
DGMGRL> add database wzsdb as connect identifier is wzsdb;
Database "wzsdb" added
DGMGRL> enable configuration
Enabled.
DGMGRL> show configuration

Configuration - DG_Config

  Protection Mode: MaxPerformance
  Databases:
	wzxdb - Primary database
	wzpdb - Physical standby database
	wzsdb - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:
SUCCESS

After fixing the issue in primary database, let’s goto the standby database with issues. It still has the same error from show configuration command. So I went ahead bouncing the database.
srvctl stop database -d wzsdb
srvctl start database -d wzsdb

DGMGRL> show configuration

Configuration - DG_Config

  Protection Mode: MaxPerformance
  Databases:
	wzxdb - Primary database
	wzpdb - Physical standby database
	wzsdb - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:
SUCCESS

Here is part of the content from data guard broker log on this standby database.

07/16/2014 09:29:58
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:31:09
REMOVE DATABASE wzsdb [PRESERVE DESTINATIONS]
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:31:37
DMON Deregistering service wzsdb_DGB with listener(s)
07/16/2014 09:32:12
DMON Registering service wzsdb_DGB with listener(s)
07/16/2014 09:32:15
Apply Instance for Database wzsdb set to wzdb1
07/16/2014 09:32:19
Failed to send message to site wzxdb. Error code is ORA-16501.
Command EDIT DATABASE wzsdb SET PROPERTY ActualApplyInstance = wzdb1 completed
07/16/2014 09:32:29
Command ENABLE CONFIGURATION completed
07/16/2014 09:32:48
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:33:04
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:33:23
Failed to connect to remote database wzxdb. Error is ORA-12154
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:34:15
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:35:30
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:36:45
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:38:00
Failed to send message to site wzxdb. Error code is ORA-16501.
07/16/2014 09:38:27
Data Guard Broker shutting down
RSM0 successfully terminated
07/16/2014 09:38:29
>> DMON Process Shutdown <<
07/16/2014 09:39:18
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
	  dg_broker_config_file1 = "+RECO/wzsdb/dataguardconfig/dgb_config02.ora"
	  dg_broker_config_file2 = "+DATA/wzsdb/dataguardconfig/dgb_config01.ora"
07/16/2014 09:39:22
DMON Registering service wzsdb_DGB with listener(s)
Broker Configuration:       "DG_Config"
	  Protection Mode:            Maximum Performance
	  Fast-Start Failover (FSFO): Disabled, flags=0x0, version=0
	  Primary Database:           wzxdb (0x03010000)
	  Standby Database:           wzsdb, Enabled Physical Standby (0x01010000)
	  Standby Database:           wzpdb, Enabled Physical Standby (0x02010000)
07/16/2014 09:39:25
wzsdb version check successfully completed
wzsdb has current configuration metadata,
	  completing bootstrap
Creating process RSM0
07/16/2014 09:39:28
Apply Instance for Database wzsdb set to wzdb1
07/16/2014 09:39:37 

We can see it seems the standby database received commands like REMOVE DATABASE wzsdb and ENABLE CONFIGURATION from primary DG Broker, but just can not send the message back to primary database. After bouncing the standby database, it returned normal and can communicate back to primary database.

Finally, all databases have this SUCCESS status no matter where I run the show configuration command.