Conference clt::cma

1548.0. "Blocked kernel, manager thread, exit, context??" by KERNEL::PULLEY (Come! while living waters flow) Thu May 22 1997 14:02

Hi,

I've a customer on Digital UNIX v4.0b, C++ v5.5-004.

If a number of clients are connected to the server, (E.g., 10), and they are
shutdown in quick succession, then it is likely, but not predictable,
that one or more server-side connection processes will become 'stuck'.
Here's what happens in pseudo-code (albeit in simplified form)...
I think it gets stuck in pthreadlib.so, and in three out of four of the examples
below, is says something about a blocked kernel.
Is this likely to be something wrong in the way he's doing things or a problem
with the threads?

Thanks for any suggestions,
Steve.

SERVER CODE (problem occurs during exit()...)
-----------

while( !receivedQuit )
{
    Listen( listeningSocket );
    conSocket = Accept( listeningSocket );

    for each conSocket
    {
        // Create connection process.
        fork();
        if( parent )
            close( conSocket );
        else if( child )
        {
            close( listeningSocket );

            // Create connection thread.
            conThread = pthread_create( conSocket );
            pthread_start( conSocket );
            pthread_join( conSocket );

            close( conSocket );

            exit( retVal );
        }
    }
}


--------------------------------------------------------------------------------
Welcome to the Ladebug Debugger Version 4.0-25
------------------ 
object file name: Debug/RACSd 
Reading symbolic information ...done
Attached to process id 1624  ....
Thread received signal INT
stopped at [nxm_idle: ??? 0x3ff8053ea8c]	
(ladebug) thread 1
Thread State      Substate        Policy     Priority Name
------ ---------- --------------- ---------- -------- -------------
>    1 blocked    mutex wait      throughput 11       default thread

(ladebug) where
>0  0x3ff8057c324 in /usr/shlib/libpthread.so
#1  0x3ff80579b30 in hstTransferContext(0x1, 0x140031278, 0x3ffc0183508, 0x4, 0x3ffc0188b50, 0x140075dc0) DebugInformationStrippedFromFile109:???
#2  0x3ff805643c4 in dspDispatch(0x14002fa10, 0x3ffc0183680, 0x3ffc0183508, 0x3ffc15267a8, 0x3ffc0082770, 0x0) DebugInformationStrippedFromFile89:???
#3  0x3ff80567cd0 in pthread_mutex_block(0x3ffc1526810, 0x3ffc1520220, 0x3ffc1520220, 0x3ffc15267a8, 0x3ffc0082770, 0x0) DebugInformationStrippedFromFile95:???
#4  0x3ff8057c120 in __pthread_mutex_lock(0x3ffc1520220, 0x3ffc1520220, 0x3ffc15267a8, 0x3ffc0082770, 0x0, 0x3ff80575568) DebugInformationStrippedFromFile111:???
#5  0x3ff80575564 in UnknownProcedure3FromFile103(0x3ffc15267a8, 0x3ffc0082770, 0x0, 0x3ff80575568, 0x3ff800d1fa0, 0x1400678c0) DebugInformationStrippedFromFile103:???
#6  0x3ff800d1f9c in free(0x3ff800d1fa0, 0x1400678c0, 0x1201cfee0, 0x0, 0x0, 0x3ff00000018) DebugInformationStrippedFromFile22:???
#7  0x1201cfedc in sntpdels(0x0, 0x0, 0x3ff000007eb, 0x3ff8057b414, 0x1201cda04, 0x11fffdab8) network/src/ntp/sntp.c:2150
#8  0x1201cda48 in sntpreap(0x12009e01c, 0x100000000, 0x1400678c0, 0x0, 0x3ff805643c8, 0x3ff000007eb) network/src/ntp/sntp.c:479
#9  0x3ff800d3b28 in __sigtramp(0x1400678c0, 0x0, 0x3ff805643c8, 0x3ff000007eb, 0x11fffdb78, 0x0) DebugInformationStrippedFromFile105:???
#10 0x3ff8057c1c8 in __pthread_mutex_unlock(0x3ffc1520220, 0x3ffc1520220, 0x3ffc15267a8, 0x3ffc0082770, 0x3ff800d1fb0, 0x3ff80575618) DebugInformationStrippedFromFile111:???
#11 0x3ff80575614 in UnknownProcedure5FromFile103(0x3ffc15267a8, 0x3ffc0082770, 0x3ff800d1fb0, 0x3ff80575618, 0x3ff800d1fc8, 0x3ffc008ae28) DebugInformationStrippedFromFile103:???
#12 0x3ff800d1fc4 in free(0x3ff800d1fc8, 0x3ffc008ae28, 0x3ff81d350a8, 0x14003cc00, 0x4, 0x14003cc00) DebugInformationStrippedFromFile22:???
#13 0x3ff81d350a4 in operator delete(0x3ff81d350a8, 0x14003cc00, 0x4, 0x14003cc00, 0x3ff81d44b14, 0x3ffc1527538) DebugInformationStrippedFromFile2:???
#14 0x3ff81d44b10 in ~filebuf(0x3ff81d44b14, 0x3ffc1527538, 0x3ff81d43b00, 0x3ffc1527538, 0x1, 0x14003ca80) DebugInformationStrippedFromFile2:???
#15 0x3ff81d43afc in ~Iostream_init(0x140035640, 0x11fffde50, 0x1, 0x3ffc1527600, 0x100000000, 0x14000a6a0) DebugInformationStrippedFromFile2:???
#16 0x3ff81d33078 in UnknownProcedure8FromFile2(0x1, 0x3ffc1527600, 0x100000000, 0x14000a6a0, 0x12005ca34, 0x11fffde50) DebugInformationStrippedFromFile2:???
#17 0x12005ca30 in Debug/RACSd
#18 0x12028bc08 in Debug/RACSd
(ladebug) show mutex
Mutex 1 (normal) "malloc" is locked by 1, 1 thread waiting
Mutex 2 (normal) "brk" is not locked
Mutex 3 (normal) "debActiveMubs" is not locked
Mutex 4 (normal) "known cond queue" is not locked
Mutex 5 (normal) "VM 0 lookaside" is not locked
Mutex 6 (normal) "VM 1 lookaside" is not locked
Mutex 7 (normal) "VM 2 lookaside" is not locked
Mutex 8 (normal) "VM 3 lookaside" is not locked
Mutex 9 (normal) "VM 4 lookaside" is not locked
Mutex 10 (normal) "VM 0 cache" is not locked
Mutex 11 (normal) "VM 1 cache" is not locked
Mutex 12 (normal) "VM 2 cache" is not locked
Mutex 13 (normal) "VM 3 cache" is not locked
Mutex 14 (normal) "thread 1 mutex" is not locked
Mutex 15 (normal) "thread 1 wait" is not locked
Mutex 16 (recursive) "Global lock" is not locked
Mutex 21 (normal) "debugger client registry" is not locked
Mutex 22 (normal) "mutex at 0x14003c800" is not locked
Mutex 23 (normal) "mutex at 0x14003c880" is not locked
Mutex 24 (normal) "mutex at 0x14003c8c0" is not locked
Mutex 25 (normal) "mutex at 0x14003c940" is locked
Mutex 26 (normal) "mutex at 0x14003c9c0" is not locked
Mutex 27 (normal) "mutex at 0x14003ca40" is not locked
Mutex 28 (normal) "mutex at 0x14003cac0" is not locked
Mutex 29 (normal) "mutex at 0x14003cb40" is not locked
Mutex 30 (normal) "mutex at 0x14003cf40" is not locked
Mutex 31 (normal) "thread -1 mutex" is not locked
Mutex 32 (normal) "thread -1 wait" is not locked
Mutex 33 (normal) "thread -2 mutex" is not locked
Mutex 34 (normal) "thread -2 wait" is not locked
Mutex 35 (normal) "mutex at 0x3ffc0082818" is not locked
Mutex 36 (normal) "thread 2 mutex" is not locked
Mutex 37 (normal) "thread 2 wait" is not locked
Mutex 38 (normal) "mutex at 0x14002b3a0" is not locked
Mutex 39 (normal) "mutex at 0x14002b3d0" is not locked
(ladebug) set $verbose
(ladebug) show mutex 1
Mutex 1 (normal) "malloc" (0x3ffc0082770, block 0x14002fa10) is locked by 1, 1
  thread waiting; ref count is 2; waiters: 1
(ladebug) quit

Welcome to the Ladebug Debugger Version 4.0-25
------------------ 
object file name: Debug/RACSd 
Reading symbolic information ...done
Attached to process id 31024  ....
Thread received signal INT
stopped at [nxm_idle: ??? 0x3ff8053ea8c]	
(ladebug) show thread
Thread State      Substate        Policy     Priority Name
------ ---------- --------------- ---------- -------- -------------
>*  -1 running                    idle        0       null thread for VP 0x0
     1 blocked    mutex wait      throughput 11       default thread
    -2 blocked    kernel          fifo       32       manager thread
(ladebug) thread 1
Thread State      Substate        Policy     Priority Name
------ ---------- --------------- ---------- -------- -------------
>    1 blocked    mutex wait      throughput 11       default thread

(ladebug) where
>0  0x3ff8057c324 in /usr/shlib/libpthread.so
#1  0x3ff80579b30 in hstTransferContext(0x1, 0x140031278, 0x3ffc0183508, 0x4, 0x3ffc0188b50, 0x1400e2d40) DebugInformationStrippedFromFile109:???
#2  0x3ff805643c4 in dspDispatch(0x14002fa10, 0x3ffc0183680, 0x3ffc0183508, 0x3ffc15267a8, 0x3ffc0082770, 0x3ff00000000) DebugInformationStrippedFromFile89:???
#3  0x3ff80567cd0 in pthread_mutex_block(0x3ffc0183508, 0x0, 0x3ffc1520220, 0x3ffc15267a8, 0x3ffc0082770, 0x0) DebugInformationStrippedFromFile95:???
#4  0x3ff8057c120 in __pthread_mutex_lock(0x0, 0x3ffc1520220, 0x3ffc15267a8, 0x3ffc0082770, 0x0, 0x3ff80575568) DebugInformationStrippedFromFile111:???
#5  0x3ff80575564 in UnknownProcedure3FromFile103(0x3ffc15267a8, 0x3ffc0082770, 0x0, 0x3ff80575568, 0x3ff800d1fa0, 0x3ffc0080310) DebugInformationStrippedFromFile103:???
#6  0x3ff800d1f9c in free(0x3ff800d1fa0, 0x3ffc0080310, 0x1201cfd50, 0x0, 0x0, 0x26) DebugInformationStrippedFromFile22:???
#7  0x1201cfd4c in sntpdels(0x0, 0x500000001, 0x3ff00006430, 0x0, 0x1201cd874, 0x140048031) network/src/ntp/sntp.c:2150
#8  0x1201cd8b8 in sntpreap(0x12009decc, 0x100000000, 0x140069800, 0x0, 0x3ffc018fb40, 0x100006430) network/src/ntp/sntp.c:479
#9  0x3ff800d3b28 in __sigtramp(0x140069800, 0x0, 0x3ffc018fb40, 0x100006430, 0x11fffdb38, 0x0) DebugInformationStrippedFromFile105:???
#10 0x3ff80568358 in pthread_mutex_block(0x3ffc1526810, 0x3ffc1520220, 0x3ffc1520220, 0x3ffc15267a8, 0x3ffc0082770, 0x0) DebugInformationStrippedFromFile95:???
#11 0x3ff8057c120 in __pthread_mutex_lock(0x3ffc1520220, 0x3ffc1520220, 0x3ffc15267a8, 0x3ffc0082770, 0x0, 0x3ff80575568) DebugInformationStrippedFromFile111:???
#12 0x3ff80575564 in UnknownProcedure3FromFile103(0x3ffc15267a8, 0x3ffc0082770, 0x0, 0x3ff80575568, 0x3ff800d1fa0, 0x14003cc00) DebugInformationStrippedFromFile103:???
#13 0x3ff800d1f9c in free(0x3ff800d1fa0, 0x14003cc00, 0x3ff81d350a8, 0x14003cc00, 0x4, 0x14003cc00) DebugInformationStrippedFromFile22:???
#14 0x3ff81d350a4 in operator delete(0x3ff81d350a8, 0x14003cc00, 0x4, 0x14003cc00, 0x3ff81d44b14, 0x3ffc1527538) DebugInformationStrippedFromFile2:???
#15 0x3ff81d44b10 in ~filebuf(0x3ff81d44b14, 0x3ffc1527538, 0x3ff81d43b00, 0x3ffc1527538, 0x1, 0x14003ca80) DebugInformationStrippedFromFile2:???
#16 0x3ff81d43afc in ~Iostream_init(0x140035640, 0x11fffdcf0, 0x1, 0x3ffc1527600, 0x100000000, 0x26) DebugInformationStrippedFromFile2:???
#17 0x3ff81d33078 in UnknownProcedure8FromFile2(0x1, 0x3ffc1527600, 0x100000000, 0x26, 0x12005c8b4, 0x11fffdcf0) DebugInformationStrippedFromFile2:???
#18 0x12005c8b0 in Debug/RACSd
#19 0x12028ba78 in Debug/RACSd
(ladebug) quit

Welcome to the Ladebug Debugger Version 4.0-25
------------------ 
object file name: Debug/RACSd 
Reading symbolic information ...done
Attached to process id 27945  ....
Thread received signal INT
stopped at [nxm_idle: ??? 0x3ff8053ea8c]	
(ladebug) show thread
Thread State      Substate        Policy     Priority Name
------ ---------- --------------- ---------- -------- -------------
>*  -1 running                    idle        0       null thread for VP 0x0
     1 blocked    mutex wait      throughput 11       default thread
    -2 blocked    kernel          fifo       32       manager thread
(ladebug) thread 1
Thread State      Substate        Policy     Priority Name
------ ---------- --------------- ---------- -------- -------------
>    1 blocked    mutex wait      throughput 11       default thread

(ladebug) where
>0  0x3ff8057c324 in /usr/shlib/libpthread.so
#1  0x3ff80579b30 in hstTransferContext(0x1, 0x140031278, 0x3ffc0183508, 0x4, 0x3ffc0188b50, 0x140075d40) DebugInformationStrippedFromFile109:???
#2  0x3ff805643c4 in dspDispatch(0x14002fa10, 0x3ffc0183680, 0x3ffc0183508, 0x11fffdcf0, 0x3ffc0082770, 0xffffffff00000000) DebugInformationStrippedFromFile89:???
#3  0x3ff80567cd0 in pthread_mutex_block(0x3ffc0183508, 0x0, 0x140035640, 0x11fffdcf0, 0x3ffc0082770, 0x0) DebugInformationStrippedFromFile95:???
#4  0x3ff8057c120 in __pthread_mutex_lock(0x0, 0x140035640, 0x11fffdcf0, 0x3ffc0082770, 0x0, 0x3ff80575568) DebugInformationStrippedFromFile111:???
#5  0x3ff80575564 in UnknownProcedure3FromFile103(0x11fffdcf0, 0x3ffc0082770, 0x0, 0x3ff80575568, 0x3ff800d1fa0, 0x11fffdae0) DebugInformationStrippedFromFile103:???
#6  0x3ff800d1f9c in free(0x3ff800d1fa0, 0x11fffdae0, 0x1201cfd50, 0x0, 0x0, 0x0) DebugInformationStrippedFromFile22:???
#7  0x1201cfd4c in sntpdels(0x140048030, 0x3ffc0183508, 0x10000618d, 0x11fffd9b8, 0x1201cd874, 0x0) network/src/ntp/sntp.c:2150
#8  0x1201cd8b8 in sntpreap(0x3ff805644b0, 0x3ff00000000, 0x1, 0x3ffc0183508, 0x3ff80560024, 0x3ff0000618d) network/src/ntp/sntp.c:479
#9  0x3ff800d3b28 in __sigtramp(0x1, 0x3ffc0183508, 0x3ff80560024, 0x3ff0000618d, 0x11fffdbb8, 0x0) DebugInformationStrippedFromFile105:???
#10 0x3ff80567958 in pthread_mutex_block(0x14002f800, 0x0, 0x140035640, 0x11fffdcf0, 0x3ffc0082770, 0x0) DebugInformationStrippedFromFile95:???
#11 0x3ff8057c120 in __pthread_mutex_lock(0x0, 0x140035640, 0x11fffdcf0, 0x3ffc0082770, 0x0, 0x3ff80575568) DebugInformationStrippedFromFile111:???
#12 0x3ff80575564 in UnknownProcedure3FromFile103(0x11fffdcf0, 0x3ffc0082770, 0x0, 0x3ff80575568, 0x3ff800d1fa0, 0x3ff80575618) DebugInformationStrippedFromFile103:???
#13 0x3ff800d1f9c in free(0x3ff800d1fa0, 0x3ff80575618, 0x3ff800df6e8, 0x0, 0x3ffc0082800, 0x0) DebugInformationStrippedFromFile22:???
#14 0x3ff800df6e4 in __exc_remove_gp_range(0x3ff800fdf90, 0x3ffc008a088, 0x3ff80197b30, 0x7, 0x3ffc0004200, 0x7) DebugInformationStrippedFromFile304:???
#15 0x3ff800fdf8c in _call_remove_gp_range(0x3ffc0004200, 0x7, 0x3ff80197bec, 0x3ffc0001df8, 0x3ffc0001b18, 0x7) DebugInformationStrippedFromFile924:???
#16 0x3ff80197be8 in __tis_init(0x3ffc0004200, 0x7, 0x3ff80197bec, 0x3ffc0001df8, 0x3ffc0001b18, 0x7) DebugInformationStrippedFromFile11:???
#17 0x3ff8057c120 in __pthread_mutex_lock(0x7, 0x3ff80197bec, 0x3ffc0001df8, 0x3ffc0001b18, 0x7, 0x3ff800127ec) DebugInformationStrippedFromFile111:???
#18 0x3ff800127e8 in ???
(ladebug) quit

Welcome to the Ladebug Debugger Version 4.0-25
------------------ 
object file name: Debug/RACSd 
Reading symbolic information ...done
Attached to process id 24933  ....
Thread received signal INT
stopped at [nxm_idle: ??? 0x3ff8053ea8c]	
(ladebug) tshow thread
Thread State      Substate        Policy     Priority Name
------ ---------- --------------- ---------- -------- -------------
>*  -1 running                    idle        0       null thread for VP 0x0
     1 blocked    mutex wait      throughput 11       default thread
    -2 blocked    kernel          fifo       32       manager thread
(ladebug) thread 1
Thread State      Substate        Policy     Priority Name
------ ---------- --------------- ---------- -------- -------------
>    1 blocked    mutex wait      throughput 11       default thread

(ladebug) where
>0  0x3ff8057c324 in /usr/shlib/libpthread.so
#1  0x3ff80579b30 in hstTransferContext(0x1, 0x140031278, 0x3ffc0183508, 0x4, 0x3ffc0188b50, 0x140075d40) DebugInformationStrippedFromFile109:???
#2  0x3ff805643c4 in dspDispatch(0x14002fa10, 0x3ffc0183680, 0x3ffc0183508, 0x11fffdcf0, 0x3ffc0082770, 0x100000000) DebugInformationStrippedFromFile89:???
#3  0x3ff80567cd0 in pthread_mutex_block(0x14002a130, 0x26, 0x140035640, 0x11fffdcf0, 0x3ffc0082770, 0x0) DebugInformationStrippedFromFile95:???
#4  0x3ff8057c120 in __pthread_mutex_lock(0x26, 0x140035640, 0x11fffdcf0, 0x3ffc0082770, 0x0, 0x3ff80575568) DebugInformationStrippedFromFile111:???
#5  0x3ff80575564 in UnknownProcedure3FromFile103(0x11fffdcf0, 0x3ffc0082770, 0x0, 0x3ff80575568, 0x3ff800d1fa0, 0x11fffdcf0) DebugInformationStrippedFromFile103:???
#6  0x3ff800d1f9c in free(0x3ff800d1fa0, 0x11fffdcf0, 0x1201cfd50, 0x0, 0x0, 0x3ffc0183508) DebugInformationStrippedFromFile22:???
#7  0x1201cfd4c in sntpdels(0x11fffdcf0, 0x3ffc0183508, 0x79d2, 0x3ff80575618, 0x1201cd874, 0x0) network/src/ntp/sntp.c:2150
#8  0x1201cd8b8 in sntpreap(0x100000002, 0x20676e6900000000, 0x746e65690005ac80, 0x654e646165726854, 0x50ada0, 0x79d2) network/src/ntp/sntp.c:479
#9  0x3ff800d3b28 in __sigtramp(0x746e65690005ac80, 0x654e646165726854, 0x50ada0, 0x79d2, 0x11fffddb8, 0x0) DebugInformationStrippedFromFile105:???
#10 0x3ff80193d0c in UnknownProcedure8FromFile22(0x32, 0x14002a130, 0x3ff80193fc8, 0x140034020, 0x3ffc008ae28, 0x3ffc0082770) DebugInformationStrippedFromFile22:???
#11 0x3ff80193fc4 in UnknownProcedure6FromFile22(0x3ffc008ae28, 0x3ffc0082770, 0x3ff800d1fb0, 0x140034020, 0x3ffc008ae28, 0x32) DebugInformationStrippedFromFile22:???
#12 0x3ff800d1fac in free(0x3ffc008ae28, 0x32, 0x3ff8013549c, 0x140034020, 0x140034340, 0x0) DebugInformationStrippedFromFile22:???
#13 0x3ff80135498 in /usr/shlib/libc.so
#14 0x3ff801353f4 in /usr/shlib/libc.so
#15 0x3ff80134b44 in __free_libc_contexts(0x0, 0x0, 0x3ff80134b48, 0x11fffdcf0, 0x3ff800dcb24, 0x0) DebugInformationStrippedFromFile597:???
#16 0x3ff800dcb20 in exit(0x3ff800dcb24, 0x0, 0x12006628c, 0x0, 0x0, 0xfffffffffffff137) DebugInformationStrippedFromFile114:???
#17 0x120066288 in ClientProcessNew(lsd=3, sslCtx=0x14003cf00, csd=4, dbTimeout=60) ../RACSd/ServerModel.cpp:222
#18 0x1200663fc in ClientConnectionNew(lsd=3, sslCtx=0x14003cf00, csd=4, dbTimeout=60) ../RACSd/ServerModel.cpp:270
#19 0x120067e7c in Accept(serverInfo={ ... }) ../RACSd/RACS.cpp:822
#20 0x120067fe4 in Listen(serverInfo={ ... }) ../RACSd/RACS.cpp:877
#21 0x120068158 in main(argc=4, argv=0x11fffe228) ../RACSd/RACS.cpp:907
(ladebug) quit

.0> Mutex 1 (normal) "malloc" (0x3ffc0082770, block 0x14002fa10) is locked by 1, 
.0>   1 thread waiting; ref count is 2; waiters: 1

As you should be able to see from this, thread #1 is waiting for a mutex which
it already holds -- a self-deadlock.

For the source of this problem, check the stack trace:

.0> #6  0x3ff800d1f9c in free(...)
.0> #7  0x1201cfd4c in sntpdels(...) network/src/ntp/sntp.c:2150
.0> #8  0x1201cd8b8 in sntpreap(...) network/src/ntp/sntp.c:479
.0> #9  0x3ff800d3b28 in __sigtramp(...)
.0> #10 0x3ff80568358 in pthread_mutex_block(...)
.0> #11 0x3ff8057c120 in __pthread_mutex_lock(...)
.0> #12 0x3ff80575564 in UnknownProcedure3FromFile103(...)
.0> #13 0x3ff800d1f9c in free(...)

You'll notice that a call to free() was interrupted by a signal whose handler,
sntpreap(), called a routine which called into free() -again-.

Unfortunately, free() is not an async-safe (signal-safe) function (see
signal(4)) and therefore it cannot be reliably called from a signal handler (for
just such reasons as the above).

.0> something about a blocked kernel.

FYI, that means the indicated thread's execution is blocked because it is
waiting in a (kernel) system call.


				Webb

    Thanks,
    
    Just to let you know, he was missing a signal in his handler.
    Now he's catching it, (don't know which one), and seems to be fine.