Failover

Why is my failover taking a long time?

There are many factors that can influence failover time. If a failover is taking longer than expected, the rsfmon logs should be checked to find which part(s) of the failover is taking the time.

The main RSF-1 log file is /opt/HAC/RSF-1/log/rsfmon.log. Each line in the log is timestamped, so it is possible to work out how much time each stage is taking. The log file will also contain a line telling you how long a service start or stop took in total:

[23440 Jan 31 17:18:50] [pool4 rsfexec] Total run time for service start: 9 seconds

Log file parser

Log files can be complex to read - especially when multiple services are starting or stopping simultaneously. To help with diagnosis, the tool /opt/HAC/RSF-1/bin/rsflog-summary.sh can be used to provide a summary of the activity stored in the log files.

Here is an example of running the log summary tool:

# /opt/HAC/RSF-1/bin/rsflog-summary.sh -h

Usage: rsflog-summary.sh [-l|--log <logfile|logdir>] [service]...

Options:
        -l --log <log>: Specify a log file or log directory to search.
                        If a file is given, only that file will be searched.
                        If a directory is given, that directory will be searched
                        for rsfmon.log and rsfmon.log.[0-9].
                        The default is to use the standard RSF-1 log directory
                        /opt/HAC/RSF-1/log

        -h --help:      Show this help text and exit

The config file /opt/HAC/RSF-1/etc/config will be scanned for services to search for
unless a list has been provided on the command line.

# /opt/HAC/RSF-1/bin/rsflog-summary.sh

Services to search for:  cpw_pool pool4
Searching log files in /opt/HAC/RSF-1/log:
rsfmon.log.9 rsfmon.log.8 rsfmon.log.7 rsfmon.log.6 rsfmon.log.5 rsfmon.log.4 rsfmon.log.3 rsfmon.log.2 rsfmon.log.1 rsfmon.log.0 rsfmon.log
###############################################
Service startups and shutdowns for cpw_pool:
###############################################
Reading rsfmon.log.9...
Reading rsfmon.log.8...
Reading rsfmon.log.7...
Reading rsfmon.log.6...
Reading rsfmon.log.5...
Reading rsfmon.log.4...
Reading rsfmon.log.3...
Reading rsfmon.log.2...
Reading rsfmon.log.1...
Reading rsfmon.log.0...
Reading rsfmon.log...
Delay before service start - 6 seconds
Service startup #1: Feb 04 10:59:25 (rsfmon.log)
Fping test complete for testvip: 2 seconds
Script S01announce          run time: 0 seconds (write to log file)
Script S02ApplianceStarting run time: 0 seconds (event notify)
Script S14res_drives        run time: 6 seconds (create initial res_drives)
Script S15zfs_mhdc          run time: 5 seconds (place reservations)
        Reservations taken in 4 seconds.
Script S20zfs               run time: 3 seconds (import pool + LUs)
        Zpool import completed status 0, in 3 seconds
        Comstar mapping restored in 0 seconds
Script S21res_drives        run time: 1 seconds (refresh res_drives)
Script S98ApplianceStarted  run time: 1 seconds (event notify)
Script S99announce          run time: 1 seconds (write to log file)
Service start scripts took 17 seconds
Plumb in VIP interface: 0 seconds
Total run time for service start: 17 seconds

Delay before service start - 6 seconds
Service startup #2: Feb 04 11:06:26 (rsfmon.log)
Fping test complete for testvip: 2 seconds
Script S01announce          run time: 0 seconds (write to log file)
        Reservations released in 0 seconds.
Script S02ApplianceStarting run time: 1 seconds (event notify)
Script S14res_drives        run time: 6 seconds (create initial res_drives)
Script S15zfs_mhdc          run time: 4 seconds (place reservations)
        Reservations taken in 4 seconds.
Script S20zfs               run time: 4 seconds (import pool + LUs)
        Zpool import completed status 0, in 3 seconds
        Comstar mapping restored in 0 seconds
Script S21res_drives        run time: 0 seconds (refresh res_drives)
Script S98ApplianceStarted  run time: 1 seconds (event notify)
Script S99announce          run time: 0 seconds (write to log file)
Service start scripts took 16 seconds
Plumb in VIP interface: 0 seconds
Total run time for service start: 16 seconds

###############################################
Service startups and shutdowns for pool4:
###############################################
Reading rsfmon.log.9...
Reading rsfmon.log.8...
Reading rsfmon.log.7...
Reading rsfmon.log.6...
Reading rsfmon.log.5...
Reading rsfmon.log.4...
Reading rsfmon.log.3...
Delay before service start - 18 seconds
Service startup #1: Jan 29 15:29:37 (rsfmon.log.3)
Fping test complete for vip4: 2 seconds
Script S01announce          run time: 0 seconds (write to log file)
Script S02ApplianceStarting run time: 0 seconds (event notify)
Script S14res_drives        run time: 6 seconds (create initial res_drives)
Script S15zfs_mhdc          run time: 5 seconds (place reservations)
        Reservations taken in 4 seconds.
Script S20zfs               run time: 3 seconds (import pool + LUs)
        Zpool import completed status 0, in 2 seconds
        Comstar mapping restored in 0 seconds
Script S21res_drives        run time: 0 seconds (refresh res_drives)
Script S98ApplianceStarted  run time: 1 seconds (event notify)
Script S99announce          run time: 0 seconds (write to log file)
Service start scripts took 15 seconds
Plumb in VIP interface: 0 seconds
Total run time for service start: 15 seconds

Service shutdown #1: Jan 29 15:39:24 (rsfmon.log.3)
Script K01announce          run time: 0 seconds (write to log file)
Script K02ApplianceStarted  run time: 0 seconds
Script K02ApplianceStopping run time: 1 seconds (event notify)
Script K79res_drives        run time: 0 seconds (nothing)
Script K80zfs               run time: 1 seconds (export pool + LUs)
        Comstar mapping removed in 0 seconds
        Zpool export completed in 1 seconds
Script K85zfs_mhdc          run time: 1 seconds (release reservations)
        Reservations released in 0 seconds.
Script K86res_drives        run time: 0 seconds (nothing)
Script K98ApplianceStarting run time: 0 seconds
Script K98ApplianceStopped  run time: 1 seconds (event notify)
Script K99announce          run time: 0 seconds (write to log file)
Service stop scripts took 4 seconds
Total run time for service stop: 4 seconds

Reading rsfmon.log.2...
Reading rsfmon.log.1...
Reading rsfmon.log.0...
Reading rsfmon.log...
Delay before service start - 6 seconds
Service startup #2: Jan 31 17:18:39 (rsfmon.log)
Fping test complete for vip4: 2 seconds
Script S01announce          run time: 0 seconds (write to log file)
Script S02ApplianceStarting run time: 1 seconds (event notify)
Script S14res_drives        run time: 0 seconds (create initial res_drives)
Script S15zfs_mhdc          run time: 4 seconds (place reservations)
        Reservations taken in 4 seconds.
Script S20zfs               run time: 3 seconds (import pool + LUs)
        Zpool import completed status 0, in 2 seconds
        Comstar mapping restored in 0 seconds
Script S21res_drives        run time: 1 seconds (refresh res_drives)
Script S98ApplianceStarted  run time: 0 seconds (event notify)
Script S99announce          run time: 0 seconds (write to log file)
Service start scripts took 9 seconds
Plumb in VIP interface: 0 seconds
Total run time for service start: 9 seconds

Service shutdown #2: Jan 31 17:18:56 (rsfmon.log)
Script K01announce          run time: 1 seconds (write to log file)
Script K02ApplianceStarted  run time: 0 seconds
Script K02ApplianceStopping run time: 0 seconds (event notify)
Script K79res_drives        run time: 0 seconds (nothing)
Script K80zfs               run time: 1 seconds (export pool + LUs)
        Comstar mapping removed in 0 seconds
        Zpool export completed in 0 seconds
Script K85zfs_mhdc          run time: 1 seconds (release reservations)
        Reservations released in 0 seconds.
Script K86res_drives        run time: 0 seconds (nothing)
Script K98ApplianceStarting run time: 1 seconds
Script K98ApplianceStopped  run time: 0 seconds (event notify)
Script K99announce          run time: 0 seconds (write to log file)
Service stop scripts took 4 seconds
Total run time for service stop: 4 seconds

Service startup #3: Jan 31 17:19:01 (rsfmon.log)
Fping test complete for vip4: 2 seconds
Script S01announce          run time: 0 seconds (write to log file)
Script S02ApplianceStarting run time: 0 seconds (event notify)
Script S14res_drives        run time: 1 seconds (create initial res_drives)
Script S15zfs_mhdc          run time: 4 seconds (place reservations)
        Reservations taken in 4 seconds.
Script S20zfs               run time: 2 seconds (import pool + LUs)
        Zpool import completed status 0, in 2 seconds
        Comstar mapping restored in 0 seconds
Script S21res_drives        run time: 1 seconds (refresh res_drives)
Script S98ApplianceStarted  run time: 1 seconds (event notify)
Script S99announce          run time: 0 seconds (write to log file)
Service start scripts took 9 seconds
Plumb in VIP interface: 0 seconds
Total run time for service start: 9 seconds

Service shutdown #3: Jan 31 17:27:32 (rsfmon.log)
Script K01announce          run time: 1 seconds (write to log file)
Script K02ApplianceStarted  run time: 0 seconds
Script K02ApplianceStopping run time: 0 seconds (event notify)
Script K79res_drives        run time: 0 seconds (nothing)
Script K80zfs               run time: 1 seconds (export pool + LUs)
        Comstar mapping removed in 0 seconds
        Zpool export completed in 0 seconds
Script K85zfs_mhdc          run time: 1 seconds (release reservations)
        Reservations released in 0 seconds.
Script K86res_drives        run time: 0 seconds (nothing)
Script K98ApplianceStarting run time: 1 seconds
Script K98ApplianceStopped  run time: 0 seconds (event notify)
Script K99announce          run time: 0 seconds (write to log file)
Service stop scripts took 4 seconds
Total run time for service stop: 4 seconds