Профилируем Rails-приложение

Илья • 8 апреля 2008 г.

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

Интересуемые нас скрипты находятся в корне вашего приложения в папке script/performance. Если там их нет, то скорее всего приложение было создано рельсами версии младше 1.2.6 и вам следует обновить папку scripts, чтобы воспользоваться примерами из этой заметки. Следующая команда обновит все скрипты из папки scripts в соответствии с той версией Ruby on Rails, которая используется приложением в данный момент:

ilya$ rake rails:update:scripts

Всего в нашем распоряжении 3 скрипта для замера производительности: benchmarker, profiler  и request. Первые два принимают аргументом Ruby-код, который следует измерить. Последний скрипт работает с приложением целиком и замеряет производительность запросов к тем или иным контроллерам.

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

Benchmarker

Самый простой из представленных скриптов — выводит количество времени, потребовавшегося для выполнения кода:

ilya$ ./script/performance/benchmarker 100 'Article.find(:all)'
            user     system      total        real
#1      0.310000   0.130000   0.440000 (  0.771757)

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

Profiler

Прежде чем использовать этот скрипт, убедитесь что у вас установлен gem ruby-prof версии 0.4.1, так как последняя версия 0.6.0 не работает с профилером.

Профилер является более мощным инструментом. С его помощью вы можете узнать какие методы были вызваны при выполнении кода, сколько времени заняло выполнение каждого из них и сколько процентов это заняло от общего времени выполнения. Результат запуска профилера выглядит примерно так:

lya$ script/performance/profiler "Article.find(:all)" 
Loading Rails...
Using the ruby-prof extension.
Thread ID: 2279160
Total: 0.005417

 %self     total     self     wait    child    calls  name
 60.86      0.00     0.00     0.00     0.00        1  Mysql#query (ruby_runtime:0}
 13.22      0.00     0.00     0.00     0.00        1  Mysql::Result#each_hash (ruby_runtime:0}
  2.71      0.00     0.00     0.00     0.00       12  #instantiate
  1.70      0.00     0.00     0.00     0.00        1  Mysql::Result#free (ruby_runtime:0}
  0.92      0.00     0.00     0.00     0.00        1  #measure 
  0.70      0.00     0.00     0.00     0.00        1  #construct_finder_sql
  0.70      0.00     0.00     0.00     0.00       28  Hash#[] (ruby_runtime:0}

Как видите, 60% времени от выполнения всего кода Article.find(:all) занял 1 вызов метода Mysql.query.

Request

Последний скрипт в нашем арсенале объединяет в себе два предыдущих и работает на прямую с rails-приложением, а не отдельными кусочками кода.

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

get('/')

Сценарии поддерживают тот же синтаксис, что и интеграционные тесты Rails. Подробнее смотреть в API.

Как видите, это простой GET запрос в корень вашего приложения. Полагаю у вас обязательно там что-нибудь лежит. Давайте проверим насколько производительным окажется этот запрос.

Как я уже сказал, request может как профилировать запрос, так и просто замерять время выполнения в секундах. По умолчанию используется профилирование, но если вы хотите просто замерить время, то используйте флаг -b:

ilya$ ./script/performance/request -b -n 10 scenario.rb
Warming up once
0.26 sec, 1 requests, 3 req/sec

Benchmarking 10x
  x.........
7.23 sec, 10 requests, 1 req/sec

Флаг -n регулирует количество раз выполнения запроса (по умолчанию 100 раз). Большее количество запросов обеспечивает более точные цифры.

Как видите, 10 запросов к главной странице моего приложения выполнились за 7 с лишним секунд. В среднем 1 запрос в секунду.

Обратите внимание, что по стандарту скрипт request запускает приложение в development окружении. Чтобы проверить как приложение будет работать в реальных условиях, просто подставьте переменную RAILS_ENV перед запуском скрипта:

ilya$ RAILS_ENV=production ./script/performance/request -b -n 10 scenario.rb
Warming up once
0.16 sec, 1 requests, 6 req/sec

Benchmarking 10x
  x.........
0.26 sec, 10 requests, 38 req/sec

Как видите, использование production окружения позволило ускорить этот запрос в 38 раз.

Для профилирования запросов, запускайте request без флага -b. В результате, скрипт сгенерирует текстовый и html-документы в папке tmp, где будут подробно расписаны вызовы всех методов.

6 комментариев:

  1. alone:

    А откуда может расти такая бяка?

    Profiling 100x x………x………x………x………x………x………x………x………x………x……… 16.44 sec, 100 requests, 6 req/sec (erb):107:in `expand_path': user Ghh�5q��s doesn't exist (ArgumentError) from (erb):107:in `print' from (erb):95:in `each' from (erb):95:in `print' [skip]

  2. Илья Сабанин:

    Какая у вас операционка и имя пользователя, под которым запускаете профилер?

  3. Junior:

    Спасибо за хорошую статью.

  4. Kolinzzz:

    это пройдёт..)

  5. alex:

    Спасибо. Оч. полезная статья.

  6. Женя:

    Нужна помощь: поставил у себя InstantRails, потом добавил в систему обычный Руби из которого через “gem install” добавил Рельсы (версии 2);

    но ни там не там – не могу найти папку Script

    /работаю на Win/

Извините, но комментарии для этой статьи уже закрыты.