Re: some preliminary timings
Executive summary for python-dev folks seeing this for the first time: This thread started at http://mail.python.org/pipermail/spambayes/2003-February/003520.html Running in a single interpreter loop, I can score roughly 46 messages per second. Running from the shell using hammiefilter.py (which takes a msg on stdin and spits a scored message to stdout) performance drops to roughly 2 messages per second. Neil Schmenenauer noted all the failed open() calls during import lookup, which got me started trying to whittle them down. Two more things to try before abandoning this quixotic adventure... It appears $prefix/python23.zip is left in sys.path even if it doesn't exist (Just van Rossum explained to me in a bug report I filed that nonexistent directories might actually be URLs or other weird hacks which import hooks could make use of), so I went with the flow and created it, populating it with the contents of $prefix/python2.3. My averate wallclock time went from 0.5 seconds to 0.47 seconds and user+sys times went from 0.43 seconds to 0.41 seconds. A modest improvement. One more little tweak. I moved the lib-dynload directory to the front of sys.path (obviously only safe if nothing there appears earlier in sys.path). Wall clock average stayed at 0.47 seconds and user+sys at 0.41 seconds, though the total number of system calls as measured by ktrace went from 3454 to 3042. Hammiefilter itself really does very little. Looking at the last ktrace/kdump output, I see 3042 system calls. The hammie.db file isn't opened until line 2717. All the rest before that is startup stuff, the largest chunk of which are nami operations (731) and open (557) calls, most of them involving nonexistent files (as evidenced by seeing only 164 calls to close()). In contrast, only 278 system calls appear to be directly related to manipulating the hammie database. This is still somewhat off-topic for this list (except for the fact that my intention was to get hammiefilter to run faster), so I'll cc python-dev to keep Tim happy, and perhaps mildly irritate Guido by discussing specific apps on python-dev. Skip
Executive summary for python-dev folks seeing this for the first time:
This thread started at
http://mail.python.org/pipermail/spambayes/2003-February/003520.html
Running in a single interpreter loop, I can score roughly 46 messages per second. Running from the shell using hammiefilter.py (which takes a msg on stdin and spits a scored message to stdout) performance drops to roughly 2 messages per second. Neil Schmenenauer noted all the failed open() calls during import lookup, which got me started trying to whittle them down.
Two more things to try before abandoning this quixotic adventure...
It appears $prefix/python23.zip is left in sys.path even if it doesn't exist (Just van Rossum explained to me in a bug report I filed that nonexistent directories might actually be URLs or other weird hacks which import hooks could make use of), so I went with the flow and created it, populating it with the contents of $prefix/python2.3. My averate wallclock time went from 0.5 seconds to 0.47 seconds and user+sys times went from 0.43 seconds to 0.41 seconds. A modest improvement.
One more little tweak. I moved the lib-dynload directory to the front of sys.path (obviously only safe if nothing there appears earlier in sys.path). Wall clock average stayed at 0.47 seconds and user+sys at 0.41 seconds, though the total number of system calls as measured by ktrace went from 3454 to 3042.
Hammiefilter itself really does very little. Looking at the last ktrace/kdump output, I see 3042 system calls. The hammie.db file isn't opened until line 2717. All the rest before that is startup stuff, the largest chunk of which are nami operations (731) and open (557) calls, most of them involving nonexistent files (as evidenced by seeing only 164 calls to close()). In contrast, only 278 system calls appear to be directly related to manipulating the hammie database.
This is still somewhat off-topic for this list (except for the fact that my intention was to get hammiefilter to run faster), so I'll cc python-dev to keep Tim happy, and perhaps mildly irritate Guido by discussing specific apps on python-dev.
Far from it, I wish spambayes well (and wish I could still be involved) :-). The issue seems to be that a moderately sized application takes a long time to start, right? How much of the user+sys time was user, how much was sys? Have you used python -v to see which modules it imports? Long ago I knew Hammie; I believe it reads a possibly large database. How much time does opening +closing the database take? (I presume that the 46 messages/second was not opening the database afresh for each message.) --Guido van Rossum (home page: http://www.python.org/~guido/)
Guido van Rossum
The issue seems to be that a moderately sized application takes a long time to start, right? How much of the user+sys time was user, how much was sys? Have you used python -v to see which modules it imports?
Long ago I knew Hammie; I believe it reads a possibly large database. How much time does opening +closing the database take? (I presume that the 46 messages/second was not opening the database afresh for each message.)
Hammie's since been modified to use a Berkeley database (bsddb3), so there's very little penalty associated with the database at startup time AFAICT. The constant pickling and unpickling of objects may incur some penalty, but I don't think it would account for such a drastic slowdown. Experience (and Tim ;) has tought me not to trust intuition, though. I have very little experience performance tuning Python apps thus far, so I need to defer to someone else to devise an adequate test of the speed hit from pickling. Surely someone's considered using the profiler, right? Neale
Long ago I knew Hammie; I believe it reads a possibly large database. How much time does opening +closing the database take? (I presume that the 46 messages/second was not opening the database afresh for each message.)
Hammie's since been modified to use a Berkeley database (bsddb3), so there's very little penalty associated with the database at startup time AFAICT. The constant pickling and unpickling of objects may incur some penalty, but I don't think it would account for such a drastic slowdown.
Experience (and Tim ;) has tought me not to trust intuition, though. I have very little experience performance tuning Python apps thus far, so I need to defer to someone else to devise an adequate test of the speed hit from pickling. Surely someone's considered using the profiler, right?
Profiler, schmofiler. I use this to time specific operations: t0 = time.clock() <action> t1 = time.clock() print t1-t0 On Unix, clock() measures CPU time. If real time is more important than CPU time, use time.time(). On Windows, clock() is a real time timer that's more precise than time(), so you should always use clock() there. --Guido van Rossum (home page: http://www.python.org/~guido/)
Guido> The issue seems to be that a moderately sized application takes a Guido> long time to start, right? How much of the user+sys time was Guido> user, how much was sys? Have you used python -v to see which Guido> modules it imports? Actually, hammmiefilter is a rather small application, so it seems its runtime is completely dominated by startup costs. It reads a single message on stdin, scores it and writes it out with one or two new headers on stdout. (Perhaps the architecture is just wrong and we should be shipping it off to a long-running process for scoring.) About one-third of user+sys is sys time. Guido> Long ago I knew Hammie; I believe it reads a possibly large Guido> database. How much time does opening +closing the database take? Guido> (I presume that the 46 messages/second was not opening the Guido> database afresh for each message.) The database is now a bsddb hash file. It's no longer a pickle. As I indicated, relatively few system calls (slightly less than 10% of the total) seem to be involved in opening and probing the database. It's probably somewhat invalid to equate number of system calls with application runtime. I redumped my last ktrace file just now with timestamps. Here are some computed intervals: interval time -------- ---- start -> open hammiefilter.pyc 0.071 open hammiefilter.pyc -> open hammie.db 0.516 open hammie.db -> close hammie.db 0.084 close hammie.db -> program end 0.011 The first interval is pure system startup - load interpreter executable, link in shared libraries, etc. The second interval is application startup - import modules, execute module-level code, etc. The third interval is where the application actually does useful work. The last interval is application shutdown. While application startup is not exclusively importing modules, from the looks of things it's a fair chunk. Skip
Skip Montanaro wrote:
My averate wallclock time went from 0.5 seconds to 0.47 seconds and user+sys times went from 0.43 seconds to 0.41 seconds. A modest improvement.
Of course imports are the only part of startup cost. Damn that Amdahl guy. :-) Neil
participants (4)
-
Guido van Rossum -
Neale Pickett -
Neil Schemenauer -
Skip Montanaro