Mentat

Prvni testy jsou za mnou.
Vygenerovane dotazy mam jiz z minula (kde jsem pouzil tehdy jine hodnoty a zaznamenal si to rucne, bez analyzy).

generated_1692
generated_1696
generated_1694
generated_1695

1. test - cca 4,5 hod. Dotazy nad dve minuty..

./mongotest -f -s -r 10 -q -c mongotest.cfg mongotest2.cfg

"Delka trvani vykonani dotazu", cislo dotazu
"0:02:54.299726",925
"0:03:22.548216",690
"0:03:27.031381",689
"0:03:27.043367",691
"0:03:36.672472",693
"0:04:01.801571",1689
"0:04:27.658923",662
"0:04:34.753272",697
"0:04:40.803156",669
"0:04:46.035580",663
"0:04:57.748062",692
...
"0:05:05.623534",1690, "count": "0”, AND {"IP4.min”, "IP4.max”, “IP4.min”, “IP4.max”}
"0:05:08.716137”,694, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP”, …..}
"0:05:11.312348”,695, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP”, …..}
"0:05:16.553314",670, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:05:23.006646”,698, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:05:30.696048”,671, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:05:33.283824”,661, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:05:36.738205”,699, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:05:41.952723”,664, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:05:45.230626”,701, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:06:25.123316”,1691, "count": "0”, AND {"IP4.min”, "IP4.max”}
"0:06:28.623963”,696, "count": "0”, “IP4.min”, “IP4.max”
"0:06:40.473151”,672, "count": "0”, “IP4.min”, “IP4.max”
"0:07:06.788909”,700, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:07:18.448093”,703, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:07:18.799745”,702, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:07:23.564200”,1693, "count": "0”, AND {"IP4.min”, "IP4.max”, “IP4.min”, “IP4.max”}
"0:08:29.159541”,704, "count": "0”, AND {"IP4.min”, "IP4.max”}, OR {NECO, “IP4.min”, “IP4.max”, …..}
"0:08:43.540545”,1692, "count": "0”, AND {"IP4.min”, "IP4.max”, “IP4.min”, “IP4.max”}
"0:10:05.249022”,1696, "count": "0”, AND {"IP4.min”, "IP4.max”, “IP4.min”, “IP4.max”}
"0:10:43.061353”,1694, "count": “0”, AND {"IP4.min”, "IP4.max”, “IP4.min”, “IP4.max”}
"0:11:21.335533”,1695, "count": “0”, AND {"IP4.min”, "IP4.max”, “IP4.min”, “IP4.max”}

2. test (-j 4) - cca 2 hod. (1.50 hod.), dotazy nad 2 minuty (tucnym pismem je TOP 10 z minule).
./mongotest -f -s -r 10 -q -j 4 -c mongotest.cfg mongotest2.cfg

"0:02:01.159265",1664
"0:02:08.962256",1920
"0:04:40.309627",689
"0:05:30.266695",1689
"0:05:42.980159",691
"0:05:56.269039",661
"0:05:56.883650",690
"0:05:59.273574",693
"0:06:38.398288",662
"0:06:46.255860",669
"0:07:01.580776",663
"0:07:10.430846",1690
"0:07:44.672685",670
"0:07:52.383137",1691
"0:08:14.206944",671
"0:08:30.592774",664
"0:08:40.857322",1693
"0:09:08.280507",698
"0:09:17.806060",692
"0:09:24.828555",697
"0:09:35.950651",699
"0:09:39.644531",701
"0:10:15.403521",672
"0:10:19.658654",1692
"0:10:32.092717",695
"0:10:52.150497",694
"0:11:46.863455",1695
"0:12:00.885621",1694
"0:12:02.009624",700
"0:12:21.640767",702
"0:12:22.578819",703
"0:13:04.726792",696
"0:13:18.761245",1696
"0:13:37.953849",704

Vysledky dvou testu jsem porovnaval a vsiml jsem si, ze leak (vse co trvalo nad minutu) byl VZDY spojen s dotazen na sit.

Rikal jsem si, ze by bylo dobre si to potvrdit i nejak poloautomatizovane. Vsechny vysledky testu jsem nakopiroval do jednoho adresare a smazal vsechny soubory (1 soubor = 1 test jednoho dotazu), ktere obsahovaly IP4.min.
Tim jsem chtel docilit toho, ze bych chtel najit vse, co je nad minutu a v dotazu nebyla sit (Source.IP4.min/max, Target.IP4.min/max).

Vysledek me neprekvapil a rika, ze zadny dotaz nebezel dele nez minutu, pokud v nem NEBYLA sit.

1. ls -al | wc -l
   1028

1. grep -r stop_time * | grep -v "0:00:" | wc -l
   0

1. grep -r stop_time * | wc -l
   1024

Můžu být úplně mimo, jen mě napadlo v souvislosti s #2809 jestli to nemůže souviset i s pořadím dotazů a jestli třeba nejsou vybrané tak, že dotaz na síť trvá dlouho, protože načte hromadu dat do paměti a následné jsou v pohodě (až do dalšího většího dotazu - shodou okolností třeba na síť). Jen ke zvážení, aby ty sítě nebyly jen vtipná souhra náhod.

A ještě jsem si teď náhodou všiml v konfiguraci tvých testů pro Sabu - u monga 2.4 a 2.6 máš kombinované indexy source_ip4_min_max a target_ip4_min_max, zatímco u monga 3 je máš každý zvlášť - source_ip4_min, source_ip4_max a target_ip4_min, target_ip4_max (na ostrém je zdá se také kombinovaný source_ip4_min_max).

Pavel Kácha wrote:

A ještě jsem si teď náhodou všiml v konfiguraci tvých testů pro Sabu - u monga 2.4 a 2.6 máš kombinované indexy source_ip4_min_max a target_ip4_min_max, zatímco u monga 3 je máš každý zvlášť - source_ip4_min, source_ip4_max a target_ip4_min, target_ip4_max (na ostrém je zdá se také kombinovaný source_ip4_min_max).

Mas pravdu, toto bylo spatne a urcite bych na to v budoucnu narazil. V cache a sabu to sice pouzivat asi nikdy nebudu (pravdepodobne oba cfg brzo smazu), ale v mongotest.cfg to je nutne opravit - opraveno.

Pavel Kácha wrote:

Můžu být úplně mimo, jen mě napadlo v souvislosti s #2809 jestli to nemůže souviset i s pořadím dotazů a jestli třeba nejsou vybrané tak, že dotaz na síť trvá dlouho, protože načte hromadu dat do paměti a následné jsou v pohodě (až do dalšího většího dotazu - shodou okolností třeba na síť). Jen ke zvážení, aby ty sítě nebyly jen vtipná souhra náhod.

Nasel jsem pricinu.., postupne to zde doplnim.

Najit pricinu me stalo kupu nervu (zakomentovaval jsem v dotaze, co se dalo), ale od toho tady jsem;-). Do mongotestu jsem dodal automatizovany export leaked dotazu, abych to nemusel vykopirovavat, ale mel to na jednom miste.

Cca 100 dotazu bylo od minula vzdy leaked a skript je exportuje (leak dotazy) do samostatneho souboru, takze jsem schopen opakovane dotazy spoustet, napriklad realne pouzivane:
./mongotest -f -i -r 10 -q -c mongotest.cfg mongotest_leaked.json

Nakonec jsem analyzou zjistil, ze chybi index target_ip4_min_max (v produkcni db!). Zatimco source_ip4_min_max tam byl:( Jak to nezjistim a predpokladam, ze Mek taky nebude vedet.

Vytvoril jsem ho:

...
        {
                "v" : 1,
                "key" : {
                        "Target.IP4.min" : 1,
                        "Target.IP4.max" : 1
                },
                "name" : "target_ip4_min_max",
                "ns" : "mentat.alerts",
                "background" : 1
        }

MINULE...

1. test cca 4,5 hod.
./mongotest -f -s -r 10 -q -c mongotest.cfg mongotest2.cfg

2. test (-j 4) - cca 2 hod. (1.50 hod.)
./mongotest -f -s -r 10 -q -j 4 -c mongotest.cfg mongotest2.cfg

NYNI... (po vytvoreni indexu)

1. test 15s s jednim jobem a vsech 2048 dotazu!
./mongotest -f -s -r 10 -q -c mongotest.cfg mongotest2.cfg
Total elapsed time of script: 0:00:14.532030

Dalsi testy delam, vcetne umisteni skriptu do cronu:

15 *    * * *   root    /root/ork01/mongotest/cronjob.sh >/dev/null 2>&1

Diky implementaci nove funkce by se mely leak dotazy (nad 1 minutu) exportovat do export_leaked

Tak to by možná stálo za to se podívat, jaké dotazy tam chybí, nebo čím se to liší od reálného Alerts formuláře - třeba samotný dotaz na události od LaBrey (tj. nejspíš Node/Name and Node/SW and From and To) mi trval přes 5 minut...

Pavel Kácha wrote:

Tak to by možná stálo za to se podívat, jaké dotazy tam chybí, nebo čím se to liší od reálného Alerts formuláře - třeba samotný dotaz na události od LaBrey (tj. nejspíš Node/Name and Node/SW and From and To) mi trval přes 5 minut...

Omlouvam se, ale tomu nerozumim... .
Zadne dotazy mi tam podle me nechybi... .
Je to kombinace vsech moznych dotazu, dohromady jich je 2048.

Ten index je vtipný... takže šlo sice o síť, ale vlastně jenom o Target síť bez indexu? Pěkné.

Pavel Kácha wrote:

Ten index je vtipný... takže šlo sice o síť, ale vlastně jenom o Target síť bez indexu? Pěkné.

Presne tak.
Jen by me zajimalo, jak dlouho tam ten index chybi. Zakerne:(

Ted bojuji s tim dlouhym trvanim dotazu s vice nez 101 dokumenty viz #2808

Bezi uz vice nez hodinu...
./mongotest -f -s -r 0 -q -c mongotest.cfg mongotest2.cfg

Bezelo 10s, ale vyse uvedeny dotaz zkusim spustit s batch_size, cili tohle moc pro nas ted neznamena.
./mongotest -f -s -r 10 -q -c mongotest.cfg mongotest2.cfg

Oprava, bezelo ne 10s, ale 15s, ale to je jen formalita.

Radomír Orkáč wrote:

Pavel Kácha wrote:

Tak to by možná stálo za to se podívat, jaké dotazy tam chybí, nebo čím se to liší od reálného Alerts formuláře - třeba samotný dotaz na události od LaBrey (tj. nejspíš Node/Name and Node/SW and From and To) mi trval přes 5 minut...

Omlouvam se, ale tomu nerozumim... .
Zadne dotazy mi tam podle me nechybi... .
Je to kombinace vsech moznych dotazu, dohromady jich je 2048.

No, myslím to tak, že když vlezu na Alerts, zakliknu Detector: cesnet.au1/LaBrea a nechám defaultní From (týden zpátky), tak to trvá déle, než všechny tvoje testovací dotazy dohromady. Takže dotaz, položený z Alerts se musí v něčem lišit od verze testovacího dotazu, který zkoušíš ty. Může to být jiným rozsahem nebo zrovna blbým případem dat, a možná se s tím nedá nic dělat, ale bylo by asi dobré vědět, proč v reálu to neodpovídá testům.

Pavel Kácha wrote:

No, myslím to tak, že když vlezu na Alerts, zakliknu Detector: cesnet.au1/LaBrea a nechám defaultní From (týden zpátky), tak to trvá déle, než všechny tvoje testovací dotazy dohromady. Takže dotaz, položený z Alerts se musí v něčem lišit od verze testovacího dotazu, který zkoušíš ty. Může to být jiným rozsahem nebo zrovna blbým případem dat, a možná se s tím nedá nic dělat, ale bylo by asi dobré vědět, proč v reálu to neodpovídá testům.

Moc diky za upresneni, zjistim, proc to tak je.

Pavel Kácha wrote:

No, myslím to tak, že když vlezu na Alerts, zakliknu Detector: cesnet.au1/LaBrea a nechám defaultní From (týden zpátky), tak to trvá déle, než všechny tvoje testovací dotazy dohromady. Takže dotaz, položený z Alerts se musí v něčem lišit od verze testovacího dotazu, který zkoušíš ty. Může to být jiným rozsahem nebo zrovna blbým případem dat, a možná se s tím nedá nic dělat, ale bylo by asi dobré vědět, proč v reálu to neodpovídá testům.

Potvrzuji. S mym testem se to kazdopadne uplne srovnavat neda pro 10 hodnot je stejne rychly, pro neomezeny pocet dokumentu vytece. Budu testovat a podivam se na explain:

Viewing duration: 2m 38s
Displaying items 1 to 30 (30 items of 9,172,801 total) | Page 1 of 305,761

# ./mongotest -f -r 10 -q -c pavel.cfg
I am going to use MongoDB version 24
Name pavel Count >= 10
*Name pavel 0:00:00.023250*

# ./mongotest -f -r 0 -q -c pavel.cfg
I am going to use MongoDB version 24
ano 417.029821
Name pavel Count >= 8079320
*Name pavel 0:06:57.029821*

Testuji dále, dneska jsou o poznání horší výsledky.

1. ./mongotest -f -r 0 -q -c pavel.cfg
   I am going to use MongoDB version 24
   ano 417.029821
   Name pavel Count >= 8079320
   Name pavel 0:06:57.029821

1. ./mongotest -f -r 0 -q -c pavel.cfg
   ano 479.087042
   Name pavel Count >= 8084928
   Name pavel 0:07:59.087042
   Total elapsed time of script: 0:07:59.093902

Vcera bez leaku za 15s:
./mongotest -f -s -r 10 -q -c mongotest.cfg mongotest2.cfg
Total elapsed time of script: 0:00:14.532030

Dnes s leaky za 96m a 33s:
./mongotest -f -s -r 10 -q -c mongotest.cfg mongotest2.cfg
Total elapsed time of script: 1:36:32.076250

1. grep "generated" 2016-03-15T12\:07\:01.416184_mongo24.json
   "name": "generated_1425",
   "name": "generated_1426",
   "name": "generated_1427",
   "name": "generated_1428",
   "name": "generated_1429",
   "name": "generated_1430",
   "name": "generated_1431",
   "name": "generated_1432",
   "name": "generated_1433",
   "name": "generated_1434",
   "name": "generated_1435",
   "name": "generated_1436",
   "name": "generated_1437",
   "name": "generated_1438",
   "name": "generated_1439",
   "name": "generated_1440",
   "name": "generated_1748",

Zatim nehodnotim, jen merim, pokracuji...

Stale nedokazu rozumne vysvetlit, proc jednou k leaku dojde a jindy zase ne.

Nedeterministické chování:
./mongotest -f -s -r 100 -q -c mongotest.cfg mongotest2.cfg

Apr  7 23:42
generated_1425, generated_1426, generated_1427, generated_1428, generated_1429, generated_1430, generated_1431, generated_1432, generated_1433, generated_1434, generated_1435, generated_1436, generated_1437, generated_1438, generated_1439, generated_1440

Apr  8 08:42
generated_1425, generated_1426, generated_1427, generated_1428, generated_1429, generated_1430, generated_1431, generated_1432, generated_1433, generated_1434, generated_1435, generated_1436, generated_1437, generated_1438, generated_1439, generated_1440

Apr 11 15:35
Bez leaku

Apr 11 17:04
Bez leaku

Apr 12 09:28
generated_1425, generated_1426, generated_1427, generated_1428, generated_1429, generated_1430, generated_1431, generated_1432, generated_1433, generated_1434, generated_1435, generated_1436, generated_1437, generated_1438, generated_1439, generated_1440

Apr 12 11:02
generated_1425, generated_1426, generated_1427, generated_1428, generated_1429, generated_1430, generated_1431, generated_1432, generated_1433, generated_1434, generated_1435, generated_1436, generated_1437, generated_1438, generated_1439, generated_1440

Pavlem nahlaseny leak, ktery vypozoroval nahodne z weboveho rozhrani. Staci vybrat Detector a From ponechat v defaultu.

Pavluv dotaz:

"filter": {
        "$and": [
        {
                "DetectTime": {
                    "$gte": "b'\\xda\\xb0\\x81\\xbf\\x00\\x04H\\xac'" 
                }
            },
        {
                "DetectTime": {
                    "$lte": "b'\\xda\\xb9\\xbc?\\x00\\x04H\\xe2'" 
                }
            },
        {
                "Node.SW": "LaBrea" 
            },
        {
                "Node.Name": "cesnet.au1" 
            }
        ]
    }

Planovac vybral index node_sw:
"cursor": "BtreeCursor node_sw",

Napada me otestovat s vyuzitim "force index" a zkusit, jestli budeme na tom lepe s jinym indexem
"Pavluv" dotaz leakuje VZDY!

Vsechny nedeterministicky opakujici se dotazy "generated_1425" - "generated_1440" maji zahrnut DetectTime a zkousel jsem ho nahradit ts_u, ktery je cislem:

"name": "generated_1425" 
                "{gte}": {
                    "value": 3,
                    "type": "datetime" 
                },
                "{lte}": {
                    "value": 0,
                    "type": "datetime" 
                },

                        "$and": [
                            {
                                "DetectTime": {
                                    "$gte": "{gte}" 
                                }
                            },
                            {
                                "DetectTime": {
                                    "$lte": "{lte}" 
                                }
                            }
                        ]

ano 83.442873
Name generated_1425 Count >= 17
Name generated_1425 0:01:23.442873

"name": "generated_1425_changed" 
                "{gte}": {
                    "value": 1460344932,
                    "type": "number" 
                },
                "{lte}": {
                    "value": 1460604132,
                    "type": "number" 
                },

                        "$and": [
                            {
                                "ts_u": {
                                    "$gte": "{gte}" 
                                }
                            },
                            {
                                "ts_u": {
                                    "$lte": "{lte}" 
                                }
                            }
                        ]

Name generated_1425_changed Count >= 10
Name generated_1425_changed 0:00:18.274281

Myslel jsem si, ze mam(e) vyhrano, ale v zapeti opet leaky:

ano 288.783988
Name generated_1425 Count >= 10
Name generated_1425 0:04:48.783988

ano 77.824788
Name generated_1425_changed Count >= 10
Name generated_1425_changed 0:01:17.824788

• lze-li replikovat jinde, než na produkci, otestovat vždy s předem vylitými kešemi (před každým podezřelým dotazem) - tím se dozvíme, zda to přece jen nemůže souviset s cold/hot daty, pokud nebude příliš fluktuovat
• zaznamenávat curOp (procesy monga), nejlépe i plus top systému, na neprodleně před a po spuštění jednoho konkrétního dotazu - u leakujících dotazů se pak lze podívat, jestli současně neběželo i něco jiného, případně často stejného

Update - hot/cold vylití keší budeme testovat až po přechodu na wiredtiger
Ale - ty souběžné procesy by se daly asi celkem levně otestovat i teď, případně přidat podporu do skriptu.