PREEMPT RT LINUX系统pmqtest两个案例

mick.li

已于 2023-06-07 15:00:47 修改

阅读量503

点赞数 1

文章标签： linux 开源软件

于 2023-06-07 14:13:04 首次发布

本文链接：https://blog.csdn.net/kkqier/article/details/131082353

版权

1. pmqtest原理简单介绍：

测试程序中有两个线程：sender、receiver，两个消息队列：syncmq、testmq。syncmq用来通知sender线程每个循环的开始时间，testmq用来计算消息从mq_send()到mq_receive()之间的时间。

具体原理如下（默认一对线程）：

主线程初始化两个消息队列syncmq、testmq，建立两个子线程receiver、sender，然后每隔50ms打印一次测试结果，包括最小时间、当前循环计算的时间、最大时间；
receiver线程中会通过clock_nanosleep系统调用休眠一段时间（可通过“-i”参数指定），休眠结束后通过mq_send()发送syncmsg，唤醒sender线程，然后调用mq_receive()，阻塞休眠等待testmq中的testmsg消息；
sender线程唤醒得到调度后，首先通过gettimeofday记录开始时间sent，然后调用mq_send()，发送消息testmsg到消息队列testmq；最后调用mq_receive()，阻塞休眠等待下一个loop的syncmsg消息；
testmq中有消息后，接收线程receiver被唤醒，开始运行后，记录结束时间received；
在receiver线程中，通过计算received - sent时间，得出本次loop的消息传递时间；
receiver线程执行clock_nanosleep休眠，准备下一个loop。

2. 分析定位方法：

使用ftrace工具进行定位分析。

由于项目上系统深度裁剪，不支持trace-cmd工具，所以通过直接操作ftrace设备节点的方式，抓取ftrace event log命令如下：

/* 挂载debugfs */
mount -t debugfs none /sys/kernel/debug/

/* 使能所有event */
echo 1 > /sys/kernel/debug/tracing/events/enable

/* 抓取cpu1上ftrace event，保存到log文件 */
cat /sys/kernel/debug/tracing/per_cpu/cpu1trace_pipe > log &

/* 使能ftrace功能，抓取event log */
echo 1 > /sys/kernel/debug/tracing/tracing_on

/* 执行测试命令，当最大值大于40us后跳出，然后关闭ftrace */
pmqtest -p 99 -i 1000 -l 300000 -b 40 -a1;echo 0 > /sys/kernel/debug/tracing/tracing_on

/* kill 掉抓取log命令 */
Kill “cat cmd”

3. 案例分析

3.1 案例1

此场景：通过循环读写内存工具将测试工具pmqtest所运行的CPU核压倒100%情况下，pmqtest设置绑核，pmqtes最大值47us左右。

原因：arch_timer中断处理耗时25us左右。

log具体分析如下：

********************* LOG1 START*********************************

// MICK_START(arch_timer):：receiver线程中nanosleep设置的定时器超时，产生arch_timer中断

d2000v_l2_demo.-365   [001] d..h...  3287.355589: irq_handler_entry: irq=3 name=arch_timer

d2000v_l2_demo.-365   [001] d..h1..  3287.355592: hrtimer_cancel: hrtimer=00000000e1325509

d2000v_l2_demo.-365   [001] d..h...  3287.355594: hrtimer_expire_entry: hrtimer=00000000e1325509 function=hrtimer_wakeup now=3287349941596

// MICK: 定时器arch_timer中断处理中唤醒了任务pmqtest-502，即receiver线程

d2000v_l2_demo.-365   [001] d..h1..  3287.355595: sched_waking: comm=pmqtest pid=502 prio=0 target_cpu=001

d2000v_l2_demo.-365   [001] dn.h2..  3287.355599: sched_wakeup: comm=pmqtest pid=502 prio=0 target_cpu=001

d2000v_l2_demo.-365   [001] dn.h...  3287.355600: hrtimer_expire_exit: hrtimer=00000000e1325509

d2000v_l2_demo.-365   [001] dn.h...  3287.355601: irq_handler_exit: irq=3 ret=handled

// MICK_END(arch_timer)： arch_timer中断处理结束。

// MICK: 从中断处理返回时，检查到TIF_NEED_RESCHED标志被设置，需要进行任务切换。

d2000v_l2_demo.-365   [001] dn..1..  3287.355603: rcu_utilization: Start context switch

d2000v_l2_demo.-365   [001] dn..1..  3287.355604: rcu_utilization: End context switch

d2000v_l2_demo.-365   [001] dn..2..  3287.355605: sched_stat_runtime: comm=d2000v_l2_demo. pid=365 runtime=996145 [ns] vruntime=3119271661844 [ns]

// MICK：从当前任务d2000v_l2_demo.-365切换到任务pmqtest-502，即receiver线程

d2000v_l2_demo.-365   [001] d...2..  3287.355607: sched_switch: prev_comm=d2000v_l2_demo. prev_pid=365 prev_prio=120 prev_state=R ==> next_comm=pmqtest next_pid=502 next_prio=0

         pmqtest-502   [001] d...2..  3287.355611: ipi_entry: (IRQ work interrupts)

         pmqtest-502   [001] d..h2..  3287.355612: softirq_raise: vec=1 [action=TIMER]

         pmqtest-502   [001] d...3..  3287.355614: sched_waking: comm=ktimersoftd/1 pid=23 prio=98 target_cpu=001

         pmqtest-502   [001] d...4..  3287.355616: sched_wakeup: comm=ktimersoftd/1 pid=23 prio=98 target_cpu=001

         pmqtest-502   [001] d...2..  3287.355617: ipi_exit: (IRQ work interrupts)

// MICK: 从nanosleep系统调用返回

         pmqtest-502   [001] .......  3287.355618: sys_exit: NR 115 = 0

// MICK_START(mq_send)： mq_send()系统调用，发送syncmsg消息，此过程中唤醒休眠等待syncmsg的sender任务

         pmqtest-502   [001] .......  3287.355623: sys_enter: NR 182 (3, 4045a0, 7, 1, 0, 0)

         pmqtest-502   [001] .......  3287.355626: kmalloc: call_site=ffff0000083e777c ptr=00000000a10d1896 bytes_req=55 bytes_alloc=128 gfp_flags=GFP_KERNEL_ACCOUNT

         pmqtest-502   [001] .....11  3287.355629: kfree: call_site=ffff0000083f1210 ptr=          (null)

// MICK：休眠等待syncmsg的任务pmqtest-503（sender线程）被唤醒，放到CPU1的对应调度类的就绪队列里

         pmqtest-502   [001] d...1..  3287.355631: sched_waking: comm=pmqtest pid=503 prio=0 target_cpu=001

         pmqtest-502   [001] d...2..  3287.355632: sched_wakeup: comm=pmqtest pid=503 prio=0 target_cpu=001

         pmqtest-502   [001] .......  3287.355633: sys_exit: NR 182 = 0

// MICK_END(mq_send)： mq_send()系统调用结束

// MICK： mq_receive()系统调用，等待testmsg，由于此时消息队列中没有testmsg，当前任务需要休眠等待，从而发生任务切换。

         pmqtest-502   [001] .......  3287.355634: sys_enter: NR 183 (4, 155cb344, 8, 0, 0, 0)

         pmqtest-502   [001] .....11  3287.355636: kfree: call_site=ffff0000083f0d18 ptr=          (null)

         pmqtest-502   [001] d...1..  3287.355638: rcu_utilization: Start context switch

         pmqtest-502   [001] d...1..  3287.355638: rcu_utilization: End context switch

// MICK： sched_switch任务切换，调度器选择合适的任务进行调度，此时为sender线程（pmqtest-503），其优先级最高

         pmqtest-502   [001] d...2..  3287.355641: sched_switch: prev_comm=pmqtest prev_pid=502 prev_prio=0 prev_state=S ==> next_comm=pmqtest next_pid=503 next_prio=0

         pmqtest-503   [001] .......  3287.355645: kfree: call_site=ffff0000083e7724 ptr=00000000a10d1896

// MICK： sender线程从mq_receive()系统调用中返回

         pmqtest-503   [001] .......  3287.355646: sys_exit: NR 183 = 7

// MICK： sender线程在mq_send()前记录时间

// MICK_START(mq_send)： mq_send()系统调用发送testmsg，过程中会将休眠等待testmsg的receiver线程唤醒

         pmqtest-503   [001] .......  3287.355649: sys_enter: NR 182 (4, 404598, 7, 1, 0, 0)

         pmqtest-503   [001] .......  3287.355650: kmalloc: call_site=ffff0000083e777c ptr=00000000a10d1896 bytes_req=55 bytes_alloc=128 gfp_flags=GFP_KERNEL_ACCOUNT

// MICK： mq_send()过程中，时钟tick中断arch_timer到来，开始处理arch_timer中断

         pmqtest-503   [001] d..h2..  3287.355650: irq_handler_entry: irq=3 name=arch_timer

         pmqtest-503   [001] d..h3..  3287.355650: hrtimer_cancel: hrtimer=0000000073bbac77

         pmqtest-503   [001] d..h2..  3287.355650: hrtimer_expire_entry: hrtimer=0000000073bbac77 function=tick_sched_timer now=3287350002616

         pmqtest-503   [001] d..h2..  3287.355650: rcu_utilization: Start scheduler-tick

         pmqtest-503   [001] d..h2..  3287.355650: rcu_utilization: End scheduler-tick

         pmqtest-503   [001] d..h2..  3287.355650: softirq_raise: vec=7 [action=SCHED]

         pmqtest-503   [001] d..h2..  3287.355650: hrtimer_expire_exit: hrtimer=0000000073bbac77

         pmqtest-503   [001] d..h3..  3287.355650: hrtimer_start: hrtimer=0000000073bbac77 function=tick_sched_timer expires=3287360000000 softexpires=3287360000000 mode=ABS

         pmqtest-503   [001] d..h2..  3287.355650: irq_handler_exit: irq=3 ret=handled

// MICK：时钟tick中断arch_timer处理完，从arch_timer开始处理到其结束后开始执行sender线程，总共花费约时间 3287.355677 - 3287.355650 = 27us，此段时间记录在消息传递测试时间中

         pmqtest-503   [001] .....11  3287.355677: kfree: call_site=ffff0000083f1210 ptr=          (null)

// MICK： mq_send()过程中唤醒receiver线程pmqtest-502

         pmqtest-503   [001] d...1..  3287.355679: sched_waking: comm=pmqtest pid=502 prio=0 target_cpu=001

         pmqtest-503   [001] d...2..  3287.355680: sched_wakeup: comm=pmqtest pid=502 prio=0 target_cpu=001

         pmqtest-503   [001] .......  3287.355681: sys_exit: NR 182 = 0

// MICK_END(mq_send)： mq_send()系统调用结束

// MICK: mq_receive()系统调用，等待syncmsg，即下一个loop，此时消息队列中没有syncmsg，所以sender任务休眠，发生任务切换

         pmqtest-503   [001] .......  3287.355682: sys_enter: NR 183 (3, 155cb5fc, 8, 0, 0, 0)

         pmqtest-503   [001] .....11  3287.355683: kfree: call_site=ffff0000083f0d18 ptr=          (null)

         pmqtest-503   [001] d...1..  3287.355685: rcu_utilization: Start context switch

         pmqtest-503   [001] d...1..  3287.355685: rcu_utilization: End context switch

// MICK：任务切换，调度器选择合适的任务进行切换，这里是pmqtest-502（receiver线程）

         pmqtest-503   [001] d...2..  3287.355687: sched_switch: prev_comm=pmqtest prev_pid=503 prev_prio=0 prev_state=S ==> next_comm=pmqtest next_pid=502 next_prio=0

         pmqtest-502   [001] .......  3287.355689: kfree: call_site=ffff0000083e7724 ptr=00000000a10d1896

         pmqtest-502   [001] .......  3287.355689: sys_exit: NR 183 = 7

// MICK： receiver线程从mq_receive()返回

// MICK：之后记录时间，消息传递时间约为 3287.355689 - 3287.355646 = 43us

// MICK：排除arch_timer中断时间27us外，花费时间16us，误差5us左右。

         pmqtest-502   [001] .......  3287.355708: sys_enter: NR 79 (ffffffffffffff9c, 404608, ffff88bfc6d0, 0, cd7, 0)

         pmqtest-502   [001] .......  3287.355712: kmem_cache_alloc: call_site=ffff0000082510e4 ptr=000000008033d399 bytes_req=4096 bytes_alloc=4096 gfp_flags=GFP_KERNEL

         pmqtest-502   [001] .......  3287.355754: kmem_cache_free: call_site=ffff000008251094 ptr=000000008033d399

         pmqtest-502   [001] .......  3287.355759: sys_exit: NR 79 = 0

         pmqtest-502   [001] .......  3287.355770: sys_enter: NR 56 (ffffffffffffff9c, ffff88bfc8c8, 1, 0, 0, ffff88bfd8e0)

         pmqtest-502   [001] .......  3287.355772: kmem_cache_alloc: call_site=ffff0000082510e4 ptr=000000008033d399 bytes_req=4096 bytes_alloc=4096 gfp_flags=GFP_KERNEL

         pmqtest-502   [001] .......  3287.355778: kmem_cache_alloc: call_site=ffff0000082420e8 ptr=00000000458b64bc bytes_req=344 bytes_alloc=384 gfp_flags=GFP_KERNEL|__GFP_ZERO

         pmqtest-502   [001] .......  3287.355795: kmem_cache_alloc: call_site=ffff00000825c34c ptr=00000000e379fb22 bytes_req=264 bytes_alloc=264 gfp_flags=GFP_KERNEL

         pmqtest-502   [001] .......  3287.355816: kmem_cache_free: call_site=ffff000008251094 ptr=000000008033d399

         pmqtest-502   [001] .......  3287.355817: sys_exit: NR 56 = -2

// MICK: clock_nanosleep()系统调用，通过hrtimer实现，开始休眠等待下一个loop

         pmqtest-502   [001] .......  3287.355832: sys_enter: NR 115 (1, 0, 155cb2d0, 0, 0, ffff88bfd8e0)

         pmqtest-502   [001] .......  3287.355834: hrtimer_init: hrtimer=00000000e1325509 clockid=CLOCK_MONOTONIC mode=REL

         pmqtest-502   [001] d...1..  3287.355836: hrtimer_start: hrtimer=00000000e1325509 function=hrtimer_wakeup expires=3287351184846 softexpires=3287351184846 mode=REL

         pmqtest-502   [001] d...1..  3287.355837: rcu_utilization: Start context switch

         pmqtest-502   [001] d...1..  3287.355838: rcu_utilization: End context switch

         pmqtest-502   [001] d...2..  3287.355842: sched_switch: prev_comm=pmqtest prev_pid=502 prev_prio=0 prev_state=S ==> next_comm=ktimersoftd/1 next_pid=23 next_prio=98

********************* LOG1 END*********************************

3.2 案例二

此场景为：stress-ng将所有CPU核压倒80%，pmqtest工具不绑核。由于不绑核，分析定位时在抓取所有CPU核的log中过滤了pmqtest关键词

原因：

arch_timer中断处理10us。sender线程在唤醒receiver线程前发生处理了时钟tick的arch_timer中断
ipi中断处理耗时20us左右，receiver线程得到调度后，在记录结束时间前除了ipi中断，花费了20us左右
任务迁移及迁移后cache-miss，耗时10us左右

具体log分析如下：

// MICK: 上次loop中receiver线程中nanosleep设置的定时器超时，产生arch_timer中断，中断处理中唤醒receiver线程pmqtest-534

   Line 352062:        stress-ng-374   [002] d..h1..  8547.278291: sched_waking: comm=pmqtest pid=534 prio=0 target_cpu=002

    Line 352063:        stress-ng-374   [002] dn.h2..  8547.278292: sched_wakeup: comm=pmqtest pid=534 prio=0 target_cpu=002

    Line 352069:        stress-ng-374   [002] d...2..  8547.278299: sched_switch: prev_comm=stress-ng prev_pid=374 prev_prio=120 prev_state=R ==> next_comm=pmqtest next_pid=534 next_prio=0

// MICK：切换到receiver线程pmqtest-534，clock_nanosleep系统调用返回

    Line 352070:          pmqtest-534   [002] .......  8547.278301: sys_exit: NR 115 = 0

// MICK_START(mq_send)： receiver线程使用系统调用mq_send()发送syncmsg消息，此过程会唤醒休眠的sender线程

    Line 352071:          pmqtest-534   [002] .......  8547.278302: sys_enter: NR 182 (3, 4045a0, 7, 1, 0, 0)

    Line 352072:          pmqtest-534   [002] .......  8547.278303: kmalloc: call_site=ffff0000083e777c ptr=00000000472f1aa0 bytes_req=55 bytes_alloc=128 gfp_flags=GFP_KERNEL_ACCOUNT

    Line 352073:          pmqtest-534   [002] .....11  8547.278305: kfree: call_site=ffff0000083f1210 ptr=          (null)

// MICK：休眠等待syncmsg消息的sender线程pmqtest-535在CPU0被唤醒

    Line 352074:          pmqtest-534   [002] d...1..  8547.278306: sched_waking: comm=pmqtest pid=535 prio=0 target_cpu=000

    Line 352074:          pmqtest-534   [002] d...1..  8547.278306: sched_waking: comm=pmqtest pid=535 prio=0 target_cpu=000

    Line 352075:          pmqtest-534   [002] d...2..  8547.278308: ipi_raise: target_mask=00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001 (Rescheduling interrupts)

    Line 352076:          pmqtest-534   [002] d...2..  8547.278310: sched_wakeup: comm=pmqtest pid=535 prio=0 target_cpu=000

    Line 352076:          pmqtest-534   [002] d...2..  8547.278310: sched_wakeup: comm=pmqtest pid=535 prio=0 target_cpu=000

    Line 352078:          pmqtest-534   [002] .......  8547.278310: sys_exit: NR 182 = 0

// MICK_END(mq_send)： receiver线程mq_send(syncmsg)结束

// MICK: receiver线程执行mq_receive()等待testmsg消息，此时会休眠发生任务切换

    Line 352079:          pmqtest-534   [002] .......  8547.278311: sys_enter: NR 183 (4, 1d05f344, 8, 0, 0, 0)

    Line 352082:          pmqtest-534   [002] .....11  8547.278312: kfree: call_site=ffff0000083f0d18 ptr=          (null)

    Line 352084:          pmqtest-534   [002] d...1..  8547.278314: rcu_utilization: Start context switch

    Line 352086:          pmqtest-534   [002] d...1..  8547.278315: rcu_utilization: End context switch

// MICK： sender线程在CPU0上被唤醒（过滤了pmqtest关键字，实际log中可以在前文看到ipi中断Rescheduling interrupts）

    Line 352087:        stress-ng-379   [000] d...2..  8547.278316: sched_switch: prev_comm=stress-ng prev_pid=379 prev_prio=120 prev_state=R ==> next_comm=pmqtest next_pid=535 next_prio=0

    Line 352088:          pmqtest-534   [002] d...2..  8547.278317: sched_switch: prev_comm=pmqtest prev_pid=534 prev_prio=0 prev_state=S ==> next_comm=stress-ng next_pid=374 next_prio=120

    Line 352088:          pmqtest-534   [002] d...2..  8547.278317: sched_switch: prev_comm=pmqtest prev_pid=534 prev_prio=0 prev_state=S ==> next_comm=stress-ng next_pid=374 next_prio=120

    Line 352089:          pmqtest-535   [000] .......  8547.278318: kfree: call_site=ffff0000083e7724 ptr=00000000472f1aa0

// MICK： sender线程pmqtest-535从mq_receive()中返回

    Line 352090:          pmqtest-535   [000] .......  8547.278319: sys_exit: NR 183 = 7

// MICK：记录开始时间

// MICK_START(mq_send)：CPU0上sender线程执行mq_send()，发送testmsg，在此之前记录开始时间

    Line 352091:          pmqtest-535   [000] .......  8547.278321: sys_enter: NR 182 (4, 404598, 7, 1, 0, 0)

    Line 352092:          pmqtest-535   [000] .......  8547.278322: kmalloc: call_site=ffff0000083e777c ptr=00000000cf3ecf6b bytes_req=55 bytes_alloc=128 gfp_flags=GFP_KERNEL_ACCOUNT

// MICK_START1(arch_timer)：CPU0上sender线程发送testmsg过程中，处理时钟tick的arch_timer中断

    Line 352093:          pmqtest-535   [000] d..h21.  8547.278324: irq_handler_entry: irq=3 name=arch_timer

    Line 352103:          pmqtest-535   [000] d..h31.  8547.278325: hrtimer_cancel: hrtimer=0000000041ef87d8

    Line 352108:          pmqtest-535   [000] d..h21.  8547.278326: hrtimer_expire_entry: hrtimer=0000000041ef87d8 function=tick_sched_timer now=8547270002413

    Line 352114:          pmqtest-535   [000] d..h21.  8547.278327: softirq_raise: vec=1 [action=TIMER]

    Line 352119:          pmqtest-535   [000] d..h21.  8547.278328: rcu_utilization: Start scheduler-tick

    Line 352124:          pmqtest-535   [000] d..h21.  8547.278329: rcu_utilization: End scheduler-tick

    Line 352137:          pmqtest-535   [000] d..h21.  8547.278331: ipi_raise: target_mask=00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000040 (Rescheduling interrupts)

    Line 352148:          pmqtest-535   [000] d..h21.  8547.278333: hrtimer_expire_exit: hrtimer=0000000041ef87d8

    Line 352154:          pmqtest-535   [000] d..h31.  8547.278333: hrtimer_start: hrtimer=0000000041ef87d8 function=tick_sched_timer expires=8547280000000 softexpires=8547280000000 mode=ABS

    Line 352160:          pmqtest-535   [000] d..h21.  8547.278334: irq_handler_exit: irq=3 ret=handled

// MICK_END1(arch_timer)：arch_timer中断处理完，此时未唤醒receiver线程，此段时间记录在测试时间中。

    Line 352165:          pmqtest-535   [000] d...31.  8547.278335: sched_waking: comm=ktimersoftd/0 pid=10 prio=98 target_cpu=000

    Line 352182:          pmqtest-535   [000] d...41.  8547.278338: sched_wakeup: comm=ktimersoftd/0 pid=10 prio=98 target_cpu=000

    Line 352188:          pmqtest-535   [000] .....11  8547.278339: kfree: call_site=ffff0000083f1210 ptr=          (null)

// MICK： arch_timer处理中有raise_softirq(TIMER_SOFTIRQ)，所以在irq_exit时，唤醒了内核线程ktimersoftd，用来处理TIMER_SOFTIRQ。

// MICK：所以时钟tick的arch_timer中断相关处理共耗时8547.278339 - 8547.278322 = 17us左右，这段时间都记录在测试时间中。

// MICK：尝试唤醒receiver线程，唤醒过程中，发生了任务迁移，从CPU2迁移到了CPU4上

    Line 352195:          pmqtest-535   [000] d...1..  8547.278341: sched_waking: comm=pmqtest pid=534 prio=0 target_cpu=002

    Line 352195:          pmqtest-535   [000] d...1..  8547.278341: sched_waking: comm=pmqtest pid=534 prio=0 target_cpu=002

    Line 352212:          pmqtest-535   [000] d...1..  8547.278344: sched_migrate_task: comm=pmqtest pid=534 prio=0 orig_cpu=2 dest_cpu=4

    Line 352212:          pmqtest-535   [000] d...1..  8547.278344: sched_migrate_task: comm=pmqtest pid=534 prio=0 orig_cpu=2 dest_cpu=4

    Line 352228:          pmqtest-535   [000] d...2..  8547.278347: sched_wakeup: comm=pmqtest pid=534 prio=0 target_cpu=004

    Line 352228:          pmqtest-535   [000] d...2..  8547.278347: sched_wakeup: comm=pmqtest pid=534 prio=0 target_cpu=004

    Line 352231:          pmqtest-535   [000] .......  8547.278348: sys_exit: NR 182 = 0

// MICK_END(mq_send)：唤醒结束，从mq_send()前记录时间，到唤醒receiver任务用时8547.278347 - 8547.278319 = 28us左右，其中arch_timer中断处理耗时17us左右

    Line 352234:          pmqtest-535   [000] .......  8547.278349: sys_enter: NR 168 (ffffaf750838, 0, 0, ffffaf7512e8, ffffaf7510e0, ffffaf7510e0)

    Line 352237:          pmqtest-535   [000] .......  8547.278349: sys_exit: NR 168 = 0

    Line 352238:          pmqtest-535   [000] .......  8547.278350: sys_enter: NR 183 (3, 1d05f5fc, 8, 0, 0, 0)

// MICK： receiver线程pmqtest-534在CPU0上被唤醒（过滤了pmqtest关键字，实际log中可以在前文看到ipi中断Rescheduling interrupts）

    Line 352239:        stress-ng-381   [004] d...2..  8547.278350: sched_switch: prev_comm=stress-ng prev_pid=381 prev_prio=120 prev_state=R ==> next_comm=pmqtest next_pid=534 next_prio=0

    Line 352242:          pmqtest-535   [000] .....11  8547.278351: kfree: call_site=ffff0000083f0d18 ptr=          (null)

    Line 352244:          pmqtest-535   [000] d...1..  8547.278353: rcu_utilization: Start context switch

    Line 352246:          pmqtest-535   [000] d...1..  8547.278353: rcu_utilization: End context switch

    Line 352250:          pmqtest-535   [000] d...2..  8547.278356: sched_switch: prev_comm=pmqtest prev_pid=535 prev_prio=0 prev_state=S ==> next_comm=ktimersoftd/0 next_pid=10 next_prio=98

    Line 352250:          pmqtest-535   [000] d...2..  8547.278356: sched_switch: prev_comm=pmqtest prev_pid=535 prev_prio=0 prev_state=S ==> next_comm=ktimersoftd/0 next_pid=10 next_prio=98

// MICK： receiver线程从唤醒到得到CPU调度耗时8547.278359 - 8547.278350 = 9us左右。由于任务从CPU2迁移到CPU4，应该触发cache-miss。

// MICK_START(ipi中断)：一些IPI中断处理

    Line 352254:          pmqtest-534   [004] d...2..  8547.278359: ipi_entry: (Function call interrupts)

    Line 352265:          pmqtest-534   [004] d..h3..  8547.278363: ipi_raise: target_mask=00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000010 (IRQ work interrupts)

    Line 352266:          pmqtest-534   [004] d...2..  8547.278366: ipi_exit: (Function call interrupts)

    Line 352268:          pmqtest-534   [004] d...2..  8547.278367: ipi_entry: (IRQ work interrupts)

    Line 352272:          pmqtest-534   [004] d...2..  8547.278369: ipi_exit: (IRQ work interrupts)

    Line 352279:          pmqtest-534   [004] .......  8547.278373: kfree: call_site=ffff0000083e7724 ptr=00000000cf3ecf6b

    Line 352281:          pmqtest-534   [004] d...1..  8547.278376: ipi_entry: (Function call interrupts)

    Line 352283:          pmqtest-534   [004] d..h2..  8547.278378: ipi_raise: target_mask=00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000010 (IRQ work interrupts)

    Line 352284:          pmqtest-534   [004] d...1..  8547.278379: ipi_exit: (Function call interrupts)

    Line 352285:          pmqtest-534   [004] d...1..  8547.278380: ipi_entry: (IRQ work interrupts)

    Line 352286:          pmqtest-534   [004] d...1..  8547.278381: ipi_exit: (IRQ work interrupts)

// MICK_END(ipi中断)： ipi中断处理结束，耗时8547.278381 - 8547.278359 = 22us左右

// MICK： receiver线程从mq_receive返回

    Line 352287:          pmqtest-534   [004] .......  8547.278382: sys_exit: NR 183 = 7

// MICK： mq_receive返回后，记录下结束时间。

// MICK：消息传递时间用时约为8547.278382 - 8547.278319 = 62us左右。

// MICK：其中arch_timer处理时间17us左右，ipi中断处理22us左右，另外还有一点任务迁移和cache-miss影响。



    Line 352288:          pmqtest-534   [004] .......  8547.278400: sys_enter: NR 79 (ffffffffffffff9c, 404608, ffffaff516d0, 0, 2163, 0)

    Line 352289:          pmqtest-534   [004] .......  8547.278402: kmem_cache_alloc: call_site=ffff0000082510e4 ptr=00000000740343d5 bytes_req=4096 bytes_alloc=4096 gfp_flags=GFP_KERNEL

    Line 352290:          pmqtest-534   [004] .......  8547.278432: kmem_cache_free: call_site=ffff000008251094 ptr=00000000740343d5

    Line 352291:          pmqtest-534   [004] .......  8547.278435: sys_exit: NR 79 = 0

    Line 352292:          pmqtest-534   [004] .......  8547.278444: sys_enter: NR 56 (ffffffffffffff9c, ffffaff518c8, 1, 0, 0, ffffaff528e0)

    Line 352293:          pmqtest-534   [004] .......  8547.278445: kmem_cache_alloc: call_site=ffff0000082510e4 ptr=00000000740343d5 bytes_req=4096 bytes_alloc=4096 gfp_flags=GFP_KERNEL

    Line 352294:          pmqtest-534   [004] .......  8547.278450: kmem_cache_alloc: call_site=ffff0000082420e8 ptr=0000000056c6ccd1 bytes_req=344 bytes_alloc=384 gfp_flags=GFP_KERNEL|__GFP_ZERO

    Line 352295:          pmqtest-534   [004] .......  8547.278466: kmem_cache_alloc: call_site=ffff00000825c34c ptr=0000000079481da9 bytes_req=264 bytes_alloc=264 gfp_flags=GFP_KERNEL

    Line 352296:          pmqtest-534   [004] .......  8547.278483: kmem_cache_free: call_site=ffff000008251094 ptr=00000000740343d5

    Line 352297:          pmqtest-534   [004] .......  8547.278484: sys_exit: NR 56 = -2

    Line 352298:          pmqtest-534   [004] .......  8547.278494: sys_enter: NR 168 (ffffaff51838, 0, 0, 40100401, 5504000000005554, 72656b2f7379732f)

    Line 352299:          pmqtest-534   [004] .......  8547.278495: sys_exit: NR 168 = 0

// MICK： receiver线程，执行nanosleep进行休眠，等待下一次loop

    Line 352300:          pmqtest-534   [004] .......  8547.278496: sys_enter: NR 115 (1, 0, 1d05f2d0, 0, 0, ffffaff528e0)

    Line 352301:          pmqtest-534   [004] .......  8547.278500: hrtimer_init: hrtimer=000000008f180db2 clockid=CLOCK_MONOTONIC mode=REL

    Line 352302:          pmqtest-534   [004] d...1..  8547.278502: hrtimer_start: hrtimer=000000008f180db2 function=hrtimer_wakeup expires=8547271178558 softexpires=8547271178558 mode=REL

    Line 352303:          pmqtest-534   [004] d...1..  8547.278503: rcu_utilization: Start context switch

    Line 352304:          pmqtest-534   [004] d...1..  8547.278504: rcu_utilization: End context switch

    Line 352305:          pmqtest-534   [004] d...2..  8547.278508: sched_switch: prev_comm=pmqtest prev_pid=534 prev_prio=0 prev_state=S ==> next_comm=ktimersoftd/4 next_pid=47 next_prio=98

    Line 352305:          pmqtest-534   [004] d...2..  8547.278508: sched_switch: prev_comm=pmqtest prev_pid=534 prev_prio=0 prev_state=S ==> next_comm=ktimersoftd/4 next_pid=47 next_prio=98