URL: https://www.opennet.me/cgi-bin/openforum/vsluhboard.cgi
Форум: vsluhforumID9
Нить номер: 6692
[ Назад ]
Исходное сообщение
"Interrupted system call"
Отправлено dimonna , 21-Авг-07 09:34 
Здравствуйте господа!

Очередная проблема: в главном потоке программы запускаем 200-300 тредов которые делают send-recv данных с соккетов и после этого ждем пока работает хоть один тред. примерно после 300 тысяч сеансов программа как-бы засыпает. В чем это выражается - не пишутся записи в логи, не идет работа с соккетами. топиком вижу что программа занимает процессорное время, утечек памяти судя по всему нет - на коротких тестах гонял через valgrind да и показаниям топа особых приростов потребляемой памяти за сутки работы нет. если в такой момент когда программа уснула заатачить ее gdb - то там все как обычно - в глаза ничего не теряется - треды в разных состояниях, кто работает с соккетами, кто еще чегото делает. потом детачим процесс gdb - и программа заработала дальше - а в лог пишет Interrupted system call в месте где происходит чтение-запись в соккеты. единственная тонкость - все соккеты биндятся на конкретный интерфейс.

В чем может быть проблема?
Спасибо заранее всем!

Содержание
Сообщения в этом обсуждении
"Interrupted system call"
Отправлено vic , 21-Авг-07 11:47 
>[оверквотинг удален]
>нет. если в такой момент когда программа уснула заатачить ее gdb
>- то там все как обычно - в глаза ничего не
>теряется - треды в разных состояниях, кто работает с соккетами, кто
>еще чегото делает. потом детачим процесс gdb - и программа заработала
>дальше - а в лог пишет Interrupted system call в месте
>где происходит чтение-запись в соккеты. единственная тонкость - все соккеты биндятся
>на конкретный интерфейс.
>
>В чем может быть проблема?
>Спасибо заранее всем!

Скорее всего программа из-за большого количества тредов занята на 100% переключением между тредами и между ядром и юзерспейсом, попробуйте использовать pool тредов и другую архитектуру приложения (последовательно/параллельную вместо параллельной).

"Interrupted system call"
Отправлено dimonna , 23-Авг-07 08:41 
>[оверквотинг удален]
>>дальше - а в лог пишет Interrupted system call в месте
>>где происходит чтение-запись в соккеты. единственная тонкость - все соккеты биндятся
>>на конкретный интерфейс.
>>
>>В чем может быть проблема?
>>Спасибо заранее всем!
>
>Скорее всего программа из-за большого количества тредов занята на 100% переключением между
>тредами и между ядром и юзерспейсом, попробуйте использовать pool тредов и
>другую архитектуру приложения (последовательно/параллельную вместо параллельной).

да нет, вот если к примеру из 200 тредов после продолжительной работы 190 завершают свою работу, остается 10 тредов, и всеравно в них наблюдается такое явление - они висят на recv, хотя были явно указаны таймауты чтения и записи в 30 секунд. потом к примеру делаешь strace -f -p пид программы и все, программа завершает своб работу т.к. recv прерывается с таким сообщением

"Interrupted system call"
Отправлено dimonna , 23-Авг-07 09:36 
Может ли быть что проблема связана с тем, что я в main() делаю

void signal_handler(int sig)
{
...
exit(0);
}

signal(SIGINT, signal_handler);

??

Хотя с другой стороны, если этого не сделать, то как мне тогда перехватывать этот сигнал чтобы корректно завершать работу программы?

"Interrupted system call"
Отправлено Forth , 23-Авг-07 10:09 
Надо не вываливаться с ошибкой по EINTR, а просто повторно вызывать прерванный системный вызов.
"Interrupted system call"
Отправлено dimonna , 23-Авг-07 10:19 
>Надо не вываливаться с ошибкой по EINTR, а просто повторно вызывать прерванный
>системный вызов.

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

"Interrupted system call"
Отправлено Forth , 23-Авг-07 10:48 
>>Надо не вываливаться с ошибкой по EINTR, а просто повторно вызывать прерванный
>>системный вызов.
>
>Проблема не в том что я вываливаюсь или не вываливаюсь с ошибкой,
>а в том что перед тем как я получу сигнал с
>момента входа в recv проходят десятки часов, т.е. вызвав recv тред
>спит до тех пор пока его не трасернешь или не подцепишь
>и отцебишь дебагером - только тогда приходит сигнал.

Блокируете SIGINT? Хотя дебаггер и не должен вроде маску сигналов процесса менять, но черт его знает.

"Interrupted system call"
Отправлено dimonna , 23-Авг-07 10:55 
>[оверквотинг удален]
>>>системный вызов.
>>
>>Проблема не в том что я вываливаюсь или не вываливаюсь с ошибкой,
>>а в том что перед тем как я получу сигнал с
>>момента входа в recv проходят десятки часов, т.е. вызвав recv тред
>>спит до тех пор пока его не трасернешь или не подцепишь
>>и отцебишь дебагером - только тогда приходит сигнал.
>
>Блокируете SIGINT? Хотя дебаггер и не должен вроде маску сигналов процесса менять,
>но черт его знает.

я только что проверил - даже если не блокировать не обин сигнал то картина не меняется - всеравно EINTR не приходит пока не дернешь процесс дебагером - просто висит и все, в итоге после 100-200 тысяч циклов все треды попадают в это состояние и работа программы останавливается

"Interrupted system call"
Отправлено vic , 23-Авг-07 10:56 
>[оверквотинг удален]
>...
>exit(0);
>}
>
>signal(SIGINT, signal_handler);
>
>??
>
>Хотя с другой стороны, если этого не сделать, то как мне тогда
>перехватывать этот сигнал чтобы корректно завершать работу программы?

1. exit() нет в списке signal safe function, есть только _exit() и _Exit()
http://www.opengroup.org/onlinepubs/009695399/functions/xsh_...
Это первый нюанс. Во-вторых, раз вы вызываете exit() из обработчика, есть сильное подозрение что у вас проблемы с освобождением ресурсов (закрытие дескрипторов, free()/delete на все выделенное). В-третьих:
void signal_handler(int sig)
{
   flag_stop = true; // ух! объявление переменной должно быть хитрым :) (sig_atomic_t)
}
далее в main():
..
while(!flag_stop)
{
// тут крутимся это как бы традиционная схема.
}
..


2. а как связаны таймауты и recv? Вы не можете поставить таймаут на recv(), это в select() отслеживается по хорошему, иначе что-то не так, видимо надо постить кусок кода где recv :)

"Interrupted system call"
Отправлено dimonna , 23-Авг-07 11:17 
>[оверквотинг удален]
>>
>>??
>>
>>Хотя с другой стороны, если этого не сделать, то как мне тогда
>>перехватывать этот сигнал чтобы корректно завершать работу программы?
>
>1. exit() нет в списке signal safe function, есть только _exit() и
>_Exit()
>http://www.opengroup.org/onlinepubs/009695399/functions/xsh_...
>Это первый нюанс.

Во-вторых, раз вы вызываете exit() из обработчика, есть сильное
>[оверквотинг удален]
>}
>далее в main():
>..
>while(!flag_stop)
>{
>// тут крутимся это как бы традиционная схема.
>}
>..
>
>

Возможно, но сюда дело не доходит - при попадании в этот обработчик пишется
мессага сперва, что проверяется по kill - поэтому я уверен что этот моент не
имеет отношения к зависаниям, но за информацию спасибо!!
Кстати, sig_atomic_t это обычный int, почему тогда "особым"? :)

>2. а как связаны таймауты и recv? Вы не можете поставить таймаут
>на recv(), это в select() отслеживается по хорошему, иначе что-то не
>так, видимо надо постить кусок кода где recv :)

вот смотрите

// Устанавливаю таймаут на чтение
if (setsockopt(m_socket, SOL_SOCKET, SO_RCVTIMEO, (const char*)&timeout, sizeof(timeout))==-1)

...

// Собственно чтение
fprintf(stderr, "start\n");
ssize_t readed=::recv(m_socket, tmp, pageSize, 0);
fprintf(stderr, "end\n");

Так вот, если описаннае мною проблемма случилась, то "end" я не увижу до тех пор пока не проведу фокус с strace или gdb и я буду видеть только "start".

Вот к примеру что показала strace когда осталось 5 таких зависших тредов:
Process 19352 attached with 6 threads - interrupt to quit
[pid 19092] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 19151] futex(0x488260, FUTEX_WAKE, 1 <unfinished ...>
[pid 19183] time( <unfinished ...>
[pid 19213] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19339] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19352] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19151] <... futex resumed> )       = 0
[pid 19183] <... time resumed> NULL)    = 1187852478
[pid 19151] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19183] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 117) = 117
[pid 19183] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19339] <... futex resumed> )       = 0
[pid 19183] <... futex resumed> )       = 1
[pid 19339] time( <unfinished ...>
[pid 19183] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19339] <... time resumed> NULL)    = 1187852478
[pid 19339] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 117) = 117
[pid 19339] futex(0x8886014, FUTEX_WAKE, 1) = 1
[pid 19213] <... futex resumed> )       = 0
[pid 19339] time( <unfinished ...>
[pid 19213] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19339] <... time resumed> NULL)    = 1187852478
[pid 19339] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 91) = 91
[pid 19339] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19352] <... futex resumed> )       = 0
[pid 19339] <... futex resumed> )       = 1
[pid 19352] time( <unfinished ...>
[pid 19339] shutdown(85, 2 /* send and receive */ <unfinished ...>
[pid 19352] <... time resumed> NULL)    = 1187852478
[pid 19339] <... shutdown resumed> )    = 0
[pid 19352] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 117 <unfinished ...>
[pid 19339] close(85)                   = 0
[pid 19352] <... write resumed> )       = 117
[pid 19339] read(6,  <unfinished ...>
[pid 19352] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19339] <... read resumed> "", 131072) = 0
[pid 19151] <... futex resumed> )       = 0
[pid 19352] <... futex resumed> )       = 1
[pid 19339] time( <unfinished ...>
[pid 19151] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19352] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19339] <... time resumed> NULL)    = 1187852478
[pid 19339] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 92) = 92
[pid 19339] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19183] <... futex resumed> )       = 0
[pid 19339] <... futex resumed> )       = 1
[pid 19183] time( <unfinished ...>
[pid 19339] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19183] <... time resumed> NULL)    = 1187852478
[pid 19183] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 91) = 91
[pid 19183] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19213] <... futex resumed> )       = 0
[pid 19183] <... futex resumed> )       = 1
[pid 19213] time( <unfinished ...>
[pid 19183] shutdown(181, 2 /* send and receive */ <unfinished ...>
[pid 19213] <... time resumed> NULL)    = 1187852478
[pid 19183] <... shutdown resumed> )    = 0
[pid 19213] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 117 <unfinished ...>
[pid 19183] close(181 <unfinished ...>
[pid 19213] <... write resumed> )       = 117
[pid 19183] <... close resumed> )       = 0
[pid 19213] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19183] read(6, "", 131072)         = 0
[pid 19151] <... futex resumed> )       = 0
[pid 19213] <... futex resumed> )       = 1
[pid 19183] time( <unfinished ...>
[pid 19151] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19213] munmap(0x1100000, 1048576 <unfinished ...>
[pid 19183] <... time resumed> NULL)    = 1187852478
[pid 19213] <... munmap resumed> )      = 0
[pid 19183] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 92 <unfinished ...>
[pid 19213] mmap2(0x81f2000, 32768, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 19183] <... write resumed> )       = 92
[pid 19213] <... mmap2 resumed> )       = 0x81f2000
[pid 19183] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19352] <... futex resumed> )       = 0
[pid 19213] time( <unfinished ...>
[pid 19183] <... futex resumed> )       = 1
[pid 19352] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19213] <... time resumed> NULL)    = 1187852478
[pid 19183] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19213] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 91) = 91
[pid 19213] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19339] <... futex resumed> )       = 0
[pid 19213] <... futex resumed> )       = 1
[pid 19339] time( <unfinished ...>
[pid 19213] shutdown(182, 2 /* send and receive */ <unfinished ...>
[pid 19339] <... time resumed> NULL)    = 1187852478
[pid 19213] <... shutdown resumed> )    = 0
[pid 19339] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 100 <unfinished ...>
[pid 19213] close(182 <unfinished ...>
[pid 19339] <... write resumed> )       = 100
[pid 19213] <... close resumed> )       = 0
[pid 19339] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19151] <... futex resumed> )       = 0
[pid 19213] read(6,  <unfinished ...>
[pid 19339] <... futex resumed> )       = 1
[pid 19151] time( <unfinished ...>
[pid 19213] <... read resumed> "", 131072) = 0
[pid 19339] munmap(0x8add6000, 10489856 <unfinished ...>
[pid 19151] <... time resumed> NULL)    = 1187852478
[pid 19213] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19339] <... munmap resumed> )      = 0
[pid 19151] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 117 <unfinished ...>
[pid 19339] _exit(0)                    = ?
Process 19339 detached
[pid 19151] <... write resumed> )       = 117
[pid 19151] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19352] <... futex resumed> )       = 0
[pid 19151] <... futex resumed> )       = 1
[pid 19352] time( <unfinished ...>
[pid 19151] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19352] <... time resumed> NULL)    = 1187852478
[pid 19352] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 91) = 91
[pid 19352] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19183] <... futex resumed> )       = 0
[pid 19352] <... futex resumed> )       = 1
[pid 19183] time( <unfinished ...>
[pid 19352] shutdown(242, 2 /* send and receive */ <unfinished ...>
[pid 19183] <... time resumed> NULL)    = 1187852478
[pid 19352] <... shutdown resumed> )    = 0
[pid 19183] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 99 <unfinished ...>
[pid 19352] close(242 <unfinished ...>
[pid 19183] <... write resumed> )       = 99
[pid 19352] <... close resumed> )       = 0
[pid 19183] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19213] <... futex resumed> )       = 0
[pid 19352] read(6,  <unfinished ...>
[pid 19183] <... futex resumed> )       = 1
[pid 19213] time( <unfinished ...>
[pid 19352] <... read resumed> "", 131072) = 0
[pid 19183] munmap(0x3f19f000, 10489856 <unfinished ...>
[pid 19213] <... time resumed> NULL)    = 1187852478
[pid 19352] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19183] <... munmap resumed> )      = 0
[pid 19213] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 92 <unfinished ...>
[pid 19183] _exit(0)                    = ?
Process 19183 detached
[pid 19213] <... write resumed> )       = 92
[pid 19213] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19151] <... futex resumed> )       = 0
[pid 19213] <... futex resumed> )       = 1
[pid 19151] time( <unfinished ...>
[pid 19213] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19151] <... time resumed> NULL)    = 1187852478
[pid 19151] write(4, "\33[0;31;40mEE 20070823 07:01:18 ["..., 91) = 91
[pid 19151] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19352] <... futex resumed> )       = 0
[pid 19151] <... futex resumed> )       = 1
[pid 19352] time( <unfinished ...>
[pid 19151] shutdown(63, 2 /* send and receive */ <unfinished ...>
[pid 19352] <... time resumed> NULL)    = 1187852478
[pid 19151] <... shutdown resumed> )    = 0
[pid 19352] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 92 <unfinished ...>
[pid 19151] close(63 <unfinished ...>
[pid 19352] <... write resumed> )       = 92
[pid 19151] <... close resumed> )       = 0
[pid 19352] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19213] <... futex resumed> )       = 0
[pid 19151] read(6,  <unfinished ...>
[pid 19352] <... futex resumed> )       = 1
[pid 19213] time( <unfinished ...>
[pid 19151] <... read resumed> "", 131072) = 0
[pid 19352] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19213] <... time resumed> NULL)    = 1187852478
[pid 19151] futex(0x8886014, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid 19213] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 100) = 100
[pid 19213] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19352] <... futex resumed> )       = 0
[pid 19213] <... futex resumed> )       = 1
[pid 19352] time( <unfinished ...>
[pid 19213] munmap(0x7b1ff000, 10489856 <unfinished ...>
[pid 19352] <... time resumed> NULL)    = 1187852478
[pid 19213] <... munmap resumed> )      = 0
[pid 19352] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 100 <unfinished ...>
[pid 19213] _exit(0)                    = ?
Process 19213 detached
[pid 19352] <... write resumed> )       = 100
[pid 19352] futex(0x8886014, FUTEX_WAKE, 1 <unfinished ...>
[pid 19151] <... futex resumed> )       = 0
[pid 19352] <... futex resumed> )       = 1
[pid 19151] time( <unfinished ...>
[pid 19352] munmap(0x38394000, 10489856 <unfinished ...>
[pid 19151] <... time resumed> NULL)    = 1187852478
[pid 19352] <... munmap resumed> )      = 0
[pid 19151] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 92 <unfinished ...>
[pid 19352] _exit(0)                    = ?
Process 19352 detached
[pid 19151] <... write resumed> )       = 92
[pid 19151] futex(0x8886014, FUTEX_WAKE, 1) = 0
[pid 19151] time(NULL)                  = 1187852478
[pid 19151] write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 99) = 99
[pid 19151] munmap(0x7f9c4000, 10489856) = 0
[pid 19151] _exit(0)                    = ?
Process 19151 detached
<... restart_syscall resumed> )         = 0
time(NULL)                              = 1187852478
write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 111) = 111
time(NULL)                              = 1187852478
write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 82) = 82
time(NULL)                              = 1187852478
write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 76) = 76
time(NULL)                              = 1187852478
write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 87) = 87
close(8)                                = 0
munmap(0xb7f8a000, 131072)              = 0
close(6)                                = 0
munmap(0xb7569000, 131072)              = 0
time(NULL)                              = 1187852478
write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 73) = 73
unlink("checker.conf.pid")              = 0
time(NULL)                              = 1187852478
write(4, "\33[1;32;40mII 20070823 07:01:18 ["..., 82) = 82
exit_group(0)                           = ?
Process 19092 detached

"Interrupted system call"
Отправлено vic , 23-Авг-07 11:34 
>Возможно, но сюда дело не доходит - при попадании в этот обработчик
>пишется
>мессага сперва, что проверяется по kill - поэтому я уверен что этот
>моент не
>имеет отношения к зависаниям, но за информацию спасибо!!
>Кстати, sig_atomic_t это обычный int, почему тогда "особым"? :)

Да я вижу не хорошую конструкцию и начинаю ворчать ;)
особым образом потому что строго говоря а) компилятор может заоптимизировать while(variable) до while(1) если с его точки зрения переменная не меняется (volatile) б) при многопоточности и мультипроцессорности для разделяемых ресурсов следует юзать средства атомарного доступа/изменения.
вот типа умничаю :)

>// Устанавливаю таймаут на чтение
>if (setsockopt(m_socket, SOL_SOCKET, SO_RCVTIMEO, (const char*)&timeout, sizeof(timeout))==-1)

используйте select()/poll() т.к. SO_RCVTIMEO не везде поддерживается.

"Interrupted system call"
Отправлено dimonna , 23-Авг-07 11:38 
>>// Устанавливаю таймаут на чтение
>>if (setsockopt(m_socket, SOL_SOCKET, SO_RCVTIMEO, (const char*)&timeout, sizeof(timeout))==-1)
>
>используйте select()/poll() т.к. SO_RCVTIMEO не везде поддерживается.

Да, пробую сейчас poll перед чтением, может поможет, а вот SO_RCVTIMEO поддерживается однозначно - я уже экспериментировал с этим - ставил разные таймауты и натравливал чтобы на них попасть - все точно срабатывает.

"Interrupted system call"
Отправлено dimonna , 23-Авг-07 12:59 
таак, помоему селект перед чтением помог. а вот от пола результата никакого не было. продолжу тестирование пока, спасибо!