HP OpenVMS Systems Documentation

HP OpenVMS System Analysis Tools Manual

Stops the acquisition of instructions.

Format

OCLA STOP [/CPU=n]

Parameters

None.

Qualifier

/CPU=n

Specifies the CPU on which to stop acquisition. If this qualifier is omitted, acquisition is stopped on all CPUs.

Description

Stops the acquisition of instructions.

Unloads the OCLA$PCTRACE execlet and returns the acquisition buffers to the system.

Format

OCLA UNLOAD

Parameters

None.

Qualifiers

None.

Description

Unloads the OCLA$PCTRACE execlet and returns the acquisition buffers to the system.

The Alignment Fault Utility can be used to find alignment faults.

7.1 Overview of FLT

The utility can be started and stopped as required without the need for a system reboot. It records all alignment faults into a ring buffer, which can be sized when starting alignment fault tracing. The summary screen displays the results sorted by the program counter (PC) that has incurred the most alignment faults. The detailed trace output also shows the process identification (PID) of the process that caused the alignment fault, with the virtual address that triggered the fault.

Output can be directed to a file with the SDA SET OUTPUT command.

7.2 FLT Commands

To use the FLT utility, several commands and qualifiers are available. Table 7-1 describes these commands and qualifiers.

Lists the FLT commands.

Format

FLT

Parameters

None.

Qualifiers

None.

Description

When entered by itself, the FLT command lists the available FLT commands.

Example

SDA> FLT
      

Loads the FLT$DEBUG execlet. Do this before starting alignment fault tracing.

Format

FLT LOAD

Parameters

None.

Qualifiers

None.

Description

The FLT LOAD command loads the FLT$DEBUG execlet.

Example

SDA> FLT LOAD
      

Displays detail about the trace.

Format

FLT SHOW TRACE /SUMMARY

Parameters

None.

Qualifier

/SUMMARY

Displays the results sorted by the program counter (PC) that has incurred the most alignment faults.

Description

The FLT SHOW TRACE command displays detail about the trace.

Example

SDA> FLT SHOW TRACE
      

Starts alignment fault tracing.

Format

START TRACE [/BUFFER=pages] [/BEGIN=pc_range_low][/END=pc_range_high]

Parameters

None.

Qualifiers

/BUFFER=pages

The number of pages to size the trace buffer. The default is 128 pages or 1MB.

/BEGIN=pc_range_low

Start of range of PCs to trace.

/END=pc_range_high

End of range of PCs to trace.

Description

The FLT START TRACE command starts alignment fault tracing. By default, all PCs are traced.

Example

SDA> FLT START TRACE
      

Stops tracing.

Format

FLT STOP TRACE

Parameters

None.

Qualifiers

None.

Description

The FLT STOP TRACE command stops tracing.

Example

SDA> FLT STOP TRACE
      

Unloads the FLT$DEBUG execlet.

Format

FLT UNLOAD

Parameters

None.

Qualifiers

None.

Description

The FLT UNLOAD command unloads the FLT$DEBUG execlet.

Example

SDA> FLT UNLOAD
      

This chapter presents an overview of the SDA Spinlock Tracing Utility commands, and describes the SDA Spinlock Tracing commands.

8.1 Overview of the SDA Spinlock Tracing Utility

To synchronize access to data structures, the OpenVMS operating system uses a set of static and dynamic spinlocks, such as IOLOCK8 and SCHED. The operating system acquires a spinlock to synchronize data, and at the end of the critical code path the spinlock is then released. If a CPU attempts to acquire a spinlock while another CPU is holding it, the CPU attempting to acquire the spinlock has to spin, waiting until the spinlock is released. Any lost CPU cycles within such a spinwait loop are charged as MPsynch time.

By using the MONITOR utility, you can monitor the time in process modes, for example, with the command $ MONITOR MODES. A high rate of MP synchronization indicates contention for spinlocks. However, until the implementation of the Spinlock Tracing utility, there was no way to tell which spinlock was heavily used, and who was acquiring and releasing the contended spinlocks. The Spinlock Tracing utility allows a characterization of spinlock usage. It can also collect performance data for a given spinlock on a per-CPU basis.

This tracing ability is built into the system synchronization execlet, which contains the spinlock code, and can be enabled or disabled while the system is running. There is no need to reboot the system to load a separate debug image. The images that provide spinlock tracing functionality are as follows:

SYS$LOADABLE_IMAGES:SPL$DEBUG.EXE
SYS$SHARE:SPL$SDA.EXE

The SDA> prompt provides the command interface. From this command interface, you can load and unload the spinlock debug execlet using SPL LOAD and SPL UNLOAD, and start, stop and display spinlock trace data. This allows you to collect spinlock data for a given period of time without system interruption. Once information is collected, the trace buffer can be deallocated and the execlet can be unloaded to free up system resources. The spinlock trace buffer is allocated from S2 space and pages are taken from the free page list.

Should the system crash while spinlock tracing is enabled, the trace buffer is dumped into the system dump file, and it can later be analyzed using the spinlock trace utility. This is very useful in tracking down CPUSPINWAIT bugcheck problems.

Note that by enabling spinlock tracing, there is a performance impact. The amount of the impact depends on the amount of spinlock usage.

8.2 How to Use the SDA Spinlock Tracing Utility

The following steps will enable you to collect spinlock statistics using the Spinlock Tracing Utility.

1. Load the Spinlock Tracing Utility execlet.

   SDA> SPL LOAD

2. Allocate a trace buffer and start tracing.

   SDA> SPL START TRACE

3. Wait a few seconds to allow some tracing to be done, then find out which spinlocks are incurring the most acquisitions and the most spinwaits.

   SDA> SPL SHOW TRACE/SUMMARY

   
   For example, you might see contention for the SCHED and IOLOCK8 spinlocks (a high acquisition count, with a significant proportion of the acquisitions being forced to wait).
4. Look to see if the spinlocks with a high proportion of spinwaits caused a significant delay in the acquisition of the spinlock. You must now collect more detailed statistics on a specific spinlock.

   SDA> SPL START COLLECT/SPINLOCK=SCHED

   
   This command accumulates additional data for the specified spinlock. As long as tracing is not stopped, collection will continue to accumulate spinlock-specific data from the trace buffer.
5. Display the additional data collected for the specified spinlock.

   SDA> SPL SHOW COLLECT

   
   This display includes the average hold time of the spinlock and the average spinwait time while acquiring the spinlock.
6. Repeat steps 4 and 5 for each spinlock that has contention. A START COLLECT cancels the previous collection.
7. Disable spinlock tracing when you have collected all the needed spinlock statistics and release all the memory used by the Spinlock Tracing utility with the following commands.

   SDA> SPL STOP COLLECT SDA> SPL STOP TRACE SDA> SPL UNLOAD

The following example shows a command procedure that can be used for gathering spinlock statistics:

$ analyze/system
  spl load
  spl start trace/buffer=1000
  wait 00:00:15
  spl stop trace
  read/executive/nolog
  set output spl_trace.lis
  spl analyze
  spl show trace/summary
  spl start collect/spin=sched
  wait 00:00:05
  spl show collect
  spl start collect/spin=iolock8
  wait 00:00:05
  spl show collect
  spl start collect/spin=lckmgr
  wait 00:00:05
  spl show collect
  spl start collect/spin=mmg
  wait 00:00:05
  spl show collect
  spl start collect/spin=timer
  wait 00:00:05
  spl show collect
  spl start collect/spin=mailbox
  wait 00:00:05
  spl show collect
  spl start collect/spin=perfmon
  wait 00:00:05
  spl show collect
  spl stop collect
  spl unload
  exit
$ exit

A more comprehensive procedure is provided as SYS$EXAMPLES:SPL.COM.

8.4 SDA Spinlock Tracing Commands

The following is a list of the spinlock tracing commands:

SPL ANALYZE
SPL LOAD
SPL SHOW COLLECT
SPL SHOW TRACE
SPL START COLLECT
SPL START TRACE
SPL STOP COLLECT
SPL STOP TRACE
SPL UNLOAD

Analyzes collected spinlock data and presents the most relevant data.

Format

SPL ANALYZE [/[NO]CPU_STATISTICS |/[NO]PLATFORM | /[NO]HOLD_TIMES=n/[NO]WAIT_TIMES=n |/[NO]USAGE=(HOLD=n,SPIN=n,TOP_PCS=n)]

Parameters

None.

Qualifiers

/CPU_STATISTICS (default)

/NOCPU_STATISTICS

Displays per-CPU statistics.

/PLATFORM (default)

/NOPLATFORM

Displays system platform information.

/HOLD_TIMES=n

/NOHOLD_TIMES=n

Displays occurrences of spinlocks held longer than n microseconds. The default is 1000 microseconds.

/WAIT_TIMES=n

/NOWAIT_TIMES=n

Displays occurrences of spinlocks held longer than n microseconds. The default is 1000 microseconds.

/USAGE=(HOLD=n,SPIN=n, TOP_PCS=n)

Specifies thresholds for displaying information on a spinlock. If the percentage of time a spinlock is held exceeds the value of HOLD=n, where n is a value from 0 to 100, displays the information on the spinlock. The default is 10%. If the percentage of time a spinlock is spinning exceeds the value of SPIN=n, displays the information on the spinlock. The default is 10%. If either the HOLD or SPIN thresholds are exceeded, displays information on a spinlock. The TOP_PCS=n keyword displays the top n unique callers to lock a spinlock. The default is to display the top five unique callers.

By specifying either /USAGE=(HOLD=0) or /USAGE=(SPIN=0), SPL displays information on all spinlock usage from the trace buffer.

Description

The SPL ANALYZE command analyzes collected spinlock data and displays the most relevant data.

The SPL ANALYZE command provides an overview of SPINLOCK usage on a system. Data are provided by CPU and by spinlock. When looking at a system with high MP_Synch time, this is a good command to start with. Stop spinlock tracing before using this command.

Example

SDA> SPL ANALYZE/HOLD=50/WAIT=50/USAGE=HOLD=5 Spinlock Analysis (1) Platform ------------------------------------------------ Node: CLU21 Hardware: AlphaServer ES45 Model 2 Active CPUs: 4 Memory: 16.00 GB CPU Frequency: 1.000 GHz Trace Buffer: 1280 pages (10.00 MB) Trace Time: 0.48 seconds Trace Start: 15-OCT 10:51:53.427386 CPU statistics (2) % Time in % Time % Time All Spinlocks All Spinlocks CPU ID Fork Dispatcher Spinlocks Held MP_Synch Acquires/sec Waits/sec ------ --------------- -------------- ---------- ------------- ------------- 00 0.1 16.2 1.1 82210.4 1434.7 01 0.1 15.8 1.2 79551.5 1548.3 02 0.0 16.4 1.2 85690.9 1511.1 03 1.7 17.7 1.1 86601.3 1451.2 ------ --------------- -------------- ---------- ------------- ------------- Total 1.9 66.1 4.6 334054.1 5945.3 Spinlock Usage (3) Spin to Spinlock % Time Held Acquires/sec Average Hold % Time Spinning Waits/sec Average Spin Hold Ratio ------------ ----------- ------------ ------------ --------------- ------------ ------------ ----------- FILSYS 15.6 33776.8 4609 2.6 2314.1 11379 0.2 LCKMGR 9.3 26198.6 3560 1.2 2208.8 5494 0.1 PCB$00000426 7.2 49420.4 1451 0.0 35.1 6342 0.0 PCB$00000428 7.1 49125.2 1437 0.0 14.5 7532 0.0 Spinlock (4) % Time Acquires Spinwaits Average Caller's PC Held /sec Average /sec Spinwait ---------------------------------------------- ------ --------- --------- --------- --------- FILSYS 8022CA44 SEARCH_FCB_C+00604 12.0 4021.3 29793 303.5 11985 80222E10 SET_DIRINDX_C+00030 0.5 4194.7 1163 247.7 11477 8021B06C START_REQUEST_C+0006C 0.4 2438.0 1607 384.0 15838 8021B208 FINISH_REQUEST_C+00058 0.4 2440.1 1510 206.4 15862 800FC508 IOC_STD$MAPVBLK_C+000C8 0.3 2014.8 1713 402.5 9518 LCKMGR 801DEB14 EXE$ENQ_C+00A44 3.5 12984.7 2657 988.8 5727 801E3B94 EXE$DEQ_C+00114 3.0 5943.2 5109 538.8 4849 801E03BC LOCKING+023BC 2.6 5941.2 4315 392.2 5682 801E5C84 LCK$DEQLOCK_C+00F54 0.3 1323.2 2091 289.0 5642 PCB$00000426 801782F8 SCH$ASTDEL_C+00078 1.9 15525.9 1256 0.0 0 80179AC4 SCH$QAST_C+00094 1.7 8907.6 1935 0.0 0 8017A780 SCH$QUEUE_AST_CURRENT_C+00070 1.2 7859.0 1532 0.0 0 80178FE0 SCH$ASTDEL_K_C+00090 1.2 8895.3 1320 8.3 2346 80179124 SCH$ASTDEL_K_C+001D4 1.1 7780.5 1355 0.0 0 PCB$00000428 801782F8 SCH$ASTDEL_C+00078 2.0 15606.4 1308 0.0 0 80179AC4 SCH$QAST_C+00094 1.6 8810.6 1794 0.0 0 80178FE0 SCH$ASTDEL_K_C+00090 1.2 8810.6 1344 6.2 2589 8017A780 SCH$QUEUE_AST_CURRENT_C+00070 1.2 7904.4 1492 0.0 0 80179124 SCH$ASTDEL_K_C+001D4 1.0 7728.9 1340 0.0 0 8017A780 SCH$QUEUE_AST_CURRENT_C+00070 1.1 8655.8 1298 0.0 0 80179124 SCH$ASTDEL_K_C+001D4 1.1 8598.0 1225 0.0 0 80178FE0 SCH$ASTDEL_K_C+00090 1.1 9192.5 1144 2.1 2326 Long Spinlock Hold Times (> 50 microseconds) (5) Timestamp CPU Spinlock | Forklock Calling PC | Forking PC EPID Hold (us) ---------------------- --- --------------------- -------------------------------------- -------- --------- 15-OCT 10:51:53.801244 00 81D6A200 81D6A200 8051B380 LAN$COMPLETE_VCRP_CSMACD_C+00 00000000 64 15-OCT 10:51:53.538665 00 818BBE00 POOL 8004B334 EXE$ALONPAGVAR_C+002F4 00000000 59 15-OCT 10:51:53.538331 03 81F75980 PCB$00000429 8017A808 SCH$QUEUE_AST_CURRENT_C+000F8 00000000 56 15-OCT 10:51:53.597448 03 818BBE00 POOL 8004B334 EXE$ALONPAGVAR_C+002F4 00000000 52 15-OCT 10:51:53.670228 03 818BBE00 POOL 8004B334 EXE$ALONPAGVAR_C+002F4 00000000 51 Long Spinlock Wait Times (> 50 microseconds) (6) Timestamp CPU Spinlock | Forklock Calling PC | Forking PC EPID Wait (us) ---------------------- --- --------------------- -------------------------------------- -------- --------- 15-OCT 10:51:53.454082 03 818BCB00 FILSYS 800FC508 IOC_STD$MAPVBLK_C+000C8 00000000 79 15-OCT 10:51:53.661343 02 818BCB00 FILSYS 8021B208 FINISH_REQUEST_C+00058 00000000 76 15-OCT 10:51:53.661256 00 818BCB00 FILSYS 8021EDD0 F11BXQP+08DD0 00000000 66 15-OCT 10:51:53.898618 00 818BCB00 FILSYS 8021B06C START_REQUEST_C+0006C 00000000 53

This example shows the output of the SPL ANALYZE command, which is divided into several sections:

1. Spinlock Analysis:
   Shows information on the platform such as the hardware type, the number of CPUs and the speed of the CPUs.
2. CPU Statistics:
   Shows spinlock information on a per CPU basis. The percentage of time the CPU owns spinlock is displayed along with a percentage of time the CPU was executing from the fork dispatcher. This information can be very useful in determing the amount of time a CPU is in use for processing I/O.
3. Spinlock Usage:
   Shows information on the spinlock usage by the system. This data is sorted by the percentage of time the spinlocks are held. The average hold time displayed is in system cycles. The display also includes the percent of time that CPUs are waiting on this spinlock along with the average number of cycles a CPU needed to wait before it was able to acquire the spinlock.
4. Spinlock:
   For each spinlock displayed in section 3, the top callers are displayed sorted by the number of acquires per second that occurred. In addition, the average hold and wait time for each caller is displayed in system cycles.
5. Long Spinlock Hold Times:
   The section on Long Spinlock Hold Times shows occurrences of spinlocks whose hold time exceeded a threshold. In the above report, the threshold was specified as 50 microseconds. The EPID at the time of the acquire is also displayed. An EPID of 0 indicates that the spinlock acquire did not occur in process context.
6. Long Spinlock Wait Times:
   The section on Long Spinlock Wait Times shows occurrences of spinlocks whose wait time exceeded a threshold. In the above report, the threshold was specified as 50 microseconds. The EPID at the time of the acquire is also displayed. An EPID of 0 indicates that the spinlock acquire did not occur in process context.