Компания
1 682,79
рейтинг
11 ноября 2013 в 01:27

Разработка → Профилирование и отладка Python

Некоторое время назад я рассказывал о «Профилировании и отладке Django». После выступления я получил много вопросов (как лично, так и по email), с парой новых знакомых мы даже выбрались в бар, чтобы обсудить важные проблемы программирования за кружечкой отменного эля, со многими людьми я продолжаю общаться до сих пор.

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

Материала много, статья получилась огромная, поэтому я решил разбить её на несколько частей:


Введение


В первую очередь необходимо разобраться с определениями. Читаем в Википедии:

Профилирование — сбор характеристик работы программы с целью их дальнейшей оптимизации.

Итак, для профилирования нам нужна работающая программа, причём работающая не совсем так, как нам хотелось бы: либо работающая слишком медленно, либо потребляющая слишком много ресурсов.

Какие же характеристики работы программы можно собирать?
  • время выполнения отдельных строк кода (инструкций)
  • количество вызовов и время выполнения отдельных функций
  • дерево вызовов функций
  • «hot spots» (участки кода, на которые приходится существенная доля исполненных инструкций)
  • загрузку CPU и потребление памяти
  • обращение к другим ресурсам компьютера (например, к файловым дескрипторам)
  • и т.д. и т.п.

Конечно, не всегда есть смысл изучать проект подробно под микроскопом, разбирая каждую инструкцию и изучая всё досканально, но знать что, как и где мы можем посмотреть, полезно и нужно.

Давайте определимся с понятием «оптимизация». Википедия подсказывает нам, что:

Оптимизация — это модификация системы для улучшения её эффективности.

Понятие «эффективность» — очень расплывчатое, и напрямую зависит от поставленной цели, например, в одних случаях программа должна работать максимально быстно, в других можно пренебречь скоростью и гораздо важнее сэкономить оперативную память или другие ресурсы (такие, как диск). Как справедливо сказал Фредерик Брукс, «серебрянной пули не существует».

Очевидно, что оптимизацией программы можно заниматься бесконечно: в любом достаточно сложном проекта всегда найдётся узкое место, которое можно улучшить, поэтому важно уметь останавливаться вовремя. В большинстве случаев (исключения крайне редки и относятся, скорее, к фольклору, чем к реальной жизни) нет смысла тратить, скажем, три дня рабочего времени ради 5% выигрыша по скорости.

С другой стороны, как любил повторять Дональд Кнут: «Преждевременная оптимизация — это корень всех бед».

Какая статья про оптимизацию обходится без этой цитаты? Многие полагают, что её автор — Дональд Кнут, но сам Дональд утверждает, что впервые её произнёс Энтони Хоар. Энтони же отпирается и предлагает считать высказывание «всеобщим достоянием».

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

Хочу заметить ещё один немаловажный момент: часто оптимизация сопровождается значительным ухудшением читаемости кода. По возможности, старайтесь избегать этого, а в случае, если всё-таки пришлось написать менее читаемый код в критичных местах, не поленитесь и оставьте комментарий с подробным описанием его работы. Ваши коллеги скажут вам спасибо, да и вы сами посчитаете себя удивительно проницательным, когда вернётесь к этим строкам через некоторое время.

Я не буду больше затрагивать вопрос оптимизации, поскольку, как я сказал выше, всё очень сильно зависит от поставленной задачи и каждый случай нужно разбирать отдельно. Сосредоточимся на обнаружении проблемных участков программы.

Подходы к профилированию


Существует, по крайней мере, три подхода к профилированию:
  • метод пристального взгляда
  • ручное профилирование
  • с использованием инструментов

С методом пристального взгляда (и родственным ему «методом тыка») всё понятно. Просто садимся перед текстовым редактором, открываем код и думаем, где может быть проблема, пробуем починить, смотрим на результат, откатываемся. И только в редких случаях (либо при высочайшей квалификации разработчика) метод оказывается действенным.

Достоинства и недостатки этого метода:
+ не требует особых знаний и умений
– сложно оценить трудозатраты и результат

Ручное профилирование удобно использовать, когда есть обоснованное предположение об узких местах и требуется подтвердить или опровергнуть гипотезу. Либо если нам, в отличие от первого метода, нужно получить численные показатели результатов нашей оптимизации (например, функция выполнялась за 946 милисекунд, стала отрабатывать за 73 милисекунды, ускорили код в 13 раз).

Суть этого метода в следующем: перед выполнением спорного участка программы сохраняем в переменную текущее системное время (с точностью до микросекунд), а после заново получаем текущее время и вычитаем из него значение сохранённой переменной. Получаем (с достаточной для нас погрешностью) время выполнения анализируемого кода. Для достоверного результата повторяем N раз и берём среднее значение.

Достоинства и недостатки этого метода:
+ очень простое применение
+ ограниченно подходит для продакшена
– вставка «чужеродного» кода в проект
– использование возможно не всегда
– никакой информации о программе, кроме времени выполнения анализируемого участка
– анализ результатов может быть затруднительным

Профилирование с помощью инструментов помогает, когда мы (по тем или иным причинам) не знаем, отчего программа работает не так, как следует, либо когда нам лень использовать ручное профилирование и анализировать его результаты. Подробнее об инструментах в следующем разделе.

Должен заметить, что независимо от выбранного подхода, главным инструментом разработчика остаётся его мозг. Ни одна программа (пока(?)) не скажет:
Эй, да у тебя в строке 619 файла project/app.py ерунда написана! Вынеси-ка вызов той функции из цикла и будет тебе счастье. И ещё, если ты используешь кэширование, и перепишешь функцию calculate на Си, тогда быстродействие увеличится в среднем в 18 раз!

Какие бывают инструменты


Инструменты бывают двух видов (на самом деле вариантов классификации и терминологии гораздо больше, но мы ограничимся двумя):
  • статистический (statistical) профайлер
  • событийный (deterministic, event-based) профайлер

К сожалению, я так и не смог придумать красивого названия на русском языке для «детерминистического» профайлера, поэтому я буду использовать слово «событийный». Буду благодарен, если кто-нибудь поправит меня в комментариях.

Большинство разработчиков знакомы только с событийными профайлерами, и большой неожиданностью для них оказывается тот факт, что статистический профайлер появился первым: в начале семидесятых годов прошлого столетия программисты компьютеров IBM/360 и IBM/370 ставили прерывание по таймеру, которое записывало текущее значение Program status word (PSW). Дальнейший анализ сохранённых данных позволял определить проблемные участки программы.

Первый событийный профайлер появился в конце тех же семидесятых годов, это была утилита ОС Unix prof, которая показывала время выполнения всех функций программы. Спустя несколько лет (1982 год) появилась утилита gprof, которая научилась отображать граф вызовов функций.

Статистический профайлер


Принцип работы статистического профайлера прост: через заданные (достаточно маленькие) промежутки времени берётся указатель на текущую выполняемую инструкцию и сохраняет эту информацию («семплы») для последующего изучения. Выглядит это так:

видно, функция bar()выполнялась почти в два с половиной раза дольше, чем функции foo(), baz() и какая-то безымянная инструкция.

Один из недостатков статистического профайлера заключается в том, что для получения адекватной статистики работы программы нужно провести как можно большее (в идеале — бесконечное) количество измерений с как можно меньшим интервалом. Иначе некоторые вызовы вообще могут быть не проанализированы:

например, из рисунка видно, что безымянная функция не попала в выборку.

Так же сложно оценить реальное время работы анализируемых функций. Рассмотрим ситуацию, когда функция foo() выполняется достаточно быстро, но вызывается очень часто:

и ситуацию, когда функция foo() выполняется очень долго, но вызывается лишь один раз:

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

Тем не менее, с поиском самых «тяжёлых» и «горячих» мест программы статистический профайлер справляется великолепно, а его минимальное влияние на анализируемую программу (и, как следствие, пригодность к использованию в продакшене) перечёркивает все минусы. К тому же Python позволяет получить полный stacktrace для кода при семплировании и его анализ позволяет получать более полную и подробную картину.

Достоинства и недостатки статистического профайлера:
+ можно пускать в продакшен (влияние на анализируемую программу минимально)
– получаем далеко не всю информация о коде (фактически только «hot spots»)
– возможно некорректное интерпретирование результата
– требуется длительное время для сбора адекватной статистики
– мало инструментов для анализа

Событийный профайлер


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


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

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

Достоинства и недостатки событийных профайлеров:
+ не требуется изменения кода
+ получаем всю информаци о работе программы
+ огромное количество инструментов
– в некоторых случаях профайлер меняет поведение программы
– очень медленно
– практически непригодно для продакшена

В следующей статье мы на практике разберём ручное профилирование и статистические профайлеры. Оставайтесь на связи =)
Автор: @Dreadatour

Комментарии (14)

  • +17
    Только подумал, щаз конкретика попрёт, даже IDLE открыл, а статья кончилась. Жду продолжения.
    • +1
      Всё будет!
  • +3
    Да, пора бы узнать об инструментах, а то кроме print и ручного профилирования больше ничего и не пробовал
    • +4
      Инструментов очень много разных, тут Python вне конкуренции.
    • +2
      Рекомендую попробовать начать использовать logging вместо print. Вот пост небольшой был.
      • +2
        да, согласен, логи можно потом не удалять, в отличие от print'ов, да и в продакшене можно оставить, дебажные, надо взять за правило
    • 0
      Программисты по дебаггингу делятся на print и не print.
  • +1
    Раз уж обошлось без конкретики, от себя советую kernprof
    • +3
      В следующий раз обязательно добавлю в статью секцию «tl;dr» ;)

      Если совсем уж не терпится, то список инструментов можно посмотреть в презентации по самой первой ссылке в статье. Например, вот событийные профайлеры: speakerdeck.com/moscowdjango/profilirovaniie-i-otladka-django?slide=38
      • +3
        тысячи их...

        А есть хоть один качественный визуальный? Наколбасить декораторов и консольных тулов на базе profile/cProfile каждый горазд, а до ума довести? А законченный продукт сделать?
        Тут тоже интересуются. RunSnakeRun — это… хм, как-то не очень. :)
        В PTVS, например, есть кое-что.
        Нужно, чтобы был удобный, наглядный и мощный инструмент. И ещё, чтобы красивые отчёты делать умел. :)
        Вот JetBrains давно просят-просят, а они внимания не обращают.

        Хочется, чтобы выглядело вот как-то так примерно (это Matlab):



        • 0
          В моей практике самые удобные результаты профилирования и отчёты были у NYTProf (профайлер для Perl, авторы из New York Times).
          В питоне всё не так удобно и красиво, конечно (к слову картинка профайлера из Matlab меня ужаснула =), но это не мешает профилировать программы и оптимизировать их.

          Всегда хочется чего-то лучшего. Комментарий совершенно справедлив, и если этот вопрос действительно интересен, есть предложение пообщаться более плотно в личке.
          • +1
            к слову картинка профайлера из Matlab меня ужаснула =)

            Да, может показаться страшненьким, но зато он довольно логичный и удобный. Тормозит, конечно, как и все подобные профайлеры, но понять где узкое место позволяет.

            Вот контр-пример с cProfile. Например, есть у меня модуль с некой математической функцией.

            Например, с такой вот:
            def bspline_deboor(px, py, weights=None, degree=3, knots=None, t=100):
                def _bspline_deboor_interval(u, k):
                    idx = (u >= k) & (u < np.hstack((k[1:], 2*k[-1])))
                    row, col = np.nonzero(idx)
                    sidx = np.argsort(row)
            
                    return col[sidx]
            
                len_p = len(px)
                d = degree
                d1 = degree + 1
            
                if weights is None:
                    weights = np.ones(len_p)
            
                if knots is None:
                    knots = np.hstack((
                        np.zeros(d),
                        np.linspace(0, 1, len_p-d1+2),
                        np.ones(d),
                    ))
            
                if isinstance(t, int):
                    t = np.linspace(knots[d], knots[-d1], t)
            
                px = px * weights
                py = py * weights
            
                len_knots = len(knots)
                len_t = len(t)
            
                m = 3
                tt = np.array(t, ndmin=2).T
            
                s = np.sum(util.fuzzy_equal(knots, tt), axis=1)
                ii = _bspline_deboor_interval(tt, knots)
            
                p = np.vstack((px, py, weights))
                pk = np.zeros((d1, m, len_p))
                c = np.zeros((m, len_t))
            
                for i in xrange(len_t):
                    ti = t[i]
                    si = s[i]
                    ix = ii[i]
            
                    r = slice(ix-d, ix-si+1)
                    pk[0, :, r] = p[:, r]
            
                    h = d - si
            
                    if h > 0:
                        # de Boor recursion formula
                        for r in xrange(h):
                            r1 = r + 1
                            q = ix - 1
            
                            for j in xrange(q-d+r1, q-si+1):
                                j1 = j + 1
            
                                a = (ti - knots[j1]) / (knots[j1+d-r] - knots[j1])
                                pk[r1, :, j1] = (1 - a) * pk[r, :, j] + a * pk[r, :, j1]
            
                        val = pk[d-si, :, ix-si]
            
                    elif ix == (len_knots-1):
                        val = p[:, -1]
                    else:
                        val = p[:, ix-d]
            
                    c[:, i] = val
            
                # Normalize and remove weights from computed points
                c = c[:-1, :] / c[-1, :]
            
                sx = np.array(c[0, :])
                sy = np.array(c[1, :])
            
                return sx, sy
            



            Которая работает, скажем ~0.016-0.017 сек. в некоторых условиях. Скажем, померил я это через time.clock()/timeit. Теперь хочу посмотреть профайлером более подробно:

            p = cProfile.Profile()
            p.enable()
            sx, sy = splines.bspline_deboor(px, py, degree=3, t=100)
            p.disable()
            p.print_stats()
            


            И что я вижу:
            93 function calls in 0.016 seconds
            
               Ordered by: standard name
            
               ncalls  tottime  percall  cumtime  percall filename:lineno(function)
                    1    0.000    0.000    0.000    0.000 _methods.py:16(_sum)
                    1    0.000    0.000    0.000    0.000 fromnumeric.py:1172(nonzero)
                    1    0.000    0.000    0.000    0.000 fromnumeric.py:1422(sum)
                    1    0.000    0.000    0.000    0.000 fromnumeric.py:599(argsort)
                    2    0.000    0.000    0.000    0.000 function_base.py:6(linspace)
                    2    0.000    0.000    0.000    0.000 numeric.py:120(ones)
                    8    0.000    0.000    0.000    0.000 numeric.py:322(asanyarray)
                    1    0.000    0.000    0.000    0.000 shape_base.py:177(vstack)
                    2    0.000    0.000    0.000    0.000 shape_base.py:228(hstack)
                    3    0.000    0.000    0.000    0.000 shape_base.py:58(atleast_2d)
                    5    0.000    0.000    0.000    0.000 shape_base.py:6(atleast_1d)
                    1    0.015    0.015    0.016    0.016 splines.py:14(bspline_deboor)
                    1    0.000    0.000    0.000    0.000 splines.py:73(_bspline_deboor_interval)
                    1    0.000    0.000    0.000    0.000 util.py:136(fuzzy_equal)
                    2    0.000    0.000    0.000    0.000 {isinstance}
                   22    0.000    0.000    0.000    0.000 {len}
                    3    0.000    0.000    0.000    0.000 {map}
                    8    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
                    1    0.000    0.000    0.000    0.000 {method 'argsort' of 'numpy.ndarray' objects}
                    1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
                    1    0.000    0.000    0.000    0.000 {method 'nonzero' of 'numpy.ndarray' objects}
                    1    0.000    0.000    0.000    0.000 {method 'reduce' of 'numpy.ufunc' objects}
                    1    0.000    0.000    0.000    0.000 {method 'reshape' of 'numpy.ndarray' objects}
                    2    0.000    0.000    0.000    0.000 {numpy.core.multiarray.arange}
                   11    0.000    0.000    0.000    0.000 {numpy.core.multiarray.array}
                    3    0.000    0.000    0.000    0.000 {numpy.core.multiarray.concatenate}
                    2    0.000    0.000    0.000    0.000 {numpy.core.multiarray.copyto}
                    2    0.000    0.000    0.000    0.000 {numpy.core.multiarray.empty}
                    3    0.000    0.000    0.000    0.000 {numpy.core.multiarray.zeros}
            



            Я ничего не понял из этого отчёта, правда. Я так и не знаю где же узкое место в моей функции. :)
            Я просто запустил профайлер с настройками по умолчанию и не получил ничего вразумительного на первый взгляд, да и на второй тоже. Я считаю, что это не очень здорово. :)
            • +1
              Как уже отметили выше, лучше использовать другой профайлер — который выдает информацию по каждой строчке: pythonhosted.org/line_profiler/
        • +1
          Кстати, если в профайлере PTVS вам чего-то не хватает — напишите, пожалуйста.

          (из вышеприведенных картинок с Matlab несколько неочевидно — вроде бы есть все то же самое, кроме построчной выборки)

Только зарегистрированные пользователи могут оставлять комментарии. Войдите, пожалуйста.

Самое читаемое Разработка