I am using allgero common lisp 6.2 on readhat linux 9.0
I called a function within the time macro and i got the
following output
; cpu time (non-gc) 10 msec user, 0 msec system
; cpu time (gc) 0 msec user, 0 msec system
; cpu time (total) 10 msec user, 0 msec system
; real time 2 msec
; space allocation:
; 5 cons cells, 56 other bytes, 0 static bytes
I exceuted the same function again and i got the following output
; 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 1 msec
; space allocation:
; 5 cons cells, 56 other bytes, 0 static bytes
what might be the problem?
Explain me each line of output
On Tue, Sep 16, 2003 at 10:18:10PM -0700, Venkat wrote:
> ; cpu time (non-gc) 10 msec user, 0 msec system
> ; cpu time (gc) 0 msec user, 0 msec system
> ; cpu time (total) 10 msec user, 0 msec system
> ; real time 2 msec
> ; space allocation:
> ; 5 cons cells, 56 other bytes, 0 static bytes
> I exceuted the same function again and i got the following output
> ; 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 1 msec
> ; space allocation:
> ; 5 cons cells, 56 other bytes, 0 static bytes
> what might be the problem?
There is no problem. Your function runs so fast, that it runs in less
than 10 msec. Your system's timer has a resolution of 10 msec, very
likely. This means that it cannot measure durations smaller than 10
msec with any reliability.
An easy way to get more useful readings is to run your function in a
loop many thousands of times.
> Explain me each line of output
cpu time is the amount of time given to your program, by the OS, that
you are using the processor. The distinction between (gc) and (non-gc)
is made by Allegro, to tell you how much cpu time the garbage collector
took, versus how much cpu time your function took. real time is how
much apparent time passed according to your real-world perspective.
--
; Matthew Danish <·······@andrew.cmu.edu>
; OpenPGP public key: C24B6010 on keyring.debian.org
; Signed or encrypted mail welcome.
; "There is no dark side of the moon really; matter of fact, it's all dark."
············@yahoo.com (Venkat) wrote in message news:<···························@posting.google.com>...
> I am using allgero common lisp 6.2 on readhat linux 9.0
> I called a function within the time macro and i got the
> following output
>
> ; cpu time (non-gc) 10 msec user, 0 msec system
> ; cpu time (gc) 0 msec user, 0 msec system
> ; cpu time (total) 10 msec user, 0 msec system
> ; real time 2 msec
> ; space allocation:
> ; 5 cons cells, 56 other bytes, 0 static bytes
>
>
> I exceuted the same function again and i got the following output
>
>
> ; 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 1 msec
> ; space allocation:
> ; 5 cons cells, 56 other bytes, 0 static bytes
>
> what might be the problem?
I personally don't have a problem with this, so I'll try to guess what
yours was: the timings are different. Given that they're so short (so
that levels of accuracy are at least the same magnitude as the thing
you're measuring), and given also the non-determinacy of your system
(the OS is multi-threaded; also paging can make things take longer
first time you run them), this should come as no suprise.
You need to time something that takes longer. Try
(compile (defun test (n) (dotimes (i n) (test-my-actual-code))))
and (test 1000) / (test 1000000), depending on whether the #\m in msec
stands for milliseconds or microseconds. If you sit watching paint dry
for less than 5-10 seconds, add a zero and try again.
Hopefully you'll end up with timings which are relatively stable,
with the random noise less significant than the timings themselves.
If you're still getting significant variations, I suggest you post
your code and someone may tell you why its time is unstable. But I
think that's unlikely.
If you can't extract your function and run it in a tight loop like the
above, you'll have to be more subtle. Look up "Internal Time" (section
25.1.4.3) in the ANSI spec.
> Explain me each line of output
Hopefully by now you've had time to locate your ACL documentation
set. However: the timings differentiate between the garbage collector
("GC") and your program. They also differentiate between time in which
the lisp system was actively burning the CPU ("user") and time spent
by the OS, eg paging.
I am at a loss to explain what "real time" is, given that it appears
to be less than the time spent in CPU.
- nick
>>>>> "Nick" == Nick Levine <···@ravenbrook.com> writes:
Nick> ············@yahoo.com (Venkat) wrote in message news:<···························@posting.google.com>...
>> I am using allgero common lisp 6.2 on readhat linux 9.0
>> I called a function within the time macro and i got the
>> following output
>>
>> ; cpu time (non-gc) 10 msec user, 0 msec system
>> ; cpu time (gc) 0 msec user, 0 msec system
>> ; cpu time (total) 10 msec user, 0 msec system
>> ; real time 2 msec
>> ; space allocation:
>> ; 5 cons cells, 56 other bytes, 0 static bytes
>>
>>
>> I exceuted the same function again and i got the following output
>>
>>
>> ; 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 1 msec
>> ; space allocation:
>> ; 5 cons cells, 56 other bytes, 0 static bytes
>>
>> what might be the problem?
Nick> I personally don't have a problem with this, so I'll try to guess what
I do, sort of. The total real time of 2 msec is less than the total
CPU time. I wish I had a computer that could do that.
Ray
Raymond Toy <···@rtp.ericsson.se> writes:
> >>>>> "Nick" == Nick Levine <···@ravenbrook.com> writes:
>
> Nick> ············@yahoo.com (Venkat) wrote in message news:<···························@posting.google.com>...
> >> I am using allgero common lisp 6.2 on readhat linux 9.0
> >> I called a function within the time macro and i got the
> >> following output
> >>
> >> ; cpu time (non-gc) 10 msec user, 0 msec system
> >> ; cpu time (gc) 0 msec user, 0 msec system
> >> ; cpu time (total) 10 msec user, 0 msec system
> >> ; real time 2 msec
> >> ; space allocation:
> >> ; 5 cons cells, 56 other bytes, 0 static bytes
> >>
> >>
> >> I exceuted the same function again and i got the following output
> >>
> >>
> >> ; 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 1 msec
> >> ; space allocation:
> >> ; 5 cons cells, 56 other bytes, 0 static bytes
> >>
> >> what might be the problem?
>
> Nick> I personally don't have a problem with this, so I'll try to guess what
>
> I do, sort of. The total real time of 2 msec is less than the total
> CPU time. I wish I had a computer that could do that.
Get a dual processor box. (Not saying that's what's happening here.)
-Peter
--
Peter Seibel ·····@javamonkey.com
Lisp is the red pill. -- John Fraser, comp.lang.lisp
In article <··············@edgedsp4.rtp.ericsson.se>,
Raymond Toy <···@rtp.ericsson.se> wrote:
> Nick> I personally don't have a problem with this, so I'll try to
> Nick> guess what
>
> I do, sort of. The total real time of 2 msec is less than the total
> CPU time. I wish I had a computer that could do that.
I believe what you're seeing here is a difference in timing methods.
The Unix "process time" measurements are statistical. Every timer tick
(which is probably 100Hz in the Linux the OP was using), the kernel
notes which process it was executing at the time, notes whether it was
running user or system code, and increments a counter giving 10ms (one
time period at 100Hz) of time to that process.
Over long time periods this method gives good statistical averages. And
it is almost free, which is good since the system is doing it all the
time. For short time periods there is not enough samples to get good
data--for times under 10ms real time you will either get 0ms or 10ms
process time.
See the times(2) man page if you have access to a Unix.
The "real time" is an absolute measurement. The wall clock time is
measured before the function begins, and after it ends. Then subtract.
This has a far finer granularity than process time because you can
usually get wall clock time down to microseconds.
So probably the OP's function, which takes somewhere between 1 and 2
milliseconds to run, just happened to get a kernel timer tick in it the
first time, and as such got 10ms of process time allocated. The second
run it didn't.
-bcd
--
*** Brian Downing <bdowning at lavos dot net>