Asterisk - sehr hohe durchschnittliche Auslastung ohne Grund

Asterisk - sehr hohe durchschnittliche Auslastung ohne Grund

Es gibt ein Problem mit dem Asterisk-Server, der eine hohe durchschnittliche Auslastung aufweist, die ich nicht erklären kann. Mein Setup ist:

  1. Asterisk 13.1.0
  2. Linux 3.13.0-24 (Ubuntu Server)
  3. Dual-Socket-Server (Xeon E5-2620), HT-fähig – insgesamt 24 Kerne; 32 GB RAM

Asterisk wird zum Senden von Sprachnachrichten verwendet. Ich habe einen Upstream-SIP-Provider, keine Hardware-Telefoniekarten. In sip.conf sind nur alaw/ulaw zulässig.

Ich verwende den AMI Originate-Befehl, um einen Anruf zu starten; dann führe ich Playback() im Kontext aus, um eine vorab aufgezeichnete Sprachnachricht zu senden (ulaw-Dateien im lokalen ext4-FS). Es gibt keine weitere Interaktion mit dem Angerufenen, kein IVR-Menü, keine Anrufaufzeichnung. Ein paar sehr einfache Perl-AGI-Skripte speichern das Anrufergebnis in Datenbanken (MySQL und MSSQL (über Perl Sybase)); normalerweise gibt es 1-2 AGI-Anrufe pro Originate. Außerdem gibt es fast keine Verarbeitung in der Erweiterung – buchstäblich 20 Zeilen mit voreingestellten Veriablen für CDR() und ein paar AGI-Anrufe. Es gibt nur eine AMI-Verbindung, die ich zum Einleiten aller Anrufe verwende.

Das Besondere ist - die meisten Anrufe werden nicht beantwortet. Ich tätige bis zu 50 Anrufe pro Sekunde, aber nur 5-10 werden tatsächlich entgegengenommen und abgehört.

Das Problem ist: Ich habe eine sehr geringe CPU-Auslastung, aber eine sehr hohe LA. Wenn ich 20–25 cps starte, sind es 20–24 LA, aber wenn ich versuche, es auf 50 cps zu erhöhen, steigt die LA auf über 90. Nach ~50 LA gibt es Probleme mit der Audioqualität (und ich kann verstehen, warum).

Die meisten Asterisk-Benutzer behaupten, dass sie mit weniger leistungsstarker Hardware ein weitaus höheres Anrufvolumen hätten.

# 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 |

Wie Sie sehen, sind in den Feldern cs und vmstat sehr hohe Zahlen vorhanden. Ich kann sie nicht erklären.

Soweit ich es verstehe, gibt es Schübe von Threads, die in sehr kurzer Zeit ausführbar werden (Sie können einen solchen Schub in der vmstat-Ausgabe sehen). Aber was in meinem Setup kann so etwas verursachen?

Ich habe es versucht:

  1. Spielen mit der Codec-Paketierung in sip.conf (ich hatte das Gefühl, dass ich zu viele Mikropakete sende);
  2. Ändern des Wiedergabedateiformats;
  3. Vollständiges Deaktivieren von AGI-Skriptaufrufen (indem Sie sie in extensions.conf auskommentieren);
  4. Ändern der Art und Weise, wie ich den AMI-Kanal verwende (Ändern von Intervallen und Burst-Mengen, um die Belastung zu verringern)

aber nichts hat geholfen.

Ich habe alles überprüft, was mir eingefallen ist – es gibt keine Disk-E/A, keine anderen Anwendungen auf diesem Server. Es gibt Leute in der Mailingliste mit einem ähnlichen Problem, aber das wurde nicht gelöst und ist schon ziemlich lange her.

Noch ein Gedanke: Ich habe noch einen weiteren Server mit demselben Problem mit sehr ähnlicher Hardware und Asterisk-Konfiguration, aber dort werden Asterisk 1.8 (FreePBX) und CentOS verwendet. Ich vermute, das führt zu meiner speziellen Nutzung.

Vielleicht ist dies das Kernproblem von AMI und ich sollte für Masseninitialisierungsanrufe etwas anderes verwenden?

BEARBEITEN1: Hier ist mein LA-Diagramm:

Bildbeschreibung hier eingeben

EDIT2:Hier ist Asterisk strace. Es ist bei hoher und niedriger Belastung relativ gleich. Ich bin selbst kein Linux-Programmierer und kann es nicht richtig interpretieren.

# 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

Antwort1

Okay, ich habe es herausgefunden. Das ist nur eine Problemumgehung, aber das Problem ist für mich auf ein akzeptables Niveau gesunken.

Nach einem ungewollten Neustart mitten am Tag fiel mir auf, dass die durchschnittliche Auslastung stark abfiel! Ich überprüfte unser Serverüberwachungssystem – die durchschnittliche Auslastung stieg bei 3-4 Stunden kontinuierlicher (und stabiler) Auslastung immer langsam an. Das war nicht zu bemerken, weil ich es am Tag zuvor nicht neu starten konnte.

Wie gesagt, ich habe ein paar Perl-Skripte, die über AGI()die Anwendung aufgerufen werden. Eines davon wird in der hErweiterung aufgerufen; es führt nur eine einfache DB-Abfrage aus. Es stellte sich heraus, dass die DB manchmal etwas überlastet wird; Abfragen müssen 200-500 ms warten; Asterisk muss warten, bis das Perl-Skript fertig ist.

Also habe ich fork()zu Beginn an meinem Perl-Skript gespart und dafür gesorgt, dass der AGI()-Aufruf immer sofort zurückkehrt. Das hat sehr geholfen! LA wurde viel stabiler. Das ist keine vollständige Lösung – es scheint, dass es im Inneren von Asterisk immer noch etwas beschädigt, aber es ist viel langsamer, das ist fast kein Problem.

Für diejenigen, die einen gebrauchsfertigen Codeabschnitt suchen (vergessen Sie nicht, alle Variablen vor fork()dem ing abzurufen, da Sie danach nicht mehr darauf zugreifen können $AGI):

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';

Es scheint ein Fehler zu sein, aber ich frage mich, warum außer mir niemand ein solches Problem hat.

BEARBEITEN1:Nun, das Problem ist nach dem Eliminieren AGIder Anrufe vollständig verschwunden. Ich habe einfach ein paar benutzerdefinierte ODBCFunktionen ( func_odbc.conf) erstellt, die nur Informationen für die asynchrone Verarbeitung speichern (sie werden später von einem separaten Perl-Daemon verarbeitet). LA sank von 20-25 auf 0,5-0,9 (!). Ich hätte nie gedacht, dass dies AGIeine so große Belastung verursachen kann.

verwandte Informationen