0.23 to 0.31 performance issue

[mb]

I have a web service that queries a database and returns a fairly
large xml document based on parameters in the URL.

This morning, with web.py 0.23, it would return a 17,142 line response
(491k) in 200 ms.

This afternoon I upgraded to 0.31, and it now takes 56 seconds for the
same action.

For the entire 56 seconds, the cpu is pegged at 100% on the python
process with just one request, where on 0.23 I could run many
simultaneous requests and the cpu was rarely over 40%.

Any ideas why my performance has dropped by a factor of 300?

[Aaron Swartz]

Can you share more details? Code? Profiler output?

[mb]

It looks like iterating over the db result object is what's causing
the slowdown.

With a small result set (20 records), here are the times in 0.31 to do
the db query and to render xml by iterating over the result object:
db: 0.01993 second
render: 0.00087 second
total: 0.02671 second

Then with a large result set (17,142 records):
db: 0.09306 second
render: 67.98967 seconds
total: 68.08277

On version 0.23 and the large result set (17,142 records):
db: 0.06552
render: 0.16659
total: 0.23248

Clearly the render function is the problem. This function takes the
db result object as a parameter, and iterates over it to create the
xml:

def render_xml(items):
xml = '<?xml version=\"1.0\"?>\n'
xml += '<rootnode>\n'
for item in items:
xml += '<itemnumber>%s</itemnumber>\n' % item.id
xml += '<description>%s</description>\n' % item.descr
xml += '<quantity>%s</quantity>\n' % item.qty
...
return xml

dbresult = db.query(querystring)
return render_xml(dbresult)

On Jan 1, 8:04 pm, "Aaron Swartz" <m...@aaronsw.com> wrote:
> Can you share more details? Code? Profiler output?
>

[hhsuper]

apparently, the render method use string concat often cause the problem, it should have other method to process
string concat method you can try simulate other languages StringBuilder, use a list append your string,
and then use a join method get the string to output

--
Su zhaohui   苏召辉

[mb]

The render function didn't change between version 0.23 and 0.31, but
the speed went from 0.16659 second to 67.98967 seconds for the same
action.

But there were changes to the database module, so I'm wondering if
iterating over the db result object is causing the performance hit.

[mb]

I think I've isolated the performance issue to the web.py database
module, specifically its handling of char fields in the db result
Storage object.

To isolate the issue, I simplified the code and compared results of
the web.py database module to the same logic using MySQL-python 1.2.2
for the database connection.

Here are the times to extract 4000 records from the database and
render 28,003 lines of XML by iterating over the database result set.
Each version produced identical output.

With the web.py database module:
Database time: 0.17220 second
Render time: 176.08740 seconds <---- Here's the problem
Total time: 176.25962 seconds

With MySQL-python 1.2.2:
Database time: 0.12736 second
Render time: 0.07125 second <---- No problem here
Total time: 0.22433 second

All the fields in the database result set are integers, floats and
dates except one -- a char(50) field. When I eliminate the char(50)
field, the problem goes away:

With the web.py database module, eliminating the char(50) field:
Database time: 0.15156 second
Render time: 0.11541 seconds <---- Nice and fast now!
Total time: 0.26698 seconds

With MySQL-python 1.2.2, eliminating the char(50) field:
Database time: 0.11003 second
Render time: 0.04565 second
Total time: 0.18564 second

So it looks like I can work around the issue by using MySQL-python
instead of the new web.py database module. Or I could revert to
version 0.23 since it works fine, and this appears to be a new issue
with 0.31.

For what it's worth, here's my test code that uses the web.py database
module:

class diag_webpydb:
def GET(self):
query = """SELECT d.id, d.item, d.store, d.tdate, i.descr
FROM t09_diag d
JOIN t07_items i
ON d.item = i.item
WHERE d.id BETWEEN 170001 AND 174000"""

result = db.query(query)

xml = '<?xml version=\"1.0\"?>\n'

xml += '<root>\n'
for row in result:
xml += ' <product>'
xml += ' <id>%s</id>\n' % row.id
xml += ' <item>%s</item>\n' % row.item
xml += ' <store>%s</store>\n' % row.store
xml += ' <date>%s</date>\n' % row.tdate

# comment out the char(50) field to solve perf issue
# xml += ' <descr>%s</descr>\n' % row.descr

xml += ' </product>\n'
xml += '</root>\n'
return xml

And here's the test code using MySQL-python:

class diag_mysqldb:
def GET(self):
query = """SELECT d.id, d.item, d.store, d.tdate, i.descr
FROM t09_diag d
JOIN t07_items i
ON d.item = i.item
WHERE d.id BETWEEN 170001 AND 174000"""

cursor = mydb.cursor()
numrows = cursor.execute(query)

xml = '<?xml version=\"1.0\"?>\n'

xml += '<root>\n'
for i in range(numrows):
row = cursor.fetchone()
xml += ' <product>'
xml += ' <id>%s</id>\n' % row[0]
xml += ' <item>%s</item>\n' % row[1]
xml += ' <store>%s</store>\n' % row[2]
xml += ' <date>%s</date>\n' % row[3]

# comment out the char(50) to compare with web.py
# xml += ' <descr>%s</descr>\n' % row[4]

xml += ' </product>\n'
xml += '</root>\n'
return xml

[hhsuper]

oh, we never use web.py's db module, we only use it's web app func, why doesn't use the powerful orm tool sqlalchemy and
the owner michael bayer will do his best to reply your question

2009/1/3 mb <doi...@gmail.com>

--
Su zhaohui   苏召辉

[Anand Chitipothu]

> So it looks like I can work around the issue by using MySQL-python
> instead of the new web.py database module. Or I could revert to
> version 0.23 since it works fine, and this appears to be a new issue
> with 0.31.

In web.py 0.3x, there were some changes to MySQLDB to return unicode
values from the resultset. That could be causing the trouble.
It can be disabled by passing charset=None to web.database function
when creating the database.

Can you please try with that option and let us know the execution time?

[mb]

Looks like that's the problem. After setting charset=None, response
time is better.

With the web.py database module, charset=None
Database time: 176 ms
Render time: 183 ms
Total time: 360 ms

With the web.py database module and unicode:
Database time: 172 ms
Render time: 176,087 ms <---- Here's the problem
Total time: 176,260 ms

With MySQL-python 1.2.2 instead of the web.py db module:
Database time: 127 ms
Render time: 71 ms
Total time: 224 ms

[mb]

Just for kicks, I downgraded to 0.23, and performance (at least for my
use cases) is significantly better than with 0.31.

web.py 0.31 with charset=None

Database time: 176 ms
Render time: 183 ms
Total time: 360 ms

web.py 0.23
Database time: 104 ms
Render time: 124 ms
Total time: 228 ms <---- 37% faster

[Aaron Swartz]

Filed this as a bug: http://bugs.launchpad.net/webpy/+bug/314969

[slav0nic]

why web.py 0.31 is slowly for hellow world app?

v0.31
import web

urls = (
'/', 'hello'
)
app = web.application(urls, globals())

class hello:
def GET(self):
return 'Hello, world!'

if __name__ == "__main__":
app.run()

v0.23
import web

urls = (
'/', 'hello'
)

class hello:
def GET(self, name):
return 'Hello, world!'

if __name__ == "__main__":
web.run(urls, globals())

-------------------------------
python test_webpy.py 8000 2> /dev/null

/usr/sbin/ab -c 100 -n 1000 http://localhost:8000/

result :
v0.31 Requests per second: 66.84 [#/sec] (mean)

v0.23 Requests per second: 640.85 [#/sec] (mean)

WTF?

[Aaron Swartz]

anand, can you repeat this?

--~--~---------~--~----~------------~-------~--~----~ You received this message because you are sub...

[Roy Shan]

I did some profiling for this issue and found the time spent on the
accept method of socket is doubled in v .31. what's the cause?

v .31 profiling stats:

126384 function calls (125084 primitive calls) in 29.613 CPU
seconds

Ordered by: cumulative time
List reduced from 552 to 10 due to restriction <10>

ncalls tottime percall cumtime percall filename:lineno
(function)
1 0.000 0.000 29.613 29.613 <string>:1(<module>)
1 0.000 0.000 29.613 29.613 {execfile}
1 0.000 0.000 29.613 29.613 ./hello2.py:3(<module>)
1 0.000 0.000 29.440 29.440 /home/worker/test//lib/
python/web/application.py:279(run)
1 0.000 0.000 29.440 29.440 /home/worker/test//lib/
python/web/wsgi.py:24(runwsgi)
1 0.001 0.001 29.440 29.440 /home/worker/test//lib/
python/web/httpserver.py:130(runsimple)
1 0.019 0.019 29.414 29.414 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:1540(start)
2011 0.156 0.000 29.289 0.015 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:1635(tick)
2011 0.050 0.000 27.723 0.014 /usr/local/lib/python2.5/
socket.py:166(accept)
2011 27.564 0.014 27.564 0.014 {method 'accept' of
'_socket.socket' objects}

126384 function calls (125084 primitive calls) in 29.613 CPU
seconds

Ordered by: internal time
List reduced from 552 to 10 due to restriction <10>

ncalls tottime percall cumtime percall filename:lineno
(function)
2011 27.564 0.014 27.564 0.014 {method 'accept' of
'_socket.socket' objects}
2002 0.672 0.000 0.672 0.000 <string>:1(settimeout)
4002 0.177 0.000 0.177 0.000 {fcntl.fcntl}
4037 0.174 0.000 0.174 0.000 {built-in method
acquire}
2011 0.156 0.000 29.289 0.015 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:1635(tick)
12 0.101 0.008 0.101 0.008 {time.sleep}
2002 0.065 0.000 0.110 0.000 /usr/local/lib/python2.5/
socket.py:152(__init__)
2010 0.065 0.000 0.327 0.000 /usr/local/lib/python2.5/
Queue.py:105(put)
2001 0.062 0.000 0.248 0.000 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:1408(prevent_socket_inheritance)
2000 0.062 0.000 0.125 0.000 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:1134(__init__)

v .23 Stats:
146593 function calls (144969 primitive calls) in 16.003 CPU
seconds

Ordered by: cumulative time
List reduced from 395 to 10 due to restriction <10>

ncalls tottime percall cumtime percall filename:lineno
(function)
1 0.000 0.000 16.003 16.003 <string>:1(<module>)
1 0.000 0.000 16.003 16.003 {execfile}
1 0.000 0.000 16.003 16.003 ./hello1.py:2(<module>)
1 0.000 0.000 15.653 15.653 /home/worker/test//lib/
python/web/request.py:136(run)
1 0.000 0.000 15.653 15.653 /home/worker/test//lib/
python/web/wsgi.py:24(runwsgi)
1 0.001 0.001 15.653 15.653 /home/worker/test//lib/
python/web/httpserver.py:129(runsimple)
1 0.022 0.022 15.626 15.626 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:794(start)
2053 0.070 0.000 15.499 0.008 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:893(tick)
2053 0.040 0.000 13.816 0.007 /usr/local/lib/python2.5/
socket.py:166(accept)
2053 13.665 0.007 13.665 0.007 {method 'accept' of
'_socket.socket' objects}

146593 function calls (144969 primitive calls) in 16.003 CPU
seconds

Ordered by: internal time
List reduced from 395 to 10 due to restriction <10>

ncalls tottime percall cumtime percall filename:lineno
(function)
2053 13.665 0.007 13.665 0.007 {method 'accept' of
'_socket.socket' objects}
2043 0.976 0.000 0.976 0.000 <string>:1(settimeout)
4127 0.280 0.000 0.280 0.000 {built-in method
acquire}
2041 0.111 0.000 0.184 0.000 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:574(__init__)
11 0.099 0.009 0.099 0.009 {time.sleep}
2053 0.070 0.000 15.499 0.008 /home/worker/test//lib/
python/web/wsgiserver/__init__.py:893(tick)
2043 0.068 0.000 0.111 0.000 /usr/local/lib/python2.5/
socket.py:152(__init__)
2051 0.063 0.000 0.450 0.000 /usr/local/lib/python2.5/
Queue.py:105(put)
2051 0.046 0.000 0.100 0.000 /usr/local/lib/python2.5/
threading.py:249(notify)
2053 0.040 0.000 13.816 0.007 /usr/local/lib/python2.5/
socket.py:166(accept)

On Feb 17, 10:50 am, Aaron Swartz <m...@aaronsw.com> wrote:
> anand, can you repeat this?
>

> /usr/sbin/ab -c 100 -n 1000http://localhost:8000/

[Aaron Swartz]

That suggests it's a CherryPy bug. We know CherryPy is slow, so you
shouldn't use it for anything performance-related.

[Anand Chitipothu]

2009/2/18 Aaron Swartz <m...@aaronsw.com>:

>
> That suggests it's a CherryPy bug. We know CherryPy is slow, so you
> shouldn't use it for anything performance-related.

Yes. I did a performance test with lighttpd+factcgi and results
weren't very different.

[Alex K]

Anyone knows what's the status on this issue? Thank you.

2009/2/18 Anand Chitipothu <anand...@gmail.com>: