Net toen vorig jaar ten einde liep, kwam een van onze vaste klanten naar ons toe omdat een van hun al lang bestaande PostgreSQL-query's met PostGIS-geometrieberekeningen veel langzamer was voor specifieke waarden. We hebben het probleem onderzocht en ontdekt hoe we het konden oplossen; Lees verder! Wat we als oorzaak van het probleem hebben gevonden, zal u verbazen!
De eerste observatie, gerapporteerd door onze klant, was dat het uitvoeren van een query met ST_DistanceSpheroid duurde ongeveer 7 milliseconden toen gevraagd werd om de afstand terug te brengen naar POINT(33.681953 23.155994) op een specifieke sferoïde, maar als dat punt werd verplaatst naar POINT(33.681953 23.1559941) (een verschil van slechts 0.0000001 ) daarna duurde het 0,13 milliseconde. 60 keer sneller! Wat zou er in vredesnaam (nog een sferoïde!) aan de hand kunnen zijn?
Aanvankelijk konden we de traagheid in onze testomgevingen niet reproduceren. In onze handen zouden beide zoekopdrachten even snel worden uitgevoerd, zonder vertraging. We groeven naar de specifieke versies van software die in gebruik waren, denkend dat een update nodig zou kunnen zijn. We gebruikten de door de klant gerapporteerde versies:PostgreSQL 10.11, PostGIS 2.4.4, libproj 4.93. We keerden terug naar de grottijd door te downgraden naar die precieze versies, zonder succes.
Uiteindelijk werden we ons ervan bewust dat de klant Ubuntu 18.04 gebruikte, dus we probeerden dat ... en zie, het probleem reproduceerde zich daar. Het volstaat te zeggen dat we de kans hebben aangegrepen om de zoekopdracht in die machine te profileren. We hebben dit:
Samples: 224K of event 'cpu-clock', Event count (approx.): 56043500000 Children Self Command Shared Object Symbol + 84.86% 0.00% postgres [unknown] [.] 0xffffffffffffffff + 84.59% 0.00% postgres postgres [.] DirectFunctionCall4Coll + 84.58% 0.00% postgres postgis-2.5.so [.] geometry_distance_spheroid + 84.56% 0.00% postgres liblwgeom-2.5.so.0.0.0 [.] lwgeom_distance_spheroid + 84.31% 0.19% postgres libm-2.27.so [.] __sincos + 84.18% 0.00% postgres libm-2.27.so [.] __cos_local (inlined) + 84.13% 0.00% postgres libm-2.27.so [.] cslow2 (inlined) + 84.05% 0.01% postgres libm-2.27.so [.] __mpcos + 83.95% 0.32% postgres libm-2.27.so [.] __c32 + 83.87% 0.00% postgres postgres [.] ExecInterpExpr + 83.75% 0.00% postgres postgres [.] standard_ExecutorRun + 83.75% 0.00% postgres postgres [.] ExecutePlan (inlined) + 83.73% 0.00% postgres postgres [.] ExecProcNode (inlined) + 83.73% 0.00% postgres postgres [.] ExecScan + 83.67% 0.00% postgres postgres [.] ExecProject (inlined) + 83.67% 0.00% postgres postgres [.] ExecEvalExprSwitchContext (inlined) + 83.65% 0.00% postgres postgres [.] _SPI_execute_plan + 83.60% 0.00% postgres postgres [.] _SPI_pquery (inlined) + 83.49% 0.01% postgres plpgsql.so [.] exec_stmts + 83.49% 0.00% postgres plpgsql.so [.] exec_stmt (inlined) + 83.49% 0.00% postgres plpgsql.so [.] exec_stmt_fori (inlined) + 83.48% 0.00% postgres plpgsql.so [.] exec_stmt_perform (inlined) + 83.48% 0.00% postgres plpgsql.so [.] exec_run_select + 83.47% 0.00% postgres postgres [.] SPI_execute_plan_with_paramlist + 81.67% 0.01% postgres liblwgeom-2.5.so.0.0.0 [.] edge_distance_to_point + 81.67% 0.00% postgres liblwgeom-2.5.so.0.0.0 [.] 0x00007f2ce1c2c0e6 + 61.85% 60.82% postgres libm-2.27.so [.] __mul + 54.83% 0.01% postgres liblwgeom-2.5.so.0.0.0 [.] sphere_distance + 27.14% 0.00% postgres plpgsql.so [.] exec_stmt_block + 26.67% 0.01% postgres liblwgeom-2.5.so.0.0.0 [.] geog2cart + 19.24% 0.00% postgres libm-2.27.so [.] ss32 (inlined) + 18.28% 0.00% postgres libm-2.27.so [.] cc32 (inlined) + 12.55% 0.76% postgres libm-2.27.so [.] __sub + 11.46% 11.40% postgres libm-2.27.so [.] sub_magnitudes + 8.15% 4.89% postgres libm-2.27.so [.] __add + 4.94% 0.00% postgres libm-2.27.so [.] add_magnitudes (inlined) + 3.18% 3.16% postgres libm-2.27.so [.] __acr + 2.66% 0.00% postgres libm-2.27.so [.] mcr (inlined) + 1.44% 0.00% postgres liblwgeom-2.5.so.0.0.0 [.] lwgeom_calculate_gbox_geodetic + 1.44% 0.00% postgres liblwgeom-2.5.so.0.0.0 [.] ptarray_calculate_gbox_geodetic
Gebrabbel, zegt u. Er is echter iets heel merkwaardigs aan dit profiel ... en je moet de eerste 26 regels negeren en je concentreren op de __mul lijn daar. Zie je die 60,82% van de "zelf"-tijd? (Ik kan het geluid van realisatie horen dat je zojuist hebt gemaakt). Dus waarom kost het zoveel tijd voor bepaalde punten op de sferoïde en niet voor andere? En ook waarom duurt het lang in Ubuntu 18.04, maar niet in andere machines? Waarom lost het upgraden van PostGIS het probleem niet op?
Het antwoord werd me voorgesteld toen ik me realiseerde wat duidelijk was:PostGIS doet veel trigonometrie (sinus, cosinus, tangens enz.) door libm te bellen functies. Als we naar de glibc changelogs kijken, hebben we enkele optimalisaties gevonden in trigonometrische functies:voor bepaalde invoer nemen trigonometrische berekeningen snelkoppelingen die niet kunnen worden gebruikt voor andere invoer; en dergelijke snelkoppelingen zijn in de loop van de tijd geoptimaliseerd. Inderdaad, de glibc kondigt aan dat voor zowel 2.27 als 2.29 beide optimalisaties in sinus/cosinus/etc-functies worden genoemd. Blijkbaar waren er eens enkele optimalisaties door Intel die zeer nauwkeurige resultaten moesten opleveren, maar toen realiseerde iemand zich dat de nauwkeurigheidsclaim onjuist was, dus glibc schakelde het gebruik van die optimalisaties uit; later werd dat spul opnieuw geïmplementeerd op een andere maar opnieuw snelle manier. Of zoiets - voor buitenstaanders zoals ik is het moeilijk om de exacte details te achterhalen.
We vermoedden dat een upgrade naar een nieuwere versie van glibc het probleem zou oplossen, terwijl al het andere hetzelfde zou blijven. Onze klant probeerde dat, en het was inderdaad waar, en ze waren blij. We weten niet echt zeker welke van deze glibc-wijzigingen waren verantwoordelijk, maar één ding is duidelijk:het is altijd een goed idee om dingen op up-to-date software te draaien.
Houd er rekening mee dat de bloedranden scherp zijn ... dus wees voorzichtig daarbuiten.