perf sched查看调度延迟与唤醒延迟

ftrace也可以通过内核中固定的调度相关的tracepoint来记录线程的调度信息，但ftrace只能抓到调度的原始数据（线程调度切换流程），不能提供统计分析功能，只提供类似于perf sched script的功能。perf也是利用内核中固定的调度trcepoint，但perf提供了统计分析功能，例如可以查看某段时间内的最大调度延迟等信息。

1，perf sched record

2，perf sched latency --sort max

如下某段时间内的最大调度延迟是0.467ms，调度性能较好。

所谓调度延迟的意义：

如下图所示，线程sh（pid=17030）在.918368秒被别的线程唤醒（被唤醒在本核 或者 通过IPI唤醒到其他核 或者 若其他核正处于idle就设置NEED_RESCHED，这样idle线程就能POLLING到有新线程要在本核上运行），sched_wakeup表示该线程被唤醒在cpu2上，即将该线程放在cpu2上的运行队列上（对于normal线程来说是CFS调度算法的红黑树的叶子节点上，根据vruntime的值）。.948070秒的sched_switch表示该线程17030才真正在cpu2上投入运行。

即线程17030从ready（放在cpu2运行队列的那个时刻）到开始真正在cpu2上运行的延迟是29ms。

存在调度延迟的原因可能是：

1，即使线程17030的vruntime比cpu2上正在运行线程的vruntime小，但两者的vruntime差值小于最小抢占粒度（sched_wakeup_granularity_ns），所以不能立即抢占cpu2上当前正在运行的线程。要等当前线程运行结束，即在cpu2的时钟中断或中断返回用户空间(通用centos内核不支持内核抢占)时判断是否选择新线程（可能是线程17030，也可能不是）运行。

2，cpu2上当前正在运行的线程已运行的时间还小于最小运行时间（sched_min_granularity_ns），为防止切换太频繁，所以不能切换17030线程运行；

3，唤醒抢占的feature关闭，即sched_features中WAKEUP_PREEMPT特性关闭，不允许唤醒抢占

另外可通过如下命令图形化的查看线程调度情况：

perf timechart record #几秒后ctl+c中断

perf timechart #结果输出在当前目录中，文件output.svg

perf sched timehist

perf sched timehist 功能是 Linux 4.10 加入的（https://lore.kernel.org/patchwork/patch/738098/），可以按照调度事件查看任务等待被唤醒的时间 (wait time) 和任务从被唤醒之后到运行态的调度延迟，同时也显示了调度延迟。wait time可以查看线程因等待资源（锁，信号量等）而消耗的时间：

也可以加更多的参数，如：perf sched timehist -MVw，可以显示更多的选项。

 

其他perf用法可查看：

http://www.brendangregg.com/blog/2017-03-16/perf-sched.html

https://blog.gmem.cc/perf：

性能剖析

Shell

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34

# 以99HZ的频率剖析指定的命令，默认情况下工作在Per-thread模式 perf record -F 99 command   # 以99HZ的频率剖析指定的PID perf record -F 99 -p PID # 以99HZ的频率剖析指定的PID，持续10秒 perf record -F 99 -p PID sleep 10 # 以99HZ的频率剖析整个系统 perf record -F 99 -ag -- sleep 10   # 基于事件发生次数，而非采样频率来指定采样周期 perf record -e retired_instructions:u -c 2000   # 进行栈追踪（通过Frame Pointer） perf record -F 99 -p PID -g -- sleep 10 # 进行栈追踪（通过DWARF） perf record -F 99 -p PID --call-graph dwarf sleep 10 # 全局性栈追踪 perf record -F 99 -ag -- sleep 10  # 4.11之前 perf record -F 99 -g -- sleep 10   # 4.11之后 # 追踪某个容器的栈 perf record -F 99 -e cpu-clock --cgroup=docker/1d567f4393190204...etc... -a -- sleep 10   # 每发生10000次L1缓存丢失，进行一次采样 perf record -e L1-dcache-load-misses -c 10000 -ag -- sleep 5 # 每发生以100次最后级别的CPU缓存丢失，进行一次采用 perf record -e LLC-load-misses -c 100 -ag -- sleep 5   # 采样内核指令 perf record -e cycles:k -a -- sleep 5 # 采用用户指令 perf record -e cycles:u -a -- sleep 5 # 精确采样用户指令，基于PEBS perf record -e cycles:up -a -- sleep 5

静态追踪

Shell

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45

# 追踪新进程的创建 perf record -e sched:sched_process_exec -a   # 追踪上下文切换 perf record -e context-switches -a perf record -e context-switches -c 1 -a perf record -e context-switches -ag # 追踪通过sched跟踪点的上下文切换 perf record -e sched:sched_switch -a   # 追踪CPU迁移 perf record -e migrations -a -- sleep 10   # 追踪所有connect调用（出站连接） perf record -e syscalls:sys_enter_connect -ag # 追踪所有accepts调用（入站连接） perf record -e syscalls:sys_enter_accept* -ag   # 追踪所有块设备请求 perf record -e block:block_rq_insert -ag # 追踪所有块设备发起和完成 perf record -e block:block_rq_issue -e block:block_rq_complete -a # 追踪100KB（200扇区）以上的块操作完成 perf record -e block:block_rq_complete --filter 'nr_sector > 200' # 追踪所有同步写操作的完成 perf record -e block:block_rq_complete --filter 'rwbs == "WS"' # 追踪所有写操作的完成 perf record -e block:block_rq_complete --filter 'rwbs ~ "*W*"'   # 采样Minor faults（RSS尺寸增加） perf record -e minor-faults -ag perf record -e minor-faults -c 1 -ag # 采样页面错误 perf record -e page-faults -ag   # 追踪所有Ext4调用，并把结果写入到非Ext4分区 perf record -e 'ext4:*' -o /tmp/perf.data -a   # 追踪kswapd唤醒事件 perf record -e vmscan:mm_vmscan_wakeup_kswapd -ag   # 添加Node.js USDT 探针，要求Linux 4.10+ perf buildid-cache --add `which node` # 跟踪Node.js http__server__request USDT事件 perf record -e sdt_node:http__server__request -a