Bug #1450
closedPoměrně malé dotazy trvají neúměrně dlouho
Added by Pavel Kácha over 10 years ago. Updated about 10 years ago.
50%
Description
Vygenerovaný dotaz:
MongoDB filter:[FIND] Filter '{"$and":[{"Alert.Source.Node.Address.ipv4.min":{"$gte":"DEBA3E00"},"Alert.Source.Node.Address.ipv4.max":{"$lte":"DEBA3EFF"}},{"$and":[{"Alert.DetectTime.@ntpstamp":{"$gte":"D6B1077000000000"}},{"$and":[{"Alert.DetectTime.@ntpstamp":{"$lte":"D6BA41F000000000"}},{"Alert.Analyzer.@analyzerid":""}]}]}]}' with sorting '{"Alert.CreateTime.@ntpstamp":-1}' with limit '20'
MongoDB filter:[FIND] Filter '{"$and":[{"$or":[{"Alert.Source.Node.Address.ipv4.min":{"$gte":"DEBA3E00"},"Alert.Source.Node.Address.ipv4.max":{"$lte":"DEBA3EFF"}},{"Alert.Target.Node.Address.ipv4.min":{"$gte":"DEBA3E00"},"Alert.Target.Node.Address.ipv4.max":{"$lte":"DEBA3EFF"}}]},{"$and":[{"Alert.DetectTime.@ntpstamp":{"$gte":"D6B1077000000000"}},{"$and":[{"Alert.DetectTime.@ntpstamp":{"$lte":"D6BA41F000000000"}},{"Alert.Analyzer.@analyzerid":""}]}]}]}' with sorting '{"Alert.CreateTime.@ntpstamp":-1}' with limit '20'
Zkus prosím pustit z shellu, pokud proběhnou rychle, souvisí to s tím, že se mongo dostalo do podivného stavu tehdy, jinak bude potřeba řešit s výkonem.
Files
mongo-profiling.tar.gz (16.2 MB) mongo-profiling.tar.gz | Použité skripty a výstupy z profiléru | Jan Mach, 06/24/2014 10:17 AM | |
mentat.message.query.mongo.pl (1.08 KB) mentat.message.query.mongo.pl | Skript pro otestování vrstvy Mentat::Message::Query::Mongo | Jan Mach, 06/24/2014 10:18 AM | |
mentat.storage.mongo.pl (1.31 KB) mentat.storage.mongo.pl | Skript pro otestování vrstvy Mentat::Storage::Mongo | Jan Mach, 06/24/2014 10:18 AM | |
mentat.message.storage.mongo.pl (1.54 KB) mentat.message.storage.mongo.pl | Skript pro otestování vrstvy Mentat::Message::Storage::Mongo | Jan Mach, 06/24/2014 10:18 AM | |
msm-a_graph.png (39.9 KB) msm-a_graph.png | Graf - Výstup z profileru pro Mentat::Storage::Mongo::find() | Jan Mach, 06/24/2014 10:19 AM | |
msm-a_table.png (98.1 KB) msm-a_table.png | Tabulka - Výstup z profileru pro Mentat::Storage::Mongo::find() | Jan Mach, 06/24/2014 10:19 AM | |
msm-b_graph.png (66.9 KB) msm-b_graph.png | Graf - Výstup z profileru pro Mentat::Storage::Mongo::find_i() | Jan Mach, 06/24/2014 10:19 AM | |
msm-b_table.png (100 KB) msm-b_table.png | Tabulka - Výstup z profileru pro Mentat::Storage::Mongo::find_i() | Jan Mach, 06/24/2014 10:19 AM |
Related issues
Updated by Pavel Kácha over 10 years ago
- Assignee changed from Jan Mach to Radomír Orkáč
- Priority changed from Normal to High
Updated by Pavel Kácha over 10 years ago
Používají se správně indexy? Co variace různě zadaných/nezadaných polí? Bylo by vhodné jiné indexy udělat nebo naopak zrušit? Optimální by bylo, aby se využily indexy na všechna zadaná pole, je možné, že na to budou potřeba složené.
Není problém s {"Alert.Analyzer.@analyzerid":""}? Proč tam vlastně je?
Vhodné by bylo nasimulovat si variace dotazů a podívat se na explainy.
Updated by Radomír Orkáč over 10 years ago
- Status changed from New to In Progress
Pavel Kácha wrote:
Používají se správně indexy? Co variace různě zadaných/nezadaných polí? Bylo by vhodné jiné indexy udělat nebo naopak zrušit? Optimální by bylo, aby se využily indexy na všechna zadaná pole, je možné, že na to budou potřeba složené.
Uz jsem nekolik absentujicich indexu nasel, do VC je budu mit sepsane.
Není problém s {"Alert.Analyzer.@analyzerid":""}? Proč tam vlastně je?
Troufam si rict, ze tentokrat je chyba u Meka. Uz to dlouhou dobu krokuji a zalozim na to samostatny bug report.
Vhodné by bylo nasimulovat si variace dotazů a podívat se na explainy.
jj, jinak to nejde:(
Updated by Radomír Orkáč over 10 years ago
SOURCE IP AND DETECTOR TARGET IP AND DETECTOR MongoDB filter:[FIND] Filter '{"$and":[{"Alert.Source.Node.Address.ipv4.ip":"015D22D6"},{"$and":[{"Alert.Analyzer.@analyzerid":""},{"Alert.Analyzer.@name":""}]}]}' with sorting '{"Alert.DetectTime.@ntpstamp":-1}' with limit '30' db.alerts.find({"$and":[{"Alert.Source.Node.Address.ipv4.ip":"015D22D6"},{"$and":[{"Alert.Analyzer.@analyzerid":"au1-pickup"},{"Alert.Analyzer.@name":"LaBrea"}]}]}).explain() { "cursor" : "BtreeCursor Alert.Source.Node.Address.ipv4.ip_1", ... "indexBounds" : { "Alert.Source.Node.Address.ipv4.ip" : [ ... } db.alerts.find({"$and":[{"Alert.Source.Node.Address.ipv4.ip":"015D22D6"},{"$and":[{"Alert.Analyzer.@analyzerid":"au1-pickup"},{"Alert.Analyzer.@name":"LaBrea"}]}]}).explain() { "cursor" : "BtreeCursor test2", ... "indexBounds" : { "Alert.Source.Node.Address.ipv4.ip" : [ ... "Alert.Analyzer.@analyzerid" : [ ... "Alert.Analyzer.@name" : [ ... }
Updated by Pavel Kácha over 10 years ago
Tohle se výrazně zlepšilo! Variace různých polí se mi teď vracejí vcelku svižně.
Zádrhel bude ale ještě nejspíš u rozsahů:
Na ostrém dotaz na source 109.227.213.155/24 and dest 195.113.251.178/24 vytikává; stejně tak dotaz pouze na source 109.227.213.155/24.
Updated by Pavel Kácha over 10 years ago
Ovšem po konzultaci s Mekem nás to překvapuje, protože to vypadá, že na ostrém žádné nové indexy nejsou.
Bylo by potřeba, abychom byli připraveni na seminář - přihoď pls i info, co jsi udělal tady - a pokud je potřeba, aby Mek něco pullnul či vybuildil indexy, je to potřeba co nejdříve (indexy se taky můžou stavět den).
Updated by Radomír Orkáč over 10 years ago
Ad ostry) Zadne indexy jsem tam nedodaval, ale o vikendu je tam dodam, viz tento pozadavek.
Ad pull) Na pullu se s Mekem ted domluvim, mam tam minimalne opravu v devel kodu.
Na ostrém dotaz na source 109.227.213.155/24 and dest 195.113.251.178/24 vytikává; stejně tak dotaz pouze na source 109.227.213.155/24.
Jakmile o vikendu rucne nasadim indexy, ihned toto overim.
Diky, R.
Updated by Pavel Kácha over 10 years ago
- update na 2.6
- proč nepoužívá indexy z webového rozhraní? špatné konverze? (při pokusech na string nepoužil indexy, na bindata ano)
- možná problém, že máme mnoho zapisujících procesů, které zamykají db/indexy?
- Index Intersection v 2.6? (http://docs.mongodb.org/manual/core/index-intersection/)
Updated by Pavel Kácha over 10 years ago
- možná má 2.6 detailnější pohledy na plán (http://docs.mongodb.org/manual/reference/method/js-plan-cache/)
Updated by Pavel Kácha over 10 years ago
- mluvili jsme o prohození pořadí položek ve složeném indexu, kvůli kardinalitě - zkus ještě jednou a pozor na skutečné pořadí (hash/ixhash) a jména indexů
Updated by Pavel Kácha over 10 years ago
Zdá se, že Mongo vybírá indexy (které pasují) podle pořadí vytvoření indexu (WTF?), místo aby použilo složený index s odpovídající sadou polí. Zatím nemáme jinou možnost, než s tím žít, tj.:
- na ostrý s tím - přegenerovat potřebné indexy ve správném pořadí, pozor na zamykání na pozadí pro zápis, na ostrý klienti pořád píší
- ts a ts_u ponechat
Tím ale nezavíráme - bude chtít zjistit víc - jaký je v Mongu mechanismus, jestli něco nepřehlížíme, zda by nešlo Mongo znásilnit lépe, etc. "verbose" u explainu, tj. jaké plány a proč bere v úvahu a vybírá?
Index Intersection nám zřejmě úplně nepomůže, podle diskusí Mongo umí použít max dva současně.
Updated by Pavel Kácha over 10 years ago
Logování explainu:
- do logu jen explain.cursor
- (případně do devel toolbaru celý explain (klidně verbose))
Updated by Radomír Orkáč over 10 years ago
S Mekem jsme otestovali, ze parametr background pri vytvareni indexu zajisti nezamykani kolekci - aby byla zachovana spravna funkcnost (cteni/zapis).
Dale jsme se s Mekem domluvili, ze za kazdou cenu musim ponechat indexy ts a ts_u.
R.
Pavel Kácha wrote:
Zdá se, že Mongo vybírá indexy (které pasují) podle pořadí vytvoření indexu (WTF?), místo aby použilo složený index s odpovídající sadou polí. Zatím nemáme jinou možnost, než s tím žít, tj.:
- na ostrý s tím - přegenerovat potřebné indexy ve správném pořadí, pozor na zamykání na pozadí pro zápis, na ostrý klienti pořád píší
- ts a ts_u ponechat
Tím ale nezavíráme - bude chtít zjistit víc - jaký je v Mongu mechanismus, jestli něco nepřehlížíme, zda by nešlo Mongo znásilnit lépe, etc. "verbose" u explainu, tj. jaké plány a proč bere v úvahu a vybírá?
Index Intersection nám zřejmě úplně nepomůže, podle diskusí Mongo umí použít max dva současně.
Updated by Radomír Orkáč over 10 years ago
Pavel ma ve svych Alerts dotazech ulozeny nasledujici:
User queries - Test (simple) - Slow - range (simple) - Slow - source, detector, class (simple)
Vsechny tri jsem si vytvoril pod svym uzivatelem a jsou provedeny rychle.
Myslim si, ze je to tedy posun k lepsimu.
Pavle, muzes to testnout?
Pokud narazis na nejaky dalsi pomaly dotaz, dej vedet.
Zkousel jsem rozsah VSB (Source = 158.196.0.0/16):
Viewing duration: 4m 30s
Kdyz jsem dotaz vice omezil (Source = 158.196.0.0/16 && Class = Botnet B58-DGA2), tak rychlost byla:
Viewing duration: 1.0445s
R.
Updated by Pavel Kácha over 10 years ago
Source = 94.156.57.0/24 && Detector = mentat-wardenin/honeyscan && Class = Probe trvá 8 minut
Updated by Pavel Kácha over 10 years ago
Zajímavé, na druhý pokus 107 vteřin. Obávám se, že nám do toho leze kešování a tím pádem jsou výsledky nekonzistentní.
Updated by Radomír Orkáč over 10 years ago
Nejenom to.. dokazu si predstavit, ze u detectoru za to muze i find bez Tie::IxHash.
Samotny Source: 94.156.57.0/24 20.0829s
Ja ted pro tu indexaci udelal v Alerts maximum:(
Budeme navic chytrejsi, az budeme mit logovani pouzivani indexu.
R.
Updated by Radomír Orkáč over 10 years ago
Stejne indexy jsou na dev a ostrem. Pouziti indexu z konzole (bez ovlivneni ixhash) je na obou serverech jine (pravdepodobne diky jine verzi mongodb - 2.4.x verzus 2.6.x).
Ostry (evidentne spatne):
db.alerts.find({"$and":[{"Alert.Source.Node.Address.ipv4.min":{"$gte": HexData(0, "5E9C3900")},"Alert.Source.Node.Address.ipv4.max":{"$lte": HexData(0, "5E9C39FF")}},{"$and":[{"Alert.Classification.@text":"Probe"},{"$and":[{"Alert.Analyzer.@analyzerid":"mentat-wardenin"},{"Alert.Analyzer.@name":"honeyscan"}]}]}]}).explain() { "cursor" : "BtreeCursor analyzername",
Dev (dokazal bych si predstavit, ze je to spravne):
db.alerts.find({"$and":[{"Alert.Source.Node.Address.ipv4.min":{"$gte": HexData(0, "5E9C3900")},"Alert.Source.Node.Address.ipv4.max":{"$lte": HexData(0, "5E9C39FF")}}, {"$and":[{"Alert.Classification.@text":"Probe"},{"$and":[{"Alert.Analyzer.@analyzerid":"mentat-wardenin"},{"Alert.Analyzer.@name":"honeyscan"}]}]}]}).explain() { "cursor" : "BtreeCursor sourcecidr_and_targetcidr_and_detecttime_and_detector_and_class",
Updated by Radomír Orkáč over 10 years ago
Pavel Kácha wrote:
Zdá se, že Mongo vybírá indexy (které pasují) podle pořadí vytvoření indexu (WTF?), místo aby použilo složený index s odpovídající sadou polí.
Az parametr verbose mi celou vec objasnil. Na mentat-dev to proste tak vypadalo. Teprve az jsem zacal pouzivat explain s verbose a mam identicke indexy (ostry a dev), zjistuji, ze na poradi skutecne nezalezi (reakce na WTF?).
Zatím nemáme jinou možnost, než s tím žít, tj.:
- na ostrý s tím - přegenerovat potřebné indexy ve správném pořadí, pozor na zamykání na pozadí pro zápis, na ostrý klienti pořád píší
- ts a ts_u ponechat
Splneno. FYI, pregenerovani trvalo cca 12 hodin (respektive 849m7.885s). Pri tvorbe indexace byla zachovana funkcnost (zapis a cteni).
Tím ale nezavíráme - bude chtít zjistit víc - jaký je v Mongu mechanismus, jestli něco nepřehlížíme, zda by nešlo Mongo znásilnit lépe, etc. "verbose" u explainu, tj. jaké plány a proč bere v úvahu a vybírá?
Ano, prehlizel jsem. Zde zabral tebou navrhovany "verbose" explain.
Index Intersection nám zřejmě úplně nepomůže, podle diskusí Mongo umí použít max dva současně.
To je otazka, protoze jiz Complex plan konecne vidim. Opet diky verbose.
Neprijemne pro me ted je, ze mame rozdilnou verzi na ostrem a devu.
Nemohu overit, co presne za index nabidne dotazu pres webove rozhrani (nezohledneno ixhash):
Source = 94.156.57.0/24 && Detector = mentat-wardenin/honeyscan && Class = Probe trvá 8 minut
Prepsano:
db.alerts.find({"$and":[{"Alert.Source.Node.Address.ipv4.min":{"$gte": HexData(0, "5E9C3900")},"Alert.Source.Node.Address.ipv4.max":{"$lte": HexData(0, "5E9C39FF")}},{"$and":[{"Alert.Classification.@text":"Probe"},{"$and":[{"Alert.Analyzer.@analyzerid":"mentat-wardenin"},{"Alert.Analyzer.@name":"honeyscan"}]}]}]})
Diky "verbose" explain zjisteno
Na ostrem voli misto indexu "sourcecidr_and_targetcidr_and_detecttime_and_detector_and_class" index "analyzername".
Duvodem je (moje spekulace!) pocet skenovanych dokumentu / polozek v indexu - nscanned, ktery je u "analyzername" mensi.
Doba behu - "millis" : 28879 "cursor" : "BtreeCursor sourcecidr_and_targetcidr_and_detecttime_and_detector_and_class", "n" : 60, "nscannedObjects" : 60, "nscanned" : 758009, "cursor" : "BtreeCursor analyzername", "n" : 60, "nscannedObjects" : 758003, "nscanned" : 758003,
Pokud na ostrem u stejneho dotazu vynutim hintem index, ktery chci "sourcecidr_and_targetcidr_and_detecttime_and_detector_and_class", pak se cas zlepsi.. . Ziskal jsem samozrejme stejny vysledek (pocet dokumentu).
Doba behu - "millis" : 3093
V tuto chvili netusim, proc si na devu (novejsi) mongodb vybira z meho pohledu spravnejsi index, ale pokud se nepletu, pak je to diky intersection, ktera se mi u stejneho dotazu konecne objevuje (opet diky verbose):
... { "cursor" : "Complex Plan", "n" : 0, "nscannedObjects" : 0, "nscanned" : 32, "nChunkSkips" : 0 }, { "cursor" : "Complex Plan", "n" : 0, "nscannedObjects" : 0, "nscanned" : 32, "nChunkSkips" : 0 }, { "cursor" : "Complex Plan", "n" : 0, "nscannedObjects" : 0, "nscanned" : 61, "nChunkSkips" : 0 }, { "cursor" : "Complex Plan", "n" : 0, "nscannedObjects" : 0, "nscanned" : 32, "nChunkSkips" : 0 } ...
Updated by Radomír Orkáč over 10 years ago
Pavel Kácha wrote:
Logování explainu:
- do logu jen explain.cursor
Thu May 15 12:16:16 2014 mentat-dev hawat_fastcgi_devel.pl[26073]: INFO: [MMSM] Executing MongoDB command: [FIND] Filter '{"$and":[{"Alert.Analyzer.@analyzerid":"au1"},{"Alert.Analyzer.@name":"X2"}]}' with sorting '{"Alert.DetectTime.@ntpstamp":-1}' with limit '30' Thu May 15 12:16:16 2014 mentat-dev hawat_fastcgi_devel.pl[26073]: INFO: [MMSM] MongoDB index: BtreeCursor detector
- (případně do devel toolbaru celý explain (klidně verbose))
Database queries [27] Find alerts: [FIND] Filter '{"$and":[{"Alert.Analyzer.@analyzerid":"au1"},{"Alert.Analyzer.@name":"X2"}]}' with sorting '{"Alert.DetectTime.@ntpstamp":-1}' with limit '30' [27] Indexes: {"nscannedObjectsAllPlans":169,"filterSet":"0","cursor":"BtreeCursor detector","nscannedObjects":169, "millis":910,"nscannedAllPlans":169,"scanAndOrder":"0", "server":"mentat-dev:27017","isMultiKey":"0","n":169,"stats": {"needFetch":8,"yields":10,"works":178,"needTime":0,"children": [{"yields":10,"boundsVerbose":"field #0['Alert.Analyzer.@analyzerid']: [\"au1\", \"au1\"], field #1['Alert.Analyzer.@name']: [\"X2\", \"X2\"]", ...
Updated by Pavel Kácha over 10 years ago
Rozchází se nám kód (např. ixHash) a verze db na ostrém a nedá se testovat. Tudíž:
- opravit fetch (mongodump + mongorestore, NE mongoexport/import) #1606
- dotlačit kód do funkčního stavu
- otestovat readonly hawata na mentat-dev proti mongu 2.4 na ostrém
- balíky, import na ostrý
- upgrade Mongo 2.4 na 2.6
Pak bude pokračovat výkonové ladění na mongo-dev + ověřování na ostrém.
Updated by Radomír Orkáč over 10 years ago
- % Done changed from 0 to 50
S mensim zpozdenim.. .
Na mentat-dev jsem odinstaloval mongodb 2.6 a z ciste vody nainstaloval mongodb 2.4.
Provedl jsem import dat za 3 mesice a importoval i 1:1 kolekce groups, users.
Vyse uvedene nebylo predem domluveno, nicmene mi to prislo jako vhodne s ohledem na chystany upgrade
ostre mongodb. At to muzeme nejprve provest na mentat-dev. Dale jsem tam overoval funkcnost devel kodu
vuci mongodb 2.4.
Na devel kodu (proti mongodb 2.4) jsem overil vse co se dalo. Narazil jsem nakonec na potize s kesovanim selectoru (koncilo to na timeoutech). Po delsim zjistovani a overovani vuci stable kodu jsem usoudil, ze se nic nemenilo a ze to je problem pouze mentat-dev (horsi systemove prostredky CPU/RAM? nebo spise rychlost disku - mentat.cesnet.cz ma 3x rychlejsi bufferovane cteni z disku - 666.14 MB/sec versus 199.22 MB/sec).
Mek provedl merge "devel/stable" a kod nasadil na mentat.cesnet.cz. Po spusteni kesovani se ukazalo, ze problem s kesovanim selektoru je skutnecne jen zalezitost mentat-dev.cesnet.cz nikoliv mentat.cesnet.cz.
Dalsi domluva:
- do nedele budu provadet testovani rychlosti a pouzivani indexu (vcetne PLANu mongodb).
- v nedeli provedu upgrade mongodb z 2.4 na 2.6 na mentat-dev.cesnet.cz
- v pondeli se s Mekem potkame na kecadle a provedeme upgrade mongodb z 2.4 na 2.6 na mentat.cesnet.cz
- v utery mame VC v 9:00.
R.
Updated by Radomír Orkáč about 10 years ago
Nasel jsem drobnou chybu, ale mozna dulezitou v indexech:
{ "v" : 1, "key" : { "Alert.DetectTime.@ntpstamp" : NumberLong(-1), "Alert.Classification.@text" : NumberLong(1), "Alert.Analyzer.@analyzerid" : NumberLong(1), "Alert.Analyzer.@name => 1" : null }, "name" : "detecttime_and_detector_and_class", "ns" : "mentat.alerts", "background" : true }
Stalo by za to udelat reindex i s ohledem na reverzni indexy (kvuli sort - create/detect time), ktere nebyly mnou vytvareny.
Updated by Radomír Orkáč about 10 years ago
opravit indexy (#1450)
O vikendu jsem smazal a znovu vytvoril vsechny indexy na ostrem mentatu -> poresil jsem tim chybu REVERS INDEX, dale pak indexy s "Alert.Analyzer.@name => 1" : null.
mongo hlásí krátký průběh dotazu, ale webové rozhraní ale laguje (zřejmě patří také hlavně do #1450)
Resim to jiz delsi chvili na MENTAT-DEV a zatim jsem se nedostal k pricine.. . Nicmene, casovy nesoulad tam je. Pokud najdu jeste chvili, zkusim se dostat dale.
Vysledky rucniho skriptu..
PRES NASI VRSTVU
($alerts, $count_all) = $storage1->find_msg($filter, $sort, $limit, $skip); Count_all: 7, time: 6.26
WEBOVE ROZHRANI
Viewing duration: 6.9075s Displaying entries 1 to 7 Informace z indexu: millis: 2491 "n":7
MIMO NASI VRSTVU
my $result = $storage2->find($filter); Time: 0.00 Zpracovani dat v cyklu.. while (my $record = $result->next()) { ... } Count_all: 7, time: 1.26 Informace z indexu: Count_all: 7, millis: 1250
Updated by Radomír Orkáč about 10 years ago
Tak jsem sel do knihovny, ktera je nasi nadstavbou nad mongem a ze srandy jsem zakomentoval nasledujici...
lib/Mentat/Storage/Mongo.pm
sub find_i(;$$$$$) ... #my $count = $cursor->count(); my $count = 7; # # Apply the projection # if ($projection) { # Log::Loger->debug(__PACKAGE__, "[MMSM] Projecting results") if $DEVEL; # $cursor = $cursor->fields($projection); # } # # # Apply the sorting # if ($sort) { # Log::Loger->debug(__PACKAGE__, "[MMSM] Sorting results") if $DEVEL; # $cursor = $cursor->sort($sort); # } # # # Skip few first records # Log::Loger->debug(__PACKAGE__, "[MMSM] Skiping '$skip' results from beginning") if $DEVEL; # $cursor = $cursor->skip($skip) if ($skip > 0); # # # Return limited number of records # if ($limit > 0) { # Log::Loger->debug(__PACKAGE__, "[MMSM] Limiting results to max '$limit'") if $DEVEL; # $cursor = $cursor->limit($limit); # } # else { # Log::Loger->debug(__PACKAGE__, "[MMSM] Results are unlimited") if $DEVEL; # } # # # Info about mongodb index # $self->_set_last_index($cursor); # Log::Loger->info(__PACKAGE__, "[MMSM] MongoDB index: ".$self->get_last_index());
A casy?
PRED VRSTVOU Time: 0.00 Count_all: 7, time: 1.26 Count_all: 7, millis: 1238 --- ZA VRSTVOU Count_all: 7, time: 1.27 --- WEB Viewing duration: 1.8993s
Misto puvodnich:
PRED VRSTVOU Time: 0.00 Count_all: 7, time: 1.25 Count_all: 7, millis: 1253 --- ZA VRSTVOU Count_all: 7, time: 6.26 --- WEB Viewing duration: 6.8893s
Musim to jeste otestovat na ostrem, abych mohl rict, ze to je smerodatne:)
R.
Updated by Radomír Orkáč about 10 years ago
Overeno na ostrem mentat.cesnet.cz, je tam velmi znatelne zrychleni..
Kdyz tak vysvetlim na VC.
$filter = {'Alert.Source.Node.Address.ipv4.min' => { '$gte' => $min}, 'Alert.Source.Node.Address.ipv4.max' => { '$lte' => $max}, 'Alert.Classification.@text' => 'Webattack'}; PRED VRSTVOU Count_all: 9, time: 2.25 Count_all: 9, millis: 2326 --- ZA VRSTVOU Count_all: 9, time: 10.85 --- WEB Viewing duration: 12.4319s -------------------------- PRED VRSTVOU Count_all: 9, time: 2.14 Count_all: 9, millis: 2135 --- ZA VRSTVOU Count_all: 9, time: 2.14 --- WEB Viewing duration: 3.4621s ------------------------------------------------ $filter = {'Alert.Source.Node.Address.ipv4.min' => { '$gte' => $min}, 'Alert.Source.Node.Address.ipv4.max' => { '$lte' => $max}}; PRED VRSTVOU Count_all: 1, time: 5.25 Count_all: 1, millis: 5467 --- ZA VRSTVOU Count_all: 1, time: 24.23 --- WEB Viewing duration: 26.5013s -------------------------- PRED VRSTVOU Count_all: 1, time: 5.64 Count_all: 1, millis: 4956 --- ZA VRSTVOU Count_all: 1, time: 4.98 --- WEB Viewing duration: 5.9708s
Updated by Jan Mach about 10 years ago
- File mongo-profiling.tar.gz mongo-profiling.tar.gz added
- File mentat.message.query.mongo.pl mentat.message.query.mongo.pl added
- File mentat.message.storage.mongo.pl mentat.message.storage.mongo.pl added
- File mentat.storage.mongo.pl mentat.storage.mongo.pl added
- File msm-a_graph.png msm-a_graph.png added
- File msm-a_table.png msm-a_table.png added
- File msm-b_graph.png msm-b_graph.png added
- File msm-b_table.png msm-b_table.png added
Tak jsem na to zkusil jít odlesa, napsal jsem si pár skriptíků a na ostrém serveru jsem na to poštval profilér. Výsledek bohužel není dobrý, respektive jsem touto cestou došel k tomu, že v našich nadstavbových knihovnách asi problém není.
Celková doba běhu skriptu byla cca 13s a viník na vrchu profiléru byl tento:
Calls P F Exclusive Time Inclusive Time Subroutine
4 1 1 12.8s 12.8s MongoDB::MongoClient::recv (xsub)
Přikládám všechny skripty k nahlédnutí, zároveň pár print screenů z výsledků a balík s komprimovanými výsledky z profiléru.
Spustil jsem to zatím jen jednou, použil jsem stejné filtrační podmínky jako ve svých skriptech Radek, ale teď si neuvědomuji, jestli zrovna nebyl nějaký provoz na databázi. Profiling jsem udělal jen pro skript mentat.storage.mongo.pl pro klasický find(), i jeho inkrementální variantu find_i() a když jsem viděl výsledky, tak jsem to už pro další skripty nedělal. Možná by se na to po mě mohl podívat i Radek a zkontrolovat to, jestli jsem se nedopustil nějaké chyby, skripty jsou na ostrém serveru v umístění /root/mek.
Ať se to nemusí nikde hledat, tak skripty se spustí takto:
cd /root/mek perl -T -d:NYTProf mentat.storage.mongo.pl nytprofhtml
Updated by Jan Mach about 10 years ago
Pokud to stihneš, tak možná Radku také zkus poštvat profilér i na ty svoje testovací skripty a vlož jsem zase svůj výsledek, ať máme na VC nad čím podumat...divné totiž je, že jednak máme neskutečně odlišné výstupy a druhak mě to v databázi nic nenašlo a tobě koukám že jo.
Updated by Radomír Orkáč about 10 years ago
Delal jsi odlisne mereni nez ja.
Po prekontrolovani a predelani jsem to sjednotil a vysledky mame srovnatelne..
ZA VRSTVOU Count_all: 1, time: 14.48 DURATION: 14.9935939311981, COUNT: 1
Meku sorry, ale venoval jsem tomu dost casu (nemyslim to zle) a dneska navic nestiham, vystupu profilovani moc nerozumim, domluvme se, prosim, az na VC.
Updated by Jan Mach about 10 years ago
Jen abychom to nikde nehledali, tak tady je návod jak pustit libovolný dotaz v mongo shellu ze skriptu, tak, aby se vypsal kurzor a zároveň u toho změřit čas:
Příklad testovacího skriptu test.js:
db.alerts.find({"Alert.Source.Node.Address.ipv4.min":{ $gte : HexData(0,"9EC49E00")}, "Alert.Source.Node.Address.ipv4.max" : { $lte : HexData(0,"9EC49EFF")}}).limit(30).sort({"Alert.DetectTime.@ntpstamp":-1}).toArray();
Pak samotné měření:
root@mentat:~# more test.js root@mentat:~# time mongo mentat test.js
Updated by Radomír Orkáč about 10 years ago
Pro deterministicke testovani jsem udelal dva skripty. Je to pushnuto do devel kodu a delal i testoval jsem to na mentat-dev.
prototypes/Mongodb.pm prototypes/Mongodb.pl
Mongodb shell - Prime volani javascriptoveho kodu pres mongoshell:
($limit, $skip, $sort) = (30, 0, {'Alert.DetectTime.@ntpstamp' => -1}); $shell = 'function shell () { var a = db.alerts.find({"Alert.Source.Node.Address.ipv4.min" : {$gte : HexData(0,"B78E8800")}, "Alert.Source.Node.Address.ipv4.max" : {$lte : HexData(0, "B78E88FF")}, "Alert.Classification.@text" : "Portscan"}).limit('.$limit.').skip('.$skip.').sort({"Alert.DetectTime.@ntpstamp" : -1}).toArray(); return a.length; };'; my $count = `echo '$shell' | mongo --quiet mentat`;
Mongodb shell Time: 1.50 s
Perl find - Volani pres perl mongodb driver
($limit, $skip, $sort) = (30, 0, {'Alert.DetectTime.@ntpstamp' => -1}); $filter = {'Alert.Source.Node.Address.ipv4.min' => { '$gte' => $min}, 'Alert.Source.Node.Address.ipv4.max' => { '$lte' => $max}, 'Alert.Classification.@text' => 'Portscan'}; @query = (Tie::IxHash->new(%$filter), { limit => $limit, skip => $skip, sort_by => $sort}); my $client = MongoDB::MongoClient->new(host => 'localhost', port => 27017); my $database = $client->get_database('mentat'); my $collection = $database->get_collection('alerts'); my $result = $collection->query(@$query);
Perl find Time: 1.46 s
Perl eval - Volani pres perl mongodb driver, ale predan javascriptovy kod (obdoba volani pres shell) - $query je identicke viz shell nahore.
($limit, $skip, $sort) = (30, 0, {'Alert.DetectTime.@ntpstamp' => -1}); my $client = MongoDB::MongoClient->new(host => 'localhost', port => 27017); my $database = $client->get_database('mentat'); my $count = $database->eval($query);
Perl eval Time: 1.48 s
Mentat storage - Volani pres nas mongodb storage find (jen pro srovnani)
Mentat storage Time: 3.56 s
Mentat message - Volani pres nas mongodb storage message find_msg (zpracuje objekty) - jen pro srovnani
Mentat message Time: 3.60 s
Dotaz XYZ
($limit, $skip, $sort) = (30, 100, {'Alert.DetectTime.@ntpstamp' => -1});
Mongodb shell Time: 0.64 Perl find Time: 0.56 Perl eval Time: 0.58 Mentat storage Time: 2.81 Mentat message Time: 2.83
Dotaz XYZ - (Ukol od Pavla Mekovi: explain jen když je povolená konzole)
lib/Mentat/Storage/Mongo.pm #$self->_set_last_index($cursor); #Log::Loger->info(__PACKAGE__, "[MMSM] MongoDB index:".$self->get_last_index());
Mongodb shell Time: 0.65 (stejne) Perl find Time: 0.57 (stejne) Perl eval Time: 0.56 (stejne) Mentat storage (o 1.7 s rychlejsi) Time: 1.11 Mentat message (o 1.7 s rychlejsi) Time: 1.13
Dotaz XYZ - (JEN pro srovnani, ze nase mezivrstva je stejne rychla i se zpracovanim dat, jako dotaz pres shell).
Nikde ve skriptu totiz nenacitam count z kurzoru.
lib/Mentat/Storage/Mongo.pm #my $count = $cursor->count(); my $count = 30; #$self->_set_last_index($cursor); #Log::Loger->info(__PACKAGE__, "[MMSM] MongoDB index:".$self->get_last_index());
Mongodb shell Time: 0.63 Perl find Time: 0.56 Perl eval Time: 0.56 Mentat storage Time: 0.57 Mentat message Time: 0.58
V mailu jsem zapomnel napsat, ze pro kazdy dotaz / u kazdeho mereni jsem znovu vytvarel a navazoval spojeni s databazi. Myslim si, ze je to spravna myslenka, ze pri volani Mongo shellu musi byt znovu navazano spojeni - proto jsem chtel i pro perl find vzdy znovu navazat spojeni.
Na zaklade meho mereni dochazim k zaveru, ze nami vyuzivane a pozadovane funkce (limit, skip, sort) jsou srovnatelne rychle ve vsech merenich - testovano volani pres mongo shell, bezne volani pres perl mongodb api, javascript pres perl mongodb api, nase vrstvy/nadstavby (storage, storage-message). Meka zajimalo, jestli je perlove api pro pristup k Mongodb srovnatelne rychle jako mongo shell - podle mych mereni - ANO je - viz Dotaz XYZ.
V nasi mentat nadstavbe se pouzivaji dve veci, ktere nemam zahrnuty v mereni - count, eval (zjisteni vyuzivani indexu). Pokud tato dve mista do testovani nezahrnuji, je rychlost prakticky totozna, opet viz Dotaz XYZ.
Merenim jsem neoveril nekolik veci a mam tedy v planu otestovat:- velmi dlouhe dotazy (nad 1 minutu)
- jestli nase zpracovani v mentat nadstavbe pridava nejakou rezii (testoval jsem vse pouze s limitem 30) - zkusim to s limity 1000, 10000, 100000.
- otestuji muj skript a mereni na ostre databazi mentat.
Ze zapisu #1658 jeste zbyva:
Nereseno: - postupné nebo kompletní vyčítání výsledků? (asi cursor→next vs cursor→all) Nedoreseno - změní výkon pokud si řekneme jen o sloupce, které chceme, vs když čteme celé zprávy
Updated by Radomír Orkáč about 10 years ago
Test rychlosti dotazu, pokud si rekneme jen o nektere zaznamy/"sloupce".
Rychlost jsem testoval skriptem, pro lepsi meritelnost a vzdy jsem si zapsal nejrychlejsi vysledek (3x spusteno se stejnymi vstupnimi parametry). Testovano pomoci cisteho perl mongodb api - find (limit, skip, fields). Vystup jsem si overoval vypsanim vzdy jednoho zaznamu pomoci print Dumper($_);
$result->sort({'Alert.DetectTime.@ntpstamp' => -1}); $result->skip(1000); $result->limit(X);
BEZ fields (bez omezeni "sloupcu"). ------------------------------- $result->limit(100000); time: 6.16 $result->limit(10000); time: 0.63 $result->limit(1000); time: 0.07
Bez idmef zpravy ---------------- ->fields({ 'msg_raw' => 0, }) $result->limit(100000); time: 5.41 $result->limit(10000); time: 0.56 $result->limit(1000); time: 0.07
Pouze _id a parametry pouzivane pro vypsani v ALERTS ---------------------------------------------------- $result->sort({'Alert.DetectTime.@ntpstamp' => -1}); $result->skip(1000); ->fields({ 'Alert.Source.Node.Address.ipv4.ip' => 1, 'Alert.Source.Node.Address.ipv4.max' => 1, 'Alert.Source.Node.Address.ipv4.min' => 1, 'Alert.Target.Node.Address.ipv4.ip' => 1, 'Alert.Target.Node.Address.ipv4.max' => 1, 'Alert.Target.Node.Address.ipv4.min' => 1, 'Alert.Classification.@text' => 1, 'Alert.DetectTime.@ntpstamp' => 1 }) $result->limit(100000); time: 3.33 $result->limit(10000); time: 0.35 $result->limit(1000); time: 0.06
Moje shrnuti je takove, ze pokud bychom vypisovali a zpracovavali desetisicice zaznamu pro vystup, pak to smysl ma. Napr. pro dotaz, ktery je schopen realne vratit 100 000 zaznamu se zpracovanim na databazove urovni usetrilo zhruba 3s - (6.16s ; 5.41s bez msg_raw ; 3.33s pouze 5 sloupcu).
Updated by Pavel Kácha about 10 years ago
- Status changed from In Progress to Closed
- vytvořena a odladěna řada multiindexů nad Alerts, zakomponována do skriptů - nejvýznamnější vliv na výkon, Mongo občas single index nepoužilo, nebo použilo špatný
- Tie::IxHash místo Hash - hash způsoboval náhodné pořadí položek v indexech
- dotazy přes js vs perl vs perl->eval vs storage::find vs mentat::message - minimální a očekávatelné rozdíly
- drastický rozdíl s/bez explain a count při velkých limitech, ale pořád výrazně znatelný i při našich malých (mongo musí nejspíš dokončit dotaz i když je malý limit, aby zjistila kompletní count), viz #1658 příspěvek 6
- explain přesunout pouze do debug toolbaru
- nevracet počet položek