Hi All,
Is this something I should worry about?
Feb 12 20:27:22 sw1 kernel: [3273100.087148] INFO: task kamailio:1845 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.087206] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.087291] kamailio D 8ce9265a 0 1845 1829 Feb 12 20:27:22 sw1 kernel: [3273100.087346] f6a98da0 00000082 23f7e426 8ce9265a 000701ae f6a98f2c c302bfa0 00000002 Feb 12 20:27:22 sw1 kernel: [3273100.087427] c01344f6 001e17ce 00000001 00000000 c01190e6 f6a98da0 f6a98da0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.087538] f74eea84 f74eea8c f74eea88 f6a98da0 c02b8846 f68c3d68 f74eea8c f6a98da0 Feb 12 20:27:22 sw1 kernel: [3273100.087648] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.087730] [<c01344f6>] ktime_get +0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.087784] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.087840] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.087896] [<c02b86dc>] mutex_lock +0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.087945] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.087998] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088055] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.088109] [<c024ef76>] sock_recvmsg +0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.088165] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088223] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088273] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088327] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.088387] [<c024fd9a>] sys_recvfrom +0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.088438] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.088497] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.088554] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.088610] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.091119] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.091174] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.091218] INFO: task kamailio:1846 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.091274] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.091358] kamailio D 00000002 0 1846 1829 Feb 12 20:27:22 sw1 kernel: [3273100.091413] f6a995e0 00000086 00000000 00000002 00000000 f6a9976c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.091495] ffffffff 1d621a39 00000000 00000000 00000000 00000000 00000000 000000ff Feb 12 20:27:22 sw1 kernel: [3273100.091605] f74eea84 f74eea8c f74eea88 f6a995e0 c02b8846 f74eea8c f6b21d68 f6a995e0 Feb 12 20:27:22 sw1 kernel: [3273100.091715] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.091790] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.091847] [<c02b86dc>] mutex_lock +0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.091895] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.091949] [<c0129ab0>] lock_timer_base+0x19/0x35 Feb 12 20:27:22 sw1 kernel: [3273100.092002] [<c0129b10>] try_to_del_timer_sync+0x44/0x4a Feb 12 20:27:22 sw1 kernel: [3273100.092057] [<c024ef76>] sock_recvmsg +0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092108] [<c01297ec>] process_timeout+0x0/0x5 Feb 12 20:27:22 sw1 kernel: [3273100.092163] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092219] [<c015a0d0>] __rmqueue +0x13/0x174 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c024fd9a>] sys_recvfrom +0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.092221] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.092221] INFO: task kamailio:22820 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.092221] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.092221] kamailio D 854aa937 0 22820 22803 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f762fa40 00000086 2603ada4 854aa937 000767a5 f762fbcc c3021fa0 00000001 Feb 12 20:27:22 sw1 kernel: [3273100.092221] c01344f6 001fcdbd 00000001 00000000 c01190e6 f762fa40 f762fa40 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f6b38544 f6b3854c f6b38548 f762fa40 c02b8846 f68a3d68 f6b3854c f762fa40 Feb 12 20:27:22 sw1 kernel: [3273100.092221] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01344f6>] ktime_get +0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b86dc>] mutex_lock +0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.092274] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.092328] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092383] [<c015a05d>] __rmqueue_smallest+0x83/0xe3 Feb 12 20:27:22 sw1 kernel: [3273100.092438] [<c024ef76>] sock_recvmsg +0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092493] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092551] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092601] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092653] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092712] [<c024fd9a>] sys_recvfrom +0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092764] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092822] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092881] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092937] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092991] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.093046] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.093146] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.093230] kamailio D 8543066c 0 22821 22803 Feb 12 20:27:22 sw1 kernel: [3273100.110119] f762ede0 00000082 2603ada4 8543066c 000767a5 f762ef6c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.110201] c01344f6 001fcdbd 00000002 00000000 c01190e6 f762ede0 f762ede0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.110312] f6b38544 f6b3854c f6b38548 f762ede0 c02b8846 f6b3854c f6bfdd68 f762ede0 Feb 12 20:27:22 sw1 kernel: [3273100.110422] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.110493] [<c01344f6>] ktime_get +0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.110543] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.110598] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.110653] [<c02b86dc>] mutex_lock +0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.110702] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.110755] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110810] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.110864] [<c024ef76>] sock_recvmsg +0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.110919] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110976] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111027] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111079] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.111138] [<c024fd9a>] sys_recvfrom +0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.111189] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.111248] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.111307] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.111362] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.111417] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.111471] =======================
Hello,
yes, there is something to worry until you discovered the cause and might be something not to worry :-) ...
can you get the type of that process? Do: kamctl ps
and you will see the list of kamailio processes. If it is a SIP worker, then either is a dns block, tcp block (looks like due to timeout) or lock block.
Cheers, Daniel
On 02/12/2009 10:29 PM, Brian Chamberlain wrote:
Hi All,
Is this something I should worry about?
Feb 12 20:27:22 sw1 kernel: [3273100.087148] INFO: task kamailio:1845 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.087206] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.087291] kamailio D 8ce9265a 0 1845 1829 Feb 12 20:27:22 sw1 kernel: [3273100.087346] f6a98da0 00000082 23f7e426 8ce9265a 000701ae f6a98f2c c302bfa0 00000002 Feb 12 20:27:22 sw1 kernel: [3273100.087427] c01344f6 001e17ce 00000001 00000000 c01190e6 f6a98da0 f6a98da0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.087538] f74eea84 f74eea8c f74eea88 f6a98da0 c02b8846 f68c3d68 f74eea8c f6a98da0 Feb 12 20:27:22 sw1 kernel: [3273100.087648] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.087730] [<c01344f6>] ktime_get+0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.087784] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.087840] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.087896] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.087945] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.087998] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088055] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.088109] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.088165] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088223] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088273] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088327] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.088387] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.088438] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.088497] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.088554] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.088610] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.091119] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.091174] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.091218] INFO: task kamailio:1846 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.091274] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.091358] kamailio D 00000002 0 1846 1829 Feb 12 20:27:22 sw1 kernel: [3273100.091413] f6a995e0 00000086 00000000 00000002 00000000 f6a9976c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.091495] ffffffff 1d621a39 00000000 00000000 00000000 00000000 00000000 000000ff Feb 12 20:27:22 sw1 kernel: [3273100.091605] f74eea84 f74eea8c f74eea88 f6a995e0 c02b8846 f74eea8c f6b21d68 f6a995e0 Feb 12 20:27:22 sw1 kernel: [3273100.091715] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.091790] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.091847] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.091895] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.091949] [<c0129ab0>] lock_timer_base+0x19/0x35 Feb 12 20:27:22 sw1 kernel: [3273100.092002] [<c0129b10>] try_to_del_timer_sync+0x44/0x4a Feb 12 20:27:22 sw1 kernel: [3273100.092057] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092108] [<c01297ec>] process_timeout+0x0/0x5 Feb 12 20:27:22 sw1 kernel: [3273100.092163] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092219] [<c015a0d0>] __rmqueue+0x13/0x174 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.092221] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.092221] INFO: task kamailio:22820 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.092221] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.092221] kamailio D 854aa937 0 22820 22803 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f762fa40 00000086 2603ada4 854aa937 000767a5 f762fbcc c3021fa0 00000001 Feb 12 20:27:22 sw1 kernel: [3273100.092221] c01344f6 001fcdbd 00000001 00000000 c01190e6 f762fa40 f762fa40 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f6b38544 f6b3854c f6b38548 f762fa40 c02b8846 f68a3d68 f6b3854c f762fa40 Feb 12 20:27:22 sw1 kernel: [3273100.092221] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01344f6>] ktime_get+0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.092274] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.092328] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092383] [<c015a05d>] __rmqueue_smallest+0x83/0xe3 Feb 12 20:27:22 sw1 kernel: [3273100.092438] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092493] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092551] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092601] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092653] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092712] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092764] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092822] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092881] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092937] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092991] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.093046] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.093146] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.093230] kamailio D 8543066c 0 22821 22803 Feb 12 20:27:22 sw1 kernel: [3273100.110119] f762ede0 00000082 2603ada4 8543066c 000767a5 f762ef6c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.110201] c01344f6 001fcdbd 00000002 00000000 c01190e6 f762ede0 f762ede0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.110312] f6b38544 f6b3854c f6b38548 f762ede0 c02b8846 f6b3854c f6bfdd68 f762ede0 Feb 12 20:27:22 sw1 kernel: [3273100.110422] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.110493] [<c01344f6>] ktime_get+0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.110543] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.110598] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.110653] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.110702] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.110755] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110810] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.110864] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.110919] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110976] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111027] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111079] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.111138] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.111189] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.111248] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.111307] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.111362] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.111417] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.111471] =======================
Kamailio (OpenSER) - Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
Daniel-Constantin Mierla wrote:
kamctl ps
Hey, that's pretty neat. Didn't know about that.
So, when you add "children" in the config, are these additional SIP worker threads, or something else, or some combination?
Hello Alex,
On 02/12/2009 10:44 PM, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
kamctl ps
Hey, that's pretty neat. Didn't know about that.
another hint, try this one:
kamctl fifo which
Did you know about it :-) ?
So, when you add "children" in the config, are these additional SIP worker threads, or something else, or some combination?
here is the output of my kamailio running with children=2
Process:: ID=0 PID=24128 Type=attendant Process:: ID=1 PID=24129 Type=SIP receiver udp:192.168.1.23:5060 Process:: ID=2 PID=24130 Type=SIP receiver udp:192.168.1.23:5060 Process:: ID=3 PID=24131 Type=timer Process:: ID=4 PID=24132 Type=MI FIFO Process:: ID=5 PID=24133 Type=TCP receiver Process:: ID=6 PID=24134 Type=TCP receiver Process:: ID=7 PID=24135 Type=TCP main
The receivers are reflected by the children value, and they are the sip workers. You can have different TCP children number using tcp_children in config file.
Cheers, Daniel
Hi Daniel
Process:: ID=0 PID=22803 Type=attendant Process:: ID=1 PID=22804 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=2 PID=22805 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=3 PID=22806 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=4 PID=22807 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=5 PID=22808 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=6 PID=22809 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=7 PID=22810 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=8 PID=22811 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=9 PID=22812 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=10 PID=22813 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=11 PID=22814 Type=timer Process:: ID=12 PID=22816 Type=MI Datagram Process:: ID=13 PID=22820 Type=MI Datagram Process:: ID=14 PID=22821 Type=MI Datagram Process:: ID=15 PID=22824 Type=MI FIFO
Thanks, Brian
On 12 Feb 2009, at 20:40, Daniel-Constantin Mierla wrote:
Hello,
yes, there is something to worry until you discovered the cause and might be something not to worry :-) ...
can you get the type of that process? Do: kamctl ps
and you will see the list of kamailio processes. If it is a SIP worker, then either is a dns block, tcp block (looks like due to timeout) or lock block.
Cheers, Daniel
On 02/12/2009 10:29 PM, Brian Chamberlain wrote:
Hi All,
Is this something I should worry about?
Feb 12 20:27:22 sw1 kernel: [3273100.087148] INFO: task kamailio: 1845 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.087206] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.087291] kamailio D 8ce9265a 0 1845 1829 Feb 12 20:27:22 sw1 kernel: [3273100.087346] f6a98da0 00000082 23f7e426 8ce9265a 000701ae f6a98f2c c302bfa0 00000002 Feb 12 20:27:22 sw1 kernel: [3273100.087427] c01344f6 001e17ce 00000001 00000000 c01190e6 f6a98da0 f6a98da0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.087538] f74eea84 f74eea8c f74eea88 f6a98da0 c02b8846 f68c3d68 f74eea8c f6a98da0 Feb 12 20:27:22 sw1 kernel: [3273100.087648] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.087730] [<c01344f6>] ktime_get +0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.087784] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.087840] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.087896] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.087945] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.087998] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088055] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.088109] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.088165] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088223] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088273] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088327] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.088387] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.088438] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.088497] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.088554] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.088610] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.091119] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.091174] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.091218] INFO: task kamailio: 1846 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.091274] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.091358] kamailio D 00000002 0 1846 1829 Feb 12 20:27:22 sw1 kernel: [3273100.091413] f6a995e0 00000086 00000000 00000002 00000000 f6a9976c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.091495] ffffffff 1d621a39 00000000 00000000 00000000 00000000 00000000 000000ff Feb 12 20:27:22 sw1 kernel: [3273100.091605] f74eea84 f74eea8c f74eea88 f6a995e0 c02b8846 f74eea8c f6b21d68 f6a995e0 Feb 12 20:27:22 sw1 kernel: [3273100.091715] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.091790] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.091847] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.091895] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.091949] [<c0129ab0>] lock_timer_base+0x19/0x35 Feb 12 20:27:22 sw1 kernel: [3273100.092002] [<c0129b10>] try_to_del_timer_sync+0x44/0x4a Feb 12 20:27:22 sw1 kernel: [3273100.092057] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092108] [<c01297ec>] process_timeout+0x0/0x5 Feb 12 20:27:22 sw1 kernel: [3273100.092163] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092219] [<c015a0d0>] __rmqueue +0x13/0x174 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.092221] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.092221] INFO: task kamailio: 22820 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.092221] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.092221] kamailio D 854aa937 0 22820 22803 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f762fa40 00000086 2603ada4 854aa937 000767a5 f762fbcc c3021fa0 00000001 Feb 12 20:27:22 sw1 kernel: [3273100.092221] c01344f6 001fcdbd 00000001 00000000 c01190e6 f762fa40 f762fa40 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f6b38544 f6b3854c f6b38548 f762fa40 c02b8846 f68a3d68 f6b3854c f762fa40 Feb 12 20:27:22 sw1 kernel: [3273100.092221] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01344f6>] ktime_get +0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.092274] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.092328] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092383] [<c015a05d>] __rmqueue_smallest+0x83/0xe3 Feb 12 20:27:22 sw1 kernel: [3273100.092438] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092493] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092551] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092601] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092653] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092712] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092764] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092822] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092881] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092937] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092991] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.093046] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio: 22821 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.093146] "echo 0 > /proc/sys/ kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.093230] kamailio D 8543066c 0 22821 22803 Feb 12 20:27:22 sw1 kernel: [3273100.110119] f762ede0 00000082 2603ada4 8543066c 000767a5 f762ef6c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.110201] c01344f6 001fcdbd 00000002 00000000 c01190e6 f762ede0 f762ede0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.110312] f6b38544 f6b3854c f6b38548 f762ede0 c02b8846 f6b3854c f6bfdd68 f762ede0 Feb 12 20:27:22 sw1 kernel: [3273100.110422] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.110493] [<c01344f6>] ktime_get +0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.110543] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.110598] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.110653] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.110702] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.110755] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110810] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.110864] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.110919] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110976] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111027] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111079] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.111138] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.111189] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.111248] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.111307] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.111362] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.111417] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.111471] =======================
Kamailio (OpenSER) - Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
-- Daniel-Constantin Mierla http://www.asipto.com
Hello,
correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram
seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Cheers, Daniel
On 02/12/2009 11:00 PM, Brian Chamberlain wrote:
Hi Daniel
Process:: ID=0 PID=22803 Type=attendant Process:: ID=1 PID=22804 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=2 PID=22805 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=3 PID=22806 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=4 PID=22807 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=5 PID=22808 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=6 PID=22809 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=7 PID=22810 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=8 PID=22811 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=9 PID=22812 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=10 PID=22813 Type=SIP receiver udp:x.x.x.x:5060 Process:: ID=11 PID=22814 Type=timer Process:: ID=12 PID=22816 Type=MI Datagram Process:: ID=13 PID=22820 Type=MI Datagram Process:: ID=14 PID=22821 Type=MI Datagram Process:: ID=15 PID=22824 Type=MI FIFO
Thanks, Brian
On 12 Feb 2009, at 20:40, Daniel-Constantin Mierla wrote:
Hello,
yes, there is something to worry until you discovered the cause and might be something not to worry :-) ...
can you get the type of that process? Do: kamctl ps
and you will see the list of kamailio processes. If it is a SIP worker, then either is a dns block, tcp block (looks like due to timeout) or lock block.
Cheers, Daniel
On 02/12/2009 10:29 PM, Brian Chamberlain wrote:
Hi All,
Is this something I should worry about?
Feb 12 20:27:22 sw1 kernel: [3273100.087148] INFO: task kamailio:1845 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.087206] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.087291] kamailio D 8ce9265a 0 1845 1829 Feb 12 20:27:22 sw1 kernel: [3273100.087346] f6a98da0 00000082 23f7e426 8ce9265a 000701ae f6a98f2c c302bfa0 00000002 Feb 12 20:27:22 sw1 kernel: [3273100.087427] c01344f6 001e17ce 00000001 00000000 c01190e6 f6a98da0 f6a98da0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.087538] f74eea84 f74eea8c f74eea88 f6a98da0 c02b8846 f68c3d68 f74eea8c f6a98da0 Feb 12 20:27:22 sw1 kernel: [3273100.087648] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.087730] [<c01344f6>] ktime_get+0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.087784] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.087840] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.087896] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.087945] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.087998] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088055] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.088109] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.088165] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.088223] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088273] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.088327] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.088387] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.088438] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.088497] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.088554] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.088610] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.091119] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.091174] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.091218] INFO: task kamailio:1846 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.091274] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.091358] kamailio D 00000002 0 1846 1829 Feb 12 20:27:22 sw1 kernel: [3273100.091413] f6a995e0 00000086 00000000 00000002 00000000 f6a9976c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.091495] ffffffff 1d621a39 00000000 00000000 00000000 00000000 00000000 000000ff Feb 12 20:27:22 sw1 kernel: [3273100.091605] f74eea84 f74eea8c f74eea88 f6a995e0 c02b8846 f74eea8c f6b21d68 f6a995e0 Feb 12 20:27:22 sw1 kernel: [3273100.091715] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.091790] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.091847] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.091895] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.091949] [<c0129ab0>] lock_timer_base+0x19/0x35 Feb 12 20:27:22 sw1 kernel: [3273100.092002] [<c0129b10>] try_to_del_timer_sync+0x44/0x4a Feb 12 20:27:22 sw1 kernel: [3273100.092057] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092108] [<c01297ec>] process_timeout+0x0/0x5 Feb 12 20:27:22 sw1 kernel: [3273100.092163] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092219] [<c015a0d0>] __rmqueue+0x13/0x174 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.092221] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.092221] INFO: task kamailio:22820 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.092221] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.092221] kamailio D 854aa937 0 22820 22803 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f762fa40 00000086 2603ada4 854aa937 000767a5 f762fbcc c3021fa0 00000001 Feb 12 20:27:22 sw1 kernel: [3273100.092221] c01344f6 001fcdbd 00000001 00000000 c01190e6 f762fa40 f762fa40 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.092221] f6b38544 f6b3854c f6b38548 f762fa40 c02b8846 f68a3d68 f6b3854c f762fa40 Feb 12 20:27:22 sw1 kernel: [3273100.092221] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01344f6>] ktime_get+0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.092221] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.092274] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.092328] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092383] [<c015a05d>] __rmqueue_smallest+0x83/0xe3 Feb 12 20:27:22 sw1 kernel: [3273100.092438] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.092493] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.092551] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092601] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.092653] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.092712] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.092764] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.092822] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.092881] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.092937] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.092991] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.093046] ======================= Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. Feb 12 20:27:22 sw1 kernel: [3273100.093146] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 12 20:27:22 sw1 kernel: [3273100.093230] kamailio D 8543066c 0 22821 22803 Feb 12 20:27:22 sw1 kernel: [3273100.110119] f762ede0 00000082 2603ada4 8543066c 000767a5 f762ef6c c3017fa0 00000000 Feb 12 20:27:22 sw1 kernel: [3273100.110201] c01344f6 001fcdbd 00000002 00000000 c01190e6 f762ede0 f762ede0 c02c4dc0 Feb 12 20:27:22 sw1 kernel: [3273100.110312] f6b38544 f6b3854c f6b38548 f762ede0 c02b8846 f6b3854c f6bfdd68 f762ede0 Feb 12 20:27:22 sw1 kernel: [3273100.110422] Call Trace: Feb 12 20:27:22 sw1 kernel: [3273100.110493] [<c01344f6>] ktime_get+0xd/0x21 Feb 12 20:27:22 sw1 kernel: [3273100.110543] [<c01190e6>] hrtick_start_fair+0xeb/0x12c Feb 12 20:27:22 sw1 kernel: [3273100.110598] [<c02b8846>] __mutex_lock_slowpath+0x50/0x7b Feb 12 20:27:22 sw1 kernel: [3273100.110653] [<c02b86dc>] mutex_lock+0xa/0xb Feb 12 20:27:22 sw1 kernel: [3273100.110702] [<c02a7ea9>] unix_dgram_recvmsg+0x3e/0x245 Feb 12 20:27:22 sw1 kernel: [3273100.110755] [<c01318e9>] autoremove_wake_function+0xd/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110810] [<c011845d>] __wake_up_common+0x2e/0x58 Feb 12 20:27:22 sw1 kernel: [3273100.110864] [<c024ef76>] sock_recvmsg+0xde/0xf9 Feb 12 20:27:22 sw1 kernel: [3273100.110919] [<c01318dc>] autoremove_wake_function+0x0/0x2d Feb 12 20:27:22 sw1 kernel: [3273100.110976] [<c0117c67>] kunmap_atomic+0x55/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111027] [<c0117c79>] kunmap_atomic+0x67/0x8a Feb 12 20:27:22 sw1 kernel: [3273100.111079] [<c015ae91>] get_page_from_freelist+0x34f/0x3e3 Feb 12 20:27:22 sw1 kernel: [3273100.111138] [<c024fd9a>] sys_recvfrom+0xb4/0x116 Feb 12 20:27:22 sw1 kernel: [3273100.111189] [<c015b0fb>] __alloc_pages_internal+0xb5/0x34e Feb 12 20:27:22 sw1 kernel: [3273100.111248] [<c0163cd3>] handle_mm_fault+0x257/0x690 Feb 12 20:27:22 sw1 kernel: [3273100.111307] [<c025024d>] sys_socketcall+0x135/0x19e Feb 12 20:27:22 sw1 kernel: [3273100.111362] [<c0103853>] sysenter_past_esp+0x78/0xb1 Feb 12 20:27:22 sw1 kernel: [3273100.111417] [<c02b0000>] acpi_pci_root_add+0x165/0x296 Feb 12 20:27:22 sw1 kernel: [3273100.111471] =======================
Kamailio (OpenSER) - Users mailing list Users@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
-- Daniel-Constantin Mierla http://www.asipto.com
Daniel-Constantin Mierla wrote:
Hello,
correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram
seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Brian, I would guess CDRtool and its rating engine use a lot of MI commands as part of its interface with the proxy. Daniel, can you corroborate that?
On 12 Feb 2009, at 21:06, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
Hello, correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio: 22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Brian, I would guess CDRtool and its rating engine use a lot of MI commands as part of its interface with the proxy. Daniel, can you corroborate that?
I've been doing a lot of rerating today as it goes..
Brian Chamberlain wrote:
On 12 Feb 2009, at 21:06, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
Hello, correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Brian, I would guess CDRtool and its rating engine use a lot of MI commands as part of its interface with the proxy. Daniel, can you corroborate that?
I've been doing a lot of rerating today as it goes..
I don't know that this results in a lot of MI commands. I think CDRtool and its processes use a lot of MI for managing session timers and stuff like that, or maybe that's Call Control. I'm not really familiar with AG Projects' technology stack.
On 02/12/2009 11:11 PM, Alex Balashov wrote:
Brian Chamberlain wrote:
On 12 Feb 2009, at 21:06, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
Hello, correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Brian, I would guess CDRtool and its rating engine use a lot of MI commands as part of its interface with the proxy. Daniel, can you corroborate that?
I've been doing a lot of rerating today as it goes..
I don't know that this results in a lot of MI commands. I think CDRtool and its processes use a lot of MI for managing session timers and stuff like that, or maybe that's Call Control. I'm not really familiar with AG Projects' technology stack.
OK, so we identified the source. Thanks a lot Alex!
Brian, you could sniff the UDP traffic for MI datagram, are you using UDP sockets or unix sockets?
Anyhow, I wonder what the cdrtool would need for rating from kamailio... so if you can get the commands send by cdrtool, I can tell you where is the possible lock.
Cheers, Daniel
Daniel-Constantin Mierla wrote:
On 02/12/2009 11:11 PM, Alex Balashov wrote:
Brian Chamberlain wrote:
On 12 Feb 2009, at 21:06, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
Hello, correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Brian, I would guess CDRtool and its rating engine use a lot of MI commands as part of its interface with the proxy. Daniel, can you corroborate that?
I've been doing a lot of rerating today as it goes..
I don't know that this results in a lot of MI commands. I think CDRtool and its processes use a lot of MI for managing session timers and stuff like that, or maybe that's Call Control. I'm not really familiar with AG Projects' technology stack.
OK, so we identified the source. Thanks a lot Alex!
Brian, you could sniff the UDP traffic for MI datagram, are you using UDP sockets or unix sockets?
UNIX domain sockets. I am not aware of a good way to "sniff" those. Is there one?
I suppose one could switch to UDP sockets...
Anyhow, I wonder what the cdrtool would need for rating from kamailio... so if you can get the commands send by cdrtool, I can tell you where is the possible lock.
I do not know.
I've been trying to help Brian with this, but I just don't know enough about the AG Projects end of things.
On 02/12/2009 11:23 PM, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
On 02/12/2009 11:11 PM, Alex Balashov wrote:
Brian Chamberlain wrote:
On 12 Feb 2009, at 21:06, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
Hello, correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Brian, I would guess CDRtool and its rating engine use a lot of MI commands as part of its interface with the proxy. Daniel, can you corroborate that?
I've been doing a lot of rerating today as it goes..
I don't know that this results in a lot of MI commands. I think CDRtool and its processes use a lot of MI for managing session timers and stuff like that, or maybe that's Call Control. I'm not really familiar with AG Projects' technology stack.
OK, so we identified the source. Thanks a lot Alex!
Brian, you could sniff the UDP traffic for MI datagram, are you using UDP sockets or unix sockets?
UNIX domain sockets. I am not aware of a good way to "sniff" those. Is there one?
Never did it, but I found this after a quick googling: http://graag.blogspot.com/2007/10/unix-socket-sniffer.html
I suppose one could switch to UDP sockets...
This is the way I would do, then use ngrep/wiresharck/.... Hopefully the cdrtool supports UDP sockets.
Anyhow, I wonder what the cdrtool would need for rating from kamailio... so if you can get the commands send by cdrtool, I can tell you where is the possible lock.
I do not know.
I've been trying to help Brian with this, but I just don't know enough about the AG Projects end of things.
Neither do I, but we can do reverse engineering if you learn the commands send.
The problem could become critical, if it blocks access to some hash/location in memory for modules (e.g., usrloc).
Cheers, Daniel
Hello,
On 02/12/2009 11:06 PM, Alex Balashov wrote:
Daniel-Constantin Mierla wrote:
Hello,
correlating messages: Feb 12 20:27:22 sw1 kernel: [3273100.093090] INFO: task kamailio:22821 blocked for more than 120 seconds. and Process:: ID=14 PID=22821 Type=MI Datagram
seems that one of your MI datagram was blocked for some time. Are you using MI datagram commands often? What are they?
Brian, I would guess CDRtool and its rating engine use a lot of MI commands as part of its interface with the proxy. Daniel, can you corroborate that?
Never used CDRTool, do not want to elaborate on that why I didn't...
But yes, if it is doing heavy MI work, then it can block the MI processes.
Cheers, Daniel
-
Alex Balashov -
Brian Chamberlain -
Daniel-Constantin Mierla