Monitoring Context Switching in a Linux Process

As I learn about systems performance, one question that often arises is who is responsible for the context switching on a system. In Linux, the number of context switches per second is displayed by vmstat. To see this information every second, for example, run vmstat 1. Here is sample output from my Ubuntu 22.04 VM showing about 50000 context switches per sec. I used the -SM option to display memory info in Megabytes (which reduces the amount of output per line). The last (optional) argument is the number of updates (lines) to be displayed.

saint@ubuntuvm:~$ vmstat -SM 1 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 2  0      0   4603    386   5176    0    0     1     5   16    7 35  6 59  0  0
 4  0      0   4603    386   5176    0    0     0    88 20031 45649 51  8 41  0  0
 4  0      0   4603    386   5176    0    0     0     0 23768 52532 49  8 43  0  0
 4  0      0   4603    386   5176    0    0     0     0 23826 52931 49  7 43  0  0
 5  0      0   4603    386   5176    0    0     0     0 23328 51731 49  9 43  0  0

Use pidstat to get a per-process breakdown of context switches per second. Like vmstat, a report delay and a report count can be specified. Without specifying any specific flags, the default output is a breakdown of CPU usage.

saint@ubuntuvm:~$ pidstat 1 5
...
Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:      129       691    0.40    0.00    0.00    0.00    0.40     -  mysqld
Average:     1000       896    0.60    0.40    0.00    0.00    1.00     -  Xorg
Average:     1000      1161    2.20    0.40    0.00    0.20    2.59     -  gnome-shell
Average:     1000     23655    0.40    0.00    0.00    0.20    0.40     -  gnome-terminal-
Average:     1000     23822    0.60    0.20    0.00    0.00    0.80     -  code
Average:     1000     23880    0.20    0.00    0.00    0.00    0.20     -  code
Average:     1000     23907    0.20    0.00    0.00    0.00    0.20     -  code
Average:     1000     33819    0.80    0.20    0.00    0.00    1.00     -  firefox
Average:     1000   1149158    1.40    0.20    0.00    0.00    1.60     -  Isolated Web Co
Average:     1000   1218546  294.81   37.52    0.00    0.00  332.34     -  java
Average:     1000   1227240    0.20    0.80    0.00    0.00    1.00     -  pidstat

For our purposes, we need to specify the -w flag to report task switching activity. After the specified number of reports have been displayed, the average number of context switches (voluntary and involuntary) are displayed.

saint@ubuntuvm:~$ pidstat -w 1 5
Linux 5.19.0-45-generic (ubuntuvm) 	07/03/2023 	_x86_64_	(6 CPU)

<5 reports truncated>

Average:      UID       PID   cswch/s nvcswch/s  Command
Average:        0         1      0.20      0.00  systemd
Average:        0        14      0.60      0.00  ksoftirqd/0
Average:        0        15     28.94      0.00  rcu_preempt
Average:        0        16      0.20      0.00  migration/0
Average:        0        22      0.20      0.00  migration/1
Average:        0        23      0.20      0.00  ksoftirqd/1
Average:        0        28      0.20      0.00  migration/2
Average:        0        29      0.60      0.00  ksoftirqd/2
Average:        0        34      0.20      0.00  migration/3
Average:        0        35      1.80      0.00  ksoftirqd/3
Average:        0        40      0.60      0.00  migration/4
Average:        0        41      1.00      0.00  ksoftirqd/4
Average:        0        46      0.20      0.00  migration/5
Average:        0        47      0.60      0.00  ksoftirqd/5
Average:        0        58      1.80      0.00  kcompactd0
Average:        0       195      0.40      0.00  kworker/1:1H-kblockd
Average:        0       210      0.60      0.00  kworker/4:1H-kblockd
Average:        0       238      0.60      0.20  jbd2/sda2-8
Average:        0       369      1.00      0.00  hv_balloon
Average:      108       484      3.99      0.00  systemd-oomd
Average:      101       485      0.60      0.00  systemd-resolve
Average:        0       523      0.20      0.00  acpid
Average:        0       576      0.20      0.00  wpa_supplicant
Average:     1000       896     81.44      0.00  Xorg
Average:     1000      1161     63.67     15.17  gnome-shell
Average:     1000     23655     97.60      0.80  gnome-terminal-
Average:     1000     23719      0.40      0.00  code
Average:     1000     23782      0.20      0.00  code
Average:     1000     23822      9.78      0.60  code
Average:     1000     23880      0.40      0.00  code
Average:     1000     23906      1.40      0.00  code
Average:     1000     23907      3.39      0.40  code
Average:     1000     23936      1.60      0.00  code
Average:     1000     23954      0.20      0.00  code
Average:     1000     24009      0.20      0.00  code
Average:     1000     24019      0.20      0.00  code
Average:     1000     33819      6.99      0.00  firefox
Average:     1000     34122      0.20      0.00  Privileged Cont
Average:        0    988101      4.99      0.00  kworker/0:1-mm_percpu_wq
Average:        0    993536      6.19      0.00  kworker/5:1-mm_percpu_wq
Average:        0   1124417      4.39      0.00  kworker/4:1-events
Average:        0   1148363      4.59      0.00  kworker/2:0-mm_percpu_wq
Average:        0   1148688      3.79      0.00  kworker/1:2-mm_percpu_wq
Average:        0   1149149      2.79      0.00  kworker/3:2-events
Average:     1000   1149158     61.88      2.00  Isolated Web Co
Average:     1000   1149675     10.38      6.19  Isolated Web Co
Average:     1000   1152215      0.40      0.00  code
Average:        0   1223207     71.26      0.00  kworker/u12:1-events_unbound
Average:        0   1226506     37.13      0.00  kworker/u12:3-writeback
Average:        0   1227384     27.94      0.00  kworker/u12:4-events_unbound
Average:     1000   1228275      1.00     17.96  pidstat

I happened to have my factorization Java application running on this VM. Interestingly, it does not appear in this output despite the fact that the time command displays a large number of context switches for this application. To see this, set up the application as described in the next section.

Running a Sample Multithreaded Application

Clone the scratchpad repo then compile and launch the factorization application using these instructions (with any necessary changes to the JAVA_HOME path):

# Download a Java build if necessary
mkdir -p ~/java/binaries/jdk/x64
cd ~/java/binaries/jdk/x64
wget https://aka.ms/download-jdk/microsoft-jdk-17.0.7-linux-x64.tar.gz
tar xzf microsoft-jdk-17.0.7-linux-x64.tar.gz

# Set the JAVA_HOME environment variable
export JAVA_HOME=~/java/binaries/jdk/x64/jdk-17.0.7+7

# Get the Factorization source code
mkdir ~/repos
cd ~/repos
git clone https://github.com/swesonga/scratchpad
cd scratchpad/demos/java/FindPrimes

# Compile the factorization source code
$JAVA_HOME/bin/javac Factorize.java

# Factorize a number and display task statistics
/usr/bin/time -v $JAVA_HOME/bin/java Factorize 897151542039582592342572091 CUSTOM_THREAD_COUNT_VIA_THREAD_CLASS 6

Notice the context switching statistics when the command completes:

	Command being timed: "/home/saint/java/binaries/jdk/x64/jdk-20+36/bin/java Factorize 897151542039582592342572091 CUSTOM_THREAD_COUNT_VIA_THREAD_CLASS 6"
	User time (seconds): 37.59
	System time (seconds): 6.47
	Percent of CPU this job got: 363%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:12.12
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 298576
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 8
	Minor (reclaiming a frame) page faults: 70247
	Voluntary context switches: 367393
	Involuntary context switches: 1337
	Swaps: 0
	File system inputs: 0
	File system outputs: 64
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0

Per-Thread Task Switching Information

How can get some insight into the context switching in the Java process? We can also display statistics for threads associated with selected tasks using the -t option. We now get insight into Java’s contribution to context switching:

saint@ubuntuvm:~$ pidstat -w -t 1 5
Average:      UID      TGID       TID   cswch/s nvcswch/s  Command
Average:        0        14         -      1.58      0.00  ksoftirqd/0
Average:        0         -        14      1.58      0.00  |__ksoftirqd/0
Average:        0        15         -     32.94      0.00  rcu_preempt
Average:        0         -        15     32.94      0.00  |__rcu_preempt
Average:        0        16         -      0.39      0.00  migration/0
Average:        0         -        16      0.39      0.00  |__migration/0
Average:        0        22         -      0.20      0.00  migration/1
Average:        0         -        22      0.20      0.00  |__migration/1
...
Average:     1000     24546     24549      0.99      0.00  (java)__VM Thread
Average:     1000         -     24554      0.99      0.00  |__Monitor Deflati
Average:     1000         -     24555      0.20      0.00  |__C2 CompilerThre
Average:     1000         -     24556      0.20      0.00  |__C1 CompilerThre
Average:     1000         -     24562     20.12      0.00  |__VM Periodic Tas
Average:     1000         -     24610      0.20      0.00  |__pool-2-thread-1
Average:     1000         -     24704      2.17      0.00  |__Attach Listener
...
Average:        0   1232414         -    641.22      0.00  kworker/u12:0-events_unbound
Average:        0         -   1232414    641.22      0.00  |__kworker/u12:0-events_unbound
Average:        0   1234513         -    174.16      0.00  kworker/u12:2-events_unbound
Average:        0         -   1234513    174.16      0.00  |__kworker/u12:2-events_unbound
Average:        0   1236229         -    703.94      0.00  kworker/u12:3-ext4-rsv-conversion
Average:        0         -   1236229    703.94      0.00  |__kworker/u12:3-ext4-rsv-conversion
Average:     1000   1236678   1236680     66.27      0.20  (java)__GC Thread#0
Average:     1000         -   1236684     16.96      0.00  |__G1 Service
Average:     1000         -   1236685     56.21      1.58  |__VM Thread
Average:     1000         -   1236690      0.99      0.00  |__Monitor Deflati
Average:     1000         -   1236691      0.20      0.00  |__C2 CompilerThre
Average:     1000         -   1236692      0.20      0.00  |__C1 CompilerThre
Average:     1000         -   1236694     20.12      0.00  |__VM Periodic Tas
Average:     1000         -   1236697     22.68     20.71  |__Thread-0
Average:     1000         -   1236698     24.26    172.98  |__Thread-1
Average:     1000         -   1236699     24.65    170.22  |__Thread-2
Average:     1000         -   1236700     22.09    219.92  |__Thread-3
Average:     1000         -   1236701     65.48      1.18  |__GC Thread#1
Average:     1000         -   1236702     64.69      0.59  |__GC Thread#2
Average:     1000         -   1236703     62.13      0.39  |__GC Thread#3
Average:     1000         -   1236704     64.50      0.20  |__GC Thread#4
Average:     1000         -   1236705     64.50      0.20  |__GC Thread#5
Average:     1000   1236750         -      0.99   1119.72  pidstat
Average:     1000         -   1236750      0.99   1119.72  |__pidstat

Per-Process Task Switching Information

Given the large number of tasks on the system, it may be helpful to focus on Java alone. Running jps shows the pids of the Java processes running. We can pass the PID of interest to pidstat. Only context switches for that process will now be displayed, e.g.

saint@ubuntuvm:~$ pidstat -w -t -p 1236678 1 5
...
Average:     1000   1236678         -      0.00      0.00  java
Average:     1000         -   1236678      0.00      0.00  |__java
Average:     1000         -   1236679      0.00      0.00  |__java
Average:     1000         -   1236680     64.00      0.00  |__GC Thread#0
Average:     1000         -   1236681      0.00      0.00  |__G1 Main Marker
Average:     1000         -   1236682      0.00      0.00  |__G1 Conc#0
Average:     1000         -   1236683      0.00      0.00  |__G1 Refine#0
Average:     1000         -   1236684     18.00      0.00  |__G1 Service
Average:     1000         -   1236685     56.00      5.40  |__VM Thread
Average:     1000         -   1236686      0.00      0.00  |__Reference Handl
Average:     1000         -   1236687      0.00      0.00  |__Finalizer
Average:     1000         -   1236688      0.00      0.00  |__Signal Dispatch
Average:     1000         -   1236689      0.00      0.00  |__Service Thread
Average:     1000         -   1236690      1.00      0.00  |__Monitor Deflati
Average:     1000         -   1236691      0.20      0.00  |__C2 CompilerThre
Average:     1000         -   1236692      0.20      0.00  |__C1 CompilerThre
Average:     1000         -   1236693      0.00      0.00  |__Notification Th
Average:     1000         -   1236694     20.20      0.00  |__VM Periodic Tas
Average:     1000         -   1236695      0.00      0.00  |__Common-Cleaner
Average:     1000         -   1236697     17.80      7.60  |__Thread-0
Average:     1000         -   1236698     20.00      8.60  |__Thread-1
Average:     1000         -   1236699     21.40     12.00  |__Thread-2
Average:     1000         -   1236700     17.80      9.40  |__Thread-3
Average:     1000         -   1236701     64.40      0.20  |__GC Thread#1
Average:     1000         -   1236702     63.20      0.20  |__GC Thread#2
Average:     1000         -   1236703     66.20      0.00  |__GC Thread#3
Average:     1000         -   1236704     63.80      0.20  |__GC Thread#4
Average:     1000         -   1236705     63.60      0.20  |__GC Thread#5

The pidstat man page describes lots of other options that can be used to customize the output.