Hledání úzkého místa Wardenu¶

• Table of contents
• Hledání úzkého místa Wardenu
  • Profilování warden serveru pomocí Devel-NYTProf
    • Testy bez připojené databáze
      • Test č.1
      • Test č.2
      • Test č.3
      • Test č.4
    • Testy s připojenou databází
      • Test č.1
      • Test č.2
      • Test č.3
      • Test č.4
      • Test č.5
      • Test č.6
    • Závěr z profilování
  • Zprávy o testování z Plzně
    • Zpráva od Michala Kostěnce z 23.03.2012
    • Zpráva od Michala Kostěnce z 14.03.2012
  • Template zprávy
    • <Název testu>
    • Cíl testu
    • Stručný přehled testu
    • <libovolné další informace o testech>
    • Závěr

Stránka slouží pro zachycení informací o hledání úzkého místa v projektu Warden, které bylo zjištěno při distribuovaném testu provedeném 9.2.2012 až 12.2.2012. Zjištěn byl nepřijatelně nízký počet událostí za sekundu přijímaných Warden serverem a také efekt ukazující pravděpodobnou existenci určitého bufferu někde v systému odesílající klient -> server -> databáze událostí.

Vzhledem ke geografické roztříštěnosti osob testujících Warden, prosím, popisujte v maximální možné míře detailu a přesnosti prováděné testy (ideálně, ať jsou replikovatelné). Nedojde tak ke ztrátě informací a urychlí se vyřešení tohoto problému.

Profilování warden serveru pomocí Devel-NYTProf¶

Testy byly prováděny za účelem zjištění problémů v programovém kódu warden serveru pomocí jeho profilování nástrojem Devel-NYTProf, který je napsán a otestován pro Linux, Solaris, OS X a MS Win. Společnou vlastností všech testů je použití jednoho testovacího klienta s 1000 událostí proti profilovanému serveru, který sloužil jako generátor zátěže. Velikost prenasenych dat (posilaneho XML) je pro jednu udalost 1kB, v testu se tedy prenese celkem 1MB dat (1000 * 1kB), kdy pro kazdou udalost je vytvareno nove spojeni. Testy jsou rozděleny dle toho, zda byla k serveru připojena databáze, či nikoliv. Výsledky testů jsou shrnuty ve stručném závěru z Vzhledem k velikosti adresářů s výsledky testů, všechny testy po zabalení mají zhruba 200MB, jsou dostupné po vyžádání na emailech: cegan@ics.muni.cz a plesnik@ics.muni.cz.

Pro testování byly použity stroje warden-dev, nfsen-devel v roli klienta i serveru a warden pouze v roli klienta.

Stroj	nfsen-devel	warden-dev	warden
Distribuce	CentOS release 5.7 (Final)	Debian GNU/Linux 6.0.4 (squeeze)	Debian GNU/Linux 6.0.4 (squeeze)
Jádro	2.6.18-274.17.1.el5.centos.plus	Linux warden-dev 2.6.32-5-amd64 #1 SMP Tue Jun 14 09:42:28 UTC 2011 x86_64 GNU/Linux	Linux warden 2.6.32-5-amd64 #1 SMP Thu Nov 3 03:41:26 UTC 2011 x86_64 GNU/Linux
CPU	Xeon X5130 (2 jádra, 2GHz)	2x AMD Opteron(tm) Processor 4184 (6 jader, 2800MHz)	2x Intel(R) Xeon(R) CPU L5640 (6 jader,2.27GHz)
RAM	4GiB	32GiB	28GiB

Testy bez připojené databáze¶

V těchto testech byl eliminován vliv databáze na profilování serveru Warden.

Test č.1¶

Cíl testu

Snaha o nalezení úzkého hrdla serveru Warden. Profilování serveru na stroji warden-dev.

Stručný přehled testu

Server: warden-dev
Klient: nfsen-devel

Je profilován standardní Warden server z balíčku. Pouze byla odstraněna databáze.

Výpis z profileru

Profilování trvalo 212s. Bylo vykonáno 6002064 příkazů a 2306015 volání subrutin ve 111 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
1005	1	1	173s (81.4%)	173s (81.4%)	IO::Socket::CORE:accept (opcode)
1004	1	1	19.2s (9.0%)	19.2s (9.0%)	Net::SSLeay::accept (xsub)
6030	2	1	3.64s (1.7%)	3.64s (1.7%)	Net::SSLeay::peek (xsub)
15060	1	1	996ms (0.5%)	2.60s (1.2%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 8.08s)
164768	9	1	710ms (0.3%)	1.63s (0.8%)	SOAP::Data::new (recurses: max depth 1, inclusive time 158ms)
15060	2	1	616ms (0.3%)	2.70s (1.3%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 8.80s)
42192	7	1	408ms (0.2%)	1.06s (0.5%)	SOAP::Data::name
16064	2	1	343ms (0.2%)	684ms (0.3%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 708ms)
9040	3	1	280ms (0.1%)	1.17s (0.1%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 4.33s)
42176	4	1	233ms (0.1%)	308ms (0.1%)	SOAP::Utils::splitlongname
13052	2	1	217ms (0.1%)	1.82s (0.9%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 3.10s)
85370	35	1	203ms (0.1%)	221ms (0.1%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
1004	1	1	163ms (0.1%)	414ms (0.2%)	XML::Parser::Expat::ParseString (xsub)
142568	10	1	159ms (0.1%)	161ms (0.1%)	SOAP::Deserializer::CORE:match (opcode)
3480	4	3	149ms (0.1%)	184ms (0.1%)	Params::Validate::_validate (xsub)

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.2¶

Cíl testu

Otestování vlivu použitého socketu na chod serveru.

Stručný přehled testu

Server: nfsen-devel
Klient: warden-dev

V tomto testu bylo kromě odstranění databáze také nahrazeno standardní synchronní spojení na socketu (select) za asynchronní spojení pomocí modulu IO::Poll.

Výpis z profileru

Profilování trvalo 205s. Bylo vykonáno 7489619 příkazů a 2594702 volání subrutin ve 139 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
5303	1	1	179s (87.0%)	179s (87.0%)	IO::Poll::_poll (xsub)
4000	1	1	5.21s (2.5%)	5.21s (2.5%)	Net::SSLeay::accept (xsub)
15060	1	1	970ms (0.5%)	2.58s (1.3%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 7.97s)
164768	9	1	713ms (0.3%)	1.63s (0.8%)	SOAP::Data::new (recurses: max depth 1, inclusive time 160ms)
15060	2	1	626ms (0.3%)	2.69s (1.3%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 8.69s)
42192	7	1	403ms (0.2%)	1.06s (0.5%)	SOAP::Data::name
16064	2	1	351ms (0.2%)	699ms (0.3%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 719ms)
9040	3	1	297ms (0.1%)	1.22s (0.6%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 4.51s)
42176	4	1	231ms (0.1%)	307ms (0.1%)	SOAP::Utils::splitlongname
13052	2	1	227ms (0.1%)	1.84s (0.9%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 3.12s)
85369	35	1	212ms (0.1%)	230ms (0.1%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
5155	1	1	183ms (0.1%)	18.2s (8.9%)	IO::Async::Loop::Poll::post_poll
5303	2	1	171ms (0.1%)	179s (87.1%)	IO::Poll::poll
1004	1	1	170ms (0.1%)	170ms (0.1%)	Net::SSLeay::CTX_load_verify_locations (xsub)
1004	1	1	167ms (0.1%)	413ms (0.2%)	XML::Parser::Expat::ParseString (xsub)

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.3¶

Cíl testu

Zjištění vlivu stroje na warden server.

Stručný přehled testu

Server: nfsen-devel
Klient: warden-dev

Je profilován standardní Warden server z balíčku, který je nainstalován na stroji nfsen-devel, pro vyloučení vlivu stroje warden-dev na server. Také byla odstraněna databáze.

Výpis z profileru

Profilování trvalo 69.9s. Bylo vykonáno 6094827 příkazů a 2172572 volání subrutin ve 102 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
1000	1	1	16.7s (23.9%)	16.7s (23.9%)	Net::SSLeay::accept (xsub)
1001	1	1	14.9s (21.3%)	14.9s (21.3%)	IO::Socket::CORE:accept (opcode)
4000	2	1	3.18s (4.6%)	3.18s (4.6%)	Net::SSLeay::peek (xsub)
15000	1	1	2.12s (3.0%)	5.18s (7.4%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 16.6s)
164000	9	1	2.05s (2.9%)	4.15s (5.9%)	SOAP::Data::new (recurses: max depth 1, inclusive time 544ms)
15000	2	1	1.18s (1.7%)	5.36s (7.7%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 18.0s)
42000	6	1	1.03s (1.5%)	2.55s (3.7%)	SOAP::Data::name
16000	2	1	722ms (1.0%)	1.97s (2.8%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 2.65s)
9000	3	1	556ms (0.8%)	2.69s (3.8%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 9.83s)
85002	35	1	546ms (0.8%)	559ms (0.8%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
13000	2	1	510ms (0.7%)	4.46s (6.4%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 7.64s)
42000	4	1	407ms (0.6%)	522ms (0.7%)	SOAP::Utils::splitlongname
1000	1	1	405ms (0.6%)	672ms (1.0%)	XML::Parser::Expat::ParseString (xsub)
170028	18	4	338ms (0.5%)	338ms (0.5%)	UNIVERSAL::isa (xsub)
4010	10	4	325ms (0.5%)	377ms (0.5%)	utf8::SWASHNEW

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.4¶

Cíl testu

Zjištění vlivu stroje na warden server.

Stručný přehled testu

Server: nfsen-devel
Klient: warden-dev

Pro vyloučení vlivu stroje warden-dev je provedeno profilování serveru s modulem IO::Poll také na stroji nfsen-devel. Také v tomto případě byla odebrána databáze.

Výpis z profileru

Profilování trvalo 92.9s. Bylo vykonáno 7477921 příkazů a 2468330 volání subrutin ve 129 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
4041	1	1	44.1s (47.5%)	44.1s (47.5%)	IO::Poll::_poll (xsub)
2994	1	1	5.80s (6.2%)	5.80s (6.2%)	Net::SSLeay::accept (xsub)
15000	1	1	2.12s (2.3%)	5.20s (5.6%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 16.6s)
164000	9	1	2.04s (2.2%)	4.15s (4.5%)	SOAP::Data::new (recurses: max depth 1, inclusive time 533ms)
15000	2	1	1.19s (1.3%)	5.39s (5.8%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 18.0s)
42000	6	1	1.03s (1.1%)	2.55s (2.7%)	SOAP::Data::name
16000	2	1	722ms (0.8%)	1.98s (2.1%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 2.66s)
9000	3	1	591ms (0.6%)	2.73s (2.9%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 9.89s)
85001	35	1	545ms (0.6%)	558ms (0.6%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
13000	2	1	521ms (0.6%)	4.47s (4.8%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 7.64s)
1000	1	1	424ms (0.5%)	690ms (0.7%)	XML::Parser::Expat::ParseString (xsub)
42000	4	1	407ms (0.4%)	523ms (0.6%)	SOAP::Utils::splitlongname
169046	17	3	332ms (0.4%)	332ms (0.4%)	UNIVERSAL::isa (xsub)
4010	10	4	330ms (0.4%)	382ms (0.4%)	utf8::SWASHNEW
4019	1	1	314ms (0.3%)	31.4s (33.8%)	IO::Async::Loop::Poll::post_poll

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Testy s připojenou databází¶

Test č.1¶

Cíl testu

Profilování stroje na warden-dev s připojenou databází.

Stručný přehled testu

Server: warden-dev
Klient: nfsen-devel

Je profilován standardní Warden server z balíčku.

Výpis z profileru

Profilování trvalo 292s. Bylo vykonáno 6204694 příkazů a 2381548 volání subrutin ve 111 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
1006	1	1	251s (85.8%)	251s (85.8%)	IO::Socket::CORE:accept (opcode)
1005	1	1	19.2s (6.6%)	19.2s (6.6%)	Net::SSLeay::accept (xsub)
6040	2	1	3.60s (1.2%)	3.60s (1.2%)	Net::SSLeay::peek (xsub)
15075	1	1	975ms (0.3%)	2.59s (0.9%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 8.00s)
164960	9	1	721ms (0.2%)	1.62s (0.6%)	SOAP::Data::new (recurses: max depth 1, inclusive time 168ms)
1000	1	1	714ms (0.2%)	714ms (0.2%)	DBI::db::commit (xsub)
15075	2	1	618ms (0.2%)	2.70s (0.9%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 8.72s)
42240	7	1	398ms (0.1%)	1.06s (0.4%)	SOAP::Data::name
16080	2	1	349ms (0.1%)	694ms (0.2%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 714ms)
9050	3	1	287ms (0.1%)	1.20s (0.4%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 4.39s)
42220	4	1	232ms (0.1%)	308ms (0.1%)	SOAP::Utils::splitlongname
13065	2	1	225ms (0.1%)	1.82s (0.6%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 3.09s)
85462	35	1	209ms (0.1%)	226ms (0.1%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
1005	1	1	169ms (0.1%)	418ms (0.1%)	XML::Parser::Expat::ParseString (xsub)
142710	10	1	161ms (0.1%)	163ms (0.1%)	SOAP::Deserializer::CORE:match (opcode)

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.2¶

Cíl testu

Ověření vlivu použitého socketu na server.

Stručný přehled testu

Server: warden-dev
Klient: nfsen-devel

V tomto testu je profilován server s nahrazením standardního synchronního spojení na socketu (select) za asynchronní spojení pomocí modulu IO::Poll.

Výpis z profileru

Profilování trvalo 218s. Bylo vykonáno 7670641 příkazů a 2663653 volání subrutin ve 139 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

5319	1	1	189s (86.8%)	189s (86.8%)	IO::Poll::_poll (xsub)
3996	1	1	5.22s (2.4%)	5.22s (2.4%)	Net::SSLeay::accept (xsub)
15045	1	1	980ms (0.5%)	2.61s (1.2%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 8.00s)
1000	1	1	954ms (0.4%)	954ms (0.4%)	DBI::db::commit (xsub)
164576	9	1	714ms (0.3%)	1.62s (0.7%)	SOAP::Data::new (recurses: max depth 1, inclusive time 162ms)
15045	2	1	630ms (0.3%)	2.72s (1.3%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 8.72s)
42144	7	1	404ms (0.2%)	1.05s (0.5%)	SOAP::Data::name
16048	2	1	362ms (0.2%)	723ms (0.3%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 749ms)
9030	3	1	293ms (0.1%)	1.21s (0.6%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 4.45s)
42132	4	1	228ms (0.1%)	303ms (0.1%)	SOAP::Utils::splitlongname
13039	2	1	222ms (0.1%)	1.82s (0.8%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 3.07s)
85277	35	1	218ms (0.1%)	235ms (0.1%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
5160	1	1	185ms (0.1%)	20.2s (9.3%)	IO::Async::Loop::Poll::post_poll
1003	1	1	181ms (0.1%)	433ms (0.2%)	XML::Parser::Expat::ParseString (xsub)
1003	1	1	176ms (0.1%)	176ms (0.1%)	Net::SSLeay::CTX_load_verify_locations (xsub)

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.3¶

Cíl testu

Zjištění vlivu stroje na warden server.

Stručný přehled testu

Server: nfsen-devel
Klient: warden-dev

V tomto testu byl jako fyzický stroj pro server použit nfsen-devel, aby tak byl vyloučen vliv stroje.

Výpis z profileru

Profilování trvalo 211s. Bylo vykonáno 6277827 příkazů a 2239572 volání subrutin ve 102 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
1001	1	1	109s (51.7%)	109s (51.7%)	IO::Socket::CORE:accept (opcode)
1000	1	1	44.9s (21.3%)	44.9s (21.3%)	DBI::db::commit (xsub)
1000	1	1	16.7s (7.9%)	16.7s (7.9%)	Net::SSLeay::accept (xsub)
4000	2	1	3.19s (1.5%)	3.19s (1.5%)	Net::SSLeay::peek (xsub)
15000	1	1	2.11s (1.0%)	5.17s (2.5%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 16.5s)
164000	9	1	2.04s (1.0%)	4.14s (2.0%)	SOAP::Data::new (recurses: max depth 1, inclusive time 532ms)
15000	2	1	1.18s (0.6%)	5.36s (2.5%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 17.9s)
42000	6	1	1.02s (0.5%)	2.54s (1.2%)	SOAP::Data::name
3000	3	2	725ms (0.3%)	725ms (0.3%)	DBI::st::execute (xsub)
16000	2	1	716ms (0.3%)	1.97s (0.9%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 2.64s)
9000	3	1	568ms (0.3%)	2.69s (1.3%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 9.75s)
85002	35	1	544ms (0.3%)	557ms (0.3%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
13000	2	1	522ms (0.2%)	4.45s (2.1%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 7.61s)
1000	1	1	422ms (0.2%)	684ms (0.3%)	XML::Parser::Expat::ParseString (xsub)
42000	4	1	408ms (0.2%)	524ms (0.2%)	SOAP::Utils::splitlongname

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.4¶

Cíl testu

Zjištění vlivu stroje na server.

Stručný přehled testu

Server: nfsen-devel
Klient: warden-dev

V tomto testu byl jako fyzický stroj pro server použit nfsen-devel, aby tak byl vyloučen vliv stroje. Také bylo místo socketů se select použito asynchronních socketů z modulu IO::Poll.

Výpis z profileru

Profilování trvalo 153s. Bylo vykonáno 7659661 příkazů a 2535077 volání subrutin ve 129 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
4066	1	1	53.5s (35.1%)	53.5s (35.1%)	IO::Poll::_poll (xsub)
1000	1	1	47.4s (35.1%)	47.4s (35.1%)	DBI::db::commit (xsub)
2996	1	1	5.78s (3.8%)	5.78s (3.8%)	Net::SSLeay::accept (xsub)
15000	1	1	2.11s (1.4%)	5.20s (3.4%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 16.5s)
164000	9	1	2.04s (1.3%)	4.15s (2.7%)	SOAP::Data::new (recurses: max depth 1, inclusive time 534ms)
15000	2	1	1.19s (0.8%)	5.39s (3.5%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 17.9s)
42000	6	1	1.02s (0.7%)	2.55s (1.7%)	SOAP::Data::name
3000	3	2	842ms (0.6%)	842ms (0.6%)	DBI::st::execute (xsub)
16000	2	1	724ms (0.5%)	2.00s (1.3%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 2.68s)
9000	3	1	569ms (0.4%)	2.72s (1.8%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 9.87s)
85001	35	1	556ms (0.4%)	569ms (0.4%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
13000	2	1	513ms (0.3%)	4.46s (2.9%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 7.61s)
1000	1	1	431ms (0.3%)	701ms (0.5%)	XML::Parser::Expat::ParseString (xsub)
42000	4	1	409ms (0.3%)	525ms (0.3%)	SOAP::Utils::splitlongname
169046	17	3	336ms (0.2%)	336ms (0.2%)	UNIVERSAL::isa (xsub)

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.5¶

Cíl testu

Zjištění vlivu spojení skrz počítačovou síť na server.

Stručný přehled testu

Server: warden
Klient: warden-dev

Při tomto testu se vycházelo z předpokladu, že vliv na doručování událostí může mít také počítačová síť skrze firewally a směrovače. Proto byly za server a klienta zvoleny servery cesnetu (warden, warden-dev), u kterých se předpokládá, že mají mezi sebou nejkratší cestu v síti.

Výpis z profileru

Profilování trvalo 241s. Bylo vykonáno 6198603 příkazů a 2381510 volání subrutin ve 111 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
1006	1	1	209s (86.5%)	209s (86.5%)	IO::Socket::CORE:accept (opcode)
1005	1	1	13.6s (5.6%)	13.6s (5.6%)	Net::SSLeay::accept (xsub)
15075	1	1	972ms (0.4%)	2.59s (1.1%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 8.00s)
1000	1	1	970ms (0.4%)	970ms (0.4%)	DBI::db::commit (xsub)
164960	9	1	701ms (0.3%)	1.61s (0.7%)	SOAP::Data::new (recurses: max depth 1, inclusive time 157ms)
15075	2	1	620ms (0.3%)	2.69s (1.1%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 8.72s)
42240	7	1	405ms (0.2%)	1.06s (0.4%)	SOAP::Data::name
16080	2	1	349ms (0.1%)	695ms (0.3%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 714ms)
9050	3	1	285ms (0.1%)	1.19s (0.5%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 4.38s)
42220	4	1	232ms (0.1%)	309ms (0.1%)	SOAP::Utils::splitlongname
13065	2	1	218ms (0.1%)	1.81s (0.7%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 3.06s)
85462	35	1	211ms (0.1%)	228ms (0.1%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
1005	1	1	168ms (0.1%)	419ms (0.2%)	XML::Parser::Expat::ParseString (xsub)
142710	10	1	159ms (0.1%)	161ms (0.1%)	SOAP::Deserializer::CORE:match (opcode)
3483	4	3	158ms (0.1%)	198ms (0.1%)	Params::Validate::_validate (xsub)

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Test č.6¶

Cíl testu

Zjištění vlivu spojení skrz počítačovou síť na server.

Stručný přehled testu

Server: warden
Klient: warden-dev

Při tomto testu se vycházelo z předpokladu, že vliv na doručování událostí může mít také počítačová síť skrze firewally a směrovače. Proto byly za server a klienta zvoleny servery cesnetu (warden, warden-dev), u kterých se předpokládá, že mají mezi sebou nejkratší cestu v síti. Byly zde použity asynchronní sockety z modulu IO::Poll.

Výpis z profileru

Profilování trvalo 228s. Bylo vykonáno 7536870 příkazů a 2644881 volání subrutin ve 139 zdrojových souborech. Zachyceno je prvních 15 subrutin. Podrobný výpis je dostupný v plném výpisu testu.

Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
4376	1	1	199s (87.5%)	199s (87.5%)	IO::Poll::_poll (xsub)
3017	1	1	5.22s (2.3%)	5.22s (2.3%)	Net::SSLeay::accept (xsub)
15075	1	1	1.00s (0.4%)	2.65s (1.2%)	SOAP::Deserializer::decode_value (recurses: max depth 4, inclusive time 8.12s)
164960	9	1	713ms (0.3%)	1.63s (0.7%)	SOAP::Data::new (recurses: max depth 1, inclusive time 159ms)
1000	1	1	692ms (0.3%)	692ms (0.3%)	DBI::db::commit (xsub)
15075	2	1	638ms (0.3%)	2.76s (1.2%)	SOAP::Deserializer::decode_object (recurses: max depth 4, inclusive time 8.85s)
42240	7	1	408ms (0.2%)	1.07s (0.5%)	SOAP::Data::name
16080	2	1	355ms (0.2%)	710ms (0.3%)	SOAP::SOM::_traverse (recurses: max depth 3, inclusive time 725ms)
9050	3	1	296ms (0.1%)	1.21s (0.5%)	SOAP::Serializer::encode_object (recurses: max depth 8, inclusive time 4.46s)
42220	4	1	235ms (0.1%)	311ms (0.1%)	SOAP::Utils::splitlongname
13065	2	1	222ms (0.1%)	1.84s (0.8%)	SOAP::SOM::_as_data (recurses: max depth 2, inclusive time 3.11s)
85461	35	1	215ms (0.1%)	232ms (0.1%)	SOAP::Lite::Utils::__ANON__[SOAP/Lite/Utils.pm:22]
1005	1	1	177ms (0.1%)	177ms (0.1%)	Net::SSLeay::CTX_load_verify_locations (xsub)
1005	1	1	177ms (0.1%)	432ms (0.2%)	XML::Parser::Expat::ParseString (xsub)
3483	4	3	162ms (0.1%)	205ms (0.1%)	Params::Validate::_validate (xsub)

pozn. P označuje počet míst, ze kterých je subrutina volána. F označuje počet souborů, ze kterých je subrutina volána.

Grafické znázornění času stráveného v subrutinách

pozn. Barvy reprezentují jednotlivé balíky.

Závěr z profilování¶

V průběhu profilování serveru byly zjištěny dva zásadní poznatky. Za prvé je možné zvýšit poměrně výrazně rychlost přijímání událostí pomocí asynchronních soketů (IO:Poll). Druhým závažnějším zjištěním je podstatné zpomalení běhu serveru na stroji warden-dev oproti nfsen-devel a to i přes to, že warden-dev disponuje několikanásobně větším výkonem. Pravděpodobně tedy zatím nezjištěné nastavení stroje brání rychlejšímu přijetí událostí. Při odesílání událostí na server warden-dev je u odesílajícího klienta pozorováno přerušované odesílání, způsobené zřejmě bufferováním příchozích událostí na Warden serveru. Pokud je Warden server spuštěn na druhém serveru nfsen-devel, tak ke zmiňovanému chování nedochází. Pro odstranění podezření, že k bufferování dochází na nějakém aktivním prvku v síti mezi Warden serverem warden-dev a odesílajícím klientem nfsen-devel, bylo spuštěno i testování mezi servery warden (klient) a warden-dev (server), nicméně k podezřelému bufferování příchozích událostí dochází i v tomto případě.

Zprávy o testování z Plzně¶

Zpráva od Michala Kostěnce z 23.03.2012¶

Byl objeven bug č. #387.

Ahoj,
nacpali jsme s Bodikem do gitu (branch receive-apache2) upravenou verzi Warden serveru
napasovanou na Apache a mod_perl a MySQL.

Pokud budete chtit vyzkouset, tak muzete mrknout do gitu. Pro jistotu posilam jeste balicky
klienta a serveru v priloze. Instalace klienta je stejna u serveru se ridte souborem README.warden-apache.

Jinac jsem narazil na chybu, kdy instalace serveru do adresare jineho nez default (/opt) skonci chybou (adresar neexistuje).
Do instalatoru jsem pridal testovani na adresar a pripadne jeho vytvoreni. V uninstallu jsem to jeste neopravil. Mrknete jestli
Vam to dela taky a nebo to byl problem jen u me.

Michal. 

Zpráva od Michala Kostěnce z 14.03.2012¶

Ahoj,
bohuzel nemam uz moc casu, protoze odjizdim na hory, ale sepisu alespon nekolik poznatku. 

  1) Zasadni problemem je absence paralelniho zpracovani na strane serveru
  2) Druhym problemem jsou SSL operace
    - pri vypnuti SSL_verify_mode v SOAP serveru jsme dostali 15 zprav/sekundu
    - entropie neni problem

Nase reseni:
  Napasovali jsme Warden server 1:1 pres mod_perl na Apache
    - pouzili jsme tedy nativni SSL funkce pro zpracovani pozadavku a predani serveru
    - je mozno ladit parametry serveru pri v Apache2.conf (timeout, keep-alive, pre-fork modul apod.)

Nutne zmeny:
  - pro klienta musely byt zmeneny moduly posilani na HTTP (SOAP::Transport::HTTP)
  - nejak to neslapalo s SQLite, takze jednoducha zmena na DB MySQL
    - dalsi moznosti ladeni primo MySQL (cache, apod.)
  - uz nemame na serveru pristup k socketum, proto musime brat informace primo z EnvVars
    - pro subjAltNames musime parsovat certifikat pres jiny modul
  + dalsi drobnosti

Testovani
Testovali jsme server pri cca 40 klientech z METAcentra a s vypnutou kontrolou CN,AN,CIDR na zacatku metody saveNewEvent,
protoze jeste nemam skript pro automaticke generovani certifikatu.

Dosahli jsme rychlosti 1 MACH = cca 300 zprav / sekundu 

Pri nasi implementaci jsme narazili na problem s odesilacem na Debian Lenny, ktery zaviral otevrene sockety az pri ukoncovani skriptu,
takze pokud se odesilalo vice jak 1024 zprav, tak to padlo na Too many open files ... (nevim, jestli to takhle zlobi i pri puvodni implementaci)

Odesilani z Debian Squeeze je OK.

Dalsi postrehy:
Narazil jsem na problem, kdy jsem vygeneroval certifikat s CN kostej.zcu.cz a jako AN dal holly.cesnet.cz. Pokud jsem zkousel prijmout udalosti z holly.cesnet.cz a pouzil tento certifikat,
tak SQL dotaz vyhodil ze je to sice OK ale vysledkem byly registrovane udaje kostej.zcu.cz, coz prijimace holly.cesnet.cz odmitlo. (CIDR nesouhlasi)
Je asi na diskusi, zda to resit, ale podle me by to chtelo. 
  = pouzil bych trosku upravenou funkci registrace a navic vkladal rozsah CIDRu v long formatu (funkce inet_aton, inet_ntoa)
  = overovani by se pak zkratilo na jeden SELECT
  = zjednoduseni, vyreseni problemu:)

Zkousel jsem testovat prijimani zprav a klient mi neustale vypisoval prazdnou tabulku. Dle komentare v kodu jsem problem pochopil:
  # get last ID from ID file (if exist) or
  # get last ID from warden server DB and save it into ID file

Pokud tedy chci prijimat, tak zavolam funkci, ktera zjisti, ze jsem jeste nic neprijimal (nemam ID file) a stahne si cislo posledni zpravy, ale zadna data ????
Znamena to, ze ja si to musim jednou pustit naprazdno a pak cekat, az nejake udalosti budou a nasledne si je budu moci stahnout.

Pokud to ma byt ochrana, abych si netahal velke mnozstvi starych zprav, tak bych pridal do parametru volani datum, jak moc stara data chci, bez parametru jen nova.

Vsechny funkce jsou dostupne i pres toto testovane reseni.
Az prijedu z dovolene, tak to cele ucesu do spravne formy  a dam k dispozici. 
Proberem Jihlave nebo pres video jestli pujdem touto cestou nebo nejakou uplne jinou;)

Michal.

Template zprávy¶

Pro popisy prováděných testů prosím používejte kvůli přehlednosti níže uvedený template, který samozřejmě rozšiřujte o další užitečné části. Jako inspirace pro obsah může posloužit například zpráva o provedeném distribuovaném testu. V případě potřeby převodu html výstupu, například perl profileru, do formátu Redmine wiki je možné použít stránku Převodník html -> Redmine wiki.

<Název testu>¶

Provedl: <jméno, organizace>

Cíl testu¶

<...>

Stručný přehled testu¶

<...>

(např. počet klientů na stroji, počet strojů, počet událostí/klient, doba běhu, využití swap, RAM po dobu běhu testu, CPU po dobu běhu testu, doba běhu klientů na strojích)

<informace o strojích: distribuce, jadro, cpu, ram, sitova karta>

<libovolné další informace o testech>¶

<...>

Závěr¶

<...>