Issue1327
This issue tracker has been migrated to GitHub,
and is currently read-only.
For more information,
see the GitHub FAQs in the Python's Developer Guide.
Created on 2007-10-25 21:33 by eanxgeek, last changed 2022-04-11 14:56 by admin. 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | Date: 2008-04-22 22:42 | |
"Requested info not available", closing this ticket. |
History | |||
---|---|---|---|
Date | User | Action | Args |
2022-04-11 14:56:27 | admin | set | github: 45668 |
2008-04-22 22:42:40 | amaury.forgeotdarc | set | status: open -> closed resolution: works for me messages: + msg65692 |
2008-04-22 22:36:33 | skip.montanaro | set | messages: + msg65690 |
2008-01-22 15:06:19 | amaury.forgeotdarc | set | messages: + msg61510 |
2008-01-22 14:58:20 | eanxgeek | set | messages: + msg61509 |
2008-01-22 14:47:56 | eanxgeek | set | messages: + msg61507 |
2008-01-21 23:16:09 | amaury.forgeotdarc | set | messages: + msg61463 |
2008-01-21 18:56:34 | eanxgeek | set | messages: + msg61439 |
2008-01-21 18:42:39 | eanxgeek | set | messages: + msg61437 |
2008-01-20 19:57:46 | christian.heimes | set | priority: normal |
2008-01-16 00:05:02 | effbot | set | messages: + msg59986 |
2008-01-14 16:59:41 | skip.montanaro | set | nosy:
+ skip.montanaro messages: + msg59905 |
2008-01-14 16:00:24 | amaury.forgeotdarc | set | nosy:
+ amaury.forgeotdarc messages: + msg59900 |
2008-01-14 15:27:00 | eanxgeek | set | messages: + msg59899 |
2008-01-03 14:56:28 | effbot | set | nosy:
+ effbot messages: + msg59131 |
2007-10-26 15:43:57 | eanxgeek | set | messages: + msg56794 |
2007-10-25 21:33:43 | eanxgeek | create |