Open faassen opened 8 years ago
This is on Python 2.
I cannot reproduce this issue on Python 3.
I can reproduce this with github master of webob. The line number is 188 now but it's still lazify.
If I get rid of lazify
on line 283 in exc.py
then while I see slightly lower rps, it is stable and doesn't shrink over time.
Python 2.7.10 on OS X with master
of WebOb and pip install -r requirements.txt
in howareyou repo.
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 111361 898 481 145
With the profiler:
(howareyou)alexandra:howareyou xistence$ python -m cProfile -s tottime ~/.ve/howareyou/bin/howareyou -b notfound -f morepath -n 50000
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 43358 1153 481 145
24122935 function calls (24119073 primitive calls) in 43.737 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
50000 14.638 0.000 14.699 0.000 exc.py:188(lazify)
100000 1.385 0.000 7.850 0.000 response.py:176(__init__)
100105 1.032 0.000 3.961 0.000 {method 'sub' of '_sre.SRE_Pattern' objects}
100000 0.965 0.000 1.115 0.000 response.py:363(_status__set)
700000 0.959 0.000 1.405 0.000 headers.py:15(__getitem__)
2953708 0.902 0.000 0.902 0.000 {method 'lower' of 'str' objects}
300000 0.797 0.000 1.282 0.000 headers.py:43(__setitem__)
250000 0.763 0.000 0.990 0.000 acceptparse.py:35(parse)
300000 0.744 0.000 2.929 0.000 string.py:162(convert)
250000 0.647 0.000 1.838 0.000 acceptparse.py:252(parse)
50000 0.634 0.000 30.082 0.001 exc.py:324(generate_response)
I am seeing more tcalls/funcs than you though... are there changes that are not in the howareyou
repo?
Changing lazify
to:
class _lazify(object):
def __init__(self, func):
self.func = func
def __call__(self, value):
self.value = value
return self
def __str__(self):
return self.func(self.value)
def lazify(func):
return _lazify(func)
I get the following numbers:
(howareyou)alexandra:howareyou xistence$ howareyou -b notfound -f morepath
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 35253 2837 481 145
Nearly triple what I was getting before...
(howareyou)alexandra:howareyou xistence$ python -m cProfile -s tottime ~/.ve/howareyou/bin/howareyou -b notfound -f morepath -n 50000
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 24750 2020 481 145
24122938 function calls (24119076 primitive calls) in 25.007 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
100000 1.201 0.000 7.131 0.000 response.py:176(__init__)
700000 0.906 0.000 1.355 0.000 headers.py:15(__getitem__)
2953708 0.904 0.000 0.904 0.000 {method 'lower' of 'str' objects}
100105 0.878 0.000 3.407 0.000 {method 'sub' of '_sre.SRE_Pattern' objects}
100000 0.831 0.000 0.971 0.000 response.py:363(_status__set)
300000 0.726 0.000 1.190 0.000 headers.py:43(__setitem__)
250000 0.709 0.000 0.920 0.000 acceptparse.py:35(parse)
300000 0.622 0.000 2.529 0.000 string.py:162(convert)
250000 0.609 0.000 1.729 0.000 acceptparse.py:252(parse)
700000 0.562 0.000 1.917 0.000 _abcoll.py:379(get)
50000 0.534 0.000 13.423 0.000 exc.py:330(generate_response)
100000 0.448 0.000 3.116 0.000 response.py:796(_content_type__set)
700943 0.442 0.000 0.442 0.000 {method 'split' of 'str' objects}
250000 0.431 0.000 1.777 0.000 response.py:762(_content_type__get)
250001 0.406 0.000 0.527 0.000 {method 'decode' of 'str' objects}
1050000 0.402 0.000 0.701 0.000 response.py:432(_headers__get)
200000 0.401 0.000 1.655 0.000 util.py:12(html_escape)
250000 0.386 0.000 1.342 0.000 response.py:716(_charset__get)
350087 0.381 0.000 0.381 0.000 {method 'search' of '_sre.SRE_Pattern' objects}
1307485 0.370 0.000 0.371 0.000 {isinstance}
50000 0.331 0.000 1.344 0.000 request.py:23(__init__)
50000 0.330 0.000 0.961 0.000 response.py:852(_content_type_params__set)
50000 0.305 0.000 0.521 0.000 acceptparse.py:126(best_match)
50000 0.297 0.000 0.576 0.000 response.py:836(_content_type_params__get)
50000 0.264 0.000 8.886 0.000 core.py:171(excview_tween)
1300923 0.257 0.000 0.257 0.000 {method 'group' of '_sre.SRE_Match' objects}
301474 0.252 0.000 0.318 0.000 {getattr}
50000 0.251 0.000 1.980 0.000 acceptparse.py:30(__init__)
50000 0.245 0.000 4.476 0.000 exc.py:265(__init__)
200000 0.233 0.000 0.432 0.000 cgi.py:1039(escape)
400461 0.232 0.000 0.232 0.000 {range}
150000 0.218 0.000 0.218 0.000 __init__.py:57(get)
Here's the entries for _lazify
and lazify
:
50000 0.044 0.000 0.061 0.000 exc.py:199(lazify)
1 0.000 0.000 0.000 0.000 exc.py:188(_lazify)
I will drop that patch into WebOb and backport it to 1.6.x. I have no problems fixing performance issues as they come along.
(howareyou)alexandra:howareyou xistence$ howareyou -b notfound -f morepath -n 10000
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 3526 2836 481 145
(howareyou)alexandra:howareyou xistence$ howareyou -b notfound -f morepath -n 500000
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 174118 2872 481 145
With that patch iterations no longer matters either...
Cool, thanks, @bertjwregeer ! Definitely weird Python behavior that a nested class can have this cumulative effect...
I can't explain fully why you see a different amount of tcalls and funcs than I do, but I think earlier I was testing with an unreleased version of Morepath which affected things. When I test with the 0.15 version I get this:
ms rps tcalls funcs
morepath 37745 2649 460 141
Which is still less function calls. It's possible there are some differences depending on platform in the Python standard library; I'm testing on Linux.
That patch I provided doesn't do what it was supposed to do... I definitely should not code tired.
Updated:
class _lazified(object):
def __init__(self, func, value):
self.func = func
self.value = value
def __str__(self):
return self.func(self.value)
def lazify(func):
def wrapper(value):
return _lazified(func, value)
return wrapper
(howareyou)alexandra:howareyou xistence$ howareyou -b notfound -f morepath
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 33640 2973 483 145
(howareyou)alexandra:howareyou xistence$ howareyou -b notfound -f morepath
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 33640 2973 483 145
(howareyou)alexandra:howareyou xistence$ howareyou -b notfound -f morepath -n 500000
Benchmark : notfound
Frameworks: morepath
ms rps tcalls funcs
morepath 174269 2869 483 145
Note that this is running on my desktop, so some variations with browsers/terminal windows is to be expected. It's close enough for government work ;-)
Thanks @bertjwregeer!
So this issue should be fixed with the next release of webob, and also should be fixed if you use Python 3.
I just did some benchmarking on 'notfound' errors in Morepath. Morepath is slower at this than it should be, and it seems to get worse the more iterations I run per test. The benchmarking tool is howareyou:
https://github.com/faassen/howareyou
When I run the default amount of iterations (100,000) then I get these results:
If I use half those iterations:
if I use less iterations:
and even less iterations:
This isn't supposed to happen. When I profile, I find that
lazify
in webob'sexc.py
totally dominates performance::