terça-feira, 3 de dezembro de 2013

Melhorando a performance dos seus testes com RSpec

Após começar a ficar entendiado e frustrado por ter de esperar quase 10 segundos para rodar um teste de integração, resolvi procurar alguma solução para o problema.

Já estava utilizando o servidor de DRb spork para ter o Rails já carregado na memória antes da execução dos testes, então resolvi pesquisar no google alguma solução para o meu problema.

Encontrei um ótimo post no ótimo blog The Carbon Emitter: http://blog.carbonfive.com/2011/02/02/crank-your-specs/ que leva a outro ótimo post em outro ótimo blog, o da 37signals: http://37signals.com/svn/posts/2742-the-road-to-faster-tests

Configurei o perftools.rb para rodar na minha máquina e como era de se esperar pelos posts acima, o garbage collector do estava sendo o vilão, segue a quantidade de chamadas na saída pprof.rb e o tempo, coletado com o comando time para executar apenas 1 teste:

      271  45.5%  45.5%      271  45.5% garbage_collector
      58   9.7%  55.3%       58   9.7% OpenSSL::PKCS5.pbkdf2_hmac_sha1
      20   3.4%  58.7%       21   3.5% Nokogiri::XML::XPathContext#evaluate
 
real 8.93
user 0.07
sys 0.00

Porém adotei uma abordagem um pouco diferente dos posts acima, alterei o arquivo spec/spec_helper.rb conforme o railscast #413 Fast Test (pro):

config.before(:each) { GC.disable }
config.after(:each) { GC.enable }

Com esta pequena mudança acabei conhecendo outro vilão, conforme mostra a saída a seguir, que é fruto da utilização do módulo confirmable do devise, porém já é possível perceber uma diminuição considerável no tempo do mesmo teste:

      58  16.9%  16.9%       58  16.9% OpenSSL::PKCS5.pbkdf2_hmac_sha1
      20   5.8%  22.7%       20   5.8% Nokogiri::XML::XPathContext#evaluate
      19   5.5%  28.2%       19   5.5% Regexp#===

real 6.57
user 0.07
sys 0.01

Não encontrei nenhuma forma de fazer com que o devise utilizasse uma função menos custosa, fui então dar uma olhada no código utilizado por eles e realizei o seguinte monkey patch através do arquivo spec/spec_helper.rb:

    class Devise::KeyGenerator
      def generate_key(salt, key_size=64)
        OpenSSL::PKCS5.pbkdf2_hmac_sha1(@secret, salt, 1, key_size)
      end
    end


Alterei o 3 argumento da função para 1, sendo que no código original este valor é de 65536 iterações realizadas pelo algoritmo para gerar a chave. Com esta alteração meu tempo sofreu novamente uma queda, porém desta vez sendo bem menos significativa:

      18   6.5%   6.5%       39  14.0% Psych::Parser#parse
      17   6.1%  12.5%       17   6.1% garbage_collector
      14   5.0%  17.6%       14   5.0% Regexp#===

real 6.27
user 0.08
sys 0.00

E pela saída apresentada pelo pprof.rb não existe mais o que atacar no código para melhorar a performance. Também é possível ter ganhos marginais utilizando o bloco within do capybara restringir os testes das páginas a regiões específicas do DOM. Ao se levar em conta milhares de testes é bom utilizá-lo como uma prática.

Passei então a imaginar o que poderia estar deixando meu código lento e imaginei que fosse a interação com o banco de dados, bingo! Configurei as seguintes opções do PostgreSQL para off, tornando-o praticamente um banco em memória (não faça isso em produção) e baixando o tempo para 3.74s:

fsync = off
synchronous_commit = off

real 3.74
user 0.09
sys 0.00

Uma melhora de quase 2,4x no tempo de execução de apenas 1 teste! Ao executar toda a suíte de teste, que ainda é bem pequena (possui apenas 35 testes) é que a diferença de velocidade se torna gritante: 26.5 x 8.85. E quanto mais testes eu tiver utilizando o banco de dados, pior para os exemplos sem as modificações no Postgres.

Neste meio tempo também troquei o spork pelo spring e adotei o guard-rspec. O spring faz a mesma tarefa para os testes que o spork faz, porém ele também otimiza a execução de outros comandos, como o rake routes, rake db:migrate, rails g, etc. Já o guard permite que meus testes rodem sem que eu tenha que sair do meu editor de texto e ainda me mostra uma bela notificação quando eles acabam de rodar!

Achei esta apresentação muito boa também, porém não vi nenhuma aplicação para os meus testes no estágio que eles estão atualmente, mas o speed up alcançado por eles é impressionante.

Estou muito mais feliz com o tempo do meu ciclo de BDD agora. E você, tem alguma dica para melhorar ainda mais esta performance?

terça-feira, 12 de fevereiro de 2013

Unicorn e Thin no Heroku

Depois de ver este post http://michaelvanrooijen.com/articles/2011/06/01-more-concurrency-on-a-single-heroku-dyno-with-the-new-celadon-cedar-stack/ decidi configurar uma aplicação no Heroku para utilizar o Unicorn ao invés do Thin.

Se você observar no post acima, existe um benchmark em relação ao tempo que levou os testes e a quantidade de requisições por segundo. Fiquei realmente animado com esta possibilidade para escalar aplicações, visto que cada dyno do heroku atende a uma requisição e a única possibilidade de antender mais requisições com o servidor Thin é aumentar o número de dynos.

O Unicorn foi desenvolvido para trabalhar com vários processos, fazendo fork de instâncias, deste modo em um único dyno é possível ter aproximadamente 3 processos, isso devido a limitação de memória oferecida por cada dyno que é de 512mb, porém se você adicionar mais um dyno você tem 6 processos rodando. Legal, não acha?

Com estas possibilidades animadoras resolvi fazer alguns testes para ver se utilizá-lo é realmente uma vantagem para deixar a resposta da aplicação mais rápida. Meu arquivo de configuração do Unicorn ficou exatamente como o deste post: http://stackoverflow.com/questions/9344788/am-i-preloading-the-app-in-heroku-unicorn-correctly

Para coletar os dados utilizei o comando httperf da seguinte maneira: httperf --hog --server meuservidor.com.br --ssl --ssl-no-reuse --num-conn=500 --ra=10 --timeout 30

Este comando irá fazer 500 conexões SSL com a página raiz do meu site (que não faz acesso a banco de dados), forçando handshake através da opção --ssl-no-reuse a uma taxa (--ra=10) de 10 conexões por segundo. Rodei o comando 3 vezes e fiz a média dos resultados obtidos para os seguintes valores de --ra: 10, 40, 80, 160, 320 e 500.

Então vamos aos dados obtidos:

Confesso que esperava mais do Unicorn, já que temos 3 processos atendendo requisições. A partir de 80 conexões ele estabeleceu em média 5 conexões a mais por segundo, sendo que em um dos testes o Thin conseguiu um desempenho um pouco melhor.
O tempo de resposta foi outra surpresa para mim, sendo que o Thin conseguiu ser mais rápido quando muitas conexões estão sendo estabelecidas por segundo.

Não vejo nenhuma vantagem clara de usar o Unicorn por enquanto, além de algumas vezes (raras) ter me deparado com o erro: httperf: failed to connect to SSL server (err=-1, reason=5).

Depois destes dados compilados, achei que fui muito suave e decidi ser mais agressivo em relação ao número de requisições. Requisitei 1500 conexões a uma taxa de 100 conexões por segundo (um site bem movimentado, não acha?). Nesta configuração ambos os servidores não conseguiram antender a todas as requisições (timeout), porém a performance de ambos os servidor foi semelhante, com o Unicorn atendendo um pouco mais de requisições (1233 x 1249), a taxa de conexão praticamente igual (20,8 x 21,6) assim como o tempo de resposta (3371ms x 3025ms).

Estes últimos testes atenderam mais de 1000 conexões concorrentes. Isso na versão para desenvolvedor do Heroku. Muito bom!

Ainda pretendo fazer testes em páginas que realizem consultas não triviais ao banco de dados para ver se os servidor apresentam tempos diferentes, mas isso fica para um próximo post...