Bug 19364 - Обмен с драйвером Moxa блокирует ядро
Summary: Обмен с драйвером Moxa блокирует ядро
Status: CLOSED NOTABUG
Alias: None
Product: Sisyphus
Classification: Development
Component: kernel-image-std-srv (show other bugs)
Version: unstable
Hardware: all Linux
: P2 critical
Assignee: Michail Yakushin
QA Contact: qa-sisyphus
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-03-27 12:43 MSK by serpiph
Modified: 2009-04-01 13:37 MSD (History)
9 users (show)

See Also:


Attachments
Вывод dmesg до запуска обмена (29.80 KB, text/plain)
2009-03-27 12:44 MSK, serpiph
no flags Details
Вывод dmesg после запуска обмена и SysRq-P (30.54 KB, text/plain)
2009-03-27 12:45 MSK, serpiph
no flags Details
Вывод dmesg после запуска обмена и SysRq-T (121.70 KB, text/plain)
2009-03-27 12:45 MSK, serpiph
no flags Details
Вывод lspci -vvnn (11.65 KB, text/plain)
2009-03-27 12:46 MSK, serpiph
no flags Details
Список загруженных модулей (1.98 KB, text/plain)
2009-03-27 12:47 MSK, serpiph
no flags Details
Вывод top при обмене (5.59 KB, text/plain)
2009-03-27 12:48 MSK, serpiph
no flags Details
Устройства в /dev/inputs/by-path (191 bytes, text/plain)
2009-03-27 12:48 MSK, serpiph
no flags Details
сообщение о soft lockup (622.17 KB, image/jpeg)
2009-03-27 12:50 MSK, serpiph
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description serpiph 2009-03-27 12:43:16 MSK
Ядро 2.6.27-std-srv-alt14. Загружен модуль moxa из сборки ядра. При попытке начать обмен с модулем (Moxa C218Turbo PCI) нагружается event/0, одно ядро нагружается полностью, клавиатура практически не откликается, через полминуты появляются сообщения о блокировке ядра более, чем на 61 сек.

При этом если использовать ядро 2.6.18-std-smp-alt6 и модуль от самой Moxa, то полная нагрузка не превышает 1-2%.

Файлы сейчас приведу к ошибке. Так как для получения каждого файла приходится перезапускать программу обмена, то PID этой программы меняется. Остальное неизменно.
Comment 1 serpiph 2009-03-27 12:44:30 MSK
Created attachment 3402 [details]
Вывод dmesg до запуска обмена
Comment 2 serpiph 2009-03-27 12:45:14 MSK
Created attachment 3403 [details]
Вывод dmesg после запуска обмена и SysRq-P
Comment 3 serpiph 2009-03-27 12:45:40 MSK
Created attachment 3404 [details]
Вывод dmesg после запуска обмена и SysRq-T
Comment 4 serpiph 2009-03-27 12:46:25 MSK
Created attachment 3405 [details]
Вывод lspci -vvnn
Comment 5 serpiph 2009-03-27 12:47:22 MSK
Created attachment 3406 [details]
Список загруженных модулей
Comment 6 serpiph 2009-03-27 12:48:05 MSK
Created attachment 3407 [details]
Вывод top при обмене
Comment 7 serpiph 2009-03-27 12:48:54 MSK
Created attachment 3408 [details]
Устройства в /dev/inputs/by-path
Comment 8 serpiph 2009-03-27 12:50:45 MSK
Created attachment 3409 [details]
сообщение о soft lockup

После появления этого сообщения компьютер становится неуправляемым и откликается только на Reset.
Comment 9 Sergey Vlasov 2009-03-27 15:10:06 MSK
(В ответ на комментарий №3)
> Created an attachment (id=3404) [details]
> Вывод dmesg после запуска обмена и SysRq-T

Придётся загрузиться с параметром log_buf_len=1M и повторить ещё раз - данные для процесса events/0 не влезли в буфер.

Исходники программы transmitter у вас есть?  Вызывает подозрение следующий фрагмент:

[  855.920003] transmitter   R running      0  8273      1
[  855.920003]        f2ddbf18 c0465911 c0246795 f2ddbf44 00000000 c19121a0 f2ddbf44 f2ddbf44 
[  855.920003]        c1912228 c1912220 f2ddbee0 f7892000 f788aec0 c0605080 f26a2130 f26a23a0 
[  855.920003]        c1915080 00000001 00000282 c1915080 4a07a6e2 f2ddbf44 000000c7 f26a23a0 
[  855.920003] Call Trace:
[  855.920003]  [<c0246795>] ? hrtimer_reprogram+0x85/0xc0
[  855.920003]  [<c0466926>] do_nanosleep+0x86/0xc0
[  855.920003]  [<c02472d8>] hrtimer_nanosleep+0x98/0x110
[  855.920003]  [<c0246ba0>] ? hrtimer_wakeup+0x0/0x20
[  855.920003]  [<c0466913>] ? do_nanosleep+0x73/0xc0
[  855.920003]  [<c02473b0>] sys_nanosleep+0x60/0x70
[  855.920003]  [<c0203e72>] syscall_call+0x7/0xb

(При отсутствии исходников можно посмотреть туда strace -p)

Если там в цикле вызывается nanosleep() с достаточно малой задержкой, возможно, при переходе на новые ядра с поддержкой highres timers происходит существенное изменение поведения - раньше таймаут для обычных процессов (не realtime) фактически увеличивался до значения, кратного 1/HZ (в конфигурации ядер std HZ==250), а в новых ядрах малые задержки обрабатываются с существенно большей точностью, что может приводить к резкому росту потребления процессорного времени, если программа использует nanosleep() с малыми задержками.  В 2.6.28 аналогичный переход на hrtimer произойдёт и для системных вызовов select() и poll().  Можно попробовать загрузку с параметром highres=0 - в этом случае в ядре будет использоваться старый режим работы с таймерами.
Comment 10 serpiph 2009-03-27 15:22:14 MSK
Попробую уже на следующей неделе. transmitter - это моя программа, но она сама не использует nanosleep, только poll (в виде poll (&poller, 1, 1000); ), максимум usleep(1), но это только для ожидания клавиатуры в одном из потоков и более ничего.
Comment 11 serpiph 2009-03-27 15:24:47 MSK
Вот ещё возможный кусок:

clock_gettime (CLOCK_REALTIME, &timeToWait);
        timeToWait.tv_nsec += 20000000;
clock_gettime (CLOCK_REALTIME, &timeToWait);
        timeToWait.tv_nsec += 20000000;

        if (timeToWait.tv_nsec >= 1000000000) {
            timeToWait.tv_nsec -= 1000000000;
            timeToWait.tv_sec++;
        }

        ret = sem_timedwait (&semSend, &timeToWait);

        if (timeToWait.tv_nsec >= 1000000000) {
            timeToWait.tv_nsec -= 1000000000;
            timeToWait.tv_sec++;
        }

        ret = sem_timedwait (&semSend, &timeToWait);

Или:
    tv.it_interval.tv_sec = 0;
    tv.it_interval.tv_usec = 60000;
    tv.it_value.tv_sec = 0;
    tv.it_value.tv_usec = 60000;
    setitimer (ITIMER_REAL, &tv, NULL);

Больше нигде я не играюсь с таймерами.
Comment 12 serpiph 2009-03-27 15:28:11 MSK
Кстати, именно работа программы transmitter (которая и обменивается с Moxa), вешает всё. Но как? вживую (strace или ptrace) подключиться практически невозможно, так как она уходит на realtime=10:

    s_par.sched_priority = 10;
    sched_setscheduler (0, SCHED_FIFO, &s_par);

для обеспечения точности в интервалах передачи данных в аппаратуру через Moxa.
Comment 13 Sergey Vlasov 2009-03-27 15:57:10 MSK
(В ответ на комментарий №10)
> Попробую уже на следующей неделе. transmitter - это моя программа, но она сама
> не использует nanosleep, только poll (в виде poll (&poller, 1, 1000); ),
> максимум usleep(1), но это только для ожидания клавиатуры в одном из потоков и
> более ничего.

Функция usleep() в текущих версиях glibc превращается в системный вызов nanosleep; вероятнее всего, это как раз тот самый поток.  Если там в коде что-то типа

	for (;;) {
		if (input_available())
			handle_input();
		usleep(1);
	}

(да ещё и с realtime-приоритетом) - это очень плохо, и как раз будет вызывать огромную загрузку процессора (на E6750 usleep(1) в цикле сжирает 30%, на чём-то более медленном будет больше).

(В ответ на комментарий №11)
> Вот ещё возможный кусок:
Тут задержки вменяемые - 20 мс и 60 мс.
Comment 14 serpiph 2009-04-01 13:35:59 MSD
Да, проблема оказалась именно в usleep(1). Когда всё стало вменяемо работать, то и данные тоже стали передаваться. Закрываю.