← All posts tagged profile

fillest
работа Python profile perf пеарюсь Прокачал профайлер из #2772368, на пикрилейтеде подопытный кот и фрагмент его МРТ.

Писечка в том, что теперь оно группирует семплы по стектрейсам, и когда, например, в коде куча запросов к бд, в топ будет вылезать не совокупный схлопнутый recv сокета, по которому не понятно, какой именно запрос тормозил, а разные recv'ы по трейсам от конкретных запросов.

Эдакий недоflame graph, но у flame graph неудобный тулчейн, и я до сих пор не пойму, зачем видеть все лишние семплы, а не top N.

Mood: Lewis Parker — Communications (Feat. Jehst)

fillest
work Python profile perf nolife И тут же, с помощью #2772368 почти без боли отладили проблему с производительностью в продакшене. Прохладительная история:

Есть бесконечно крутящаяся прожка, собирающая логи с некоторыми данными и некоторым образом их обрабатывающая. Периодически она продолжительно выедает ядро цпу, что само по себе не было бы проблемой, если бы логи не накапливались быстрее, чем прога успевает их обрабатывать.

Многие в таких ситуациях начинают искать по коду, что бы соптимизировать. Конечно, есть горстка хрупких эвристик, с помощью которых иногда можно быстро сузить поиск, но это, скорее, запутывает, поэтому следует запомнить и взять в привычку один метод — если сходу или за условные 15 минут не удаётся выявить точную ясную и полную логику проблемы, дальше продолжать бессмысленно и вредно, и необходимо воспользоваться специальными инструментами. Профайлером.

Ситуацию осложняет, однако, традиционное для индус-трии отсутствие вменяемых инструментов (почти для чего-либо вообще). То они тупо не работают, то не хватает функционала, то имеют грабительские цены (и работают ещё хуже), то установка или уровень удобства вызывает бешенство, и так далее. На этом многие ловят баттхёрт и возвращаются к отлаживанию по положению звёзд и кофейной гуще. Но, если ты у мамки настоящий инженер™, ты должен сохранять буддийское спокойствие и или заколотить-таки гвоздь подручным микроскопом, или быстренько™ сделать свой инструмент.

Long story short, запилил подходящий профайлер, посекундно выводящий, какие места в коде были самими горячими. В итоге, время процессора оказалось неожиданно тонко размазано по разным участкам цикла. На первый взгляд, это озадачивает, но всё логично — все манипуляции в этом цикле хавают примерно одинаковое время — затык в "языке" (интерпретаторе, стдлибе и т.п.). Но не только — если даже максимум вымазаться байтами, если поток логов ещё вырастет, оно может опять начать упираться в ядро. Собрали вече, решили, что эффективнее начать с распараллеливания, но это уже другая история.

Мораль — если тормозит, учитесь профайлить и профайлите без особых раздумий. Даже если окажется что-то "ожидаемое" или "очевидное" (я, кстати, ожидал увидеть другое, в данном случае), время будет потрачено не зря.

fillest
Python code debug profile draft
Семплирующий профайлер тут сочинил для рентгена змеедемонов в продакшене.

Для такого кота:
def main ():
	while True:
		time.sleep(0.2)
		time.sleep(0.3)
		time.sleep(0.5)
main()

высирает посекундно такое (пока текстом в лог, потом с уеб-мордой):
2015-03-03 23:52:29,849UTC INFO  collector_new.py:aggreg:49  ---
@@@ thread 140081144379200
49.7% ('perstam/sampler_new.py', 96, 'main') time.sleep(0.5)
28.9% ('perstam/sampler_new.py', 95, 'main') time.sleep(0.3)
21.4% ('perstam/sampler_new.py', 94, 'main') time.sleep(0.2)
2015-03-03 23:52:30,851UTC INFO  collector_new.py:aggreg:49  ---
@@@ thread 140081144379200
48.7% ('perstam/sampler_new.py', 96, 'main') time.sleep(0.5)
31.6% ('perstam/sampler_new.py', 95, 'main') time.sleep(0.3)
19.8% ('perstam/sampler_new.py', 94, 'main') time.sleep(0.2)
fillest
tech debug io profile perf (i have no idea, зачем я это сюда пишу, причем первым постом, но что-то вдруг захотелось)
Листая в brendangregg.com пример с мускулом, тут же вспомнил про временно отложенные неразрешенные монгопытки и осознал одну хитроту. Но сначала — прелюдия.
Вышло, что вороне где-то б-г послал кусочек монги, под мелкой но нагрузкой. Запросы тормозят, причем периодически разными скачками вроде бы без явного паттерна и корреляции с другими показателями, а для усиления ощущений она обитает на эмозоне и не умещается в память. Про себя она какие-то чиселки рассказывает, но бессвязные — не складывается картина, вобщем. Но периодически плотно шуршит iowait. И вроде и не локи, и user/sys не высок.
Закрадывается мысль — а вдруг это и правда io-боттлнек. И вариант "послать аффтарам бомбу с гвоздями и открыткой; переписать уже наконец под человеческий поцгрес" возможно просто так и не сработает (а тестить долго, сложно и синтетично). Особенно, учитывая что это омасон, т.е. неизвестно, что или кто там вместо харда, и сколько еще лохов сидят с тобой на железке и чем занимаются; прям как в старое доброе пыховековье.
И вот щас щелкнуло, что сферическое упирание в io (как и во всё прочее) — очень неоднозначная штука, т.к. io можно закодерировать неэффективно. Размеры страниц-буферов, шедулинги операций, журнал, да мало ли что еще. Мысль-то тривиальная конечно, но при прошлом обдумывании почему-то не возникла.
И вот интересно, как такое диагнозировать. Из первого, что приходит в голову — потрейсить какие-то сисколлы (впрочем с mmap-то это наверно вместе с ведром надо трейсить..), порисовать всякие длины, locality. Вобщем, что-то такое как профайлинг, но под адскую специфику disk io. А для исключения облакодилд погонять генерилку искуственного ровного io на предмет скачков (но это опять же, синтетика).
В рукаве еще есть карты под задачу — частично вынести запись за очередь с ручным батчингом, например, но хочется именно научиться аналитически отлаживать, по-инженерному, мол.