Como fazer benchmark e profiling com Ruby e Rails
Muitos desenvolvedores não sabem como fazer benchmark e profiling das suas aplicações, e uma dica, o desenvolvedor sempre se engana onde estão os bottlenecks. No meu trabalho atual trabalhei bastante com otimização e benchmark, utilizando desde o simples ab ao Dtrace no Solaris e agora no OSX.
Uma preocupação recorrente de todos é otimização da aplicação, mas isso só é de fato preciso se o desenvolvedor souber exatamente o que é lento! Depois disso se pode usar várias técnicas como cache.
Esse breve artigo visa explicar e exemplificar o uso de:
- Apache Bench
- Rails Benchmark
- Ruby Benchmark Lib
- Dtrace
Esse NÃO é um artigo avançado com milhões de exemplos e não pretende ser um guia para melhorar sua aplicação, apenas quero mostrar brevemente que o desenvolvedor pode, deve e tem maneiras de verificar onde deve se preocupar.
OBS: Esse artigo ainda está sendo escrito, qualquer boa contribuição é sempre muito bem vinda.
Iniciando
Para começar criei uma simples applicação usando Rails 2.3.2 chamada tutor.
rails tutor -d mysqlCriei um controller para ser minha homepage, imprimindo apenas um texto.
class HomepageController < ApplicationController
def index
render :text => "Hello World"
end
endE uma rota para essa action:
map.root :controller => "homepage" Agora podemos começar a fazer alguns benchmarks.
Apache benchmark
Apache benchmark é uma ferramenta distribuída junto com o servidor Apache para benchmark. Podemos fazer testes de performance bastante satisfatórios com ele. Para utilizar o Apache Benchmark, que vem distribuído junto com o Apache Httpd, basta apenas utilizar a o shell.
Fazendo o benchmark da página inicial ab -n 10 -c 2 http://127.0.0.1:3000/
-n 10 indica que você fara 10 request com -c 2, isso é, concorrrência 2.
O apache usará threads para simular diferentes usuários acessando o site simultaneamente, no caso, 2 usuários.
Podemos ver aqui o output do ab:
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 127.0.0.1 (be patient).....done
Server Software:
Server Hostname: 127.0.0.1
Server Port: 3000
Document Path: /
Document Length: 11 bytes
Concurrency Level: 2
Time taken for tests: 0.033 seconds
Complete requests: 10
Failed requests: 0
Write errors: 0
Total transferred: 2540 bytes
HTML transferred: 110 bytes
Requests per second: 300.07 [#/sec] (mean)
Time per request: 6.665 [ms] (mean)
Time per request: 3.333 [ms] (mean, across all concurrent requests)
Transfer rate: 74.43 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.0 0 0
Processing: 6 6 1.0 6 9
Waiting: 4 5 0.8 5 7
Total: 6 7 1.0 7 9
Percentage of the requests served within a certain time (ms)
50% 7
66% 7
75% 7
80% 8
90% 9
95% 9
98% 9
99% 9
100% 9 (longest request)O dado mais importante no output do ab é o tempo gasto por cada request, que aqui é muito baixo, afinal não estamos fazendo nenhum tipo de cumputação:
Time per request: 6.665 [ms] (mean)Obs: Eu estou rodando a aplicação em modo de produção usando uma instância apenas do Mongrel.
Outro dado importante é o “Percentage of the requests served within a certain time (ms)” que pode lhe indicar indícios de bottlenecks quando um request anda demorando muito. Se você tiver um resultado como:
Percentage of the requests served within a certain time (ms)
50% 48
66% 58
75% 67
80% 110
90% 149
95% 149
98% 149
99% 149
100% 149 (longest request)Isso indica que o request mais longo foi de 149 ms enquanto o menor foi de 48 ms. Talvez tenha alguma coisa de errado na aplicação, algum recurso compartilhado como IO segurando requests.
Outro fator importante para benchmarking e otimização de código é medir a aplicação antes e depois de envolver algum tipo de otimização como cache para ver se realmente você está fazendo a coisa certa.
Sinceramente devo falar, se você quer que sua app escrita em Rails seja rápida, use muito cache, mas antes de usar, verifique sempre com benchmarks se ele realmente vale a pena e o quanto ele vale em números.
Outra dica importante é: Vá de cima pra baixo, não faça microbenchmarks antes de saber do todo e não faça otimização em pequenas partes antes de saber o quanto elas valem no todo.
Rails Benchmark Tool
O próprio rails tem ferramentas bastante úteis para fazer benchmark de partes de seu código. Aqui em baixo é um simples exemplo de uma biblioteca que tem que alguns métodos para gerar tokens.
require 'sha1'
require 'md5'
module FakeApi
def self.genarate_token
SHA1.sha1(Time.now.to_s).hexdigest
end
def self.genarate_token2
MD5.md5(Time.now.to_s).hexdigest
end
def self.genarate_token3
rand(36**8).to_s(36) + rand(36**8).to_s(36)
end
def self.genarate_token4
ActiveSupport::SecureRandom.hex(8)
end
endUtilizando o Rails Benchmark podemos obter resultados como esse:
bastos@tiago-bastoss-macbook!tutor: script/performance/benchmarker 500 'FakeApi::genarate_token'
user system total real
#1 0.010000 0.000000 0.010000 ( 0.009395)
bastos@tiago-bastoss-macbook!tutor: script/performance/benchmarker 500 'FakeApi::genarate_token2'
user system total real
#1 0.000000 0.000000 0.000000 ( 0.008564)
bastos@tiago-bastoss-macbook!tutor: script/performance/benchmarker 500 'FakeApi::genarate_token3'
user system total real
#1 0.000000 0.000000 0.000000 ( 0.006788)
bastos@tiago-bastoss-macbook!tutor: script/performance/benchmarker 500 'FakeApi::genarate_token4'
user system total real
#1 0.000000 0.000000 0.000000 ( 0.005576)Podendo assim avaliar que gerar tokens com o ActiveSupport é bem mais rápido no nosso caso.
Ruby Benchmark Lib
O Ruby vem com uma biblioteca padrão para benchmark de código, abaixo vamos fazer alguns testes com ela utilizando a biblioteca FakeApi.
require "rubygems"
require 'benchmark'
require 'active_support'
require 'fake_api'
Benchmark.bm do |x|
x.report { FakeApi::genarate_token }
x.report { FakeApi::genarate_token2 }
x.report { FakeApi::genarate_token3 }
x.report { FakeApi::genarate_token4 }
endO output seria algo como:
user system total real
0.000000 0.000000 0.000000 ( 0.000136)
0.000000 0.000000 0.000000 ( 0.000037)
0.000000 0.000000 0.000000 ( 0.000132)
0.040000 0.020000 0.060000 ( 0.075202)Essas três colunas mostram o que foi usado pelo seu usuário, pelo sistema, o total e o real.
Sempre faça testes mais de uma vez, faça sempre mudar alguma parte significativa do código como sua biblioteca de cache ou mesmo a versão do Rails.
Lembre-se que benchmarks podem ser bastante diferentes se você rodar em máquinas diferentes. Se você usar uma arquitetura pra deployment diferente da sua de desenvolvimento, tente rodar benchmarks e profiling na sua máquida de produção também. Um exemplo eu tive quando comecei a fazer testes com uma Máquina SPARC com tecnologia Coolthreads,elas são extremamente lentas para Ruby. Sua arquitetura foi feita pra rodar centenas de threads nativas que usam muito IO e pouca CPU, então a empresa começou a usar x86 ao invés de SPARC.
Usar Dtrace para achar bottlenecks
Dtrace é uma ferramenta pre profiling, ela é extremamente útil quando você precisa saber realmente o que anda acontecendo com sua aplicação, quais são os métodos que estão sendo chamados, o número de chamadas etc. Ela está disponível para OSX e Solaris.
Para começar você precisa baixar os scrips
Depois vamos fazer uma mudança na app adicionando mais uso de CPU.
Controller:
class HomepageController < ApplicationController
def index
@token = FakeApi::genarate_token
@token2 = FakeApi::genarate_token2
@token3 = FakeApi::genarate_token3
@token4 = FakeApi::genarate_token4
end
endView:
SHA1 <%= @token %>
MD5 <%= @token2 %>
CUSTOM1 <%= @token3 %>
ActiveSupport <%= @token4 %>Agora rode o script rb_functime:
sudo dtrace -s rb_functime.d -p 22719Troque 22719 pelo PID do processo rails que você está rodando (use ps -ef para achar).
O output é algo parecido com isso.
___ OVERLAP TIMES: ___ ______ ELAPSED ______
CLASS METHOD COUNT AVG(us) SUM(us)
...
ActionController::Base render_for_file 1 33373 33373
Module module_eval 155 241 37366
Object DelegateClass 1 44201 44201
Class method_added 358 148 53107
Class action_methods 1 55793 55793
ActionController::Base action_methods 1 55922 55922
Class new 67 1114 74651
Class [] 210 359 75425
ActionController::Params parse_formatted_paramet 1 94764 94764
Object find 1 117173 117173
Gem::GemPathSearcher find 1 117241 117241
Gem::GemPathSearcher matching_files 210 676 142062
Gem::GemPathSearcher matching_file? 210 808 169705
Kernel gem_original_require 22 7979 175552
Array each 44 6956 306074
Object require 42 7321 307496Onde vemos quais são os métodos mais chamados e o tempo gasto com eles em média e somando o tempo total.
Vamos mudar (de uma forma estúpida) o código do controller para fazer com que o método generate_token apareça no resultado.
class HomepageController < ApplicationController
def index
1000.times do
@token = FakeApi::genarate_token
end
@token2 = FakeApi::genarate_token2
@token3 = FakeApi::genarate_token3
@token4 = FakeApi::genarate_token4
end
endO output:
Class now 1014 75 76636
Class orig_new 1001 84 84302
ActionController::Params parse_formatted_paramet 1 96759 96759
Object find 1 115469 115469
Gem::GemPathSearcher find 1 115536 115536
Gem::GemPathSearcher matching_files 210 676 142018
Gem::GemPathSearcher matching_file? 210 807 169589
Object to_s 1002 171 172235
Kernel gem_original_require 22 8203 180485
Object hexdigest 1001 227 228174
Class sha1 1000 230 230607
Object require 42 7526 316101
Array each 49 6479 317483
Class new 1077 315 339898
Module genarate_token 1000 841 841971Assim podemos ver que o genarate_token foi chamado 1000x! Usar o Dtrace é uma ótima maneira de ver que métodos são chamados costatemente, se eles são “pesados” então podemos assim aplicar alguma forma de otimizacão seja alterando o código ou usando cache.
