Categories:
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 0Use 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 - pidstatFor 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 pidstatI 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 6Notice 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: 0Per-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 |__pidstatPer-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#5The pidstat man page describes lots of other options that can be used to customize the output.
Leave a Reply