OOREXX 3.2 Elapsed timer
Dave
I am trying to use the TIME function with the elapsed time ("R")
option.
The code is in a loop, and every 1000 rows it:
el = TIME("R");
say '* Processing row: ' rowCount 'Time: ' time("N") 'Elapsed: 'el;
Yet the elapsed time is showing as if I used the "E" parameter. Here
is a sample of the results.
* Processing row: 1000 Time: 17:19:40 Elapsed: 41.203000
* Processing row: 2000 Time: 17:20:20 Elapsed: 80.858000
* Processing row: 3000 Time: 17:20:58 Elapsed: 118.842000
* Processing row: 4000 Time: 17:21:35 Elapsed: 156.529000
* Processing row: 5000 Time: 17:22:21 Elapsed: 202.372000
Can anyone tell me what I am missing?
Thanks,
Dave
danfan46
Hi!
The same code executed in OOrexx 4.0 on Linux
returns
* Processing row: 0 Time: 07:03:47 Elapsed: 0
* Processing row: 1000 Time: 07:03:57 Elapsed: 10.000604
* Processing row: 2000 Time: 07:04:07 Elapsed: 10.000597
* Processing row: 3000 Time: 07:04:17 Elapsed: 10.000552
* Processing row: 4000 Time: 07:04:27 Elapsed: 10.000573
* Processing row: 5000 Time: 07:04:37 Elapsed: 10.000556
* Processing row: 6000 Time: 07:04:47 Elapsed: 10.000560
* Processing row: 7000 Time: 07:04:57 Elapsed: 10.000563
* Processing row: 8000 Time: 07:05:07 Elapsed: 10.000597
* Processing row: 9000 Time: 07:05:17 Elapsed: 10.000554
Maybe you should upgrade?
/dg
Dave
dg, thanks for the response. I thought you were on to something when I
installed 4.0, and saw this in CHANGES.txt
* 1856576 - bug with multiple time('r') calls on same instruction.
Alas, no such luck. Ran the pgm with the same bad results.
* Processing row: 1000 Time: 08:26:50 Elapsed: 39.733000
* Processing row: 2000 Time: 08:27:18 Elapsed: 67.374000
* Processing row: 3000 Time: 08:27:46 Elapsed: 95.545000
* Processing row: 4000 Time: 08:28:15 Elapsed: 124.435000
* Processing row: 5000 Time: 08:28:53 Elapsed: 161.997000
Any other suggestions?
Dave
Swifty
> Any other suggestions?
> Dave
According to the original REXX specification, time('R') will always
return the elapsed time since the FIRST call to time('E') or time('R')
so what you are seeing looks about right to me. An ever increasing time.
If you want to see the elapsed time for each of the groups of 1000 rows,
then use time('E'), which returns the elapsed time since the MOST RECENT
call to time('E') or time('R')
I hadn't known this, but it is very handy, as it allows you to measure
the elapsed time of a complete function (or the program) whilst
measuring the elapsed times of parts of the function (or program).
--
Steve Swift
http://www.swiftys.org.uk/swifty.html
http://www.ringers.org.uk
Jeremy Nicoll - news posts
... problems
Win XP Pro SP3, ooRexx 4.0.0
By coincidence I've been trying to evaluate two ways of doing some
processing of files, using various sysfiletree() calls, looking at whether
the code I need is easier written around one sysfiletree() call that
recurses into subdirs and produces a monster list of files which is harder
to process the way I want, vv multiple sysfiletree() calls which only look
at subsets of the whole problem.
I wondered about speed as well as my code's complexity, and shoved in some
time() calls. And oddly I kept being told that some of the sysfiletree()
calls were executing instantly, ie elapsed times of 0.
So I wrote some tests to see if time("R") and time("E") worked the way they
are meant to. Irritatingly they seemed to... The code I'd been trying to
evaluate had various nested loops and the time() calls had not all been at
the same levels of nesting, so I tried to test that too... and still it all
worked fine.
Then I put some sysfiletree() calls between the time() calls. Now it all
goes pear-shaped. From code:
-----------------------------------------------------------------------
clockbeg = time("Reset")
list9 = sysfiletree("C:\", "nine.", "D")
clockend = time("Elapse")
say "Delay 9: clockbeg" clockbeg "clockend" clockend ,
"sysfiletree rc="list9 "#="nine.0
say
clockbeg = time("Reset")
list10 = sysfiletree("C:\", "ten.", "D")
clockend = time("Elapse")
say "Delay 10: clockbeg" clockbeg "clockend" clockend ,
"sysfiletree rc="list10 "#="ten.0
say
-----------------------------------------------------------------------
I get output:
Delay 9: clockbeg 0 clockend 0.015000 sysfiletree rc=0 #=15
Delay 10: clockbeg 0.015000 clockend 0 sysfiletree rc=0 #=15
It appears the 2nd sysfiletree executed instantly. Did it really?
(I have also run the same test with different sysfiletree targets and it
also has the problem. It's not the case that the second sysfiletree()
returns instantly because it's a duplicate of the first one, and in any case
it had a different stem to populate.)
--
Jeremy C B Nicoll - my opinions are my own.
Email sent to my from-address will be deleted. Instead, please reply
to newsre...@wingsandbeaks.org.uk replacing "nnn" by "284".
Dave
Interesting; the 4.0 reference describes the opposite:
"You can use the TIME function to measure real (elapsed) time
intervals. On the first call in a program to
TIME("E") or TIME("R"), the elapsed-time clock is started, and either
call returns 0. From then on, calls to
TIME("E") and TIME("R") return the elapsed time since that first call
or since the last call to TIME("R")."
But I did try using "E" as well, with the same results. In the end I
just calculated the elapsed seconds for each iteration myself.
Dave
Dave
<jn.nntp.scrap...@wingsandbeaks.org.uk> wrote:
Initially I also was seeing 0 returned on all of my TIME("R") calls. I
had the first TIME("E") coded in a initialization sub routine. Moved
it to the main rountine, and suddenly times worked, abeit not they way
I expect "R" to work. Since many of my calls to TIME("R") are in sub
routines or functions, I expect this has something to do with this
behavior.
Dave
Arthur T.
Message-ID:<gemini.ktof2...@wingsandbeaks.org.uk.invalid>,
Jeremy Nicoll - news posts <jn.nntp....@wingsandbeaks.org.uk>
wrote:
>Then I put some sysfiletree() calls between the time() calls. Now it all
>goes pear-shaped.
Using directory lookups to test timing routines is not a good
idea under Windows. The system caches directory information.
Unless you allow a lot of time between and/or do enough
memory-intensive word to flush the buffer, the directory information
will be read from memory.
Chances are that if you rerun your program, the first
sysfiletree will also get an elapsed time of zero.
--
Arthur T. - ar23hur "at" intergate "dot" com
Looking for a z/OS (IBM mainframe) systems programmer position
Swifty
> From then on, calls to TIME("E") and TIME("R") return the elapsed
> time since that first call or since the last call to TIME("R")."
That is the same way it is described in my original reference. I admit
that all earlier implementations work the other way around.
This will be a bit of a migration headache for people who have used the
way it actually worked until 4.0
Arthur T.
Message-ID:<cf4a7389-7d9f-44ff...@d10g2000yqh.googlegroups.com>,
Dave <da...@diasoftware.ca> wrote:
>Initially I also was seeing 0 returned on all of my TIME("R") calls. I
>had the first TIME("E") coded in a initialization sub routine. Moved
>it to the main rountine, and suddenly times worked, abeit not they way
>I expect "R" to work. Since many of my calls to TIME("R") are in sub
>routines or functions, I expect this has something to do with this
>behavior.
From IBM's documentation for TSO REXX:
The clock is saved across internal routine calls, which is to say
that an internal routine inherits the time clock its caller started.
Any timing the caller is doing is not affected, even if an internal
routine resets the clock.
Poor wording. They say it's saved, but only imply (correctly)
that it's restored on return from the subroutine.
Jeremy Nicoll - news posts
> In
> Message-ID:<gemini.ktof2...@wingsandbeaks.org.uk.invalid>,
> Jeremy Nicoll - news posts <jn.nntp....@wingsandbeaks.org.uk>
> wrote:
>
> >Then I put some sysfiletree() calls between the time() calls. Now it all
> >goes pear-shaped.
>
> Using directory lookups to test timing routines is not a good
> idea under Windows. The system caches directory information.
> Unless you allow a lot of time between and/or do enough
> memory-intensive word to flush the buffer, the directory information
> will be read from memory.
>
> Chances are that if you rerun your program, the first
> sysfiletree will also get an elapsed time of zero.
I repeated the tests often and I never get a zero the first time. I did
also say:
(I have also run the same test with different sysfiletree targets and it
also has the problem. It's not the case that the second sysfiletree()
returns instantly because it's a duplicate of the first one, and in any case
it had a different stem to populate.)
- or do you think all of that gets done in 1 micro seconds?
Arthur T.
Message-ID:<gemini.ktqp6...@wingsandbeaks.org.uk.invalid>,
>I repeated the tests often and I never get a zero the first time. I did
>also say:
>
>(I have also run the same test with different sysfiletree targets and it
>also has the problem. It's not the case that the second sysfiletree()
>returns instantly because it's a duplicate of the first one, and in any case
>it had a different stem to populate.)
>
>- or do you think all of that gets done in 1 micro seconds?
Well, I'm running Regina on Windows. The minimum number
time('e') can be (other than zero) seems to be 15 milliseconds.
Also, since it's the operating system that caches directory
info, if you've done a DIR command on one of the other targets, its
data is in memory.
Before my first response, I *did* run your code. It often got
zero elapsed. And, yes, I modified the code to do sysfiletree on
different disks and still got zero as often as .015.
LesK
wording there!
Les (Change Arabic to Roman to email me)
LesK
as a bug. Are you sure?
Les (Change Arabic to Roman to email me)
Dave
forward. But the "R" option clearly does not reset the elapsed timer
in my code where its used cross multiple sub routines.
Dave
Swifty
> Before my first response, I *did* run your code. It often got
> zero elapsed. And, yes, I modified the code to do sysfiletree on
> different disks and still got zero as often as .015.
ON a system with modern disks, a sysfiletree might often complete in
less than 15mS.
I also noticed that time('E') doesn't seem to return values between 0
and 0.015 - strange (IBM Object REXX under Windows XP). On our Linux
server, time('E') seems accurate to a microsecond, but I may be thinking
of the granularity of time('L').
Jeremy Nicoll - news posts
> Dave wrote:
> > From then on, calls to TIME("E") and TIME("R") return the elapsed
> > time since that first call or since the last call to TIME("R")."
>
> That is the same way it is described in my original reference. I admit
> that all earlier implementations work the other way around.
>
> This will be a bit of a migration headache for people who have used the
> way it actually worked until 4.0
I think the way it's described is somewhat ambiguous.
In my 1990 Cowlishaw Rexx book it says:
"On the first call in a program to time('E') or time('R'), the elapsed
time clock is started and either call would return 0. From then on,
calls to time('E') and to time('R') will return the elapsed time
since that first call or since the last call to time('R')."
The ooRexx 4.0.0 rexxref manual says a virtually identical thing:
"On the first call in a program to time('E') or time('R'), the elapsed
time clock is started and either call returns 0. From then on,
calls to time('E') and time('R') return the elapsed time since that
first call or since the last call to time('R')."
The ambiguity I see is in what the 'or' in the last sentence actually
implies in that sentence. Is it that:
A) calls to either time('E') or time('R') will both return the same
result.
The result of the call is how much time has elapsed since the
most recent prior zeroing of the clock.
The most recent prior zeroing of the clock will either be the very
first one in the program or a later one as a result of other
time('R') calls.
If the call was a time('R') one the clock is reset, which does not
affect this call but will affect future ones.
B) calls to either time('E') or time('R') will return different
results.
Time('E') returns the elapsed time since the first call (ie
since the elapsed clock was zeroed for the first time).
Time('R') will return the elapsed time since the most recent
call to time('R'), and then re-zero the clock.
I think it means A.
To me, B only makes sense if there's two separate elapsed time clocks. Both
would be zeroed on the first 'starting' time('E' or 'R') call in a program.
After that time('E') calls would always tell you the time elapsed from the
'starting' call, while time('R') would tell you times since the most recent
zeroing (starting or otherwise).
I think the only difference between 'E' and 'R' calls is that after deciding
what result to return [how long ago the elapsed clock was zeroed], the 'R'
call (re)zeros the clock.
The book has an example:
time('E') == 0 /* the first call */
/* pause of 1 sec */
time('E') == 1.002345 /* ish */
/* pause of 1 sec */
time('R') == 2.004690 /* ish */
/* pause of 1 sec */
time('R') == 1.002345 /* ish */
The ooRexx 4.0.0 rexxref.pdf manual shows a similar set of results (0, 1.02,
2.03, 1.05 seconds which tells me that the effect is not supposed to have
changed).
People elsewhere in this thread are saying that it's now right that
successive calls to time('R') provide ever-increasing answers, but that is
explicitly NOT what this example shows (otherwise the last result would be a
bit more than 3). The example has always meant, to me:
time('E') == 0 start clock
/* pause of 1 sec */
time('E') == 1.002345 show it 1 sec after start
/* pause of 1 sec */
time('R') == 2.004690 show it 2 secs after start then zero it
/* pause of 1 sec */
time('R') == 1.002345 show it 3 secs after start but only
1 sec after most recent reset
Jeremy Nicoll - news posts
> Dave wrote:
> > Any other suggestions?
> > Dave
>
> According to the original REXX specification, time('R') will always
> return the elapsed time since the FIRST call to time('E') or time('R')
> so what you are seeing looks about right to me. An ever increasing time.
I think you've misinterpreted the way it's worded - see another post I just
made. Does "original REXX specification" contain an example that supports
your interpretation?
Swifty
> I think you've misinterpreted the way it's worded - see another post I just
> made. Does "original REXX specification" contain an example that supports
> your interpretation?
Because I can't be sure of the precise meaning of the section quoted
from the 1990 version of "The REXX Language" (quoted above) I decided to
test what time(E) and time(R) actually do.
As far as I can tell, they behave the same under oorexx 4 as they do
under IBM Object REXX 3.2, and that is that time(E) and time(R) both
return the elapsed time, but time(R) also resets it to zero.
Whatever I said earlier was wrong.
Jeremy Nicoll - news posts
> In
> Message-ID:<gemini.ktqp6...@wingsandbeaks.org.uk.invalid>,
> Jeremy Nicoll - news posts <jn.nntp....@wingsandbeaks.org.uk>
> wrote:
>
> >I repeated the tests often and I never get a zero the first time. I did
> >also say:
> >
> >(I have also run the same test with different sysfiletree targets and it
> > also has the problem. It's not the case that the second sysfiletree()
> > returns instantly because it's a duplicate of the first one, and in any
> > case it had a different stem to populate.)
> >
> >- or do you think all of that gets done in 1 micro seconds?
>
> Well, I'm running Regina on Windows. The minimum number
> time('e') can be (other than zero) seems to be 15 milliseconds.
>
> Also, since it's the operating system that caches directory
> info, if you've done a DIR command on one of the other targets, its
> data is in memory.
>
> Before my first response, I *did* run your code. It often got
> zero elapsed. And, yes, I modified the code to do sysfiletree on
> different disks and still got zero as often as .015.
I owe you an apology; after running lots more tests I can say that I have
now seen the "zero the first time" that I said wasn't happening.
I was over-influenced I think by the impression that populating a different
stem each time would take more than 1 micro second. (On my 1.8GHz machine,
one microsecond presumably equates to 1800 processor cycles and I'm still a
bit surprised that that's enough to get a new stem created, but it must be.
I wonder how big a stem one needs to create to exceed that?)
On the other hand, like others I have seen apart from answers of 0, a
tendency for minimum non-zero results around 0.015000 seconds, which
(1/0.015) is 1/66.6666667 of a second. That's a suspicious fraction to my
eyes.
Also tests running loops with SysSleep(0.01) in them very consistently show
each iteration taking 0.015000 or 0.016000 seconds, all of which suggests
that we're a long way from microsecond measurement even if the 'accuracy'
suggests that. What's more every so often two consecutive iterations show
the same absolute time values, suggesting that they fall in the same time
interval. So for example:
clockbeg = time("Reset") time("L")
do ii = 1 to intervls
zzzz = SysSleep(0.01)
clockend.ii = time("Elapse") time("L")
end
do ii = 1 to intervls
say "Delay 3: clockbeg" clockbeg "clockend."ii clockend.ii
end
has just produced:
Delay 3: clockbeg 0.500000 17:51:15.368000 clockend.1 0.031000
17:51:15.399000
Delay 3: clockbeg 0.500000 17:51:15.368000 clockend.2 0.046000
17:51:15.414000
Delay 3: clockbeg 0.500000 17:51:15.368000 clockend.3 0.046000
17:51:15.414000
Delay 3: clockbeg 0.500000 17:51:15.368000 clockend.4 0.062000
17:51:15.430000
Delay 3: clockbeg 0.500000 17:51:15.368000 clockend.5 0.078000
17:51:15.446000
(note lines are possible wrapped in your display). There the .2 and .3 lines
show the same time("E") values of 0.046000 even though they should have
taken place at least 0.01 seconds apart, and the corresponding time("L")
values are both the same: 17:51:15.414000.
Hmm, I just noticed (why has this never penetrated my brain before?) that
the ooRexx ref manual says of both time("R") and time("E") that:
"The number always has four trailing zeros in the decimal portion."
Looks to me as if that's wrong too! Three trailing zeros is what I'm
seeing. The manual doesn't say that time("L") is also producing values with
at best 0.001000 second accuracy, but it looks that way.
So maybe the '0' results only become non-zero when an interval crosses from
one 0.015 second interval to the next? I'd easily believe that much of what
I've tested would take less than 1/66 second to run.
With subsequent tests returning much bigger stems I have seen things like:
the first sysfiletree of something taking 20 or 30 seconds, but subsequent
calls taking 3-4 seconds, suggesting that cacheing is speeding up most of
the process but - provided enough work is required - something, perhaps the
rexx stem processing part still takes some time. These have been doing eg:
list = sysfiletree("C:\Windows\", "sft.", "DS")
which has been returning a stem, with sft.0 of 2187.
Unfortunately my first tests were producing tiny stems (only 1-20 entries
typically).
LesK
what you expect (see below). Also, it has been my
observation that on a Windows machine, time is always shown
to three significant decimal places and padded with zeros
to show microseconds.
Delay 3: clockbeg 0 14:47:26.703000 clockend.1 0.015000
14:47:26.718000
Delay 3: clockbeg 0 14:47:26.703000 clockend.2 0.047000
14:47:26.750000
Delay 3: clockbeg 0 14:47:26.703000 clockend.3 0.078000
14:47:26.781000
Delay 3: clockbeg 0 14:47:26.703000 clockend.4 0.109000
14:47:26.812000
Delay 3: clockbeg 0 14:47:26.703000 clockend.5 0.140000
14:47:26.843000
Les (Change Arabic to Roman to email me)
Swifty
> A slower processor, like my ancient Gateway desktop, shows what you
> expect (see below). Also, it has been my observation that on a Windows
> machine, time is always shown to three significant decimal places and
> padded with zeros to show microseconds.
>
> Delay 3: clockbeg 0 14:47:26.703000 clockend.1 0.015000 14:47:26.718000
> Delay 3: clockbeg 0 14:47:26.703000 clockend.2 0.047000 14:47:26.750000
> Delay 3: clockbeg 0 14:47:26.703000 clockend.3 0.078000 14:47:26.781000
> Delay 3: clockbeg 0 14:47:26.703000 clockend.4 0.109000 14:47:26.812000
> Delay 3: clockbeg 0 14:47:26.703000 clockend.5 0.140000 14:47:26.843000
From my rather old department server running IBM Object REXX under Linux:
do 30;say time(e);call syssleep 0.1;end
0
0.107751
0.217734
0.327753
0.437771
0.547811
0.657816
0.767840
0.877856
0.987896
1.098134
1.207939
1.317948
�
So, either time(E) had been updated in the light of faster processors,
or the Linux port did.
oorexx 4.0 under Debian on the commercial webserver that I use gives
similar results.
I was really lucky to stumble upon a fairly local (i.e. in the UK)
webservice that was willing to install oorexx. They bunged it, and
apache, and my virtual host on their latest top-of-the-range
experimental server. Judging by the performance I'm getting it's still
just me, one fellow who followed my example, and the sysadmin rattling
around like peas in a tin can.
Jeremy Nicoll - news posts
> So, either time(E) had been updated in the light of faster processors,
> or the Linux port did.
I've googled a bit. It turns out that the problem is Windows. You can find
threads on the same issues for every popular programming language.
Currently the Windows API call typically used returns a result that's set by
an interrupt-driven timer in Windows. Unfortunately the timer pops only 64
times a second, giving a 15.625 milisecond granularity. Worse still, it
seems common to have that interval rounded to the nearest millisecond. In
very old versions of Windows and DOS the timer popped even less often.
There's another way, which uses a 64-bit counter in the CPU which increments
on each cpu cycle, counting since the last cpu reset. There's a machine
instruction RDTSC that accesses the count.
What is a problem though is that in multi-core machines there are separate
counters, one per core. So people using this this approach need to be able
to force the counter-aquisition code always to run on the same core (or
perhaps always to store each counter value and its associated cpu id).
MS provide a wrapper around RDTSC called QueryPerformanceCounter() which
(I've read) fixes the multi-core issue (dunno how though), and another
function QueryPerformanceFrequency() which tells you the clock rate.
I've read multiple times that unfortunately the cpu clock does not run at a
constant rate on many machines (I'm not sure if it depends on workload
and/or electrical power management eg in laptops) so you can't just divide
the huge number in the counter by the full-load processor clock rate. [On
the other hand the MSDN pages for the functions say that this doesn't
occur.] Timestamping of occasional events could be hit by that, though I
would guess that benchmarking programs runnig flat-out would not be a
problem.
See eg: http://www.lochan.org/2005/keith-cl/useful/win32time.html for
details and downloadable C code for a partial solution (no good to me
without a suitable compiler).
For all I know someone may be able to work out how to use the
QueryPerformanceCounter() and QueryPerformanceFrequency() functions via
rxapi.
It seems to me that for comparing routes through code running on a specific
machine, it wouldn't matter much what the elapsed time's units actually are
if they are very finely grained. I mean, if one piece of code takes one
zillion counts to execute and another takes two zillion, you still know that
one took twice as long as the other. And if you were profiling a program
lots of small count values and bigger and much bigger ones would still be
useful. Indeed storing time("L") at a few points through a program as well
as these cpu clock counts would make it easy enough to convert one to the
other fairly accurately.