qubes-doc/Profiling.md

96 lines
2.5 KiB
Markdown
Raw Normal View History

2014-04-24 16:59:45 -04:00
---
2015-04-10 16:17:45 -04:00
layout: doc
2014-04-24 16:59:45 -04:00
title: Profiling
2015-04-10 16:17:45 -04:00
permalink: /doc/Profiling/
redirect_from: /wiki/Profiling/
2014-04-24 16:59:45 -04:00
---
Profiling
=========
This is python profiling primer.
For the purpose of this document, `qubes-dev` is name of the domain used for postprocessing profiling stats.
Requirements
------------
2015-04-10 16:17:45 -04:00
{% highlight trac-wiki %}
2014-04-24 16:59:45 -04:00
yum install gprof2dot graphviz
git clone http://git.woju.eu/qubes/profiling.git
2015-04-10 16:17:45 -04:00
{% endhighlight %}
2014-04-24 16:59:45 -04:00
If you profile something on dom0, move `Upload.sh` from repository to dom0:
2015-04-10 16:17:45 -04:00
{% highlight trac-wiki %}
2014-04-24 16:59:45 -04:00
mkdir -p ~/profiling
qvm-run -p qubes-dev 'cat ~/profiling/Upload.sh' > ~/profiling/Upload.sh
2015-04-10 16:17:45 -04:00
{% endhighlight %}
2014-04-24 16:59:45 -04:00
- WARNING: this will obviously be running third party code which is not signed by ITL nor Fedora. You have been warned.
2014-04-24 16:59:45 -04:00
Workflow
--------
### Identify function responsible for some slow action
You have to select area in which you suspect less than optimal performance. If you do not narrow the area, graphs may be unreadable.
### Replace suspect function with probe
Replace
def foo(self, bar):
# function content
with
def foo(self, *args, **kwargs):
profile.runctx('self.real_foo(*args, **kwargs)', globals(), locals(),
2014-04-24 16:59:45 -04:00
time.strftime('/home/user/profiling/foo-%Y%m%d-%H%M%S.pstats'))
def real_foo(self, bar):
2014-04-24 16:59:45 -04:00
# function content
### Run application
Beware that some functions may be called often. For example `qubesmanager/main.py:update_table` gets run once per second. This will produce one pstat file per second.
Remember to revert your changes to application afterwards.
### Upload statistics
If you are in dom0:
2015-04-10 16:17:45 -04:00
{% highlight trac-wiki %}
2014-04-24 16:59:45 -04:00
cd ~/profiling
./Upload.sh
2015-04-10 16:17:45 -04:00
{% endhighlight %}
2014-04-24 16:59:45 -04:00
### Analyse
2015-04-10 16:17:45 -04:00
{% highlight trac-wiki %}
2014-04-24 16:59:45 -04:00
make
2015-04-10 16:17:45 -04:00
{% endhighlight %}
2014-04-24 16:59:45 -04:00
For every `${basename}.pstats` this will produce `${basename}.txt` and `${basename}.svg`. SVG contains call graph. Text file contains list of all functions sorted by cumulative execution time. You may also try `make all-png`.
2015-04-10 16:17:45 -04:00
{% highlight trac-wiki %}
2014-04-24 16:59:45 -04:00
make index.html
2015-04-10 16:17:45 -04:00
{% endhighlight %}
2014-04-24 16:59:45 -04:00
This creates `index.html` with all SVG graphics linked to TXT files. Ready for upload.
2015-04-10 16:17:45 -04:00
{% highlight trac-wiki %}
2014-04-24 16:59:45 -04:00
make REMOTE=example.com:public_html/qubes/profiling/ upload
2015-04-10 16:17:45 -04:00
{% endhighlight %}
2014-04-24 17:28:12 -04:00
Example
-------
This example is from `qubes-manager` (`qubesmanager/main.py`).
!["update\_table-20140424-170010.svg"](//attachment/wiki/Profiling/update_table-20140424-170010.svg)
2014-04-24 17:28:12 -04:00
It is apparent than problem is around `get_disk_usage` which calls something via `subprocess.call`. It does it 15 times, probably once per VM.