Process Monitoring with prstat
Process Monitoring with prstatThe following chapter takes a deeper look at the Solaris tool prstat(1), the all round utility that helps understand system utilisation.
prstat– The Allround Utility
One of the most important and widely used utility found in Solaris is prstat (see prstat(1)). prstat gives fast answers to question:
-
How much is my system utilized in terms of CPU and memory?
-
Which processes (or users, zones, projects, tasks) are utilizing my system?
-
How are processes/threads using my system (user bound, I/O bound)?
In its simplest form, the command prstat <interval> (i.e. prstat 2) will examine all processes and report statistics sorted by CPU usage.
prstat – prstat 2 command reporting on all processes and sorting by CPU usage
As can be seen from the screen capture, processes are ordered from top (highest) to bottom (lowest) according to their current CPU usage (in % - 100% means all system CPUs are fully utilized). For each process in the list, following information is printed:
-
PID: the process ID of the process.
-
USERNAME: the real user (login) name or real user ID.
-
SIZE: the total virtual memory size of the process, including all mapped files and devices, in kilobytes (K), megabytes (M), or gigabytes (G).
-
RSS: the resident set size of the process (RSS), in kilobytes (K), megabytes (M), or gigabytes (G).
-
STATE: the state of the process (cpuN/sleep/wait/run/zombie/stop).
-
PRI: the priority of the process. Larger numbers mean higher priority.
-
NICE: nice value used in priority computation. Only processes in certain scheduling classes have a nice value.
-
TIME: the cumulative execution time for the process.
-
CPU: The percentage of recent CPU time used by the process. If executing in a non-global zone and the pools facility is active, the percentage will be that of the processors in the processor set in use by the pool to which the zone is bound.
-
PROCESS: the name of the process (name of executed file).
-
NLWP: the number of lwps in the process.
The <interval> argument given to prstat is the sampling/refresh interval in seconds.
Special Report – Sorting
The prstat output can be sorted by another criteria than CPU usage. Use the option -s (descending) or -S (ascending) with the criteria of choice (i.e. prstat -s time 2):
Criteria |
Comments |
cpu |
Sort by process CPU usage. This is the default. |
pri |
Sort by process priority. |
rss |
Sort by resident set size. |
size |
Sort by size of process image. |
time |
Sort by process execution time. |
Special report – Continuous Mode
With the option -c to prstat, new reports are printed below previous ones, instead of overprinting them. This is especially useful when gathering information to a file (i.e. prstat -c 2 > prstat.txt). The option -n <number of output lines> can be used to set the maximum length of a report.
prstat – continuous report sorted by ascending other of CPU usage
Special Report – by users
With the option -a or -t to prstat, additional reports about users are printed.
prstat – prstat -a 2 reports by user
Special Report – by Zones
With the option -Z to prstat, additional reports about zones are printed.
Special Report – by Projects (see projects(1))
With the option -J to prstat, additional reports about projects are printed.
prstat – prstat -J 2 reports about projects
Special Report – by Tasks (see newtask(1))
With the option -T to prstat, additional reports about tasks are printed.
prstat – prstat -T 2 reports by tasks
Special Report – Microstate Accounting
Unlike other operating systems that gather CPU statistics every clock tick or every fixed time interval (typically every hundredth of a second), Solaris 10 incorporates a technology called microstate accounting that uses high-resolution timestamps to measure CPU statistics for every event, thus producing extremely accurate statistics.
The microstate accounting system maintains accurate time counters for threads as well as CPUs. Thread-based microstate accounting tracks several meaningful states per thread in addition to user and system time, which include trap time, lock time, sleep time and latency time. prstat reports the per-process (option -m) or per-thread (option -mL) microstates.
prstat – prstat -m 2 reports on process microstates
The screen output shown above displays microstates for the running system. Looking at the top line with PID 693, one can see that the process Xorg spends 1.8% of its time in userland while sleeping (98%) the rest of its time. prstat – prstat -mL 2:
The screen output shown above displays per-thread microstates for the running system. Looking at the line with PID 1311 (display middle), one can see the microstates for LWP #9 and LWP #8 of the process firefox-bin.
prstat usage Scenario – cpu Latency
One important measure for CPU saturation is the latency (LAT column) output of prstat. Let's once again, start two (2) copies of our CPU intensive application.
prstat – observing latency with CPU intensive application
Now let's run prstat with microstate accounting reporting, i.e. prstat -m 2 and record the output:
prstat – prstat -m 2 output
Please observe the top two (2) lines of the output with PID 2223 and PID 2224. One can clearly see that both processes exhibit a high percentage of their time (50% and 52% respectively) in LAT microstate (CPU latency). The remaining time is spent in computation as expected (USR microstate). Clearly in this example, both CPU bound applications are fighting for the one CPU of the test system, resulting in high waiting times (latency) to gain access to a CPU.
prstat usage Scenario – High System Time
Let's run a system call intensive applicationand watch the output of prstat. First, start one instance of cc_sys:
prstat – system call intensive application
Then watch the prstat -m 2 output:
prstat – prstat -m 2 output for system call intensive application
Note the top line of the above output with PID 2310. One clearly identifies a high-system time usage (61%) for the process cc_sys. Also notice the high ratio of ICX/VCX (277/22) which shows that the process is frequently involuntarily context switched off the CPU.
prstat usage Scenario – Excessive Locking
Frequently, poor scaling is observed for applications on multi-processor systems. One possible root cause is badly designed locking inside the application resulting in large time spent waiting for synchronisation. The prstat column LCK reports on percentage of time spent waiting on user locks.
Let's look at an example with a sample program that implements a locking mechanism for a critical section using reader/writer locks. The programs has four (4) threads looking for access to the shared critical region as readers while one thread accesses the critical section in writer mode. To exhibit the problem, the writer has been slowed down on purpose, so that it spends some time holding the critical section (effectively barring access for the readers).
First start the program such as the writer spends zero (0) microseconds in the critical region (ideal case).
cc_lck 0 – running in ideal conditions
Now let's observe the per-thread microstates. Use prstat -mL -p 2626 2 for this.
cc_lck 0 – prstat output
One can observe, that all threads (5) are fighting almost equally for computing resources. Since nor the reader nor the writer hold the critical section for long there is no wait time registered.
Now let's restart, the whole test with a writer wait time of ten (10) microseconds.
Again, let's observe the microstates. Use prstat -mL -p 2656 2 for this.
cc_lck 10 – prstat output
Now the picture looks different. The four (4) reader threads are spending 84% of their time waiting on the lock for the critical region. The writer (LWP #1) on the other hand, is spending most of its time sleeping (82%).
While in the case of this sample application, the locking problems are obvious when looking at the source code, prstat microstate accounting capabilities can help pin-point locking weaknesses in larger applications.
Thomas Bastian was a coauthor of an earlier version of this document. The earlier version of this page has been published in the "The Developers Edge" in 2009.
- 178842 views
LCK
Does LCK contributes to User Time as reported by mpstat ?
RE:LCK
I have a process with high LCK causing kernel contention in Solaris 10 (high smtx in mpstat, high sys/user ratio, high mutex_adenters in kstat -m cpu). I can only say that in this scenario, sys time is increased because the process cannot get a mutex and it either do active wait (penalty for cpu time on user account) or otherwise wait for interruption (then probably the penalty goes in context switching and kernel processing).
jose "at" irisel.com
RE:LCK
I have a process with high LCK causing kernel contention in Solaris 10 (high smtx in mpstat, high sys/user ratio, high mutex_adenters in kstat -m cpu). I can only say that in this scenario, sys time is increased because the process cannot get a mutex and it either do active wait (penalty for cpu time on user account) or otherwise wait for interruption (then probably the penalty goes in context switching and kernel processing).