Отслеживание таинственного высокоприоритетного потока, приостановленного в ядре

Question

Описание

Я работаю над встроенной системой Linux (использующей ядро ​​3.4 и bionic, похожую на Android), работающей на многоядерной платформе ARMv7a SoC. У нас есть поток в пользовательском пространстве, который в основном обслуживает события, выходящие из ядра. События генерируются из IRQ и должны реагировать на них в пространстве пользователя с очень низкой задержкой.

Поток работает с приоритетом 0. SCHED_FIFO. Это единственный поток с приоритетом 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
        }
    }

Как правило, мы получаем очень хорошую задержку (поток совершает полный возврат обратно в poll() в течение той же миллисекунды, что и IRQ), однако случайно мы имеем задержки в десятки миллисекунд, которые разрушают все. Проследив все это, я пришел к выводу, что задержка происходит после срабатывания IRQ и до возврата системного вызова poll(), потому что поток засыпает. Затем, какое-то время, как-то просыпается неизвестная сила, и все продолжается.

Я подозревал какой-то другой IRQ, но после включения sched:,irq:, timer: * tracing мне пришлось исключить это. У меня возникли некоторые трудности при портировании системных вызовов:* tracers на ядро ​​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 а затем добровольно зашел в планировщик, а затем... проснулся без видимой причины через 20 мс.

Возникновение этого кажется, по крайней мере, в некоторой степени зависящим от времени, и различные попытки наблюдать его часто затрудняют воспроизведение.

Вопросы

1. Есть идеи, что вызывает это?
2. Любые предложения о простых способах узнать, где моя нить засыпает?
3. Любые предложения о простых способах выяснить, почему моя тема просыпается?
4. Я подумал как-то адаптировать unwind_backtrace() чтобы сгенерировать одну строку, я могу заполнить каждый trace_sched_switch() звоните, но это кажется немного пугающим. Что-нибудь попроще в том же духе?
5. Любая идея, почему трассировка syscalls:* и sched:* заставляет его взорваться с необработанной ошибкой страницы внутри кода кольцевого буфера, где ему нужно переместить хвост? Кажется, что он разыменовывает указатель пространства пользователя (основанный на сходстве чисел), но каждый раз другой.

Вещи, которые я уже пробовал и проверял

1. Это не обычный IRQ, который выполняется слишком долго или что-то с отключенными прерываниями. Трассировка с помощью irq:* показывает это. Это может быть своего рода NMI TrustZone, но почему-то я в этом сомневаюсь.

2. Это не должно быть RT-удушение / временная привязка любого рода, потому что:

   а) sched_rt_runtime_us=10000 и sched_rt_period_us=10000

   б) Поток имеет довольно низкий рабочий цикл (<30 мс в секунду, при 60-80 событиях в секунду)

3. Это, вероятно, не артефакт наличия трассировки или письма /sys/kernel/debug/tracing/trace_marker из пользовательского пространства - это происходит без этого макроса и с отключенной трассировкой (даже скомпилированной из ядра). Кроме того, код, связанный с этим в trace.c и ring_buffer.c, по-видимому, в основном не блокируется.

4. Нет ничего другого с приоритетом 0, и он не получает упреждения, а, скорее всего, добровольно отменяет планирование.

5. Я положил панику () в верхней части syscall_trace() чтобы я случайно не попал в один из путей отслеживания / аудита на моем пути из sys_poll(), Это не стреляло, так что это не так.

заранее большое спасибо

Обновление № 1

Я разочаровался в поиске чего-то легкого и реализовал unwind_backtrace_to_str() функция, которая позволяет мне обрабатывать различные точки трассировки с информацией о трассировке. После добавления обратных трассировок в trace_sched_switch() и trace_sched_wake() мне удалось выделить несколько причин задержки, основными из которых являются:

• Инверсия приоритетов из-за того, что mm->mmap_sem берется другим потоком в том же процессе, выполняющем fork()/mmap()/munmap() и, следовательно, не доступны во время futex_wait() или же tracing_mark_write() для темы RT. Этого можно избежать, если реструктурировать некоторый код и использовать vfork() вместо fork () в некоторых местах.

• Ошибка запуска запланированного задания, когда sched_wake() вызывается из другого исходного процессора, чем тот процессор, на котором он должен работать. Это кажется большей проблемой. Я проследил это через планировщик и похоже, что в плохом случае wake_up_process() звонки try_to_wake_up() который звонит ttwu_queue() где вещи становятся интересными.

внутри ttwu_queue() мы не вводим "если", потому что cpus_share_cache() всегда возвращает true для любого из наших ядер (звучит правильно, общий L2). Это означает, что это просто звонки ttwu_do_activate() для задачи и выходов. ttwu_do_activate() кажется, только поставить задачу в нужную очередь выполнения и пометить его как TASK_RUNNING, но не имеет обработки SMP.

Я добавил следующее после p->state = TASK_RUNNING; в ttwu_do_wakeup()

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

и это решает проблему, заставляя целевой процессор запустить планировщик. Тем не менее, я подозреваю, что это не так, как это должно работать, и даже если это реальная ошибка, возможно, есть более утонченное исправление. Я проверил последнее ядро ​​(3.14) и код в core.c выглядит примерно так же.

Есть идеи, почему это? Почему это не называется ttwu_queue_remote() если cpus_share_cache() возвращает истину? Так что, если они совместно используют кеш - я могу понять, насколько это важно для решения о миграции, но выполняется ли пробуждение локально или удаленно? Может быть наш cpus_share_cache() должен возвращать false? Эта функция, кажется, не хорошо документирована (или я не смотрю в нужных местах)

Answer 1

Просто дикая догадка, поскольку ответа пока нет.. Вы говорите, что система многоядерная. Вы назначаете сходство для пользовательского потока для запуска на том же ядре, где происходит прерывание? И прерывание происходит только на конкретном ядре? Я подозреваю ситуацию, когда пользовательский поток работает на одном ядре, но прерывание происходит на другом и не может возобновиться здесь немедленно (еще не спит?). Возможно, гонка данных позволяет ему заснуть, например, непосредственно перед тем, как обработчик прерываний публикует некоторые данные, которые поток опрашивает. Таким образом, он приостанавливается до следующего системного прерывания (например, по таймеру).

Поэтому попытайтесь назначить прерывание и поток одному и тому же ядру, чтобы сериализовать их и избежать потенциальных гонок данных.

в ответ на обновление #1

Похоже, я был прав насчет гонки данных между ядрами, поскольку повышение IRQ на целевом ядре решает проблему. Я предполагаю, что это не в коде ядра из-за чрезмерного перепланирования IRQ и, таким образом, дополнительных накладных расходов на планирование только в очень редких случаях или просто потому, что это можно сделать быстрее, используя обычную синхронизацию, предполагая общий кэш.

И есть некоторая синхронизация, которая выглядит как правильное направление, но, очевидно, что-то упускает. Я бы попробовал запустить средство воспроизведения на другой архитектуре / версиях, чтобы понять, является ли это общей ошибкой или специфичной для вашей версии платформы / ядра. Я надеюсь, что это не недостающий забор на p->on_cpu нагрузка / магазин..

В любом случае, возвращаясь к вашей конкретной проблеме, если вы не можете или не хотите использовать пользовательскую сборку ядра с вашим исправлением, мое предложение о привязке потоков все еще остается актуальным и действительным.

Кроме того, если вы не можете прикрепить прерывание к одному конкретному ядру, вы можете запустить такой поток опроса на каждом ядре (также прикрепленном к нему явно), чтобы гарантировать, что по крайней мере один из потоков получит событие сразу после IRQ. Конечно, это приводит к дополнительной нагрузке синхронизации на код пользовательского потока.

Answer 2

Мы закончили со следующими исправлениями:

• smp_send_reschedule(task_cpu(p)); упомянуто выше в планировщике, чтобы позволить предотвращение межпроцессорных. Я свяжусь с сопровождающим, чтобы выяснить, правильное ли это решение.

• Внедрение get_user_pages_fast() для нашей платформы, которая не блокируется mmap_sem если это не нужно. Это сняло разногласия между mmap/munmap а также futex_wait

• Переключение на vfork() + execve() в нескольких местах в пользовательском пространстве кода, где fork() было ненужным. Это сняло разногласия между mmap/munmap и вызывает то, что порождает другие процессы.

Кажется, сейчас все идет гладко.

Спасибо за твою помощь.