thread에서 prinf를 출력하다가 deadlock 상태가 발생할 수 있나요?
5개의 thread가 돌면서 printf 를 찍고있습니다.
그러전중 10분~1시간 사이에 무작위로 thread가 모두 lock 상태에 걸리는데요..
아래 gdb를 통해 thread stack 로그입니다..
vprintf 다음에 lock 걸린걸 볼수 있는데요? 어떻게 해결해야하나요?
Thread 6 (Thread 1085351040 (LWP 525)):
#0 0x4002cbbc in pthread_join () from /lib/libpthread.so.0
#1 0x00023744 in Thread::join (this=0xdd718) at src/interface/Thread.cpp:23
#2 0x0000c358 in MuMain::run (this=0xbef33cbc) at src/MuMain.cpp:30
#3 0x000236bc in Thread::run_ (pthis_=0x0) at src/interface/Thread.cpp:11
#4 0x00000000 in ?? ()
Thread 5 (Thread 1093756032 (LWP 577)):
#0 0x402a411c in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x40214d10 in vfprintf () from /lib/libc.so.6
#2 0x40219a30 in printf () from /lib/libc.so.6
#3 0x0001816c in FpgaControl::run (this=0x40b11cb4) at src/control/FpgaControl.cpp:7
#4 0x000236bc in Thread::run_ (pthis_=0x40b11cb4) at src/interface/Thread.cpp:11
#5 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#6 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 4 (Thread 1102144640 (LWP 578)):
#0 0x402a411c in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x40214d10 in vfprintf () from /lib/libc.so.6
#2 0x40219a30 in printf () from /lib/libc.so.6
#3 0x0001d4c4 in FramerControl::run (this=0x40b11cf8) at src/control/FramerControl.cpp:9
#4 0x000236bc in Thread::run_ (pthis_=0x40b11cf8) at src/interface/Thread.cpp:11
#5 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#6 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 3 (Thread 1110697088 (LWP 579)):
#0 0x402a40f4 in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x40214d10 in vfprintf () from /lib/libc.so.6
#2 0x40219a30 in printf () from /lib/libc.so.6
#3 0x00023cbc in Timer::timer_handler (this=0xdd718) at src/interface/utill/Timer.cpp:13
#4 0x00023c84 in timer_handler_wrapper (signum=26) at src/interface/utill/Timer.cpp:13
#5
#6 0x40211158 in vfprintf () from /lib/libc.so.6
#7 0x40219a30 in printf () from /lib/libc.so.6
#8 0x00051458 in Epoll::onEvent (this=0x41b17008, event=
{events = 1, data = {ptr = 0xf, fd = 15, u32 = 15, u64 = 15}}) at src/interface/Epoll.cpp:8
#9 0x0005126c in Epoll::run (this=0x41b17008) at src/interface/Epoll.cpp:8
#10 0x000236bc in Thread::run_ (pthis_=0x41b17008) at src/interface/Thread.cpp:11
#11 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#12 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 2 (Thread 1119085696 (LWP 580)):
#0 0x402a411c in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x40214d10 in vfprintf () from /lib/libc.so.6
#2 0x40219a30 in printf () from /lib/libc.so.6
#3 0x00023cbc in Timer::timer_handler (this=0xdd718) at src/interface/utill/Timer.cpp:13
#4 0x00023c84 in timer_handler_wrapper (signum=26) at src/interface/utill/Timer.cpp:13
#5
#6 0x00023ba4 in Timer::run (this=0xdd718) at src/interface/utill/Timer.cpp:13
#7 0x000236bc in Thread::run_ (pthis_=0xdd718) at src/interface/Thread.cpp:11
#8 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#9 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 1 (Thread 1073869376 (LWP 524)):
#0 0x4002cbbc in pthread_join () from /lib/libpthread.so.0
#1 0x00023744 in Thread::join (this=0xbef33cbc) at src/interface/Thread.cpp:23
#2 0x0000c83c in main (argc=1, argv=0xbef33e24) at src/main.cpp:9
#0 0x4002cbbc in pthread_join () from /lib/libpthread.so.0
일반적으로 이런 종류의 데드락 문제는 해결하기 무척
일반적으로 이런 종류의 데드락 문제는 해결하기 무척 어렵습니다.
지금은 빼고요. 지금은 쉽네요. ㅋ
누가 봐도 Thread 3의 stack trace가 이상합니다.
printf->vfprintf->?->timer_handler_wrapper->Timer::timer_handler->printf->vfprintf
printf->vfprintf가 반복되었죠. printf가 재귀 함수일 리도 없는데 왜 그럴까요?
그야, timer_handler_wrapper가, 그 이름이 암시하듯 "시각이 돼서" 돌연 실행되었기 때문이겠죠.
즉 이렇게 된 겁니다:
1. Epoll::onEvent에서 printf를 호출함
2. printf가 vfprintf를 호출하고, 이 함수는 __lll_lock_wait_private를 호출해서 lock을 잡음
3. lock을 잡은 상태에서 일 하고 있는데 운수 나쁘게도 비동기적인 메커니즘 (시그널 등?)에 의해 실행 흐름이 넘어감
4. 실행 흐름을 받은 timer_handler_wrapper가 Timer::timer_handler를 호출
5. Timer::timer_handler는 printf를, printf는 vfprintf를 호출
6. vfprintf는 (늘 그렇듯) __lll_lock_wait_private를 호출함. 어? 누가 lock을 잡았네? 풀릴 때까지 대기
7. (nobody can reach here.)
컴퓨터에서 동기화 메커니즘인 lock은 대개 내가 잡은 상태에서 한 번 더 잡으려 하면 무한히 블록당합니다. 그게 구현이 간단해서요. 그런 간단한 lock을 쓰는 경우에 lock을 두 번 잡지 않게 보장할 책임은 프로그래머에게 전가됩니다.
이 경우에는, 예컨대 Timer::timer_handler와 같이 남의 실행 흐름을 끊고 들어가는 함수에서는 printf 함수를 써서는 안 되었던 겁니다.
여기에 한표
Signal handler에서 사용할 수 있는 함수의 종류는 *매우* 제한되어 있습니다.
http://man7.org/linux/man-pages/man7/signal-safety.7.html
일단 malloc/free/new/delete/혹은 내부적으로 이런 함수를 부르는 함수는 다 안됩니다. -_-
꼭 화면이나 파일에 출력을 하고 싶다면 printf 대신 write를 사용하시면 됩니다. (sprintf는 공식적으로는 안전하지 않다고 하지만 제 경험상 쓸 수 있었습니다. 뭐, 물론 안전하다고 보장은 못합니다. -_-)
쓰레드나 타이머 동작이 deadlock의 원인은 아닙니다.
현재 stack trace를 보면 lock이 각 thread당 1개씩만 보입니다. 즉, lock 자체는 제대로 되고 있다고 볼 수 있습니다. 저 상황에서는 lock이 정상적으로 풀리지 않는 이유를 추정해야 하는데 불행히도 이런 경우는 대부분 어디선가 포인터를 잘못 사용하고 있거나 배열의 범위를 넘어서 데이터를 쓰고 있는 경우(즉, 데이터 오염)입니다. 즉, 코드 전체를 다시 리뷰 해야 할 상황으로 보입니다. 현재 보이는 데이터로는 이 정도만 확실하고 나머지는 추정 불가입니다.
추측해보면 printf로 어떤 문제의 원인을 찾는 중으로 보이는데 이 현상 자체도 그 원인에 의한 부작용일 것으로 생각됩니다.
답변 감사합니다^^
일단 문제가 될것같은 printf 를 2개빼고 모두 지우고 다시 실행시켜보니 전혀다른 상황이 발생하네요 ㅎㅎ
아래는 thread 정보 인데 참.. 너무 어렵네요 ㅠㅠ
아래 로그를 보면서 이상한게 발견됐습니다.
thread 5번에 #28에서 FramerControl클래스에서 MuControl_Common class로 데이터를 보냅니다.
#27번을 보면 MuControl_Common으로 data를 받는것이 보이는데 마지막에 at header/interface/util/Crc.hpp:48
라는 문구가 보입니다. 28, 27에서 사용한 함수들은 at header/interface/util/Crc.hpp:48 이파일과는 전혀
무관한 파일인데 저문구가 왜 뜨는걸까요? 위에 분 말처럼 포인터나 메모리를 침범하여 데이터 오염이 일어난걸까요?
Thread 7 (Thread 1119085696 (LWP 4371)):
#0 0x402a411c in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x40240670 in arena_get2 () from /lib/libc.so.6
#2 0x40242c34 in malloc () from /lib/libc.so.6
#3 0x4009e5e4 in operator new () from /lib/libstdc++.so.6
#4 0x00015648 in __gnu_cxx::new_allocator::allocate (this=0x42b3d994,
__n=2) at header/interface/util/Crc.hpp:48
#5 0x00013a08 in std::_Vector_base >::_M_allocate
(this=0x42b3d994, __n=2) at header/interface/util/Crc.hpp:48
#6 0x00014acc in std::_Vector_base >::_M_create_storage (this=0x42b3d994, __n=2) at header/interface/util/Crc.hpp:48
#7 0x00013074 in std::_Vector_base >::_Vector_base
(this=0x42b3d994, __n=2, __a=@0x42b3d96c)
at header/interface/util/Crc.hpp:48
#8 0x00011ba4 in std::vector >::vector (
this=0x42b3d994, __x=@0xdc384) at header/interface/util/Crc.hpp:48
#9 0x0000e620 in MuControl_Common::checkCommunicationFailAalrm (this=0xa8220)
at header/interface/util/Crc.hpp:48
#10 0x000170bc in std::_Mem_fn::operator() (
this=0xe2b28, __object=0xa8220) at header/interface/util/Crc.hpp:48
#11 0x00016118 in _ZNSt5_BindIFSt7_Mem_fnIM16MuControl_CommonFvvEEPS1_EE6__callIvIEILj0EEEET_OSt5tupleIIDpT0_EESt12_Index_tupleIIXspT1_EEE (this=0xe2b28,
__args=@0x42b3d9f8) at header/interface/util/Crc.hpp:48
#12 0x00014478 in _ZNSt5_BindIFSt7_Mem_fnIM16MuControl_CommonFvvEEPS1_EEclIIEvEET0_DpOT_ (this=0xe2b28) at header/interface/util/Crc.hpp:48
#13 0x00012eec in std::_Function_handler ()(MuControl_Common*)> >::_M_invoke (
__functor=@0xdc7f0) at header/interface/util/Crc.hpp:48
#14 0x00023dfc in std::function::operator() (this=0xdc7f0)
at src/interface/utill/Timer.cpp:12
#15 0x0002382c in Timer::timer_handler (this=0xdc718)
at src/interface/utill/Timer.cpp:12
#16 0x00023788 in timer_handler_wrapper (signum=26)
at src/interface/utill/Timer.cpp:12
#17
#18 0x000236a8 in Timer::run (this=0xdc718)
at src/interface/utill/Timer.cpp:12
#19 0x00023200 in Thread::run_ (pthis_=0xdc718) at src/interface/Thread.cpp:11
#20 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#21 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 6 (Thread 1110697088 (LWP 4370)):
#0 0x402a40f4 in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x4023dcfc in ptmalloc_lock_all () from /lib/libc.so.6
#2 0x40265f94 in fork () from /lib/libc.so.6
#3 0x4020c56c in do_system () from /lib/libc.so.6
#4 0x4020c9ec in system () from /lib/libc.so.6
#5 0x0000fd14 in MuControl_Common::notifyEvent (this=0xa8220,
buffer=0x42338f4c "\026\026\026\026?033\002Y\037?002Q", len=610,
recvIp=
{static npos = , _M_dataplus = {> = {<__gnu_cxx::new_allocator> = {}, }, _M_p = 0xdcc74 "12.31.240.240"}}) at header/interface/util/Crc.hpp:48
#6 0x000511ec in Epoll::eventSocket (this=0x41b17008, event=
{events = 1, data = {ptr = 0xd, fd = 13, u32 = 13, u64 = 13}})
at src/interface/Epoll.cpp:7
#7 0x00050e50 in Epoll::onEvent (this=0x41b17008, event=
{events = 1, data = {ptr = 0xd, fd = 13, u32 = 13, u64 = 13}})
at src/interface/Epoll.cpp:7
#8 0x00050cd4 in Epoll::run (this=0x41b17008) at src/interface/Epoll.cpp:7
#9 0x00023200 in Thread::run_ (pthis_=0x41b17008)
at src/interface/Thread.cpp:11
#10 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#11 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 5 (Thread 1102144640 (LWP 4369)):
#0 0x402a40f4 in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x40240670 in arena_get2 () from /lib/libc.so.6
#2 0x40242c34 in malloc () from /lib/libc.so.6
#3 0x4009e5e4 in operator new () from /lib/libstdc++.so.6
#4 0x00015648 in __gnu_cxx::new_allocator::allocate (this=0x41b158bc,
__n=2) at header/interface/util/Crc.hpp:48
#5 0x00013a08 in std::_Vector_base >::_M_allocate
(this=0x41b158bc, __n=2) at header/interface/util/Crc.hpp:48
#6 0x00014acc in std::_Vector_base >::_M_create_storage (this=0x41b158bc, __n=2) at header/interface/util/Crc.hpp:48
#7 0x00013074 in std::_Vector_base >::_Vector_base
(this=0x41b158bc, __n=2, __a=@0x41b15894)
at header/interface/util/Crc.hpp:48
#8 0x00011ba4 in std::vector >::vector (
this=0x41b158bc, __x=@0xdc384) at header/interface/util/Crc.hpp:48
#9 0x0000e620 in MuControl_Common::checkCommunicationFailAalrm (this=0xa8220)
at header/interface/util/Crc.hpp:48
#10 0x000170bc in std::_Mem_fn::operator() (
this=0xe2b28, __object=0xa8220) at header/interface/util/Crc.hpp:48
#11 0x00016118 in _ZNSt5_BindIFSt7_Mem_fnIM16MuControl_CommonFvvEEPS1_EE6__callIvIEILj0EEEET_OSt5tupleIIDpT0_EESt12_Index_tupleIIXspT1_EEE (this=0xe2b28,
__args=@0x41b15920) at header/interface/util/Crc.hpp:48
#12 0x00014478 in _ZNSt5_BindIFSt7_Mem_fnIM16MuControl_CommonFvvEEPS1_EEclIIEvEET0_DpOT_ (this=0xe2b28) at header/interface/util/Crc.hpp:48
#13 0x00012eec in std::_Function_handler ()(MuControl_Common*)> >::_M_invoke (
__functor=@0xdc7f0) at header/interface/util/Crc.hpp:48
#14 0x00023dfc in std::function::operator() (this=0xdc7f0)
at src/interface/utill/Timer.cpp:12
#15 0x0002382c in Timer::timer_handler (this=0xdc718)
at src/interface/utill/Timer.cpp:12
#16 0x00023788 in timer_handler_wrapper (signum=26)
at src/interface/utill/Timer.cpp:12
#17
#18 0x402406b0 in _int_malloc () from /lib/libc.so.6
#19 0x40242c4c in malloc () from /lib/libc.so.6
#20 0x4009e5e4 in operator new () from /lib/libstdc++.so.6
#21 0x00015648 in __gnu_cxx::new_allocator::allocate (this=0x41b15d34,
__n=2) at header/interface/util/Crc.hpp:48
#22 0x00013a08 in std::_Vector_base >::_M_allocate
(this=0x41b15d34, __n=2) at header/interface/util/Crc.hpp:48
#23 0x00014acc in std::_Vector_base >::_M_create_storage (this=0x41b15d34, __n=2) at header/interface/util/Crc.hpp:48
#24 0x00013074 in std::_Vector_base >::_Vector_base
(this=0x41b15d34, __n=2, __a=@0x41b15d04)
at header/interface/util/Crc.hpp:48
#25 0x00011ba4 in std::vector >::vector (
this=0x41b15d34, __x=@0xdc3e4) at header/interface/util/Crc.hpp:48
#26 0x0000e018 in MuControl_Common::checkLdPdPowerAlarm (this=0xa8220,
band=1, port=5) at header/interface/util/Crc.hpp:48
#27 0x0000d754 in MuControl_Common::receiveSfpInfoFromFramer (this=0xa8220,
sfp_data=
{band = 1 '\001', port = 5 '\005', los = 1 '\001', insert = 2 '\002', txFail = 4 '\004', ld_power_dbm = 241 '?, pd_power_dbm = 193 '?, temp_msb = 0 '\0', temp_lsb = 0 '\0', pd_alarm_status = 0 '\0', ld_alarm_status = 0 '\0', pd_alarm_cnt = 0 '\0', ld_alarm_cnt = 0 '\0', pd_normal_cnt = 0 '\0', ld_normal_cnt = 0 '\0'}) at header/interface/util/Crc.hpp:48
#28 0x0001daac in FramerControl::sendFramerStatus (this=0x40b11cf8)
at src/control/FramerControl.cpp:9
#29 0x0001d1e8 in FramerControl::run (this=0x40b11cf8)
at src/control/FramerControl.cpp:9
#30 0x00023200 in Thread::run_ (pthis_=0x40b11cf8)
at src/interface/Thread.cpp:11
#31 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#32 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 4 (Thread 1093756032 (LWP 4368)):
#0 0x402a411c in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x40240670 in arena_get2 () from /lib/libc.so.6
#2 0x40242c34 in malloc () from /lib/libc.so.6
#3 0x4009e5e4 in operator new () from /lib/libstdc++.so.6
#4 0x0001bc0c in __gnu_cxx::new_allocator >::allocate (this=0xdcd08, __n=1) at src/control/FpgaControl.cpp:7
#5 0x0001ad78 in std::_List_base >::_M_get_node (this=0xdcd08) at src/control/FpgaControl.cpp:7
#6 0x00019e70 in _ZNSt4listIN4sigc9slot_baseESaIS1_EE14_M_create_nodeIIS1_EEEPSt10_List_nodeIS1_EDpOT_ (this=0xdcd08) at src/control/FpgaControl.cpp:7
#7 0x000194e0 in _ZNSt4listIN4sigc9slot_baseESaIS1_EE7emplaceIIS1_EEESt14_List_iteratorIS1_ES6_DpOT_ (this=0xdcd08, __position={_M_node = 0xdcd08})
at src/control/FpgaControl.cpp:7
#8 0x00018a50 in std::list >::insert (this=0xdcd08, __position={_M_node = 0xdcd08}, __x=@0x41315d40)
at src/control/FpgaControl.cpp:7
#9 0x00018584 in sigc::internal::temp_slot_list::temp_slot_list (
this=0x41315d70, slots=@0xdcd08) at src/control/FpgaControl.cpp:7
#10 0x00019c1c in sigc::internal::signal_emit1::emit (impl=0xdcd00, _A_a1=@0x41315db3) at src/control/FpgaControl.cpp:7
#11 0x000193a8 in sigc::signal1::emit (
this=0x40b11cd8, _A_a1=@0x41315db3) at src/control/FpgaControl.cpp:7
#12 0x00018094 in FpgaControl::getMdtaTemperature (this=0x40b11cb4)
at src/control/FpgaControl.cpp:7
#13 0x00017ddc in FpgaControl::run (this=0x40b11cb4)
at src/control/FpgaControl.cpp:7
#14 0x00023200 in Thread::run_ (pthis_=0x40b11cb4)
at src/interface/Thread.cpp:11
#15 0x4002c5f4 in start_thread () from /lib/libpthread.so.0
#16 0x40298368 in clone () from /lib/libc.so.6
Backtrace stopped: frame did not save the PC
Thread 3 (Thread 1073869376 (LWP 4313)):
#0 0x4002cbbc in pthread_join () from /lib/libpthread.so.0
#1 0x00023288 in Thread::join (this=0xbef16c8c)
at src/interface/Thread.cpp:23
#2 0x0000c83c in main (argc=1, argv=0xbef16df4) at src/main.cpp:9
Thread 2 (Thread 1085351040 (LWP 4316)):
#0 0x4002cbbc in pthread_join () from /lib/libpthread.so.0
#1 0x00023288 in Thread::join (this=0xdc718) at src/interface/Thread.cpp:23
#2 0x0000c358 in MuMain::run (this=0xbef16c8c) at src/MuMain.cpp:30
#3 0x00023200 in Thread::run_ (pthis_=0x0) at src/interface/Thread.cpp:11
#4 0x00000000 in ?? ()
Thread 1 (LWP 4313):
#0 0x4002cbbc in pthread_join () from /lib/libpthread.so.0
#1 0x00023288 in Thread::join (this=0xbef16c8c)
at src/interface/Thread.cpp:23
#2 0x0000c83c in main (argc=1, argv=0xbef16df4) at src/main.cpp:9
#0 0x4002cbbc in pthread_join () from /lib/libpthread.so.0
...
아까도 말씀드렸지만, signal handler 안에서 쓸 수 있는 함수는 ***매우*** 제한되어 있습니다. vector 같은 건 당연히 못씁니다.
답변 감사합니다 ㅎㅎ
timmer가 돌면서 vector안에 있는 포인터 함수들을 실행해주는데.. vector가 안된다니..ㅠㅠ
std::function 으로 배열을 만드는것 또한 안될려나요..
timmer가 이렇게 제한적인데 다른분들은 어떻게들 사용하고 계신가요?
signal을 쓰지 않고 thread내에서 select로 대기 시간을 주어 이벤트를 발생하게 하는게 낫습니다.
select 또는 pselect로 일정 주기를 대기하는 쓰레드를 만들고 그 쓰레드 내에서 다른 원하는 작업을 호출하게 하면 됩니다. 아니면 timer signal handler에서 외부 semaphore를 조작하게 해서 다른 쓰레드의 실행을 멈췄다 풀어주는 식으로 해도 됩니다.
답변 감사합니다^^
답변 감사합니다^^
select와 pselect를 다뤄보지 않아 공부해봐야겠네요 ㅎㅎ
댓글 달기