Книга: Программирование на языке Ruby

16.6. Измерение производительности

16.6. Измерение производительности

Я не люблю уделять слишком много внимания оптимизации скорости. В общем случае нужно правильно выбрать алгоритм и придерживаться здравого смысла.

Конечно, быстродействие имеет значение. Иногда даже очень большое. Однако начинать думать об этом на раннем этапе цикла разработки — ошибка. Как говорится, «преждевременная оптимизация — источник всех зол»; эту мысль впервые высказал Хоар (Hoare), а потом подтвердил Кнут (Knuth). Или, перефразируя, сначала пусть работает правильно, а уж потом быстро». На уровне отдельного приложения эта рекомендация обычно оказывается хорошим эвристическим правилом, хотя для больших систем она, быть может, и не так актуальна.

Я бы еще добавил: «Не оптимизируйте, пока не измерите».

Это не такое уж серьезное ограничение. Просто не приступайте к переработке ради скорости, пока не ответите на два вопроса: «Действительно ли программа работает медленно? Какие именно ее части снижают производительность?»

Второй вопрос важнее, чем кажется на первый взгляд. Программисты часто уверены, что и так знают, на что программа тратит большую часть времени, но специальные исследования убедительно свидетельствуют о том, что в среднем эти догадки имеют очень мало общего с действительностью. «Теоретическая» оптимизация для большинства из нас — плохая идея.

Нам нужны объективные измерения. Профилировщик нужен.

В комплект поставки Ruby входит профилировщик profile. Для его вызова достаточно включить библиотеку:

ruby -rprofile myprog.rb

Рассмотрим листинг 16.6. Эта программа открывает файл /usr/share/dict/words и ищет в нем анаграммы. Затем смотрит, у каких слов оказалось больше всего анаграмм, и распечатывает их.

words = File.readlines("/usr/share/dict/words")
words.map! {|x| x.chomp }
hash = {}
words.each do |word|
 key = word.split("").sort.join
 hash[key] ||= []
 hash [key] << word
end
sizes = hash.values.map {|v| v.size }
most = sizes.max
list = hash.find_all {|k,v| v.size == most }
puts "Ни у одного слова нет более #{most-1} анаграмм."
list.each do |key,val|
 anagrams = val.sort
 first = anagrams.shift
 puts "Слово #{first} имеет #{most-1) анаграмм:"
 anagrams.each {|a| puts " #{a}" }
end
num = 0
hash.keys.each do |key|
 n = hash[key].size
 num += n if n > 1
end
puts
puts "Всего слов в словаре: #{words.size},"
puts "из них имеют анаграммы: #{num}."

Наверняка вам интересно, какие получились результаты. Вот какие:

Ни у одного слова нет более 14 анаграмм.
Слово alerts имеет 14 анаграмм:
 alters
 artels
 estral
 laster
 lastre
 rastle
 ratels
 relast
 resalt
 salter
 slater
 staler
 stelar
 talers
Всего слов в словаре: 483523,
из них имеют анаграммы: 79537.

На моем компьютере этот файл содержит более 483000 слов, и программа работала чуть меньше 18 секунд. Как вы думаете, на что ушло это время? Попробуем выяснить. Профилировщик выдал более 100 строк, отсортированных в порядке убывания времени. Мы покажем только первые 20:

%     cumulative self            self    total
time     seconds seconds  calls  ms/call ms/call  name
42.78     190.93 190.93      15 12728.67 23647.33 Array#each
10.78     239.04  48.11 1404333     0.03     0.04 Hash#[]
 7.04     270.48  31.44       2 15720.00 25575.00 Hash#each
 5.66     295.73  25.25  483523     0.05     0.05 String#split
 5.55     320.51  24.78 1311730     0.02     0.02 Array#size
 3.64     336.76  16.25       1 16250.00 25710.00 Array#map
 3.24     351.23  14.47  483524     0.03     0.03 Array#sort
 3.12     365.14  13.91  437243     0.03     0.03 Fixnum#==
 3.04     378.72  13.58  483526     0.03     0.03 Array#join
 2.97     391.98  13.26  437244     0.03     0.03 Hash#default
 2.59     403.53  11.55  437626     0.03     0.03 Hash#[]=
 2.43     414.38  10.85  483568     0.02     0.02 Array#<<
 2.29     424.59  10.21       1 10210.00 13430.00 Array#map!
 1.94     433.23  8.64   437242     0.02     0.02 Fixnum#<=>
 1.86     441.54  8.31   437244     0.02     0.02 Fixnum#>
 0.72     444.76  3.22   483524     0.01     0.01 String#chomp
 0.11     445.26  0.50        4   125.00   125.00 Hash#keys
 0.11     445.73  0.47        1   470.00   470.00 Hash#values
 0.06     446.00  0.27        1   270.00   270.00 IO#readlines
 0.05     446.22  0.22    33257     0.01     0.01 Fixnum#+

Видно, что больше всего времени программа тратит в методе Array#each. Это понятно: ведь цикл выполняется для каждого слова и на каждой итерации делает довольно много. Среднее значение в данном случае сбивает с толку, поскольку почти все время уходит на первый вызов each, а остальные 14 (см. anagrams.each) выполняются очень быстро.

Мы также видим, что Hash#[] — дорогая операция (главным образом потому что часто выполняется); на 1.4 миллиона вызовов было потрачено почти 11 секунд.

Обратите внимание, что метод readlines оказался чуть ли не в самом конце списка. Эта программа тратит время не на ввод/вывод, а на вычисления. На чтение всего файла ушло всего-то четверть секунды.

Но этот пример не показывает, в чем истинная ценность профилирования. В программе нет ни методов, ни классов. На практике вы, скорее всего, увидите свои методы среди системных. И тогда будете точно знать, какие из ваших методов находятся в числе первых 20 «пожирателей времени».

Надо ясно понимать, что профилировщик Ruby (видно, по иронии судьбы) работает медленно. Он подключается к программе во многих местах и следит за ее выполнением на низком уровне (причем сам написан на чистом Ruby). Так что не удивляйтесь, если ваша программа в ходе сеанса профилирования будет работать на несколько порядков медленнее. В нашем примере она работала 7 минут 40 секунд (460 секунд), то есть в 25 раз медленнее обычного.

Помимо профилировщика, есть еще один низкоуровневый инструмент — стандартная библиотека benchmark, которая тоже полезна для измерения производительности.

Один из способов ее применения — вызвать метод Benchmark.measure и передать ему блок.

require 'benchmark'
file = "/usr/share/dict/words"
result = Benchmark.measure { File.readlines(file) }
puts result
# Выводится: 0.350000 0.070000 0.420000 ( 0.418825)

Этот метод выводит следующую информацию:

• время, затраченное процессором в режиме пользователя (в секундах);

• время, затраченное процессором в режиме ядра (в секундах);

• полное затраченное время — сумму вышеупомянутых величин;

• время работы программы (по часам).

Для сравнения производительности отдельных участков удобен метод Benchmark.bm. Передайте ему блок, а он сам передаст блоку объект формирования отчета. Если вызвать этот объект, передав ему метку и блок, то он выведет метку, а за ней временные характеристики блока. Пример:

require 'benchmark'
n = 200_000
s1 = ""
s2 = ""
s3 = ""
Benchmark.bm do |rep|
 rep.report("str << ") { n.times { s1 << "x" } }
 rep.report("str.insert ") { n.times { s3.insert(-1,"x") } }
 rep.report("str += ") { n.times { s2 += "x" } }
end

Здесь мы сравниваем три способа добавить символ в конец строки, дающие один и тот же результат. Чтобы можно было получить более точные цифры, каждая операция выполняется 200000 раз. Вот что вышло:

      user    system     total      real
str <<      0.180000  0.000000  0.180000 ( 0.174697)
str.insert  0.200000  0.000000  0.200000 ( 0.200479)
str +=     15.250000 13.120000 28.370000 (28.375998)

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

Вы можете предположить, что оператор + почему-то работает медленно, но дело в другом. Это единственный из трех способов, который не работает с одним и тем же объектом, а каждый раз создает новый.

Стало быть, вывод такой: создание объекта — дорогая операция. Библиотека Benchmark может преподать много подобных уроков, но я все же рекомендую сначала заняться высокоуровневым профилированием.

Оглавление книги