使用Trace-Event解决系统不能深度睡眠的问题，


本文转载自微信公众号「相遇Linux」，作者JeffXie。转载本文请联系相遇Linux公众号。 

最近遇到一个问题，系统不能睡眠到c7s, 只能睡眠到c3. (c-state不能到c7s, cpu的c-state, c0是运行态，其它状态都是idle态，睡眠的越深，c-state的值越大)

这时候第一感觉是不是系统很忙导致, 使用pert top看一下耗cpu的进程和热点函数：

  1. perf top -E 100 --stdio > perf-top.txt 
  2.  
  3.     19.85%  perf                  [.] __symbols__insert 
  4.      7.68%  perf                  [.] rb_next 
  5.      4.60%  libc-2.26.so          [.] __strcmp_sse2_unaligned 
  6.      4.20%  libelf-0.168.so       [.] gelf_getsym 
  7.      3.92%  perf                  [.] dso__load_sym 
  8.      3.86%  libc-2.26.so          [.] _int_malloc 
  9.      3.60%  libc-2.26.so          [.] __libc_calloc 
  10.      3.30%  libc-2.26.so          [.] vfprintf 
  11.      2.95%  perf                  [.] rb_insert_color 
  12.      2.61%  [kernel]              [k] prepare_exit_to_usermode 
  13.      2.51%  perf                  [.] machine__map_x86_64_entry_trampolines 
  14.      2.31%  perf                  [.] symbol__new 
  15.      2.22%  [kernel]              [k] do_syscall_64 
  16.      2.11%  libc-2.26.so          [.] __strlen_avx2 

发现系统中只有perf工具本身比较耗cpu :(

然后就想到是不是系统中某个进程搞的鬼，不让cpu睡眠到c7s. 这时候使用trace event监控一下系统中sched_switch事件. 使用trace-cmd工具监控所有cpu上的sched_switch(进程切换)事件30秒:

  1. #trace-cmd record -e sched:sched_switch -M -1 sleep 30 
  2.  
  3. CPU0 data recorded at offset=0x63e000 
  4.     102400 bytes in size 
  5. CPU1 data recorded at offset=0x657000 
  6.     8192 bytes in size 
  7. CPU2 data recorded at offset=0x659000 
  8.     20480 bytes in size 
  9. CPU3 data recorded at offset=0x65e000 
  10.     20480 bytes in size 

使用trace-cmd report 查看一下监控结果，但是查看这样的原始数据不够直观，没有某个进程被切换到的统计信息:

  1. #trace-cmd report 
  2.  
  3. cpus=4 
  4.        trace-cmd-19794 [001] 225127.464466: sched_switch:         trace-cmd:19794 [120] S ==> swapper/1:0 [120] 
  5.        trace-cmd-19795 [003] 225127.464601: sched_switch:         trace-cmd:19795 [120] S ==> swapper/3:0 [120] 
  6.            sleep-19796 [002] 225127.464792: sched_switch:         sleep:19796 [120] S ==> swapper/2:0 [120] 
  7.           <idle>-0     [003] 225127.471948: sched_switch:         swapper/3:0 [120] R ==> rcu_sched:11 [120] 
  8.        rcu_sched-11    [003] 225127.471950: sched_switch:         rcu_sched:11 [120] W ==> swapper/3:0 [120] 
  9.           <idle>-0     [003] 225127.479959: sched_switch:         swapper/3:0 [120] R ==> rcu_sched:11 [120] 
  10.        rcu_sched-11    [003] 225127.479960: sched_switch:         rcu_sched:11 [120] W ==> swapper/3:0 [120] 
  11.           <idle>-0     [003] 225127.487959: sched_switch:         swapper/3:0 [120] R ==> rcu_sched:11 [120] 
  12.        rcu_sched-11    [003] 225127.487961: sched_switch:         rcu_sched:11 [120] W ==> swapper/3:0 [120] 
  13.           <idle>-0     [002] 225127.491959: sched_switch:         swapper/2:0 [120] R ==> kworker/2:2:19735 [120] 
  14.      kworker/2:2-19735 [002] 225127.491972: sched_switch:         kworker/2:2:19735 [120] W ==> swapper/2:0 [120] 

trace-cmd report 的结果使用正则表达式过滤一下，然后排序统计：

  1. trace-cmd report | grep -o '==> [^ ]\+:\?' | sort | uniq -c 
  2.       3 ==> irqbalance:1034 
  3.       3 ==> khugepaged:43 
  4.      20 ==> ksoftirqd/0:10 
  5.       1 ==> ksoftirqd/1:18 
  6.      18 ==> ksoftirqd/3:30 
  7.       1 ==> kthreadd:19798 
  8.       1 ==> kthreadd:2 
  9.       4 ==> kworker/0:0:19785 
  10.       1 ==> kworker/0:1:19736 
  11.       5 ==> kworker/0:1:19798 
  12.       5 ==> kworker/0:1H:364 
  13.      53 ==> kworker/0:2:19614 
  14.      19 ==> kworker/1:1:7665 
  15.      30 ==> tuned:19498 
  16.      ...           

发现可疑线程tuned，30秒内被切换到运行了30次，其它线程都是常规线程。

此时查看一下系统中是否开启了tuned服务:

果真是系统开启了tuned服务，然后拉起了名字为tuned的线程.

查看一下tuned服务的配置文件：

  1. localhost:/home/jeff # tuned-adm active  
  2. Current active profile: sap-hana 
  3. localhost:/home/jeff # cat /usr/lib/tuned/sap-hana/tuned.conf  
  4. [main] 
  5. summary=Optimize for SAP NetWeaver, SAP HANA and HANA based products 
  6. [cpu] 
  7. force_latency = 70 

发现关于cpu这一项，设置强制延迟时间为70秒 force_latency = 70 ,这个是为了优化HANA数据库。

到底force_latency怎样起作用，经过一顿搜索，发现这个值是被设置进了/dev/cpu_dma_latency

使用lsof /dev/cpu_dma_latency, 发现tuned线程确实是在操作这个文件

  1. #lsof /dev/cpu_dma_latency 
  2. COMMAND   PID USER   FD   TYPE DEVICE SIZE/OFF  NODE NAME 
  3. tuned   18734 root    9w   CHR  10,60      0t0 11400 /dev/cpu_dma_latency 

而且Linux内核文档也说明了/dev/cpu_dma_latency文件,如果要对它进行写操作，要open之后写数据之后不close,如果释放掉了文件描述符它就又会恢复到默认值，这也印证了上面lsof /dev/cpu_dma_latency是有输出结果的.

  1. https://github.com/torvalds/linux/blob/v5.8/Documentation/trace/coresight/coresight-cpu-debug.rst 
  2. As specified in the PM QoS documentation the requested parameter  
  3. will stay in effect until the file descriptor is released. For example: 
  4. # exec 3<> /dev/cpu_dma_latency; echo 0 >&3 
  5. ... 
  6. Do some work... 
  7. ... 
  8. # exec 3<>- 

查看一下/dev/cpu_dma_latency文件的内容，确实是70，也就是(force_latency = 70)

  1. localhost:/home/jeff # cat /dev/cpu_dma_latency | hexdump -Cv  
  2. 00000000  46 00 00 00                                       |F...| 
  3. localhost:/home/jeff # echo $((0x46)) 
  4. 70 

此时查看一下系统中cpu各个睡眠态的描述和延迟时间值:

  1. # cd /sys/devices/system/cpu/cpu0/cpuidle/ 
  2. # for state in * ; do 
  3. echo -e \ 
  4. "STATE: $state\t\ 
  5. DESC: $(cat $state/desc)\t\ 
  6. NAME: $(cat $state/name)\t\ 
  7. LATENCY: $(cat $state/latency)\t\ 
  8. RESIDENCY: $(cat $state/residency)" 
  9. done 

发现C3态的延迟时间是33微秒，C4的延时时间是133微秒，所以(force_latency = 70) ，

系统就只能睡眠到C3了 .(延迟时间就是从此睡眠态唤醒到运行态的时间)

  1. STATE: state0    DESC: CPUIDLE CORE POLL IDLE    NAME: POLL  LATENCY: 0  RESIDENCY: 0 
  2. STATE: state1    DESC: MWAIT 0x00    NAME: C1    LATENCY: 2  RESIDENCY: 2 
  3. STATE: state2    DESC: MWAIT 0x01    NAME: C1E   LATENCY: 10 RESIDENCY: 20 
  4. STATE: state3    DESC: MWAIT 0x10    NAME: C3    LATENCY: 33 RESIDENCY: 100 
  5. STATE: state4    DESC: MWAIT 0x20    NAME: C6    LATENCY: 133    RESIDENCY: 400 
  6. STATE: state5    DESC: MWAIT 0x32    NAME: C7s   LATENCY: 166    RESIDENCY: 500 

此时关闭tuned 服务, 再查看一下 /dev/cpu_dma_latency的值，变成了默认的2000秒

  1. localhost:/home/jeff # tuned-adm off 
  2. localhost:/home/jeff # cat /dev/cpu_dma_latency | hexdump -Cv  
  3. 00000000  00 94 35 77                                       |..5w| 
  4. localhost:/home/jeff # echo $((0x77359400)) 
  5. 2000000000 

然后验证一下，此时系统可以睡眠到C7s了，此问题得到解决 :)

解决此问题，主要用到了Linux内核本身提供的trace-event.

所以任何一个功能都不能小看，内核就是这样，一般看上去很无聊的功能，被一些工程师用很认真的态度打磨出来之后，潜力还是非常大的:)

相关内容