Re: [Spyce-users] profiling a spyce page

[Rimon B. <barr@CS.Cornell.EDU>]

>Can anyone suggest a good way to profile spyce pages? I'm being forced to
>use CGI on my ISP's server, I'd like to at the very least have a "this
>page took x seconds to generate" at the bottom. Should I spend some time
>hacking on spyce itself?

Fahd,

What you are asking is a little under-specified... Let me explain why, and
try to help. First, I don't think that you are in need of a profile (i.e.
the amount of time spent on different functions and operations), but
simply in the total amount of time elapsed to generate a page. I've
actually been thinking about some kind of detailed profiler/debugger and
this is not what you are in need of.

But even just measuring the total processing time is tricky, for the
reason that it's not clear what you want to measure. Here is a rough
sketch of what happens from the point that the users clicks on their mouse
until they see their next web page.

  A - client browser encodes request
  B - client machine transmits request
  C - server machine receives request
  D - server machine spawns new CGI process
  E - Python interpretter loaded and initialized
  F - Spyce engine loaded and initialized
  G - Spyce file read and compiled
  H - Spyce code executed and response generated
  I - Response sent to webserver
  J - server machine transmits response
  K - client machine receives response
  L - client machine renders response

Ideally, you would like to measure A-L. It's possible in the following
way. You have some javascript in your original page that takes a timestamp
on the client machine, and encodes it in the request. It is returned back
in the response. You then subtract this time from the current time, to
compute the time elapsed and display it using JavaScript. This requires
JavaScript, of course, and performs the computation on the client, but it
will give you the TOTAL elapsed time.

Now, you are probably referring to some smaller fraction of the process as
your "total", perhaps C-J (the server time). You can't compute that
number. You need to be the webserver to do this... Plus, it's a chicken
and an egg problem. You need to insert the time in the request, but the
request has already been sent once you know the value to insert. So, we
need to narrow things a little further.

Let total be C-H (near the end of H... the time when you insert the time
stamp). That's tough too. You need to know the time of C, and as a CGI
process you have no way of knowing this, unless it is passed to you in the
CGI environment. You could possibly write an Apache module for this, but
it seems excessive.

If you're to look for D-H, then you can request the CPU-time of the
current process from the system. On Unix, just call time.clock(), and it
will give you number of CPU seconds that were used by this process. While
these are not real seconds, but rather the amount of CPU seconds that this
process has used, it is arguably a better measure, especially when you
have simultaneous requests. This is likely what Google uses to compute its
search time. On Windows, you will have difficulty, because the
time.clock() returns the number of CPU seconds since the *previous* call.
I'm not sure what it returns on the first call.

Now, if we narrow it further to F-H (which is still a reasonable thing to
do), I could add a server startup time field to the Spyce server object,
which you could use to compute elapsed time in the Spyce.

Next, we could narrow it further to G-H... I would simply add a request
timestamp field to the internal request object, and the same applies. Note
that both of these would add overhead to an already heavy process, and it
would not be something that you could turn off for requests that do not
need it.

Lastly, we have the time time of H itself, the actual processing time of
the Spyce. Usually that is going to be really short (I can process
hundreds of Spyce requests per second, without the initialization steps),
unless you are doing some complicated or expensive operations, such as
database requests. This is the easiest alternative, if you are satisfied
with the approach. Simply write a module called, say, "timing". Declare
timing.start() to store the current time. Then declare a method
timing.elapsed to return the delta. Import timing into your Spyce, and
simply call timing.elapsed() near the end of your Spyce file.

I hope that helps. Let me know what approach you would like to follow, and
we'll take it from there.

All the best,
Rimon.