From: Robert Maas, http://tinyurl.com/uh3t
Subject: Timing the execution of a program silently
Date:
Message-ID: <REM-2008oct26-001@Yahoo.Com>
I want to write CGI applications that measure how much time they
take and use that in some way (such as billing the customer). It is
absolutely imperative that nothing whatsoever spew to standard
output or any other output during the running of the program being
measured. Note that I'm using CMU Common Lisp here...
Suppose (foo) is the call to the program I want to time.
So if I say (time (foo)) it runs (foo) and spews out the timing info.
So I need to wrap the form with WITH-OUTPUT-TO-STRING to collect
that spewed output in a string instead. But now when I try to
evaluate that form, CMUCL spews out this warning message:
Warning: TIME form in a non-null environment, forced to interpret.
Compiling entire form will produce more accurate times.
So it looks like I need to build my entire form into a LAMBDA
expression and then compile it, so that all compilation will be
done with, and at runtime there will be no output. But compiling
the form spews out this text:
Compiling LAMBDA (X):
Compiling Top-Level Form:
So if I want to build a form-to-evaluate and compile it and time it
in a CGI environment, then I need to wrap another
WITH-OUTPUT-TO-STRING around the compilation process itself.
Fortunately this doesn't produce another level of spew-out, so I
don't have infinite regress.
So now here's what I ended up with:
First, a function that given a form will wrap it with all sorts of
extra baggage to produce a lambda expression that when called (with
no args) will time the evaluation of the original form and return
both the return value from that form and the string of timing info.
I won't show the hairy code I wrote to perform that wrapping, but
here's the call to that wrapping-function and the return value:
(defparameter g*form '(list 'foo (sleep 2) 'baz))
(defvar g*lamexp)
(setq g*lamexp (form-wrap-time-to-lambda g*form))
=>
(LAMBDA ()
(LET ((F*RETURN-VALUE) (F*TIMING-OUTPUT))
(SETQ F*TIMING-OUTPUT
(WITH-OUTPUT-TO-STRING (*TRACE-OUTPUT*)
(TIME (SETQ F*RETURN-VALUE (LIST 'FOO (SLEEP 2) 'BAZ)))))
(VALUES F*RETURN-VALUE F*TIMING-OUTPUT)))
Now like I said, if I try to call that function right now, it'll
run the JIT compiler, which will spew a warning:
(funcall (eval (list 'function g*lamexp)))
Spew:
Warning: TIME form in a non-null environment, forced to interpret.
Compiling entire form will produce more accurate times.
==>
(FOO NIL BAZ)
"Evaluation took:
2.01 seconds of real time
1.25e-4 seconds of user run time
0.0 seconds of system run time
0 page faults and
0 bytes consed.
"
So instead I define this function (full code shown here):
;Given a lambda expression, compile it silently.
;Return values: The compiled function, and anything written to errout.
(defun lambda-compile-silently (lam)
(prog (fn str)
(setq str (with-output-to-string (*error-output*)
(setq fn (compile nil lam))
))
(return (values fn str))
))
I could have used LET instead of PROG, then I'd need an extra level
of parens around each variable binding, but I wouldn't need the RETURN.
Cliche: "Six of one, half a dozen of the other."
So next I use that to compile the lambda expression I built earlier.
(defvar g*compfun) (defvar g*compout)
(multiple-value-setq (g*compfun g*compout)
(lambda-compile-silently g*lamexp))
No spew from that!!
Next I call the compiled function:
(funcall g*compfun)
=>
(FOO NIL BAZ)
"Evaluation took:
2.0 seconds of real time
5.9999996e-5 seconds of user run time
7.2e-5 seconds of system run time
0 page faults and
0 bytes consed.
"
So now I can write a function that will do all of that without any
spewed output: Build the TIME form and all the other cruft into a
lambda form, compile it silently, and return the two strings of
trace/warning output and pass back the value from the inner form.
The code is a trivial toplevel script:
;Given a form, wrap TIME etc. around it to make a lambda form
; compile it silently, and run it.
;Return values: String of compiler output, String of timing output
; Return value from the form being timed.
(defun form-wrap-timer-lambda-compile-run (form)
(prog (lam compfun compout retval timestr)
(setq lam (form-wrap-time-to-lambda form))
(multiple-value-setq (compfun compout)
(lambda-compile-silently lam))
(multiple-value-setq (retval timestr)
(funcall compfun))
(return (values compout timestr retval))
))
So then calling that function, I get no spew, and 3 return values:
(form-wrap-timer-lambda-compile-run '(list 1 (sleep 1) 3))
=>
"Compiling LAMBDA NIL:
Compiling Top-Level Form:
"
"Evaluation took:
1.0 seconds of real time
2.3e-5 seconds of user run time
3.9e-5 seconds of system run time
0 page faults and
0 bytes consed.
"
(1 NIL 3)
The only thing left to do, other than write various applications
that need timing, is to parse that string of timing information in
order to obtain the various timing values as pure numbers that can
be used in calculations such as billing. I already wrote a parser
for the timing report that PowerLisp produces on my Macintosh, but
I want to re-write such a parser in a more general way that makes
it trivial to adapt it to various formats that might be generated
by timing functions in various implementations of Common Lisp and
other languages.
So my purposes in posting are to ask y'all:
- Have I done precisely what's necessary to achieve the desired
goal, or is there an easier way to accomplish that goal in CMUCL?
- How do other versions of Common Lisp compare regarding ease in
accomplishing this particular task?
- How would this task be accomplished, if it can be accomplished at
all, in other CGI-able languages, especially PHP or Perl or Java?
Robert Maas <·············@teh.intarweb.org> wrote:
+---------------
| I want to write CGI applications that measure how much time they
| take ... absolutely imperative that nothing whatsoever spew to standard
| output or any other output during the running of the program being
| measured. Note that I'm using CMU Common Lisp here...
...
| So if I say (time (foo)) it runs (foo) and spews out the timing info.
| So I need to wrap the form with WITH-OUTPUT-TO-STRING to collect
| that spewed output in a string instead. But now when I try to
| evaluate that form, CMUCL spews out this warning message:
| Warning: TIME form in a non-null environment, forced to interpret.
| Compiling entire form will produce more accurate times.
...[and much more convoluted stuff]...
| - Have I done precisely what's necessary to achieve the desired
| goal, or is there an easier way to accomplish that goal in CMUCL?
+---------------
Well, I think you're making this way harder on yourself than it
really needs to be:
cmu> (defun time-to-string (form)
(with-output-to-string (*standard-output*)
(let ((*error-output* *standard-output*)
(*trace-output* *standard-output*)
(*compile-print* nil))
(eval `(time ,form)))))
TIME-TO-STRING
cmu> (time-to-string (list '+ 1 2))
"
; Evaluation took:
; 0.0f0 seconds of real time
; 6.0f-6 seconds of user run time
; 1.0f-6 seconds of system run time
; 2,967 CPU cycles
; 0 page faults and
; 0 bytes consed.
;
"
cmu>
+---------------
| So it looks like I need to build my entire form into a LAMBDA
| expression and then compile it...
+---------------
No, TIME will compile it for you. You just need to catch the
compilation messages, or suppress them entirely by binding
*COMPILE-PRINT* to NIL (see above).
+---------------
| - How would this task be accomplished, if it can be accomplished at
| all, in other CGI-able languages, especially PHP or Perl or Java?
+---------------
Even with CMUCL, I would try to avoid constantly compiling at
HTTP request time wherever possible, by one or more of these
methods:
1. Don't use TIME at all; instead, time the calls yourself with
a simple wrapper such as this:
cmu> (defun timed-funcall (function &rest args)
(let* ((start-time (get-internal-run-time))
(results (multiple-value-list (apply function args)))
(end-time (get-internal-run-time)))
(values-list (cons (/ (float (- end-time start-time) 1.0f0)
internal-time-units-per-second)
results))))
TIMED-FUNCALL
cmu> (timed-funcall #'expt 2 100)
0.0
1267650600228229401496703205376
cmu> (timed-funcall (lambda () (dotimes (i 100000)) 'done))
0.67
DONE
cmu> (compile nil (lambda () (dotimes (i 100000)) 'done))
; Compiling LAMBDA NIL:
; Compiling Top-Level Form:
#<Function "LAMBDA NIL" {488F4A01}>
NIL
NIL
cmu> (timed-funcall *)
0.0 <== Compiling really helps!! ;-}
DONE
cmu>
Only if you really, *really* need to charge customers at a
finer grain than INTERNAL-TIME-UNITS-PER-SECOND (100/s, on CMUCL)
should you do anything more complicated than the above. And even
in that case, rather than use all the hair of TIME, I would directly
use the same internal CMUCL functions LISP::TIME-GET-SYS-INFO and/or
LISP::CYCLE-COUNT/FLOAT that TIME uses [see "cmucl/src/code/time.lisp"]
in a simple wrapper such as the above.
2. Use a persistent CMUCL daemon process and connect to it from
the web server with either <http://www.cliki.net/mod_lisp>,
if your hosting site allows you to add modules to Apache, or
perhaps <http://rpw3.org/hacks/lisp/cgi_sock.c> if they don't.
*Monster* speedup over running a new CMUCL process for each
CGI request!!
3. Whether or not you can do #2, cache the compilation of your work units,
either in memory (in case #2), or if all else fails then on disk as
FASLs (".x86f", for CMUCL on x86) which you LOAD at CGI time if the
source isn't out-of-date. Note: CMUCL makes this easy with a extension
to LOAD -- (LOAD "foo" :IF-SOURCE-NEWER :COMPILE) is a sort of
mini-"Make" if both "foo.lisp" and "foo.x86f" are visible, just
loading "foo.x86f" unless "foo.lisp" is newer, in which case it
recompiles it first, then loads. [If only one of them exists, it
just silently loads that one. It never *creates* the FASL itself.]
-Rob
-----
Rob Warnock <····@rpw3.org>
627 26th Avenue <URL:http://rpw3.org/>
San Mateo, CA 94403 (650)572-2607
From: Robert Maas, http://tinyurl.com/uh3t
Subject: Re: Timing the execution of a program silently
Date:
Message-ID: <REM-2008oct28-001@Yahoo.Com>
> From: ····@rpw3.org (Rob Warnock)
> I think you're making this way harder on yourself than it
> really needs to be:
> cmu> (defun time-to-string (form)
> (with-output-to-string (*standard-output*)
> (let ((*error-output* *standard-output*)
> (*trace-output* *standard-output*)
> (*compile-print* nil))
> (eval `(time ,form)))))
If that works here, it's the kind of help I was seeking. I tried
it, and indeed it seems to work. I don't have time to try it in a
CGI environment today, but that shouldn't make any difference.
Thanks!
> Even with CMUCL, I would try to avoid constantly compiling at
> HTTP request time wherever possible, by one or more of these
> methods:
> 1. Don't use TIME at all; instead, time the calls yourself with
> a simple wrapper such as this:
> cmu> (defun timed-funcall (function &rest args)
> (let* ((start-time (get-internal-run-time))
> (results (multiple-value-list (apply function args)))
> (end-time (get-internal-run-time)))
> (values-list (cons (/ (float (- end-time start-time) 1.0f0)
> internal-time-units-per-second)
> results))))
That gives me only the elapsed real time. For diagnostic and other
purposes I need to know the user and system run time also. I want
to run a fair comparison between different languages (PHP, Java,
etc.). If some client has been using too much service, I might want
to simply (sleep 30) before responding, and if that 30 seconds are
consumed in intense CPU load rather than system-level
wait-for-timer then it totally defeats the idea of *reducing* the
load on the ISP from a DOS attack.
> Only if you really, *really* need to charge customers at a
> finer grain than INTERNAL-TIME-UNITS-PER-SECOND (100/s, on CMUCL)
> should you do anything more complicated than the above.
For the moment I don't intend to do that. Hundredth of a second,
rounded up if less than one such unit, is fine enough resolution
for my purpose. I want to charge at least some positive quantity
per service request, but for trivial requests I don't want to
charge a full second of CPU, so one internal-time unit i.e. 1/100
second seems good enough.
> 2. Use a persistent CMUCL daemon process ...
That's not allowed here:
<http://www.rawbandwidth.com/services/dialup.html#Shell>
Personal Shell Account: $19.95/mo.
... The Personal Shell Account is like
a Network/Telnet shell, but in addition allows you to dialup with a
terminal program, but not PPP. ...
Unfortunately at the moment I can't find where it specifically says
that detached daemons are not allowed by ordinary users with these
kinds of accounts. Should I ask customer support where that
restriction is posted, or will you trust me that I found it once
and remember it correctly?
> ... if your hosting site allows you to add modules to Apache, ...
I know for sure I'm not personally allowed to tamper with the
Apache server. Whether I could *request* the admin to do it for me
and it'd be done is a big unknown.
> *Monster* speedup over running a new CMUCL process for each
> CGI request!!
Maybe, maybe not. I have noticed that when I request service for
the first time in hours, several seconds go by before I get a
response. But if I make rapid successive requests, they go by
almost instantly. I suspect the entire CMUCL executable is swapped
into RAM and merely needs to be mapped back in, so that only my own
add-on code needs to be re-loaded each time the process runs.
One thing I *am* allowed to do is run SCREEN which maintains a
persistent shell dialup process, with all the sub-processes under
it, so that when I lose my dialup connection I can dial back in and
re-attach to my SCREEN. Currently I have a wait-for-input task
running at all times (except about once every week or two when
there's a system re-start and I lose my SCREEN until I dial back in
to re-establish it). That wait-for-input task is waiting for a FIFO
link from my instant-alert application and my user-login
application. I suppose I could just as well have a full CMUCL
executable sitting there waiting for FIFO or other link from a new
Web-server application. But to avoid defeating the whole idea, the
Web-server application would have to be barebones, a shell script
perhaps, and I'm not sure how a shell script could easily package
all the urlencoded form contents to pass to the waiting persistent
SCREEN-CMUCL application. If mod_perl is installed here, then I
suppose writing a Perl script to package the urlencoded form
contents would be possible and almost as efficient as a shell
script.
> 3. Whether or not you can do #2, cache the compilation of your work units,
> either in memory (in case #2), or if all else fails then on disk as
> FASLs (".x86f", for CMUCL on x86) which you LOAD at CGI time if the
> source isn't out-of-date. Note: CMUCL makes this easy with a extension
> to LOAD -- (LOAD "foo" :IF-SOURCE-NEWER :COMPILE) is a sort of
> mini-"Make" if both "foo.lisp" and "foo.x86f" are visible, just
> loading "foo.x86f" unless "foo.lisp" is newer, in which case it
> recompiles it first, then loads. [If only one of them exists, it
> just silently loads that one. It never *creates* the FASL itself.]
I don't like that idea. First, all compiler warnings go to the
system Apache-server log file which requires ten minutes for me to
find if such warnings occurred mixed in with all the other log
entries that other people's Web pages are generating, and these
obscure LISP messages that don't contain a proper Apache-log
identification bother the sysadmin and other people looking at the
system log. I'd prefer to compile my sources *only* when I'm live
at the terminal to catch problems myself directly. Also I make a
practice of saving my edit frequently, and I'd rather not have the
compiler look at mid-edit and try to compile it just because
somebody in China tried to use my program while I was editing. I'd
rather that user just get a crash that doesn't run the compiler.
Also, if the user aborts the connection while the compiler is
running, an incomplete FASL file may be written, which is newer the
source so my application would be permanently trashed until the
next time I happen to be editing the source to make it show as
newer than the half-FASL file. Also if two users happen to try my
progarm at the same time, both CMUCL invocations will see source
more recent than FASL, so two compilations to same output file will
occur simultaneously, which is bound to fail somehow.
I'd rather compile my own code myself only when I'm pretty sure
it's stable enough that I'm willing to try compiling.
Note: Somebody else suggested I delve into the interals that CMUCL
uses to generate the TIME formatted report. I reject that because a
formatted report is a text string where I could run the same stuff
in other versions of CL and parse each such string in a uniform way
using a comparison between expected and actual output, without
needing to learn the internals for each such implementation. For
example, I have a utility that compares two strings, finding the
longest matching segments recursively, and when no further
sufficiently long matching segments exist then it considers the
non-matching parts to be changes (like in the Unix utility 'diff'
except not forced to be whole lines). It then genenerates a list of
comparisons between the two strings showing parts that are the same
and replaced and inserted and deleted. Given such a report, it
would be easy to write code to automatically locate the appropriate
changes from a canned sample message with totally-bogus
floating-point values and a live actual message to thereby find
where those live floating-point values are shown. Maybe that's
overkill, compared to hand-coding the stuff separately for each
implementation of CL, but it might be more robust and less
per-implementation new-work, so I might try it.
>>>>> "Rob" == Rob Warnock <····@rpw3.org> writes:
Rob> Well, I think you're making this way harder on yourself than it
Rob> really needs to be:
cmu> (defun time-to-string (form)
Rob> (with-output-to-string (*standard-output*)
Rob> (let ((*error-output* *standard-output*)
Rob> (*trace-output* *standard-output*)
Rob> (*compile-print* nil))
Rob> (eval `(time ,form)))))
Rob> TIME-TO-STRING
cmu> (time-to-string (list '+ 1 2))
Here is something from cl-bench. Eric Marsden wrote this, and it
looks like it basically ripped out the guts of time so it returns the
interesting values.
I haven't used it for anything other than running cl-bench, but it
works fine there.
Ray
(defun bench-time (fun times name)
(declare (ignore name))
(let (old-run-utime
new-run-utime
old-run-stime
new-run-stime
old-real-time
new-real-time
old-page-faults
new-page-faults
real-time-overhead
run-utime-overhead
run-stime-overhead
old-bytes-consed
new-bytes-consed
cons-overhead)
;; Calculate the overhead...
(multiple-value-setq
(old-run-utime old-run-stime old-page-faults old-bytes-consed)
(lisp::time-get-sys-info))
;; Do it a second time to make sure everything is faulted in.
(multiple-value-setq
(old-run-utime old-run-stime old-page-faults old-bytes-consed)
(lisp::time-get-sys-info))
(multiple-value-setq
(new-run-utime new-run-stime new-page-faults new-bytes-consed)
(lisp::time-get-sys-info))
(setq run-utime-overhead (- new-run-utime old-run-utime))
(setq run-stime-overhead (- new-run-stime old-run-stime))
(setq old-real-time (get-internal-real-time))
(setq old-real-time (get-internal-real-time))
(setq new-real-time (get-internal-real-time))
(setq real-time-overhead (- new-real-time old-real-time))
(setq cons-overhead (- new-bytes-consed old-bytes-consed))
;; Now get the initial times.
(multiple-value-setq
(old-run-utime old-run-stime old-page-faults old-bytes-consed)
(lisp::time-get-sys-info))
(setq old-real-time (get-internal-real-time))
(dotimes (i times)
(funcall fun))
(multiple-value-setq
(new-run-utime new-run-stime new-page-faults new-bytes-consed)
(lisp::time-get-sys-info))
(setq new-real-time (- (get-internal-real-time) real-time-overhead))
;; returns real user sys consed
(values
(max (/ (- new-real-time old-real-time)
(float internal-time-units-per-second))
0.0)
(max (/ (- new-run-utime old-run-utime) 1000000.0) 0.0)
(max (/ (- new-run-stime old-run-stime) 1000000.0) 0.0)
(max (- new-bytes-consed old-bytes-consed) 0))))
From: William James
Subject: Re: Timing the execution of a program silently
Date:
Message-ID: <gei8na0sf7@enews2.newsguy.com>
Rob Warnock wrote:
> Robert Maas <·············@teh.intarweb.org> wrote:
> +---------------
> > I want to write CGI applications that measure how much time they
> > take ... absolutely imperative that nothing whatsoever spew to
> > standard output or any other output during the running of the
> > program being measured. Note that I'm using CMU Common Lisp here...
> ...
> > So if I say (time (foo)) it runs (foo) and spews out the timing
> > info. So I need to wrap the form with WITH-OUTPUT-TO-STRING to
> > collect that spewed output in a string instead. But now when I try
> > to evaluate that form, CMUCL spews out this warning message:
> > Warning: TIME form in a non-null environment, forced to
> > interpret. Compiling entire form will produce more accurate
> > times.
> ...[and much more convoluted stuff]...
> > - Have I done precisely what's necessary to achieve the desired
> > goal, or is there an easier way to accomplish that goal in
> > CMUCL?
> +---------------
>
> Well, I think you're making this way harder on yourself than it
> really needs to be:
>
> cmu> (defun time-to-string (form)
> (with-output-to-string (*standard-output*)
> (let ((*error-output* *standard-output*)
> (*trace-output* *standard-output*)
> (*compile-print* nil))
> (eval `(time ,form)))))
>
> TIME-TO-STRING
> cmu> (time-to-string (list '+ 1 2))
>
> "
> ; Evaluation took:
> ; 0.0f0 seconds of real time
> ; 6.0f-6 seconds of user run time
> ; 1.0f-6 seconds of system run time
> ; 2,967 CPU cycles
> ; 0 page faults and
> ; 0 bytes consed.
> ;
> "
require "benchmark"
N = 999_999
string = Benchmark.measure{ Array.new(N){rand N} }.to_s
p string
--- output ---
" 2.052000 0.000000 2.052000 ( 2.113000)\n"
Robert Maas, http://tinyurl.com/uh3t wrote:
> I want to write CGI applications that measure how much time they
> take and use that in some way (such as billing the customer). It is
> absolutely imperative that nothing whatsoever spew to standard
> output or any other output during the running of the program being
> measured. Note that I'm using CMU Common Lisp here...
>
> Suppose (foo) is the call to the program I want to time.
> So if I say (time (foo)) it runs (foo) and spews out the timing info.
> So I need to wrap the form with WITH-OUTPUT-TO-STRING to collect
> that spewed output in a string instead. But now when I try to
> evaluate that form, CMUCL spews out this warning message:
> Warning: TIME form in a non-null environment, forced to interpret.
> Compiling entire form will produce more accurate times.
> So it looks like I need to build my entire form into a LAMBDA
> expression and then compile it, so that all compilation will be
> done with, and at runtime there will be no output. But compiling
> the form spews out this text:
> Compiling LAMBDA (X):
> Compiling Top-Level Form:
> So if I want to build a form-to-evaluate and compile it and time it
> in a CGI environment, then I need to wrap another
> WITH-OUTPUT-TO-STRING around the compilation process itself.
> Fortunately this doesn't produce another level of spew-out, so I
> don't have infinite regress.
>
> So now here's what I ended up with:
>
> First, a function that given a form will wrap it with all sorts of
> extra baggage to produce a lambda expression that when called (with
> no args) will time the evaluation of the original form and return
> both the return value from that form and the string of timing info.
> I won't show the hairy code I wrote to perform that wrapping, but
> here's the call to that wrapping-function and the return value:
> (defparameter g*form '(list 'foo (sleep 2) 'baz))
> (defvar g*lamexp)
> (setq g*lamexp (form-wrap-time-to-lambda g*form))
> =>
> (LAMBDA ()
> (LET ((F*RETURN-VALUE) (F*TIMING-OUTPUT))
> (SETQ F*TIMING-OUTPUT
> (WITH-OUTPUT-TO-STRING (*TRACE-OUTPUT*)
> (TIME (SETQ F*RETURN-VALUE (LIST 'FOO (SLEEP 2) 'BAZ)))))
> (VALUES F*RETURN-VALUE F*TIMING-OUTPUT)))
>
> Now like I said, if I try to call that function right now, it'll
> run the JIT compiler, which will spew a warning:
> (funcall (eval (list 'function g*lamexp)))
> Spew:
> Warning: TIME form in a non-null environment, forced to interpret.
> Compiling entire form will produce more accurate times.
> ==>
> (FOO NIL BAZ)
> "Evaluation took:
> 2.01 seconds of real time
> 1.25e-4 seconds of user run time
> 0.0 seconds of system run time
> 0 page faults and
> 0 bytes consed.
> "
>
> So instead I define this function (full code shown here):
>
> ;Given a lambda expression, compile it silently.
> ;Return values: The compiled function, and anything written to errout.
> (defun lambda-compile-silently (lam)
> (prog (fn str)
> (setq str (with-output-to-string (*error-output*)
> (setq fn (compile nil lam))
> ))
> (return (values fn str))
> ))
> I could have used LET instead of PROG, then I'd need an extra level
> of parens around each variable binding, but I wouldn't need the RETURN.
> Cliche: "Six of one, half a dozen of the other."
>
> So next I use that to compile the lambda expression I built earlier.
> (defvar g*compfun) (defvar g*compout)
> (multiple-value-setq (g*compfun g*compout)
> (lambda-compile-silently g*lamexp))
> No spew from that!!
>
> Next I call the compiled function:
> (funcall g*compfun)
> =>
> (FOO NIL BAZ)
> "Evaluation took:
> 2.0 seconds of real time
> 5.9999996e-5 seconds of user run time
> 7.2e-5 seconds of system run time
> 0 page faults and
> 0 bytes consed.
> "
>
> So now I can write a function that will do all of that without any
> spewed output: Build the TIME form and all the other cruft into a
> lambda form, compile it silently, and return the two strings of
> trace/warning output and pass back the value from the inner form.
> The code is a trivial toplevel script:
>
> ;Given a form, wrap TIME etc. around it to make a lambda form
> ; compile it silently, and run it.
> ;Return values: String of compiler output, String of timing output
> ; Return value from the form being timed.
> (defun form-wrap-timer-lambda-compile-run (form)
> (prog (lam compfun compout retval timestr)
> (setq lam (form-wrap-time-to-lambda form))
> (multiple-value-setq (compfun compout)
> (lambda-compile-silently lam))
> (multiple-value-setq (retval timestr)
> (funcall compfun))
> (return (values compout timestr retval))
> ))
>
> So then calling that function, I get no spew, and 3 return values:
> (form-wrap-timer-lambda-compile-run '(list 1 (sleep 1) 3))
> =>
> "Compiling LAMBDA NIL:
> Compiling Top-Level Form:
> "
> "Evaluation took:
> 1.0 seconds of real time
> 2.3e-5 seconds of user run time
> 3.9e-5 seconds of system run time
> 0 page faults and
> 0 bytes consed.
> "
> (1 NIL 3)
>
> The only thing left to do, other than write various applications
> that need timing, is to parse that string of timing information in
> order to obtain the various timing values as pure numbers that can
> be used in calculations such as billing. I already wrote a parser
> for the timing report that PowerLisp produces on my Macintosh, but
> I want to re-write such a parser in a more general way that makes
> it trivial to adapt it to various formats that might be generated
> by timing functions in various implementations of Common Lisp and
> other languages.
>
>
> So my purposes in posting are to ask y'all:
> - Have I done precisely what's necessary to achieve the desired
> goal, or is there an easier way to accomplish that goal in CMUCL?
> - How do other versions of Common Lisp compare regarding ease in
> accomplishing this particular task?
With allegrocl I macroexpanded time:
(macroexpand '(time (print "hi mom")))
-> (EXCL::TIME-A-FUNCALL #'EXCL::TIME-REPORT #'(LAMBDA NIL (PRINT "hi
mom")))
Then I clicked on time-report and in the status bar saw the arg list:
tgcu tgcs tu ts tr scons sother static
Since this:
(time (print "hi mom"))
Produces this:
; cpu time (non-gc) 0 msec user, 0 msec system
; cpu time (gc) 0 msec user, 0 msec system
; cpu time (total) 0 msec user, 0 msec system
; real time 0 msec
; space allocation:
; 17 cons cells, 344 other bytes, 0 static bytes
I was able to deduce what each parameter was. It was then quick work to
supply my own "report" function which did nothing of the kind, rather it
stashed the values away for subsequent consumption.
hth,kt
On Sun, 26 Oct 2008 19:39:40 -0700, Robert Maas, http://tinyurl.com/uh3t
wrote:
> I want to write CGI applications that measure how much time they
> take and use that in some way (such as billing the customer).
Write a FFI binding to getrusage(2) and use the ru_utime and ru_stime
slots of struct rusage or use osicat(http://common-lisp.net/project/
osicat/git/osicat.git).
--
Stelian Ionescu a.k.a. fe[nl]ix
Quidquid latine dictum sit, altum videtur.