追踪内核中神秘的高优先级线程挂起答案

【问题标题】：Tracking down mysterious high-priority thread suspend inside the kernel追踪内核中神秘的高优先级线程挂起
【发布时间】：2014-07-18 15:11:09
【问题描述】：

说明

我正在开发一个在多核 ARMv7a SoC 上运行的嵌入式 Linux 系统（使用内核 3.4 和仿生，类似 Android）。我们有一个用户空间线程，它基本上服务于来自内核的事件。这些事件是从 IRQ 生成的，并且必须由用户空间以非常低的延迟做出反应。

一个线程以 SCHED_FIFO 优先级 0 运行。它是系统中唯一的优先级 0 线程。线程的近似代码：

    while (1)
    {
        struct pollfd fds[1];
        fds[0].fd = fd;
        fds[0].events = POLLIN|POLLRDNORM|POLLPRI;

        int ret = poll(fds, 1, reallyLongTimeout);
        FTRACE("poll() exit");
        if (ret > 0)
        {
            // notify worker threads of pending events
        }
    }

通常我们得到很好的延迟（线程在 IRQ 发生的同一毫秒内完成了一次完整的往返返回 poll()），但是随机我们有几十毫秒的延迟，这会破坏一切。在到处跟踪它之后，我得出的结论是延迟发生在 IRQ 触发之后和 poll() 系统调用返回之前，因为线程使自己进入睡眠状态。然后一段时间后不知何故被某种未知的力量唤醒，一切都在继续。

我怀疑有其他 IRQ，但在启用 sched:,irq:,timer:* 跟踪后，我不得不排除它。我在将 syscalls:* 跟踪器移植到 ARM 内核时遇到了一些困难。系统调用跟踪器工作，但如果我也启用 sched:* 我会在 ring_buffer 代码中得到各种恐慌。

在 sys_poll() 中插入一些自定义跟踪点后，我得出了一个令人不安的结论，即我的线程在 sys_poll() 返回后进入休眠状态，但在它重新出现在用户空间之前。

这是我在 fs/select.c 中的自定义跟踪点的注释跟踪：

 <my thread>-915   [001] ...1    17.589394: custom: do_poll:786 - calling do_pollfd
 <my thread>-915   [001] ...1    17.589399: custom: do_poll:794 - failed, no events
 <my thread>-915   [001] ...1    17.589402: custom: do_poll:823 - going to sleep, count = 0, timed_out = 0

.... // everything going OK, then the IRQ happens, which runs a tasklet:

 <random proc>-834 [000] d.h1    17.616541: irq_handler_entry: irq=17 name=hwblock handler=hw_block_process_irq
 <random proc>-834 [000] d.h1    17.616569: softirq_raise: vec=6 [action=TASKLET]
 <random proc>-834 [000] d.h1    17.616570: irq_handler_exit: irq=17 ret=handled
 <random proc>-834 [000] ..s2    17.616627: softirq_entry: vec=6 [action=TASKLET]

.... // the tasklet signals the wait queue of the poll, which wakes up my thread:

 <my thread>-915   [001] ...1    17.616827: custom: do_poll:826 - woke up, count = 0, timed_out = 0
 <my thread>-915   [001] ...1    17.616833: custom: do_poll:772 - start of loop
 <my thread>-915   [001] ...1    17.616840: custom: do_poll:786 - calling do_pollfd
 <my thread>-915   [001] ...1    17.616852: custom: do_poll:788 - success, event!
 <my thread>-915   [001] ...1    17.616859: custom: do_poll:810 - bailing, count = 1, timed_out = 0
 <my thread>-915   [001] ...1    17.616862: custom: do_sys_poll:880 - before free_wait()
 <my thread>-915   [001] ...1    17.616867: custom: do_sys_poll:882 - before __put_user()
 <my thread>-915   [001] ...1    17.616872: custom: sys_poll:940 - do_sys_poll - exit

.... // the tasklet exits, and my thread appears to be about to be

 <random proc>-834 [000] .Ns2    17.616922: softirq_exit: vec=6 [action=TASKLET]


.... // wait wait, why is my thread going back to sleep, and what was it doing for 75us?

 <my thread>-915   [001] d..3    17.616947: sched_stat_wait: comm=<another thread> pid=1165 delay=1010000 [ns]
 <my thread>-915   [001] ...2    17.616957: sched_switch: prev_comm=<my thread> prev_pid=915 prev_prio=0 prev_state=S ==> next_comm=<another thread> next_pid=1165 next_prio=120

.... // everything running on for 20ms as if nothing is wrong, then my thread suddenly gets woken up.
.... // nothing pid 947 is doing should have any effect on <my thread>

<random proc>-947  [000] d..4    17.636087: sched_wakeup: comm=<my thread> pid=915 prio=0 success=1 target_cpu=001
<random proc>-1208 [001] ...2    17.636212: sched_switch: prev_comm=<rancom proc> prev_pid=1208 prev_prio=120 prev_state=R ==> next_comm=<my thread> next_pid=915 next_prio=0
<my thread>-915    [001] ...1    17.636713: tracing_mark_write: poll() exit

所以我的线程在某个地方变成了TASK_INTERRUPTIBLE，然后自愿进入调度程序，然后......在20ms之后显然无缘无故醒来。

这种情况的发生似乎至少在一定程度上取决于时间，并且各种观察它的尝试通常会使重现变得更加困难。

问题

您知道是什么原因造成的吗？
关于找出我的线程在哪里睡着的简单方法有什么建议吗？
对于找出我的线程唤醒原因的简单方法有什么建议吗？
我考虑过以某种方式调整unwind_backtrace() 以生成单个字符串，我可以将其填充到每个trace_sched_switch() 调用中，但这似乎有点令人生畏。同样的思路还有什么更简单的吗？
知道为什么跟踪 syscalls:* 和 sched:* 会导致它在需要移动尾部的环形缓冲区代码内因未处理的页面错误而爆炸吗？似乎它正在取消引用用户空间指针（基于数字相似性），但每次都不同。

我已经尝试和检查过的事情

运行时间过长的正常 IRQ 或禁用中断的东西不是正常的 IRQ。使用 irq:* 进行跟踪表明了这一点。它可能是某种 TrustZone NMI，但不知何故我对此表示怀疑。
它不应该是任何形式的 RT 节流/时间片，因为：

a) sched_rt_runtime_us=10000 和 sched_rt_period_us=10000

b) 线程的占空比相当低（
这可能不是从用户空间跟踪或写入/sys/kernel/debug/tracing/trace_marker 的人工制品——它在没有该宏且跟踪禁用（甚至从内核编译出来）的情况下发生。此外，trace.c 和 ring_buffer.c 中与此相关的代码似乎大多是无锁的。
没有其他优先级为 0 的内容，它并没有被抢占，而是似乎愿意自行取消调度。
我在 syscall_trace() 的顶部放置了一个 panic()，以确保我在离开 sys_poll() 时不会意外落入跟踪/审计路径之一。它没有火，所以不是这样。

非常感谢您

更新 #1

我放弃了寻找简单的方法，并实现了一个unwind_backtrace_to_str() 函数，让我可以使用回溯信息检测各种跟踪点。在将回溯添加到 trace_sched_switch() 和 trace_sched_wake() 之后，我设法隔离了几个导致延迟的原因，主要的两个是：

优先级反转，因为 mm->mmap_sem 被同一进程中的其他线程占用，执行 fork()/mmap()/munmap()，因此在 @ 期间不可用987654334@ 或 tracing_mark_write() 用于 RT 线程。这可以通过重构一些代码并在某些地方使用 vfork() 而不是 fork() 来避免。
无法运行计划任务，当sched_wake() 从与其需要运行的 CPU 不同的源 CPU 调用时。这似乎是一个更大的问题。我通过调度程序对其进行了跟踪，似乎在糟糕的情况下wake_up_process() 调用try_to_wake_up() 最终调用ttwu_queue() 这就是事情变得有趣的地方。

在ttwu_queue() 内部，我们不输入“if”，因为cpus_share_cache() 总是为我们的任何内核返回true（听起来不错，共享L2）。这意味着它只是为任务调用ttwu_do_activate() 并退出。 ttwu_do_activate() 似乎只是将任务放在正确的运行队列中并将其标记为TASK_RUNNING，但没有任何 SMP 处理。

我在ttwu_do_wakeup()p->state = TASK_RUNNING;之后添加了以下内容

#ifdef CONFIG_SMP
      if (task_cpu(p) != smp_processor_id())
          smp_send_reschedule(task_cpu(p));
#endif

它通过强制目标 CPU 运行调度程序来解决问题。但是，我怀疑这不是它应该如何工作的，即使这是一个真正的错误，也可能有一个更完善的修复。我检查了最新的内核（3.14），core.c 中的代码看起来几乎一样。

有什么想法吗？如果cpus_share_cache() 返回true，为什么它不调用ttwu_queue_remote()？那么如果他们共享缓存怎么办——我可以看到这与迁移决策有什么关系，但是唤醒是在本地还是远程完成的？也许我们的cpus_share_cache() 应该返回假？该功能似乎没有很好的记录（或者我没有在正确的地方寻找）

【问题讨论】：

您是否有任何自定义设备驱动程序可能会影响进程的调度结构？
Yuriy Romanenko，你现在的uname -a 是什么？如果您想要 RT 任务，您是否测试了 Linux 内核 (kernel.org/pub/linux/kernel/projects/rt/3.4) 的 RT（实时）版本？它可能会修复这个错误...

标签： multithreading linux-kernel embedded-linux multicore low-latency

【解决方案1】：

只是一个疯狂的猜测，因为还没有任何答案.. 你说系统是多核的。您是否为用户线程分配亲和性以在发生中断的同一内核上运行？中断是否仅发生在特定内核上？我怀疑用户线程在一个内核上运行但中断发生在另一个内核上并且无法立即在此处恢复（还没有睡觉？）的情况。可能是数据竞争让它睡着了，例如就在中断处理程序发布线程轮询的一些数据之前。因此，它会被挂起，直到下一个系统中断（例如计时器）。

因此，请尝试将中断和线程分配给同一个内核，以便将它们序列化并避免潜在的数据竞争。

响应更新 #1

看起来我对核心之间的数据竞争是正确的，因为在目标核心上提高 IRQ 可以解决问题。我猜它不在内核代码中，因为过多的重新调度 IRQ 和额外的调度开销只是为了非常罕见的情况，或者只是因为假设共享缓存使用通常的同步可以更快地完成。

而there is some synchronization 看起来是正确的方向，但显然它错过了一些东西。我会尝试在不同的架构/版本上运行复制器，以了解它是一般错误还是特定于您的平台/内核版本。我希望这不是p->on_cpu load/store 上缺少的栅栏..

无论如何，回到您的具体问题，如果您不能或不想将自定义内核构建与您的热修复一起使用，我关于线程关联的建议仍然有效。

此外，如果您无法将中断固定到一个特定的核心，您可能希望在每个核心上运行这样一个轮询线程（也明确固定到它），以确保至少有一个线程将在之后立即获得事件中断请求。当然，这会给用户线程代码带来额外的同步负担。

【讨论】：

看来您至少部分了解了这里的内容。查看我的编辑。
@YuriyRomanenko，谢谢，我没有什么要补充的（虽然，更新了），如果你不想破解内核，仍然建议尝试设置线程关联。
我怀疑这是栅栏/屏障问题。该任务还不是 on_cpu 或 on_rq。我看到的最病态的情况是 CPU0 在 CPU1 上执行 RT 任务的 sched_wake，而 CPU1 处于空闲状态并处于 WFI 中。然后什么也没有发生。 CPU1 没有运行任务 100 毫秒，它这样做的唯一原因是因为一些硬件 IRQ 唤醒了它，在出去的路上它通过调度程序返回并看到它有事情要做。因此，即使 CPU 空闲，也根本不会生成 IPI。
@YuriyRomanenko，我明白了，那么它看起来更像是一个深思熟虑的决定（尝试 RT 内核？一些补丁看起来非常接近）或逻辑失误，因为这里的 IPI 似乎是唯一的解决方案或者至少从缓存重用和资源利用的角度来看比例如更有效而是恢复 CPU0 上的线程。
@YuriyRomanenko，请说明您此时真正想要什么，修复内核或解决其行为？

【解决方案2】：

我们最终进行了以下修复：

smp_send_reschedule(task_cpu(p)); 上面提到的调度程序允许跨 CPU 预防。我会跟进维护人员，看看它是否是正确的修复。
为我们的平台实现get_user_pages_fast()，如果不需要，它不会锁定mmap_sem。这消除了mmap/munmap 和futex_wait 之间的争用
在用户空间代码中不需要fork() 的几个地方切换到vfork() + execve()。这消除了mmap/munmap 和产生其他进程的调用之间的争用。

现在看来一切都很顺利。

感谢您的所有帮助。

【讨论】：