Project

General

Profile

Actions

Bug #1450

closed

Poměrně malé dotazy trvají neúměrně dlouho

Added by Pavel Kácha over 10 years ago. Updated almost 10 years ago.

Status:
Closed
Priority:
High
Category:
Development - Core
Target version:
Start date:
03/11/2014
Due date:
% Done:

50%

Estimated time:
To be discussed:

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

Related to Mentat - Bug #1205: MongoDB - výkonnostní problémyClosedRadomír Orkáč09/06/2013

Actions
Blocked by Mentat - Bug #1479: Core, Storage/Mongo - _set_last_filterClosedJan Mach03/30/2014

Actions
Actions #1

Updated by Pavel Kácha about 10 years ago

  • Assignee changed from Jan Mach to Radomír Orkáč
  • Priority changed from Normal to High
Actions #2

Updated by Pavel Kácha about 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.

Actions #3

Updated by Radomír Orkáč about 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:(

Actions #4

Updated by Radomír Orkáč about 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" : [
...
}

Actions #5

Updated by Pavel Kácha about 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.

Actions #6

Updated by Pavel Kácha about 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).

Actions #7

Updated by Radomír Orkáč about 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.

Actions #8

Updated by Pavel Kácha about 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/)
Actions #9

Updated by Pavel Kácha about 10 years ago

Actions #10

Updated by Pavel Kácha about 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ů
Actions #11

Updated by Pavel Kácha about 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ě.

Actions #12

Updated by Pavel Kácha about 10 years ago

Logování explainu:

  • do logu jen explain.cursor
  • (případně do devel toolbaru celý explain (klidně verbose))
Actions #13

Updated by Radomír Orkáč about 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ě.

Actions #14

Updated by Radomír Orkáč about 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.

Actions #15

Updated by Pavel Kácha about 10 years ago

Source = 94.156.57.0/24 && Detector = mentat-wardenin/honeyscan && Class = Probe trvá 8 minut

Actions #16

Updated by Pavel Kácha about 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í.

Actions #17

Updated by Radomír Orkáč about 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.

Actions #18

Updated by Radomír Orkáč about 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",

Actions #19

Updated by Radomír Orkáč about 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
                }
...

Actions #20

Updated by Radomír Orkáč about 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\"]",
...
Actions #21

Updated by Pavel Kácha about 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.

Actions #22

Updated by Radomír Orkáč about 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.

Actions #23

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.

Actions #24

Updated by Radomír Orkáč almost 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

Actions #25

Updated by Radomír Orkáč almost 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.

Actions #26

Updated by Radomír Orkáč almost 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
Actions #27

Updated by Jan Mach almost 10 years ago

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

Actions #28

Updated by Jan Mach almost 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.

Actions #29

Updated by Radomír Orkáč almost 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.

Actions #30

Updated by Jan Mach almost 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

Actions #31

Updated by Radomír Orkáč almost 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

Actions #32

Updated by Radomír Orkáč almost 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).

Actions #33

Updated by Pavel Kácha almost 10 years ago

  • Status changed from In Progress to Closed
Závěry:
  • 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
Actions

Also available in: Atom PDF