| | 23 | - here's some particularly interesting profiling data from ticket:7490#comment:106, typical of a request triggering an environment reload. Edited to make it more readable: |
| | 24 | {{{ |
| | 25 | 935179 function calls (910454 primitive calls) in 6.699 CPU seconds |
| | 26 | |
| | 27 | Ordered by: cumulative time |
| | 28 | |
| | 29 | ncalls tottime percall cumtime percall filename:lineno(function) |
| | 30 | 1 0.000 0.000 6.699 6.699 ...trac/web/trac_profile.py:155(inspected) |
| | 31 | 1 0.000 0.000 6.699 6.699 ...trac/web/wsgi.py:90(run) |
| | 32 | 1 0.000 0.000 6.699 6.699 ...trac/web/main.py:314(dispatch_request) |
| | 33 | 1 0.000 0.000 4.782 4.782 ...trac/web/main.py:432(_dispatch_request) |
| | 34 | 1 0.000 0.000 4.782 4.782 ...trac/web/main.py:139(dispatch) |
| | 35 | 43/41 0.003 0.000 2.894 0.071 ...trac/core.py:65(extensions) |
| | 36 | 396/382 0.006 0.000 2.891 0.008 ...trac/core.py:194(__getitem__) |
| | 37 | 105 0.157 0.001 2.786 0.027 ...trac/env.py:222(is_component_enabled) |
| | 38 | 1 0.000 0.000 2.290 2.290 ...trac/web/chrome.py:706(render_template) |
| | 39 | 2/1 0.000 0.000 1.867 1.867 ...trac/env.py:546(open_environment) |
| | 40 | 6/2 0.001 0.000 1.733 0.867 ...genshi/template/loader.py:134(load) |
| | 41 | 4/2 0.000 0.000 1.732 0.866 ...genshi/template/loader.py:242(_instantiate) |
| | 42 | 4/2 0.001 0.000 1.732 0.866 ...genshi/template/base.py:345(__init__) |
| | 43 | 1 0.000 0.000 1.476 1.476 ...trac/web/chrome.py:689(load_template) |
| | 44 | 11699 0.098 0.000 1.423 0.000 ...trac/config.py:394(options) |
| | 45 | 1 0.000 0.000 1.390 1.390 ...trac/env.py:175(__init__) |
| | 46 | 189 0.007 0.000 1.349 0.007 ...genshi/template/eval.py:63(__init__) |
| | 47 | 1 0.001 0.001 1.316 1.316 ...trac/loader.py:101(load_components) |
| | 48 | 1 0.004 0.004 1.312 1.312 ...trac/loader.py:38(_load_eggs) |
| | 49 | 11722 0.249 0.000 1.141 0.000 ...trac/config.py:296(get) |
| | 50 | 382 0.163 0.000 1.102 0.003 {method 'sort' of 'list' objects} |
| | 51 | 189 0.012 0.000 1.010 0.005 ...genshi/template/eval.py:423(_compile) |
| | 52 | 806/67 0.010 0.000 1.006 0.015 ...genshi/template/base.py:412(_prepare) |
| | 53 | 4 0.025 0.006 1.004 0.251 ...genshi/template/markup.py:72(_parse) |
| | 54 | 1 0.000 0.000 0.995 0.995 ...trac/ticket/report.py:81(process_request) |
| | 55 | 67 0.001 0.000 0.988 0.015 build/bdist.freebsd-6.1-RELEASE-i386/egg/pkg_resources.py:1911(load) |
| | 56 | 63000 0.572 0.000 0.936 0.000 ...trac/env.py:236(<lambda>) |
| | 57 | 2748/830 0.013 0.000 0.793 0.001 ...genshi/core.py:264(_ensure) |
| | 58 | 940 0.020 0.000 0.762 0.001 ...genshi/template/interpolation.py:39(interpolate) |
| | 59 | 99 0.001 0.000 0.705 0.007 ...genshi/template/directives.py:69 (attach) |
| | 60 | 1 0.000 0.000 0.674 0.674 ...genshi/core.py:152(render) |
| | 61 | 1 0.002 0.002 0.674 0.674 ...genshi/output.py:33(encode) |
| | 62 | 231 0.004 0.000 0.667 0.003 ...genshi/output.py:302(__call__) |
| | 63 | 234 0.001 0.000 0.662 0.003 ...genshi/output.py:751(__call__) |
| | 64 | }}} |
| | 65 | - trac corresponds to Trac-0.11.5rc2-py2.5.egg and genshi to Genshi-0.5.1-py2.5-freebsd-6.1-RELEASE-i386.egg |
| | 66 | - as Shane found out, config is really taking more time than expected. Only 0.1ms per call to get/options, but as this happens 11000 times... 1.1s. |
| | 67 | - `Environment.is_component_enabled` is also unexpectedly slow, partly due to the following (line 236) |
| | 68 | {{{ |
| | 69 | #!python |
| | 70 | rules.sort(lambda a, b: -cmp(len(a[0]), len(b[0]))) |
| | 71 | }}} |
| | 72 | There is some potential for caching `rules` here. |
| | 73 | |
