Environment
Novell Open Enterprise Server 11 (OES 11) Linux Support Pack 1
Novell Open Enterprise Server 11 (OES 11) Linux Support Pack 2
Novell Cluster Services
Novell Open Enterprise Server 11 (OES 11) Linux Support Pack 2
Novell Cluster Services
Situation
On heavily used file servers with a high turn-over in number of files and data, there is a possibility that the purge log will contain millions of entries.
At one point in time, either when the server has undergone maintenance, or if it is running NCS Clustering and a node has encountered a failure, cluster resources may migrate, the server will be rebooted and NSS pools will need to be re-activated. Once the NSS pool(s) are successfully activated, the NSS volume(s) on those NSS pool also need to be mounted again.
What is observed is that during regular volume mount operations, this appears to hang on the server, since there are no visual indicators or log file entries that anything is still happening in the background. At the same time, the volume mount does not seem to proceed even after waiting on this for long period of time. (Up to several hours)
At one point in time, either when the server has undergone maintenance, or if it is running NCS Clustering and a node has encountered a failure, cluster resources may migrate, the server will be rebooted and NSS pools will need to be re-activated. Once the NSS pool(s) are successfully activated, the NSS volume(s) on those NSS pool also need to be mounted again.
What is observed is that during regular volume mount operations, this appears to hang on the server, since there are no visual indicators or log file entries that anything is still happening in the background. At the same time, the volume mount does not seem to proceed even after waiting on this for long period of time. (Up to several hours)
Resolution
The fix that was implemented is that during each one of three purge paths, when NSS attempts to purge a file, the purge will be delayed when 2000 files are already being purged.
By limiting the number of files being actively purged we limit the number of PLOG entries in the purge log. This is one key to the solution.
The purge system will have a maximum of 2000 PLOG_BEAST_DELETE entries in the purge log. In one confirmed case, volume activation was slow because we had 12 million purge log entries. With only 2000 entries allowed, the play purge log would now be 6000 (12million/2000) times faster.
The solution to this issue has been released to the public with the September 2014 Scheduled Maintenance patch.
By limiting the number of files being actively purged we limit the number of PLOG entries in the purge log. This is one key to the solution.
The purge system will have a maximum of 2000 PLOG_BEAST_DELETE entries in the purge log. In one confirmed case, volume activation was slow because we had 12 million purge log entries. With only 2000 entries allowed, the play purge log would now be 6000 (12million/2000) times faster.
The solution to this issue has been released to the public with the September 2014 Scheduled Maintenance patch.
Cause
Purgeable files are stored in the salvage tree (also called 'purge
tree'). The purge tree tracks all deleted files and is ordered by delete time.
The purge log tracks ~11 different log records for long term transactions. Three of which would be related to files being deleted (on a volume without salvage) or purged (on a volume with salvage). These log records are PLOG_BLOCK_FREE, PLOG_BEAST_DELETE and PLOG_TRUNCATE.
The PLOG_BLOCK_FREE record is generated when metadata blocks are freed, while PLOG_BEAST_DELETE and PLOG_TRUNCATE. relate to removing files from the volume.
When the slow 'slow' mount problems were observed, and Novell had obtained a NSS Pool Scan from a customer, on the NSS pool scan we found between 12 to 14 million PLOG_BEAST_DELETE entries in the purge log.
After a NSS pool is successfully activated, the volume is mounted. During the volume mount, the system is also 'playing' this purge log. This action is normally very fast and done within seconds, therefor does not provide any visual indication of the actions happening under the hood.
When the purge log is played, all entries in the purge log need to be processed before the volume _can_ successfully activate and the volume will become available.
The purge log tracks ~11 different log records for long term transactions. Three of which would be related to files being deleted (on a volume without salvage) or purged (on a volume with salvage). These log records are PLOG_BLOCK_FREE, PLOG_BEAST_DELETE and PLOG_TRUNCATE.
The PLOG_BLOCK_FREE record is generated when metadata blocks are freed, while PLOG_BEAST_DELETE and PLOG_TRUNCATE. relate to removing files from the volume.
When the slow 'slow' mount problems were observed, and Novell had obtained a NSS Pool Scan from a customer, on the NSS pool scan we found between 12 to 14 million PLOG_BEAST_DELETE entries in the purge log.
After a NSS pool is successfully activated, the volume is mounted. During the volume mount, the system is also 'playing' this purge log. This action is normally very fast and done within seconds, therefor does not provide any visual indication of the actions happening under the hood.
When the purge log is played, all entries in the purge log need to be processed before the volume _can_ successfully activate and the volume will become available.
Additional Information
Note 1: Determining the amount of purge log entries.
To determine the amount of purge log entries on a server, amongst some other I/O details, the purge log values for Pool and Volume, can be checked by starting nsscon from a console terminal, and within the NSS console typing "/ZLSSPoolIOStatistics=_summary". The output returned here system totals for all NSS pools mounted on the server, and to visualize details for individual pools, please execute "/ZLSSPoolIOStatistics=<pool_name>".
Note 2 : Offline NSS Pool and I/O details.
Can be listed in the supportconfig by inspecting :
Note 3 : Visualize the status for a volume mount.
To determine if volume mount is processing the purge log, or is not progressing for other reasons, we can enter 'nsscon /vfs' in a terminal console.
From that point onwards, all events that consume the Virtual File System (VFS) are logged to '/var/log/messages'.
(Entering 'nsscon /novfs' will disable this debug type logging again).
When this has been done, it was observed that the volume mount is still in progress since we see a line (or multiple lines) of dots that is (are) progressing. Each dot that is added to this line equals to ~100 purge log entries that are processed.
In problem cases we observed extremely slow volume mount behavior, the dots where double digit numbers ranging from ~20k to 40k, and volume mounts took around 12 hours to successfully complete.
To determine the amount of purge log entries on a server, amongst some other I/O details, the purge log values for Pool and Volume, can be checked by starting nsscon from a console terminal, and within the NSS console typing "/ZLSSPoolIOStatistics=_summary". The output returned here system totals for all NSS pools mounted on the server, and to visualize details for individual pools, please execute "/ZLSSPoolIOStatistics=<pool_name>".
Note 2 : Offline NSS Pool and I/O details.
Can be listed in the supportconfig by inspecting :
VolumeInfo.xml
PhysicalIO.xml
Note 3 : Visualize the status for a volume mount.
To determine if volume mount is processing the purge log, or is not progressing for other reasons, we can enter 'nsscon /vfs' in a terminal console.
From that point onwards, all events that consume the Virtual File System (VFS) are logged to '/var/log/messages'.
(Entering 'nsscon /novfs' will disable this debug type logging again).
When this has been done, it was observed that the volume mount is still in progress since we see a line (or multiple lines) of dots that is (are) progressing. Each dot that is added to this line equals to ~100 purge log entries that are processed.
E.g.:
Activating pool "DATA"...
** Pool layout v43.02
** Previous clean shutdown detected (consistency check OK)
** Loading system objects
** Processing volume purge log
** .
** Processing pool purge log
** .
Activating volume "DATA"...
** Volume layout v36.03
** Volume creation layout v36.03
** Processing volume purge log
**
....................................................................................................
Volume DATA set to the ACTIVE state.
Volume DATA is already in the ACTIVE state.
In problem cases we observed extremely slow volume mount behavior, the dots where double digit numbers ranging from ~20k to 40k, and volume mounts took around 12 hours to successfully complete.