Assim como o ano passado estava terminando, um de nossos clientes de longa data veio até nós porque uma de suas consultas PostgreSQL de longa data envolvendo cálculos de geometria PostGIS era muito mais lenta para valores específicos. Pesquisamos o problema e descobrimos como resolvê-lo; Leia! O que descobrimos como a causa do problema irá surpreendê-lo!
A observação inicial, relatada por nosso cliente, foi que executar uma consulta envolvendo
ST_DistanceSpheroid levou cerca de 7 milissegundos quando solicitado a retornar a distância para POINT(33.681953 23.155994) em um esferóide específico, mas se esse ponto foi movido para POINT(33.681953 23.1559941) (uma diferença de apenas 0.0000001 ) então levou 0,13 milissegundos. 60 vezes mais rápido! O que diabos (outro esferóide!) poderia estar acontecendo? Inicialmente, não conseguimos reproduzir a lentidão em nossos ambientes de teste. Em nossas mãos, ambas as consultas seriam executadas com a mesma rapidez, sem lentidão. Procuramos as versões específicas do software em uso pensando que uma atualização pode ser necessária. Usamos as versões informadas pelo cliente:PostgreSQL 10.11, PostGIS 2.4.4, libproj 4.93. Voltamos às idades das cavernas fazendo o downgrade para essas versões precisas, sem sucesso.
Eventualmente, ficamos sabendo que o cliente estava usando o Ubuntu 18.04, então tentamos isso… e eis que o problema se reproduziu lá. Basta dizer que aproveitamos a oportunidade de criar o perfil da consulta nessa máquina. Está no papo:
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
Bobagem, você diz. No entanto, há algo muito curioso nesse perfil... e você precisa ignorar as primeiras 26 linhas e se concentrar no __mul linha lá. Veja que 60,82% do tempo "auto"? (Eu posso ouvir o som de realização que sua mente acabou de fazer). Então, por que leva tanto tempo para certos pontos do esferóide e não para outros? E também por que demora muito no Ubuntu 18.04, mas não em outras máquinas? Por que a atualização do PostGIS não resolve o problema?
A resposta foi sugerida para mim quando percebi o que era óbvio:PostGIS faz muita trigonometria (seno, cosseno, tangente etc) chamando
libm funções. Observando os changelogs da glibc encontramos algumas otimizações nas funções de trigonometria:para certas entradas, os cálculos de trigonometria usam atalhos que não podem ser usados para outras entradas; e esses atalhos foram otimizados ao longo do tempo. De fato, o glibc anuncia tanto para 2.27 quanto para 2.29, ambos mencionam otimizações nas funções seno/coseno/etc. Aparentemente, uma vez houve algumas otimizações da Intel que deveriam fornecer resultados muito precisos, mas então alguém percebeu que a alegação de precisão estava incorreta, então a glibc desativou o uso dessas otimizações; mais tarde, esse material foi reimplementado de uma maneira diferente, mas rápida. Ou algo assim – para pessoas de fora como eu, é difícil descobrir os detalhes exatos. Suspeitamos que atualizar para uma versão mais recente da glibc resolveria o problema, deixando todo o resto igual. Nosso cliente tentou isso, e de fato era verdade, e eles ficaram felizes. Não temos certeza qual dessas mudanças na glibc foram responsáveis, mas uma coisa é clara:é sempre uma boa ideia rodar coisas em software atualizado.
Tenha em mente que as bordas sangrentas são afiadas... então tenha cuidado lá fora.
