Linux效能分析-CPU上下文切換
阿新 • • 發佈：2020-08-10
前言
在Linux效能分析-平均負載中，提到過一種導致平均負載升高的情況，就是有大量程序或執行緒等待cpu排程。
為什麼大量程序或者執行緒等待CPU排程會導致負載升高呢？
當大量程序或者執行緒等待排程時，cpu需要更加頻繁的切換任務，在切換任務的過程中，需要儲存上一個任務的context到核心中，並且恢復當前任務的context，這種儲存和恢復的操作也是需要cpu來執行的，導致cpu都消耗在了 儲存上文和恢復下文這個過程中。
除了程序和執行緒導致的上下文切換以外，硬體產生的中斷事件也會導致上下文切換。並且中斷事件的優先順序是高於執行緒和程序任務的。
這篇文章會模擬測試這種情況。
必備的工具介紹
vmstat
vmstat是一個觀測總體上下文切換狀況的命令。
下面指令可以每隔5秒輸出一組資料。
[root@localhost shell]# vmstat 5 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 1 0 1544 1011512 4172 1674144 0 0 5 829 39 72 1 0 99 0 0 1 0 1544 1011380 4172 1674176 0 0 0 162 163 236 1 0 99 0 0 0 0 1544 1011412 4172 1674176 0 0 0 0 142 240 1 0 99 0 0 0 0 1544 1011412 4172 1674176 0 0 0 0 119 159 1 0 99 0 0 0 0 1544 1012404 4172 1674076 0 0 0 0 533 783 1 1 97 0 0
重點關注列含義：
- r列：就緒佇列的長度，也就是正在執行和等待cpu的任務數
- b列：處於不可中斷睡眠狀態的任務數
- in列：每秒中斷的次數
- cs列：每秒上下文切換的次數
pidstat
使用vmstat關注到了整體的情況，接下來可以使用pidstat關注具體執行緒的情況
注：pidstat -wt 可以輸出執行緒的情況
[root@localhost shell]# pidstat -w 5 Linux 3.10.0-1062.el7.x86_64 (localhost.localdomain) 2020年07月08日 _x86_64_ (4 CPU) 13時55分20秒 UID PID cswch/s nvcswch/s Command 13時55分25秒 0 9 12.48 0.00 rcu_sched 13時55分25秒 0 11 0.20 0.00 watchdog/0 13時55分25秒 0 12 0.20 0.00 watchdog/1 13時55分25秒 0 14 0.20 0.00 ksoftirqd/1 13時55分25秒 0 17 0.20 0.00 watchdog/2 13時55分25秒 0 22 0.20 0.00 watchdog/3 13時55分25秒 0 47 0.20 0.00 khugepaged 13時55分25秒 0 378 1.39 0.00 irq/16-vmwgfx 13時55分25秒 0 501 0.20 0.00 kworker/0:1H 13時55分25秒 0 1891 12.87 0.20 X 13時55分25秒 0 2175 0.20 0.00 wpa_supplicant 13時55分25秒 0 2529 0.20 0.00 ssh-agent 13時55分25秒 0 2581 14.26 0.00 gnome-shell 13時55分25秒 0 2604 0.79 0.00 ibus-daemon 13時55分25秒 0 2668 0.20 0.00 goa-identity-se 13時55分25秒 0 2756 0.99 0.00 gsd-color 13時55分25秒 0 2847 10.10 0.00 vmtoolsd 13時55分25秒 0 2947 0.20 0.00 ibus-engine-sim 13時55分25秒 0 6206 5.74 0.00 gnome-terminal- 13時55分25秒 0 6833 0.99 0.00 kworker/1:28 13時55分25秒 0 15685 0.20 0.00 fwupd 13時55分25秒 0 24573 10.10 0.00 vmtoolsd 13時55分25秒 0 24900 1.58 0.00 rngd 13時55分25秒 0 112976 1.39 0.00 kworker/3:0 13時55分25秒 0 115704 0.79 0.00 kworker/2:2 13時55分25秒 0 116180 0.99 0.00 kworker/u256:2 13時55分25秒 0 119739 3.37 0.00 kworker/0:0 13時55分25秒 0 119809 0.59 0.00 kworker/0:3 13時55分25秒 0 119826 0.20 0.00 pidstat
重點關注列含義：
- cswch/s：自願切換上下文。比如IO記憶體等系統資源不足時，任務會主動切換上下文。
- nvcswch/s：非自願上下文切換，當大量任務等待排程時，系統會強制任務上下cpu。
實際測試
系統環境：
作業系統：centos7
cpu：4核，記憶體：8g
首先安裝sysbench，使用sysbench，我們可以模擬一個程序內多執行緒排程引起的上下文切換問題。
[root@localhost shell]# yum install sysbench
安裝好後，執行下面命令
[root@localhost shell]# sysbench --num-threads=20 --max-time=300 --test=threads run
檢視下vmstat和pidstat
[root@localhost shell]# vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
12 0 1544 984260 4172 1700288 0 0 5 819 42 28 1 0 99 0 0
12 0 1544 984136 4172 1700288 0 0 0 2 64063 1469914 19 66 15 0 0
[root@localhost shell]# pidstat -wt 5
Linux 3.10.0-1062.el7.x86_64 (localhost.localdomain) 2020年07月08日 _x86_64_ (4 CPU)
14時10分21秒 UID TGID TID cswch/s nvcswch/s Command
14時10分26秒 0 119981 - 3.33 0.00 kworker/0:0
14時10分26秒 0 - 119981 3.33 0.00 |__kworker/0:0
14時10分26秒 0 120045 - 0.39 0.00 kworker/0:3
14時10分26秒 0 - 120045 0.39 0.00 |__kworker/0:3
14時10分26秒 0 - 120069 13182.55 57331.57 |__sysbench
14時10分26秒 0 - 120070 13993.33 50786.86 |__sysbench
14時10分26秒 0 - 120071 17088.63 59359.61 |__sysbench
14時10分26秒 0 - 120072 15789.22 53959.61 |__sysbench
14時10分26秒 0 - 120073 13882.35 53891.57 |__sysbench
14時10分26秒 0 - 120074 14793.33 46352.75 |__sysbench
14時10分26秒 0 - 120075 13281.18 55530.78 |__sysbench
14時10分26秒 0 - 120076 14189.80 56319.61 |__sysbench
14時10分26秒 0 - 120077 14870.39 52858.24 |__sysbench
14時10分26秒 0 - 120078 13928.04 57796.47 |__sysbench
14時10分26秒 0 - 120079 13780.39 56587.25 |__sysbench
14時10分26秒 0 - 120080 14157.65 55370.00 |__sysbench
14時10分26秒 0 - 120081 13403.14 54099.22 |__sysbench
14時10分26秒 0 - 120082 16154.31 50767.06 |__sysbench
14時10分26秒 0 - 120083 15907.45 48268.24 |__sysbench
14時10分26秒 0 - 120084 14213.53 49035.69 |__sysbench
14時10分26秒 0 - 120085 14125.29 55470.78 |__sysbench
14時10分26秒 0 - 120086 13912.16 54188.63 |__sysbench
14時10分26秒 0 - 120087 14980.59 49492.55 |__sysbench
14時10分26秒 0 - 120088 15290.39 55748.24 |__sysbench
14時10分26秒 0 120102 - 0.20 1.18 pidstat
14時10分26秒 0 - 120102 0.20 1.18 |__pidstat
[root@localhost shell]# pidstat -u 5 5
Linux 3.10.0-1062.el7.x86_64 (localhost.localdomain) 2020年07月08日 _x86_64_ (4 CPU)
14時31分22秒 UID PID %usr %system %guest %CPU CPU Command
14時31分27秒 0 1891 0.40 0.00 0.00 0.40 0 X
14時31分27秒 0 2581 0.80 0.20 0.00 1.00 0 gnome-shell
14時31分27秒 0 120701 69.26 100.00 0.00 100.00 2 sysbench
14時31分27秒 0 120722 0.00 0.20 0.00 0.20 1 pidstat
14時31分27秒 UID PID %usr %system %guest %CPU CPU Command
14時31分32秒 0 1891 0.40 0.20 0.00 0.60 0 X
14時31分32秒 0 2581 0.80 0.20 0.00 1.00 1 gnome-shell
14時31分32秒 0 6206 0.00 0.20 0.00 0.20 0 gnome-terminal-
14時31分32秒 0 120701 70.20 100.00 0.00 100.00 2 sysbench
14時31分32秒 0 120722 0.20 0.20 0.00 0.40 1 pidstat
觀察vmstat結果，可以看到
- 系統整體的cs列和in列都發生了顯著的提高。
- cpu使用率，使用者程序使用率us=19% 和系統程序使用率sy=66%，加起來達到了85%，並且sy佔用了大頭，說明更多的cpu消耗在了執行系統程序。
觀察pidstat兩類結果，可以發現
- sysbench程序下的子執行緒，cswsh和nvcswsh的數值都很高，其中非自願切換次數遠大於自願切換次數。
- %user（該程序在使用者空間對cpu的使用率）和%system（該程序在系統空間對cpu的使用率）更是達到了70.20和100.00，說明系統資源大部分都被這個程序所佔用。
整體結果符合我們的預期。
針對in列顯著提高，可以檢視 /proc/interrupts 檔案，裡面記錄了中斷相關的資料，這些資料記錄的是從上次啟動到現在的累加值。
我們把系統重新啟動下，看下空閒狀態下的檔案
NMI: 0 0 0 0 Non-maskable interrupts
LOC: 28984 32366 32128 34741 Local timer interrupts
SPU: 0 0 0 0 Spurious interrupts
PMI: 0 0 0 0 Performance monitoring interrupts
IWI: 353 420 266 154 IRQ work interrupts
RTR: 0 0 0 0 APIC ICR read retries
RES: 24371 25023 24748 22077 Rescheduling interrupts
CAL: 6516 7288 6917 7134 Function call interrupts
TLB: 1706 1874 1598 1534 TLB shootdowns
TRM: 0 0 0 0 Thermal event interrupts
THR: 0 0 0 0 Threshold APIC interrupts
DFR: 0 0 0 0 Deferred Error APIC interrupts
MCE: 0 0 0 0 Machine check exceptions
MCP: 2 2 2 2 Machine check polls
ERR: 0
MIS: 0
PIN: 0 0 0 0 Posted-interrupt notification event
NPI: 0 0 0 0 Nested posted-interrupt event
PIW: 0 0 0 0 Posted-interrupt wakeup event
當執行sysbench命令後，並執行一段時間後，該檔案如下
NMI: 0 0 0 0 Non-maskable interrupts
LOC: 90200 96701 93600 97704 Local timer interrupts
SPU: 0 0 0 0 Spurious interrupts
PMI: 0 0 0 0 Performance monitoring interrupts
IWI: 616 666 505 450 IRQ work interrupts
RTR: 0 0 0 0 APIC ICR read retries
RES: 1028166 1012515 1035222 1028515 Rescheduling interrupts
CAL: 6526 7306 6963 7134 Function call interrupts
TLB: 1753 1946 1680 1661 TLB shootdowns
TRM: 0 0 0 0 Thermal event interrupts
THR: 0 0 0 0 Threshold APIC interrupts
DFR: 0 0 0 0 Deferred Error APIC interrupts
MCE: 0 0 0 0 Machine check exceptions
MCP: 3 3 3 3 Machine check polls
ERR: 0
MIS: 0
PIN: 0 0 0 0 Posted-interrupt notification event
NPI: 0 0 0 0 Nested posted-interrupt event
PIW: 0 0 0 0 Posted-interrupt wakeup event
其中，LOC和RES顯著升高
RES表示，喚醒空閒狀態的CPU來排程新的任務執行，和我們模擬的過多工排程有關。
LOC不太理解，暫時先放在這裡。