Image

Imageglader wrote in Imageru_python

Category:

Профилирование

Занялся на днях профилированием питоновского скрипта. Воспользовался hotshot.Profile. Он работает хорошо, но вывод мне сильно не нравится. Например (произвольный пример)
  ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1000    0.338    0.000    0.374    0.000 /home/parser/x12_parser.py:32(is_valid_header)
     7000    0.036    0.000    0.036    0.000 /usr/lib/python2.4/string.py:248(strip)
     1001    0.035    0.000    0.428    0.000 aggregate_parser.py:57(parse_file)
     1000    0.013    0.000    0.013    0.000 /home/parser/x12_parser.py:15(__init__)
        1    0.008    0.008    0.436    0.436 aggregate_parser.py:128(main)


Отсюда конечно видно, какая функция занимает много времени, но не видно, из-за чего. То есть может она сама медленная, а может ее потомки. Очень не хватает дерева вызовов. например на perl можно сделать вот такой вывод:

Site::Application::run x 1  	0.548s = (0.000 + 0.549)s
  Site::Controller::process x 1  	0.549s = (0.000 + 0.549)s
    DBD::_mem::common::DESTROY x 1  	0.000s
    Site::Controller::processTemplate x 1  	0.533s = (0.000 + 0.533)s
      Site::Controller::makePage x 1  	0.517s = (0.011 + 0.506)s
        Site::Controller::getItems x 2  	0.282s = (0.253 + 0.030)s
          Site::Item::BEGIN x 10  	0.030s = (0.030 + 0.000)s
            Site::Item::getItem x 1  	0.000s = (0.000 + 0.000)s
              DBD::_mem::common::DESTROY x 2  	0.000s
              DBI::db::selectall_arrayref x 1  	0.000s = (0.000 + 0.000)s
                DBD::_::db::selectall_arrayref x 1  	0.000s = (0.000 + 0.000)s
                  DBI::db::prepare x 1  	0.000s = (0.000 + 0.000)s


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

LJ Video