Výkonnostní problém Nette\Database. S $db->table() 45× pomaleji než s $db->query()

Upozornění: Tohle vlákno je hodně staré a informace nemusí být platné pro současné Nette.
Eda
Backer | 220
+
0
-

Zdarec.

U některých stránek jsem vypozoroval velmi dlouhou dobu zpracovávání požadavku. Začal jsem tedy ořezávat a zůstal jsem u následujících pár řádků:

$selection = $this->db->table('A')->order('id');

foreach ($selection as $row) {
	foreach ($row->related('AB') as $user) {
		$user->ref('B')->id;
	}
}

Je to vazba M:N mezi tabulkami A a B přes tabulku AB. V každé je do 150 záznamů a tabulky obsahují jen sloupce s IDčkem, tzn. žádná závratná velikost. Uvedený kód správně položí 3 dotazy, které podle DebugBaru trvají souhrnně ani ne půl milisekundy. Když dám ale okolo uvedeného kódu Debug::timer() naměřím průměrně 68 milisekund.

Pro srovnání jsem zkusil napsat ručně kód, který pomocí $db->query dělá to stejné, jako kód výše. Položí stejné dotazy a nalezené hodnoty několikrát projde. Naměřený čas trvání tohoto ručního kódu se pohybuje okolo 1,3 milisekundy. Tzn. cca 45× rychlejší než s využitím $db->table().

$res = $this->db->query("
	SELECT `id`
	FROM `A`
	ORDER BY `id`
");

$ids = [];
foreach ($res as $r) {
	$ids[] = $r->id;
}

foreach ($res as $r) {
	$r->id;
}

$res = $this->db->query("
	SELECT `A_id`, `B_id`
	FROM `AB`
	WHERE (`AB`.`A_id` IN (".implode(',', $ids)."))
");

$ids = [];
foreach ($res as $r) {
	$ids[] = $r->B_id;
}

foreach ($res as $r) {
	$r->B_id;
}

$res = $this->db->query("
	SELECT `id`
	FROM `B`
	WHERE (`id` IN (".implode(',', $ids)."))
");

foreach ($res as $r) {
	$r->id;
}

foreach ($res as $r) {
	$r->id;
}

Je jasné, že veškerá funkčnost, kterou NDB poskytuje, musí být vykoupena trochou rychlosti. Výsledky se několikrát prochází, testuje se spousta podmínek atd. Pochopil bych, kdyby to bylo pomalejší 2×, 3×… Ale 45×? A to není jen tento jeden dotaz, zkoušel jsem podobným způsobem měřit na více místech v projektu a statistika byla podobná. S Nette\Database je to cca o řád pomalejší. Docela se modlím, aby to byl nějaký bug. Protože jestli ne, tak se pro mne Nette\Database tímto stává nepoužitelnou. Když databázová vrstva potřebuje o řád větší čas, je čas jí vyměnit.

Je ale možné, že je chyba někde u mne, proto prosím o ostatní o otestování.

Pro úplnost: používám aktuální vývojové Nette 2.1.

Dump s testovací databází:
http://leteckaposta.cz/685143775

Editoval Eda (23. 3. 2013 23:05)

Jan Tvrdík
Nette guru | 2595
+
0
-

@Eda: Díky za skvělý report!

Potvrzuji problém. Bohužel je i ve stable verzi od 2.0.8 (2.0.7 je poslední v pořádku). Podle xdebug profileru se brutálně mockrát volá __get na ActiveRow (konkrétně 27212×).

Jan Tvrdík
Nette guru | 2595
+
0
-

Podle git bisect je první špatný commit https://github.com/…3eed18da04b4. Zakomentování problematického řádku pomůže i v masteru, akorát to dost možná rozbije něco jiného :)

hrach
Člen | 1834
+
0
-

Hele, uz to profiluju pres hodinu a toto nebude ten problem. Po zakomentovani se to vola 18000×, imo to neni zadne reseni, akorat to otevira bug. Btw, kvuli tomu sem musel naistalovat PhpEd, ten xdebug profiler stoji za ****.

Edit: mozna sem se prehlid, to 18k bude jiny cislo, nicmene stale v tom nevidim tu potrebnou optimalizaci.

Editoval hrach (24. 3. 2013 0:46)

hrach
Člen | 1834
+
0
-

Wohoho, tak diky Honzo, sem si omylem pod rukama neco posral, a ja porad, proc mi cas spis narusta :D

Jan Tvrdík
Nette guru | 2595
+
0
-

@hrach: Mě to po přechodu na 2.0.7 kleslo z 27212 na 887 a samotný „cachegrind“ soubor se zmenšil z 60 MB na 4 MB. Akorát to rozbije test Table.related().caching.phpt.

kvuli tomu sem musel naistalovat PhpEd, ten xdebug profiler stoji za ****.

Vidím to stejně :) Ale zrovna na tohle jsem si vystačil s XDebugem, protože mi stačil letmý pohled.

hrach
Člen | 1834
+
0
-

Ok, diky moc. Fix na dany test uz mam vymyslenej a otestovanej, zitra to ale trochu zrefaktoruju.

hrach
Člen | 1834
+
0
-

Tak, po 6 hodinach prace je tu fix. Uz sem to zafixoval, ale zase se rozbila jina vec, a takhle asi trikrat :D Pls testnete to na projektech, jestli vsechno porad funguje ok.

https://github.com/…tte/pull/995

hrach
Člen | 1834
+
0
-

Aktualni vysledky meho testovani tveho testcasu:

  AVG Median
NDB 45.6 44.8
native 7.8 7.7

cas v ms. Tzn. aktualni casova stopa NDB je asi 7× vetsi.

Eda
Backer | 220
+
0
-

Díky za rychlou opravu. Takovouto luxusní podporu nemá ani kdejaký enterprise produkt. Značka: „v sobotu nahlásíš, v neděli opraveno“ :-)

U mne to, zdá se, nic jiného nerozbilo. Kdybych ještě na něco přišel, neměj strach, že bych se neozval. Benchmarky u mne vychází s podobným poměrem, jako u tebe, takto je to asi přijatelné.

hrach
Člen | 1834
+
0
-

Eda napsal(a):
Značka: „v sobotu nahlásíš, v neděli opraveno“ :-)

Aneb co všechno se musí udělat, než zbyde čas na bakalářku.

Semik
Backer | 135
+
0
-

hrach napsal(a):
Aneb co všechno se musí udělat, než zbyde čas na bakalářku.

Rozumím ti :-)

Eda
Backer | 220
+
0
-

Nejste v tom sami, i já mám psát bakalářku, ale místo toho přepisuju všechny své weby do Nette… :-)