sys._current_frames(), Radiografando seu software em tempo real

Presentation at PythonBrasil 2013. Portuguese.

Apresentação na PythonBrasil[9] em 2013 sobre como fazer depuração de problemas de performance utilizando a chamada sys._current_frames() do Python

Transcript

1. © 2013 Leonardo Rochael Almeida, CC-BY-SA sys._current_frames() Radiografando seu software em tempo real Leonardo Rochael Almeida Soft. Eng. @ Geekie (We're Hiring!)
2. © 2013 Leonardo Rochael Almeida, CC-BY-SA • sys._current_frames(): – Tracebacks a qualquer momento • Tracebacks em sequência: – Diagnóstico rápido de performance Resumo
3. © 2013 Leonardo Rochael Almeida, CC-BY-SA Performance: melhores práticas • Prevenção – Teste funcional de performance • testutils.org/multi-mechanize – Antes de entrar em produção • certo?!
4. © 2013 Leonardo Rochael Almeida, CC-BY-SA Performance: melhores práticas • Produção – Espera a turba enfurecida • “Como reproduzir?” – Monitoramento proativo
5. © 2013 Leonardo Rochael Almeida, CC-BY-SA Com instruções de reprodução • “profile/cProfile” – Apenas “chamadas”, não “linhas” – Complicado: 57356 function calls (66 primitive calls) in 0.746 CPU seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 21 0.000 0.000 0.000 0.000 :0(append) 20 0.000 0.000 0.000 0.000 :0(extend) 1 0.001 0.001 0.001 0.001 :0(setprofile) 1 0.000 0.000 0.744 0.744 <string>:1(<module>) 1 0.000 0.000 0.746 0.746 profile:0(print fib_seq(20); print) 0 0.000 0.000 profile:0(profiler) 57291/21 0.743 0.000 0.743 0.035 profile_fibonacci_raw.py:13(fib) 21/1 0.001 0.000 0.744 0.744 profile_fibonacci_raw.py:22(fib_seq)
6. © 2013 Leonardo Rochael Almeida, CC-BY-SA Com instruções de reprodução • “statprof” – Amostragem de tracebacks: • Estatísticas por linha – Informação mais relevante que “cProfile” • “line_profiler” • Mas ainda não “contam a estória”
7. © 2013 Leonardo Rochael Almeida, CC-BY-SA Sem instruções de reprodução • “profile/cProfile” – Pesado demais para produção • Polvilhar temporização: – log(time.time() - start_time) – Demorado... Restarts... – Em produção?! • DeadlockDebugger
8. © 2013 Leonardo Rochael Almeida, CC-BY-SA Monitoramento proativo • Logs do servidor HTTP – Com informações de tempo • Slow Queries no DB • Insuficiente – Apenas polvilhando temporizações
9. © 2013 Leonardo Rochael Almeida, CC-BY-SA DeadlockDebugger • Tracebacks de todas as threads • URL especial • Mesmo com o sistema travado
10. © 2013 Leonardo Rochael Almeida, CC-BY-SA Zope: pequeno resumo • Z Object Publishing Environment • Uma thread de escuta – Destrincha requisição HTTP – Põe na fila • Poucas worker threads: – Calculam / renderizam a resposta
11. © 2013 Leonardo Rochael Almeida, CC-BY-SA DeadlockDebugger for thread_id, frame in sys._current_frames().items(): output = StringIO() traceback.print_stack(frame, file=output) res.append("Thread %s:\n%s" % (thread_id, output.getvalue())) res.append("End of dump") return '\n'.join(res)
12. © 2013 Leonardo Rochael Almeida, CC-BY-SA sys._current_frames() • Python dict – Chave: thread id (int) • Mesmo que thread.get_ident() em cada thread – Valor: Top Stack Frame • Executando agora nessa thread • Topo da pilha de thread
13. © 2013 Leonardo Rochael Almeida, CC-BY-SA Stack Frame • Função Atualmente executando – Arquivo e Nº de linha • Variáveis – locals – globals • Frame da Função que me chamou • [...]
14. © 2013 Leonardo Rochael Almeida, CC-BY-SA Pra que serve o Frame? • Obter valor de variáveis >>> a_list = range(5) >>> import sys, thread >>> thread_id = thread.get_ident() >>> frame = sys._current_frames()[thread_id] >>> frame.f_locals["a_list"] [0, 1, 2, 3, 4]
15. © 2013 Leonardo Rochael Almeida, CC-BY-SA Pra que serve o Frame? • Avaliar código no contexto >>> eval("len(a_list)", frame.f_globals, frame.f_locals) 5
16. © 2013 Leonardo Rochael Almeida, CC-BY-SA Pra que serve o Frame? • Imprimir todo o stack de uma thread >>> import traceback >>> traceback.print_stack(frame) File "[...]/bin/ipython", line 9, in <module> load_entry_point('ipython==0.13.2', 'console_scripts', 'ipython')() File "[...]/terminal/ipapp.py", line 389, in launch_new_instance app.start() [...] File "[...]/core/interactiveshell.py", line 2745, in run_code return outflag File "<ipython-input-5-f0e996c7314a>", line 1, in <module> frame = sys._current_frames()[thread_id]
17. © 2013 Leonardo Rochael Almeida, CC-BY-SA DeadlockDebugger • Raio-X: – Thread: 1 • Stack trace … – Thread: 2 • Stack trace …
18. © 2013 Leonardo Rochael Almeida, CC-BY-SA DeadlockDebugger • Muito bom se você está lá! – Senão, não ajuda muito...
19. © 2013 Leonardo Rochael Almeida, CC-BY-SA Dá pra melhorar? • DeadlockDebugger contínuo • Apenas em requisições lentas • Com informação adicional – URL, POST, GET, Cookies...
20. © 2013 Leonardo Rochael Almeida, CC-BY-SA LongRequestLogger • Criado na Nexedi • Design – Julien Muchembled – Sébastien Robin – Leonardo Rochael Almeida • Implementação p/ Zope2 – Leonardo Rochael Almeida • Portado para WSGI por Shane Hathaway – PYPI: slowlog
21. © 2013 Leonardo Rochael Almeida, CC-BY-SA LongRequestLogger slowlog • Intercepta e monitora cada requisição • Logfile: – Request X, thread Y, running for T seconds • Request Info • Stack trace – Request X, thread Y, running for T+2 seconds • Request Info • Stack trace – [...]
22. © 2013 Leonardo Rochael Almeida, CC-BY-SA slowlog mostra • Só requisições lentas – Não o “dano colateral” na fila • Porque são lentas • O local exato pra otimizar
23. © 2013 Leonardo Rochael Almeida, CC-BY-SA ERP5 Case Study • “T-Shirt Custom Printing company” • ERP5: ERP da Nexedi, em Zope • MRP, CRM, Contabilidade, ... • Picos de performance muito ruim • Nunca na mesma URL duas vezes • Sempre na “hora do rush”
24. © 2013 Leonardo Rochael Almeida, CC-BY-SA ERP5 Case Study • Culpado: Sale Order Line Price • Calculo sob demanda – Normalmente em Background • Resolvido em 15 linhas
25. © 2013 Leonardo Rochael Almeida, CC-BY-SA Plone Case Study • Grande portal governamental • LongRequestLogger: – Lentidão em horários específicos – Culpado: gargalo no acesso ao banco – Na hora do backup • Sobrecarga na interface de rede
26. © 2013 Leonardo Rochael Almeida, CC-BY-SA O que otimizar: Limite entre o frio e o quente • Stack Trace em Tx – A • B(...) – B • C(...) – C • D(...) – D • E(...) – E • F(...) • Stack Trace em Tx + 2 – A • B(...) – B • C(...) – C • G(...) – G • H(...) – H • I(...)
27. © 2013 Leonardo Rochael Almeida, CC-BY-SA • Profiling por amostragem • Pura probabilidade – Quem é lento sempre aparece • Stack traces (+dados) “contam a estória” • Independencia do usuário Porque funciona?
28. © 2013 Leonardo Rochael Almeida, CC-BY-SA Slowlog em Django • mysite/wsgi.py: from django.core.wsgi import get_wsgi_application application = get_wsgi_application() # Apply WSGI middleware here. from slowlog.wsgi import SlowLogApp from mysite import settings application = SlowLogApp(application, logfile=settings.SLOWLOG_FILENAME)
29. © 2013 Leonardo Rochael Almeida, CC-BY-SA Slowlog em Pyramid • paster.ini: pyramid.includes = [...] slowlog slowlog = true slowlog_file = %(here)s/tmp/slow.log
30. © 2013 Leonardo Rochael Almeida, CC-BY-SA Desafios • Volume de dados – Análise / classificação – Desentrelaçamento • (Ausência de) Interface de Usuário – grep – <seu editor de texto favorito>
31. © 2013 Leonardo Rochael Almeida, CC-BY-SA Melhorias futuras • Análise – Busca / ordenação • Mais info extraída dos frames • Log estruturado – Comparações mais profundas entre stacks
32. © 2013 Leonardo Rochael Almeida, CC-BY-SA Questões em aberto • Real impacto de performance – Quão curto pode ser o intervalo? – Contenção na GIL se muito curto?
33. © 2013 Leonardo Rochael Almeida, CC-BY-SA We're Hiring jobs@geekie.com.br
34. © 2013 Leonardo Rochael Almeida, CC-BY-SA Referencias • SlowLog: https://pypi.python.org/pypi/slowlog • LongRequestLogger: • http://www.geekie.com.br • @LeoRochael • LeoRochael@geekie.com.br • LeoRochael@gmail.com