classification
Title: Python 2.4+ spends too much time in PyEval_EvalFrame w/ xmlrpmclib
Type: behavior Stage:
Components: Library (Lib), XML Versions: Python 2.4, Python 2.5
process
Status: closed Resolution: works for me
Dependencies: Superseder:
Assigned To: Nosy List: amaury.forgeotdarc, eanxgeek, effbot, skip.montanaro
Priority: normal Keywords:

Created on 2007-10-25 21:33 by eanxgeek, last changed 2008-04-22 22:42 by amaury.forgeotdarc. This issue is now closed.

Files
File name Uploaded Description Edit
ceval.c eanxgeek, 2007-10-25 21:33
Messages (15)
msg56755 - (view) Author: Eric Sammons (eanxgeek) Date: 2007-10-25 21:33
Created a small program using xmlrpclib.  When connecting to one url
where my list is < 300 items and the program finishes no problem. 
Connect to another url where my list is over 500 items and the program
times out after 40+ minutes with no results printed.  On my RHEL system
I used oprofile and determined that time spent was in ceval.c, symbol
PyEval_EvalFrame. This issue seems to be new to Python 2.4 as shipped
with RHEL.  I am currently in the process of building non-RHEL python to
 verify issue does or does not exist there as well.

<code>
#!/usr/bin/env python

import xmlrpclib

u = 'someuser'
p = 'password'

server_url = 'http://rhn.redhat.com/rpc/api'

server = xmlrpclib.Server(server_url)

session = server.auth.login(u,p)

l = server.channel.listSoftwareChannels(session)
for a in l:
    print a['channel_label']
</code>
msg56794 - (view) Author: Eric Sammons (eanxgeek) Date: 2007-10-26 15:43
I have tested 2.4.4 and 2.5.1 from python.org and both suffer from the
exact same issue.  I have also compared ceval.c from 2.3, the last known
working copy and ceval.c from 2.4+ and found that ceval.c has undergone
some pretty significant changes.
msg59131 - (view) Author: Fredrik Lundh (effbot) * (Python committer) Date: 2008-01-03 14:56
That changes to ceval should have introduced some kind of XML-RPC
package limit seems a bit unlikely.  If you can still reproduce this,
can you try instrumenting the xmlrpclib.py library to see where it gets
stuck?

(passing in verbose=True to the Server[Proxy] constructor might be good
enough)
msg59899 - (view) Author: Eric Sammons (eanxgeek) Date: 2008-01-14 15:26
Please find the attached ceval.c.  This file was generated from oprofile
and gives clear indicators where the simple program below gets hung up.

You will find in the oprofile output, from ceval.c, that PyEval_Frame
has a total of 1649 26.2789.  This indicates with a high degree of
probabilty that the changes made in this portion of the code are
promblamatic.

Now I will be the first to admit that I am by no means a C programmer;
however, I can tell you that the code has changed a great deal with
regards to xmlrpc and it has impacted performance to the point where it
seems to be unusable with current releases of Python where expected
output is > 300 records.  

Please check it out for yourself, using a different xmlrpc server - I
currently have access to one only where the number of records is greater
than 300.
msg59900 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2008-01-14 16:00
I don't think ceval is the issue here.

> the code has changed a great deal with regards to xmlrpc 
I am not sure to understand what you mean: xmlrpc is mostly written in
python code.

ceval.c is the place where the interpreter executes python code.
PyEval_EvalFrame is the loop that reads and dispatches each python
instruction.
Of course this function is time-critical, but the problem probably is
that too many python code is executed.

I suggest you to use the python-level profiler:
http://docs.python.org/lib/profile-instant.html
This may reveal some interesting things in the xmlrpclib module.
msg59905 - (view) Author: Skip Montanaro (skip.montanaro) * (Python triager) Date: 2008-01-14 16:59
Do you have an example which doesn't require a login?  Failing that,
can you tell us how to get the requisite login?

Skip
msg59986 - (view) Author: Fredrik Lundh (effbot) * (Python committer) Date: 2008-01-16 00:05
Can you switch on verbose mode in xmlrpclib, so you can see *where* the
transfer hangs?

Arguing that a hanging Python program must be caused by a bug in the
code that *executes* the Python program isn't that meaningful, really. 
After all, that code is used to run *all* Python programs, so I think
we'd noticed if it had a tendency to hang unexpectedly...
msg61437 - (view) Author: Eric Sammons (eanxgeek) Date: 2008-01-21 18:42
Has anybody else tested this against an RPC server that has more than
300 items to be returned.  I find it interesting that before all the
xmlrpc code changed everything works fine, but after the code change
(re-write) things don't seem to work.

As for the bug, I do not claim there is a bug, I am simply pointing
out that when using oprofile to profile the test application, most of
the time is spent in a specific routine.  Now it could be a side
affect of xmlrpc, I don't know - I do not claim to be a "programmer".

I am looking to turn on verbose mode in xmlrpc.  As soon as I do that
I will test again and send the results.

On Jan 15, 2008 7:05 PM, Fredrik Lundh <report@bugs.python.org> wrote:
>
> Fredrik Lundh added the comment:
>
> Can you switch on verbose mode in xmlrpclib, so you can see *where* the
> transfer hangs?
>
> Arguing that a hanging Python program must be caused by a bug in the
> code that *executes* the Python program isn't that meaningful, really.
> After all, that code is used to run *all* Python programs, so I think
> we'd noticed if it had a tendency to hang unexpectedly...
>
>
> __________________________________
> Tracker <report@bugs.python.org>
> <http://bugs.python.org/issue1327>
> __________________________________
>
msg61439 - (view) Author: Eric Sammons (eanxgeek) Date: 2008-01-21 18:56
I have added the verbose=1 option, the processing hangs in the body: where :
<code>
for a in l:
    print a['channel_label']
</code>

Is returning the data.  Initially it returns data quickly and then slows
until it eventually stops.

Here is the sample of the body data... data removed...

<body>
body: '<?xml version="1.0"
encoding="ISO-8859-1"?><methodResponse><params><param><value><array><data><value><struct><member><name></name><value><string></string></value></member><member><name></name><value><string></string></value></member><member><name></name><value><string></string></value></member><member><name></name><value><string></string></value></member><member><name></name><value><string></string></value></member></struct></value><value><struct><member><name></name><value><string></string></value></member><member><name></name><value><string></string></value></member><member><name></name><value><string>
</string></value></member><member><name></name><value><string></string></value></member><m'
</body>

This information is repeats ~500 times in the server where the program
eventually times out.

If you require anything further from the verbose output please let me know.
msg61463 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2008-01-21 23:16
What is the length of the response?
in verbose mode, you must read a line like:
    header: Content-length: 623329

Note that I managed to produce the same kind of output as the one you
showed, with a size of ~600Kb. And the whole request takes less that 1
second.
msg61507 - (view) Author: Eric Sammons (eanxgeek) Date: 2008-01-22 14:47
Here is the header information that I get:
<snip>
reply: 'HTTP/1.1 200 OK\r\n'
header: Date: Tue, 22 Jan 2008 14:42:54 GMT
header: Server: Apache
header: Content-Length: 183
header: Content-Type: text/xml;charset=UTF-8
</snip>

Then I get addition send followed by more header info:

<snip>
reply: 'HTTP/1.1 200 OK\r\n'
header: Date: Tue, 22 Jan 2008 14:42:54 GMT
header: Server: Apache
header: Content-Length: 399191
header: Content-Type: text/xml;charset=UTF-8
header: X-Pad: avoid browser bug
</snip>

I am looking for additional Content-Length data.  Also, the above was
done using Python 2.5.1 (r251:54863, Oct 30 2007, 13:54:11).

Thank you!
msg61509 - (view) Author: Eric Sammons (eanxgeek) Date: 2008-01-22 14:58
Some strace data:

WORKS:
<Python 2.3.4 (#1, Jan  9 2007, 16:40:09)>
 strace -cf ./test.py >/tmp/out
Process 9439 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 33.10    0.009125           8      1086       956 open
 23.47    0.006469           7       930           recvfrom
  9.67    0.002667           9       311       278 stat
  8.10    0.002234          14       165           read
  3.40    0.000936           7       133           mmap
  3.25    0.000896           6       144           close
  3.24    0.000892          45        20           poll
  2.97    0.000818           5       173           fstat
  2.83    0.000780          15        53           munmap
  2.13    0.000588         118         5         3 execve
  1.34    0.000369           9        39           mprotect
  1.13    0.000312           4        72           rt_sigaction
  0.66    0.000183           5        35           futex
  0.64    0.000176          10        17           brk
  0.61    0.000169          12        14           sendto
  0.57    0.000158          26         6           write
  0.50    0.000139           4        34           fcntl
  0.49    0.000134          10        14           socket
  0.40    0.000111           4        25           lseek
  0.36    0.000100           7        14         2 connect
  0.34    0.000093          23         4           getdents64
  0.27    0.000074           5        14         2 ioctl
  0.17    0.000048           4        11           gettimeofday
  0.06    0.000016           8         2         2 access
  0.05    0.000014           7         2         2 readlink
  0.04    0.000010           5         2           arch_prctl
  0.04    0.000010           5         2           time
  0.03    0.000009           9         1           _sysctl
  0.03    0.000008           8         1           lstat
  0.03    0.000008           4         2           uname
  0.02    0.000006           6         1           rt_sigprocmask
  0.02    0.000006           6         1           getcwd
  0.01    0.000004           4         1           getrlimit
  0.01    0.000004           4         1           set_tid_address
------ ----------- ----------- --------- --------- ----------------
100.00    0.027566                  3335      1245 total
<Python 2.3.4 (#1, Jan  9 2007, 16:40:09)>

I am still compiling the same data for Python 2.4.3 (#1, Dec 11 2006,
11:39:03).  However, this could take hours...  as 2.4+ seem to be
problematic.
msg61510 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2008-01-22 15:06
Please, could you use the python profiler instead? Since most of the
time is spent in the bytecode interpreter, the results are much more
meaningful.
Something like:

#!/usr/bin/env python
import xmlrpclib
import profile

u = 'someuser'
p = 'password'
server_url = 'http://rhn.redhat.com/rpc/api'

def f():
    server = xmlrpclib.Server(server_url)
    session = server.auth.login(u,p)
    l = server.channel.listSoftwareChannels(session)
    for a in l:
        print a['channel_label']

def g():
    try:
        f()
    except:
        pass

profile.run("g()")
msg65690 - (view) Author: Skip Montanaro (skip.montanaro) * (Python triager) Date: 2008-04-22 22:36
Can this ticket be closed?  I've still yet to see anything here that
anyone could actually do anything with.
msg65692 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2008-04-22 22:42
"Requested info not available", closing this ticket.
History
Date User Action Args
2008-04-22 22:42:40amaury.forgeotdarcsetstatus: open -> closed
resolution: works for me
messages: + msg65692
2008-04-22 22:36:33skip.montanarosetmessages: + msg65690
2008-01-22 15:06:19amaury.forgeotdarcsetmessages: + msg61510
2008-01-22 14:58:20eanxgeeksetmessages: + msg61509
2008-01-22 14:47:56eanxgeeksetmessages: + msg61507
2008-01-21 23:16:09amaury.forgeotdarcsetmessages: + msg61463
2008-01-21 18:56:34eanxgeeksetmessages: + msg61439
2008-01-21 18:42:39eanxgeeksetmessages: + msg61437
2008-01-20 19:57:46christian.heimessetpriority: normal
2008-01-16 00:05:02effbotsetmessages: + msg59986
2008-01-14 16:59:41skip.montanarosetnosy: + skip.montanaro
messages: + msg59905
2008-01-14 16:00:24amaury.forgeotdarcsetnosy: + amaury.forgeotdarc
messages: + msg59900
2008-01-14 15:27:00eanxgeeksetmessages: + msg59899
2008-01-03 14:56:28effbotsetnosy: + effbot
messages: + msg59131
2007-10-26 15:43:57eanxgeeksetmessages: + msg56794
2007-10-25 21:33:43eanxgeekcreate