Точно когато миналата година беше към края си, един от нашите дългогодишни клиенти дойде при нас, защото една от техните отдавна съществуващи заявки на PostgreSQL, включващи изчисления на геометрията на PostGIS, беше много по-бавна за конкретни стойности. Проучихме проблема и открихме как да го решим; четете нататък! Това, което открихме като причина за проблема, ще ви изненада!
Началното наблюдение, докладвано от нашия клиент, беше, че се изпълнява заявка, включваща ST_DistanceSpheroid отне около 7 милисекунди при поискване да върне разстоянието до POINT(33.681953 23.155994) върху конкретен сфероид, но ако тази точка е преместена в POINT(33.681953 23.1559941) (разлика от само 0.0000001 ) след това отне 0,13 милисекунди. 60 пъти по-бързо! Какво по дяволите (още един сфероид!) може да се случва?
Първоначално не успяхме да възпроизведем бавността в нашите тестови среди. В нашите ръце и двете заявки ще се изпълняват еднакво бързо, без забавяне. Изровихме до конкретните версии на използвания софтуер, мислейки, че може да е необходима актуализация. Използвахме версиите, съобщени от клиента:PostgreSQL 10.11, PostGIS 2.4.4, libproj 4.93. Върнахме се към пещерните епохи, като понижихме до тези точни версии, без успех.
В крайна сметка разбрахме, че клиентът използва Ubuntu 18.04, така че опитахме това ... и ето, проблемът се възпроизведе там. Достатъчно е да кажем, че се възползвахме от възможността да профилираме заявката в тази машина. Разбрахме това:
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
Глупости, ще кажеш. Въпреки това, има нещо много любопитно в този профил... и трябва да игнорирате първите 26 реда и да се съсредоточите върху __mul линия там. Виждате ли, че 60,82% от времето за себе си? (Мога да чуя звука на осъзнаването, което умът ти току-що направи). Така че защо отнема толкова много време за определени точки на сфероида, а не за други? И също така защо отнема много време в Ubuntu 18.04, но не и в други машини? Защо надграждането на PostGIS не отстранява проблема?
Отговорът ми беше предложен, след като разбрах какво е очевидно:PostGIS прави много тригонометрия (синус, косинус, тангенс и т.н.), като извиква libm функции. Разглеждайки дневниците за промени на glibc, открихме някои оптимизации в тригонометричните функции:за определени входове тригонометричните изчисления използват преки пътища, които не могат да бъдат използвани за други входове; и такива преки пътища са оптимизирани с течение на времето. Всъщност, glibc обявява и за 2.27, и за 2.29 и двете споменават оптимизации във функциите синус/косинус/и т.н. Очевидно някога е имало някои оптимизации от Intel, които е трябвало да предоставят много точни резултати, но след това някой е разбрал, че твърдението за точност е неправилно, така че glibc забрани използването на тези оптимизации; по-късно тези неща бяха повторно имплементирани по различен, но отново бърз начин. Или нещо подобно — за външни лица като мен е трудно да разберат точните подробности.
Подозирахме, че надграждането до по-нова версия на glibc ще реши проблема, оставяйки всичко останало същото. Нашият клиент опита това и наистина беше вярно и те бяха доволни. Всъщност не сме сигурни вкои за тези промени в glibc бяха отговорни, но едно нещо е ясно:винаги е добра идея да се изпълняват неща на актуален софтуер.
Имайте предвид, че кървящите ръбове са остри... така че бъдете внимателни.
