Asterisco: promedio de carga muy alto sin motivo

Asterisco: promedio de carga muy alto sin motivo

Hay un problema con el servidor Asterisk que muestra un promedio de carga alto que no puedo explicar. Nueva configuración es:

  1. Asterisco 13.1.0
  2. Linux 3.13.0-24 (servidor Ubuntu)
  3. Servidor de doble socket (Xeon E5-2620), habilitado para HT: 24 núcleos en total; 32 GB de RAM

Asterisk se utiliza para enviar mensajes de voz. Tengo un proveedor SIP ascendente, no tengo tarjetas de telefonía de hardware. Sólo se permiten alaw/ulaw en sip.conf.

Utilizo el comando AMI Originate para iniciar una llamada; luego ejecuto Playback() en contexto para enviar mensajes de voz pregrabados (archivos ulaw en ext4 FS local). No hay otra interacción con la persona que llama, ni menú IVR, ni grabación de llamadas. Un par de scripts Perl AGI muy simples guardan el resultado de la llamada en bases de datos (MySQL y MSSQL (a través de Perl Sybase)); Por lo general, hay 1 o 2 llamadas de AGI por Originación. Además, casi no hay procesamiento en la extensión: literalmente 20 líneas de variables preconfiguradas para CDR() y un par de llamadas AGI. Sólo hay una conexión AMI que utilizo para iniciar todas las llamadas.

Lo específico es que la mayoría de las llamadas no son respondidas. Inicio hasta 50 llamadas por segundo, pero solo entre 5 y 10 son contestadas y escuchadas.

El problema es que tengo un porcentaje de uso de CPU muy bajo, pero un LA muy alto. Si inicio 20-25 cps - 20-24 LA, pero si intento aumentarlo hasta 50 cps, LA sube hasta 90+. Después de ~50LA, hay problemas con la calidad del audio (y puedo entender por qué).

La mayoría de los usuarios de Asterisk afirman que tienen mucho más volumen de llamadas con un hardware menos potente.

# uptime
 12:56:36 up 9 days, 15:52,  1 user,  load average: 32,10, 33,45, 33,10

#vmstat -w 1
procs ---------------memory-------------- ---swap-- -----io---- -system-- ------cpu-----
 r  b     swpd     free     buff    cache   si   so    bi    bo   in   cs us sy id wa st
 3  0        0 30322760   199176   832452    0    0     0     0 237471 38738  5  8 87  0  0
 3  0        0 30319148   199176   832500    0    0     0     0 188340 38960  4  6 90  0  0
 3  0        0 30325528   199176   832564    0    0     0    26 319903 43916  6 10 83  0  0
105  0        0 30270288   199176   832568    0    0     0    14 175216 39014  4  6 90  0  0
16  0        0 30307908   199176   832572    0    0     0     0 323598 43428 11 12 77  0  0

# mpstat 1
Linux 3.13.0-24-generic (asterisk2)         25.02.2015      _x86_64_        (24 CPU)
13:18:09     CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
13:18:10     all    5,77    0,00    7,90    0,00    0,17    0,00    0,00    0,00    0,00   86,16
13:18:11     all    5,56    0,00    8,83    0,00    0,21    0,00    0,00    0,00    0,00   85,40
13:18:12     all   10,29    0,00   11,42    0,00    0,25    0,00    0,00    0,00    0,00   78,03
13:18:13     all    9,70    0,00   10,75    0,00    0,21    0,00    0,00    0,00    0,00   79,34

# uname -a
Linux asterisk2 3.13.0-24-generic #46-Ubuntu SMP Thu Apr 10 19:11:08 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

# cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 45
model name      : Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
stepping        : 7
microcode       : 0x70d
cpu MHz         : 2000.216
cache size      : 15360 KB
physical id     : 0
siblings        : 12
core id         : 0
cpu cores       : 6
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid
bogomips        : 4000.43
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual

...

processor       : 23
vendor_id       : GenuineIntel
cpu family      : 6
model           : 45
model name      : Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
stepping        : 7
microcode       : 0x70d
cpu MHz         : 2000.216
cache size      : 15360 KB
physical id     : 1
siblings        : 12
core id         : 5
cpu cores       : 6
apicid          : 43
initial apicid  : 43
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid
bogomips        : 4001.85
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual

# cat /proc/interrupts
            CPU02      CPU23
   0:         24          0  IR-IO-APIC-edge      timer
   8:          1          0  IR-IO-APIC-edge      rtc0
   9:          2          0  IR-IO-APIC-fasteoi   acpi
  16:         33          0  IR-IO-APIC-fasteoi   ehci_hcd:usb1
  23:        107          0  IR-IO-APIC-fasteoi   ehci_hcd:usb2
  88:          0          0  DMAR_MSI-edge      dmar0
  89:          0          0  DMAR_MSI-edge      dmar1
  90:    1855369          0  IR-PCI-MSI-edge      ahci
  91:          1          0  IR-PCI-MSI-edge      eth0
  92:      11296          0  IR-PCI-MSI-edge      eth0-TxRx-0
  93:        790          0  IR-PCI-MSI-edge      eth0-TxRx-1
  94:   85066770          0  IR-PCI-MSI-edge      eth0-TxRx-2
  95:       6851          0  IR-PCI-MSI-edge      eth0-TxRx-3
  96:     174614          0  IR-PCI-MSI-edge      eth0-TxRx-4
  97:    4846139          0  IR-PCI-MSI-edge      eth0-TxRx-5
  98:     136593          0  IR-PCI-MSI-edge      eth0-TxRx-6
  99:    1294090          0  IR-PCI-MSI-edge      eth0-TxRx-7
 109:          2          0  IR-PCI-MSI-edge      ioat-msix
 110:          2          0  IR-PCI-MSI-edge      ioat-msix
 111:          2          0  IR-PCI-MSI-edge      ioat-msix
 112:          2          0  IR-PCI-MSI-edge      ioat-msix
 113:          2          0  IR-PCI-MSI-edge      ioat-msix
 114:          2          0  IR-PCI-MSI-edge      ioat-msix
 115:          2          0  IR-PCI-MSI-edge      ioat-msix
 116:          2          0  IR-PCI-MSI-edge      ioat-msix
 117:          0          0  IR-PCI-MSI-edge      ioat-msix
 118:          0          0  IR-PCI-MSI-edge      ioat-msix
 119:          0          0  IR-PCI-MSI-edge      ioat-msix
 120:          0          0  IR-PCI-MSI-edge      ioat-msix
 121:          0          0  IR-PCI-MSI-edge      ioat-msix
 122:          0          0  IR-PCI-MSI-edge      ioat-msix
 123:          0          0  IR-PCI-MSI-edge      ioat-msix
 124:          0          0  IR-PCI-MSI-edge      ioat-msix
 NMI:       3642       1990   Non-maskable interrupts
 LOC:   53207172   19108700   Local timer interrupts
 SPU:          0          0   Spurious interrupts
 PMI:       3642       1990   Performance monitoring interrupts
 IWI:     804483      60489   IRQ work interrupts
 RTR:          0          0   APIC ICR read retries
 RES:   60096784   31495629   Rescheduling interrupts
 CAL: 4046461325 4101338127   Function call interrupts
 TLB: 2390847639 1479027286   TLB shootdowns
 TRM:          0          0   Thermal event interrupts
 THR:          0          0   Threshold APIC interrupts
 MCE:          0          0   Machine check exceptions
 MCP:       2501       2501   Machine check polls
 ERR:          0
 MIS:          0

# atop
CPL | avg1   22.45 |  avg5   22.65 |              |  avg15  22.74 |              |  csw   379728 | intr 1612164 |               |              |  numcpu    24 |
MEM | tot    31.4G |  free   28.4G | cache 829.3M |  dirty   0.0M | buff  194.7M |  slab  188.0M |              |               |              |               |
SWP | tot    32.0G |  free   32.0G |              |               |              |               |              |               | vmcom 737.1M |  vmlim  47.7G |
MDD |          md0 |  busy      0% | read       0 |  write     12 | KiB/r      0 |  KiB/w      4 | MBr/s   0.00 |  MBw/s   0.01 | avq     0.00 |  avio 0.00 ms |
DSK |          sda |  busy      1% | read       0 |  write     11 | KiB/r      0 |  KiB/w      5 | MBr/s   0.00 |  MBw/s   0.01 | avq     1.00 |  avio 12.7 ms |
DSK |          sdb |  busy      1% | read       0 |  write     11 | KiB/r      0 |  KiB/w      5 | MBr/s   0.00 |  MBw/s   0.01 | avq     1.00 |  avio 11.6 ms |
NET | transport    |  tcpi    1994 | tcpo    2452 |  udpi   17159 | udpo   14811 |  tcpao    117 | tcppo      1 |  tcprs      0 | tcpie      0 |  udpip      0 |
NET | network      |  ipi    19235 | ipo    17268 |  ipfrw      0 | deliv  19235 |               |              |               | icmpi      7 |  icmpo      0 |
NET | eth0      0% |  pcki   19345 | pcko   17272 |  si 3256 Kbps | so 2954 Kbps |  coll       0 | erri       0 |  erro       0 | drpi       0 |  drpo       0 |

Puede ver que hay números muy altos en los campos cs y vmstat. No puedo explicarlos.

Entonces, hasta donde yo sé, hay ráfagas de subprocesos que se vuelven ejecutables en muy poco tiempo (puede ver una de esas ráfagas en la salida de vmstat). ¿Pero qué en mi configuración puede causar tal cosa?

Lo intenté:

  1. Jugar con la paquetización de códecs en sip.conf (había la idea de que estaba enviando demasiados micropaquetes);
  2. Cambiar el formato del archivo de reproducción;
  3. Deshabilitar completamente las llamadas de secuencias de comandos AGI (comentándolas en extensiones.conf);
  4. Cambiar la forma en que uso el canal AMI (cambiar intervalos y cantidades de ráfagas para aplanar la carga)

pero nada ayudó.

Revisé todo lo que se me ocurrió: no hay IO de disco ni otras aplicaciones en este servidor. Hay chicos en mailllist con problemas similares, pero eso no se resolvió, y fue hace bastante tiempo.

Un pensamiento más: tengo un servidor más con el mismo problema con hardware y configuración de Asterisk muy similares, pero allí se están usando Asterisk 1.8 (FreePBX) y CentOS. Sospecho que esto lleva a mi uso particular.

¿Quizás este sea el problema principal con AMI y debería usar algo más para las llamadas de inicialización masiva?

EDITAR1: Aquí está mi gráfico de Los Ángeles:

ingrese la descripción de la imagen aquí

EDITAR2:Aquí está la pista de Asterisk. Es relativamente igual con carga alta y baja. Yo no soy un programador de Linux, no puedo interpretarlo correctamente.

# strace -f -q -c -p 17150
^C% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 42.05 1595.370429       13209    120778     18231 futex
 41.21 1563.521630     6304523       248        14 restart_syscall
 15.96  605.470340        4726    128105        26 poll
  0.23    8.811410       12037       732           nanosleep
  0.16    5.903679          26    228693     22073 read
  0.15    5.600020          66     85202           write

Respuesta1

Bien, lo descubrí. Esta es sólo una solución alternativa, pero el problema ha disminuido a un nivel aceptable para mí.

Después de un reinicio no deseado a mitad del día, noté que el promedio de carga disminuyó considerablemente. Revisé nuestro sistema de monitoreo de servidores: LA siempre subía poco a poco en una carga continua (y estable) de 3 a 4 horas. Esto pasó desapercibido porque no pude reiniciarlo durante el día anterior.

Como dije, tengo un par de scripts de Perl, que se llaman a través de AGI()una aplicación. Uno de ellos se llama en hextensión; simplemente ejecuta una consulta de base de datos simple. Resultó que a veces las bases de datos se sobrecargan un poco; las consultas deben esperar entre 200 y 500 ms; Asterisk tiene que esperar hasta que finalice el script Perl.

Entonces, ataqué fork()mi script Perl al inicio, haciendo que la llamada AGI() regresara siempre inmediatamente. ¡Esto ayudó mucho! Los Ángeles se volvió mucho más estable. Esta no es una solución completa; parece que todavía está corrompiendo el interior de Asterisk, pero es mucho más lento y casi no es un problema.

Para aquellos que buscan un código listo para usar (no olviden obtener todas las variables antes de fork()ejecutar, ya que no podrán acceder $AGIdespués):

my $AGI = new Asterisk::AGI;

# get all your variables here
my $var = $AGI->get_variable('var');

undef $AGI;

if (fork) { exit 0; };
open STDIN,  '<', '/dev/null'; # dont forget to free your parent's file handles
open STDOUT, '>', '/dev/null';
open STDERR, '>&STDOUT';

Parece un error, pero me pregunto por qué no hay otras personas con este problema aparte de mí.

EDITAR1:Bueno, el problema desapareció por completo después de eliminar AGIlas llamadas. Simplemente hice un par de ODBCfunciones personalizadas ( func_odbc.conf), que simplemente guardan información para el procesamiento asincrónico (se procesa más tarde mediante un demonio Perl separado). LA cayó de 20-25 a 0,5-0,9 (!). Nunca pensé AGIque pudiera causar una carga tan grande.

información relacionada