Ospravedlňujeme sa za dnešný krátkodobý výpadok služby jabber.sk o 15:35 SEČ ako aj za viacnásobný výpadok transportov do sietí ICQ, MSN a AIM.
Výpadok bol spôsobený nedostatkom pamäte.
Zvýšené požiadavky servera ejabberd na pamäť boli pravdepodobne spôsobené veľkým množstvom dát posielaným medzi ejabberd serverom a ICQ transportom. V dôsledku čoho dochádzalo k dočasnému ukladaniu správ do pamäte.
Celá situácia bola diskutovaná s vývojármi servera ejabberd. Nedospeli sme k jednoznačnému záveru, ale úspešný pokus o vyriešenie naznačuje vyššie uvedené.
Hneď ako budeme poznať príčiny dnešných problémov, budeme vás o nich bezodkladne informovať.
váš tím jabber.sk
==========================================
Aktualizácia správy zo dňa 11.11.2009:
Po analýze súboru erl_crash.dump (vytvoreným pri páde ejabberd servera) jedným z vývojárov tohto softvéru (s prezývkou badlop) bolo zistené, že naša predchádzajúca analýza problému bola správna.
Pri analýze bolo zistené, že jeden zo smerovacích procesov servera ejabberd mal pri páde enormne veľkú frontu správ čakajúcich na spracovanie (197299).
Nebolo možné zistiť bližšie informácie o tomto procese, ale s najväčšou pravdepodobnosťou sa jednalo o smerovací proces pre ICQ transport.
Zoznam procesov s nenulovou frontou správ poskytnutý badlop-om:
Pid Name/SpawnedAs State Reductions Stack+heap MsgQLength <0.23609.227> proc_lib:init_p/5 Garbing (limited info) 7842253589 59786060 197299 <0.644.69> proc_lib:init_p/5 Waiting 656514 1346269 11651 <0.646.69> proc_lib:init_p/5 Waiting 175830 317811 2424
Okrem toho sme boli badlop-om upozornení na problém častého spúšťania príkazu ejabberdctl (využívaný okrem iného aj pre tvorbu štatistík) - v prípade záujmu si môžete prečítať bližší popis.
Na našom serveri sa za skoro 71 dní uložilo slušné množstvo záznamov:
jabber:/var/log/ejabberd# zgrep -c ejabberdctl erl_crash.dump.gz 601648
Včera v noci sme implementovali sledovanie množstva dát prenášaných cez jednotlivé transporty:
ICQ transport
MSN transport
AIM transport
Ďalším krokom pri riešení spomínaných problémov bude prepracovanie spúšťania skriptu ejabberdctl skriptami Munin-u, aby sa predchádzalo množeniu záznamov a zanášaniu pamäte servera.
Ako posledný krok sa preveria možnosti sledovania veľkostí front správ čakajúcich na spracovanie.
==========================================
Kedže mi to nedalo pokoj, tak som prešiel celý 'dump' súbor znova a našiel som exaktný dôkaz o pôvode problematického procesu.
Záznam problematického procesu:
=proc:<0.23609.227>
State: Garbing
Spawned as: proc_lib:init_p/5
Last scheduled in for: xml:'-crypt/1-lc$^0/1-0-'/1
Spawned by: <0.257.0>
Started: Sun Oct 4 14:37:10 2009
Message queue length: 197299
Number of heap fragments: 0
Heap fragment data: 0
Link list: [<0.257.0>, {from,<0.239.0>,#Ref<0.0.282.159010>}]
Reductions: 7842253589
Stack+heap: 59786060
OldHeap: 116769640
Heap unused: 61
OldHeap unused: 116769640
Program counter: 0x00007fb77184b528 (inet_db:lookup_socket/1 + 64)
CP: 0x00007fb7693e2cf8 (xml:'-crypt/1-lc$^0/1-0-'/1 + 424)
A následne v sekcii nadradeného procesu začínajúcej:
=proc_heap:<0.257.0>
som našiel nasledovné:
61D24B40:lP<0.23609.227>|H61D242E8 61D242E8:lH61D24398|H61D243B0 61D24398:t2:AF:ejabberd_socket,H61D243F8 61D243F8:t4:AC:socket_state,A7:gen_tcp,p<0.8113225>,P<0.23608.227> 61D243B0:lH61D24420|N 61D24420:lH61D244C8|H61D244E8 61D244C8:t3:A4:host,H61D24518,H61D24528 61D24528:lH61D24590|N 61D24590:t2:A8:password,H61D24628 61D24628:lI105|H61D24698 61D24698:lI99|H61D24700 61D24700:lI113|H61D24760 61D24760:lI115|H61D247D8 61D247D8:lI51|H61D24890 61D24890:lI99|H61D248F8 61D248F8:lI114|H61D24938 61D24938:lI51|H61D24978 61D24978:lI116|N 61D24518:lI105|H61D24580 61D24580:lI99|H61D24618 61D24618:lI113|H61D24688 61D24688:lI46|H61D246F0 61D246F0:lI106|H61D24750 61D24750:lI97|H61D247C8 61D247C8:lI98|H61D24880 61D24880:lI98|H61D248E8 61D248E8:lI101|H61D24928 61D24928:lI114|H61D24968 61D24968:lI46|H61D249A8 61D249A8:lI115|H61D249D8 61D249D8:lI107|N 61D244E8:lH61D24538|H61D24550 61D24538:t2:A2:ip,H61D245A8 61D245A8:t4:I127,I0,I0,I1 61D24550:lH61D245D0|H61D245E8 61D245D0:t2:A6:access,A3:all 61D245E8:lH61D24638|N 61D24638:t2:AB:shaper_rule,A3:icq 61D244F8:lH61D24560|N
V prvom riadku je číslo procesu a následne v predposlednom je názov shaper_rule - icq.