Výpadok servera

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.