[asterisk-dev] Identifying Asterisk threads

[Pavel Troller]

Hi!
  I have a problem with one of Asterisk installations. It serves
as a conference bridge and most of the time there is no traffic. When a new
call arrives after a longer time of idleness, one of Asterisk threads awakes
up and runs at 100% CPU utilization for a time, which is proportional to the
time the system was idle before. For example, when there were two hours of
idle, the thread runs about 3 seconds. When there was one week of idle, the
thread runs several minutes. During this time, the Asterisk performance is
degraded, including choppy playback of announcements and improper inband DTMF
detection. It is on a 8-core machine, where using one core fully should not
influence the total system performance. When the thread finishes its work,
it's going to (almost) sleep again and Asterisk performance returns to normal.
  I can display the asterisk threads:
bigmeat1*CLI> core show threads
0x41b5e950 netconsole           started at [ 1103] asterisk.c listener()
0x40e33950 monitor_sig_flags    started at [ 3527] asterisk.c main()
0x4031e950 tps_processing_function started at [  451] taskprocessor.c ast_taskprocessor_get()
0x41cd1950 scan_thread          started at [  516] pbx_spool.c load_module()
0x4205d950 do_monitor           started at [20996] chan_sip.c restart_monitor()
0x40ad7950 desc->accept_fn      started at [  462] tcptls.c ast_tcptls_server_start()
0x4042a950 lock_broker          started at [  463] func_lock.c load_module()
0x41c55950 do_monitor           started at [ 3513] chan_mgcp.c restart_monitor()
0x411bd950 do_timing            started at [  482] res_timing_pthread.c init_timing_thread()
0x40fb4950 do_parking_thread    started at [ 4589] features.c ast_features_init()
0x413e7950 tps_processing_function started at [  451] taskprocessor.c ast_taskprocessor_get()
0x41906950 do_devstate_changes  started at [  751] devicestate.c ast_device_state_engine_init()
0x41f76950 logger_thread        started at [ 1009] logger.c init_logger()
0x40932950 listener             started at [ 1162] asterisk.c ast_makesocket()
0x4188a950 tps_processing_function started at [  451] taskprocessor.c ast_taskprocessor_get()
0x41ae2950 canary_thread        started at [ 3369] asterisk.c main()
16 threads listed.
  I can display system threads:
root at bigmeat1:~# ps axumw |less
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
...
root      3472  0.0  0.3 498956 15496 pts/1    -    08:23   0:04 /opt/asterisk/sbin/asterisk -p -f -I -vvvg -c
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:03 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
root         -  0.0    -      -     - -        Sl   08:23   0:00 -
  As you can see, the Asterisk was started at 8:23, there was no call until
10:30. Before the call, the main process showed 0:01 of CPU time, during
the call, the time increased by 3 seconds (in the first 3 seconds of call)
and then the time consumption returned to normal. You can also see an
individual thread, which was at 0:00 before the call, and then promptly
increased to 0:03 and also stopped. This thread is IMHO responsible for
the problem.
  Can I map the threads displayed by ps to the ones shown by core show threads?
Which thread could be the time-consuming one ? I've tested with internal timing
(-I flag) as well as without it and there is no difference. DAHDI timer not
used. The problem occurs during calls of any type, for example this one was to
the Milliwatt application.
  It's Asterisk 1.6.1.7.
  With regards, Pavel.