DIRECTORY
BasicTime USING [GetClockPulses, GMT, Now, Pulses, PulsesToMicroseconds],
IO USING [card, int, PutChar, PutF, PutRope, rope, STREAM, time],
LupineExerciser USING [Counter, String],
LupineExerciserPrivate
USING [
CallSpy, CheckAbort, ExerciseHandle, PrecisionTime,
RingBufferIndex, SortBuffer, SortBufferIndex, SystemTime ],
PrincOps USING [zMISC],
Process USING [Yield],
UnsafeStorage USING [GetSystemUZone];
Start:
PUBLIC
PROC [self: Handle, name: String] =
BEGIN OPEN tp: self.tp;
LupineExerciserPrivate.CheckAbort[self];
self.outLogStream.PutF["\n\nTiming %g trials of %g", IO.int[tp.trialsPerPass], IO.rope[name]];
TimeStamp[self, " at "];
PreparePrecisionTimings[self];
IF tp.spying THEN LupineExerciserPrivate.CallSpy[self, startSpying];
StartTimer[self: self, reset: TRUE];
END;
Stamp:
PUBLIC
PROC [self: Handle] =
BEGIN
StopTimer[self];
self.outLogStream.PutF["Doing %g ", IO.int[self.tp.testsPerTrial]];
TimeStamp[self, " calls at "];
StartTimer[self];
END;
Delay:
PUBLIC
PROC [self: Handle] =
BEGIN
StopTimer[self];
LupineExerciserPrivate.CheckAbort[self];
DoDelay[self, 600];
StartTimer[self];
END;
Stop:
PUBLIC
PROC [self: Handle] =
BEGIN OPEN tp: self.tp;
ms, tenths: LONG INTEGER;
StopTimer[self];
IF tp.spying THEN LupineExerciserPrivate.CallSpy[self, stopSpying];
LupineExerciserPrivate.CheckAbort[self];
IF tp.trialsPerPass = 0
OR tp.testsPerTrial = 0
THEN ms ← tenths ← 0
ELSE [ms, tenths] ← ConvertTimer[
ReadTimer[self].elapsed /
(tp.trialsPerPass*LONG[tp.testsPerTrial]) ];
self.outLogStream.PutF["The mean call time (overhead included) was %g.%g", IO.int[ms], IO.int[tenths]];
TimeStamp[self, " ms at "];
PrintPrecisionTimings[self];
IF tp.spying
AND tp.showSpyData=afterEachTest
THEN LupineExerciserPrivate.CallSpy[self, displayStats];
END;
TimeStamp:
PROC [self: Handle, herald: String] =
BEGIN
time: BasicTime.GMT ← BasicTime.Now[];
LupineExerciserPrivate.CheckAbort[self];
self.outLogStream.PutF["%g%g.\n", IO.rope[herald], IO.time[time]];
END;
Microseconds: TYPE = LONG CARDINAL;
ReadPilotClock:
PROC
RETURNS [SystemTime] =
INLINE {RETURN[ LOOPHOLE[BasicTime.GetClockPulses[]] ]};
PilotPrecisionRead:
PROC
RETURNS [
--SystemTime-- PrecisionTime] =
INLINE { RETURN[ ReadPilotClock[] ] };
PilotPrecisionConvert:
PROC [pt:
--SystemTime-- PrecisionTime]
RETURNS [--microseconds:-- Microseconds] =
INLINE {RETURN[ SystemTimeToUsec[pt] ]};
StartTimer:
PROC [self: Handle, reset:
BOOLEAN←
FALSE] =
INLINE BEGIN OPEN time: self.timer;
IF reset THEN time.elapsed ← 0;
time.start ← ReadPilotClock[];
END;
StopTimer:
PROC [self: Handle] =
INLINE BEGIN OPEN time: self.timer;
time.event ← ReadPilotClock[] - time.start;
time.elapsed ← time.elapsed + time.event;
END;
ReadTimer:
PROC [self: Handle]
RETURNS [event, elapsed: SystemTime] =
INLINE BEGIN OPEN time: self.timer;
RETURN[time.event, time.elapsed]
END;
ConvertTimer:
PROC [time: SystemTime]
RETURNS [ms,tenthsOfMs:
LONG
INTEGER] =
INLINE BEGIN
time ← (SystemTimeToUsec[time]+50)/100;
ms ← time/10;
tenthsOfMs ← time MOD 10;
END;
SystemTimeToUsec:
PROC [time: SystemTime]
RETURNS [Microseconds] =
INLINE BEGIN
RETURN[ BasicTime.PulsesToMicroseconds[BasicTime.Pulses[time]] ]
END;
DoDelay:
PROC [self: Handle, interval:
--Microseconds--
LONG
INTEGER] =
Spin at least "interval" between executions. There is a startup glitch.
BEGIN
LastIntegerTime: SystemTime = LAST[LONG INTEGER];
DO
grossWait: SystemTime =
SystemTimeToUsec[ReadPilotClock[]-self.timer.lastDelayFinished];
waitTime:
LONG
INTEGER =
IF grossWait < LastIntegerTime THEN grossWait ELSE LastIntegerTime;
SELECT interval-waitTime
FROM
< 0 => EXIT;
< 50 => Process.Yield; --NULL;
ENDCASE => Process.Yield;
ENDLOOP;
self.timer.lastDelayFinished ← ReadPilotClock[];
END;
InitPrecisionTimings:
PUBLIC
PROCEDURE [self: Handle] =
BEGIN OPEN timer: self.precisionTimer;
timer.sortBuffer ← heap.
NEW[
LupineExerciserPrivate.SortBuffer[self.tp.testsPerTrial+2] ];
timer.ringBuffer ←
DESCRIPTOR [
@timer.sortBuffer[FIRST[LupineExerciserPrivate.SortBufferIndex]+1],
LENGTH[DESCRIPTOR[timer.sortBuffer^]]-2 ];
END;
FinishPrecisionTimings:
PUBLIC
PROCEDURE [self: Handle] =
BEGIN OPEN timer: self.precisionTimer;
heap.FREE[@timer.sortBuffer];
timer.sortBuffer ← NIL;
timer.ringBuffer ← NIL;
END;
PreparePrecisionTimings:
PROC [self: Handle] =
INLINE BEGIN OPEN timer: self.precisionTimer;
IF BASE[timer.ringBuffer] = NIL THEN ERROR;
timer.ringIndex ← PRED[LENGTH[timer.ringBuffer]];
FOR i: RingBufferIndex IN [0..LENGTH[timer.ringBuffer]) DO
timer.ringBuffer[i] ← 0 ENDLOOP;
IF LENGTH[timer.ringBuffer] > 0 THEN BEGIN
timer.ringBuffer[0] ← 0;
Inline.LongCopy[
from: @timer.ringBuffer[0],
to: @timer.ringBuffer[1],
nwords: LENGTH[timer.ringBuffer]*SIZE[PrecisionTime];
END;
IF self.tp.useDoradoClock THEN StartDoradoCounters[EmuCycles];
END;
PrintPrecisionTimings:
PROC [self: Handle] =
BEGIN OPEN timer: self.precisionTimer;
ringBufferLength: CARDINAL ← LENGTH[timer.ringBuffer];
Range: INTEGER = MIN[10, ringBufferLength];
PrintRange:
PROC [herald: String, startIndex: RingBufferIndex] =
BEGIN
self.outLogStream.PutRope[herald];
FOR i: RingBufferIndex
IN [startIndex..startIndex+Range)
DO
IF timer.ringBuffer[i] > 99999
THEN self.outLogStream.PutRope[" **********"]
ELSE self.outLogStream.PutF["%6g", IO.card[timer.ringBuffer[i]]];
ENDLOOP;
self.outLogStream.PutChar['\n];
END; -- PrintRange.
FOR i: RingBufferIndex
IN [
FIRST[RingBufferIndex]..ringBufferLength)
DO
timer.ringBuffer[i] ← PrecisionConvert[self, timer.ringBuffer[i]];
ENDLOOP;
QuickSort[DESCRIPTOR[timer.sortBuffer^]];
self.outLogStream.PutF["Some instantaneous call times (microseconds) from a %g element ring buffer:\n", IO.int[ringBufferLength]];
PrintRange[" Fastest times:", FIRST[RingBufferIndex]];
PrintRange[" Median times: ",
FIRST[RingBufferIndex] + (ringBufferLength-Range)/2 ];
PrintRange[" Slowest times:",
FIRST[RingBufferIndex]+ringBufferLength-Range];
END;
Dorado 64ns precision counter routines.
Modified from [Ivy]<McDaniel>Measurements>Measure.mesa.
doradoCounters: CounterVector ← ZeroCounterVector;
DoradoPrecisionRead:
PROC [self: Handle]
RETURNS [PrecisionTime] =
INLINE BEGIN
ReadDoradoCounters[@doradoCounters];
RETURN[
IF self.tp.countOnlyEmulatorCycles
THEN doradoCounters.A.low ELSE doradoCounters.B.low ];
END;
DoradoPrecisionConvert:
PROC [pt: PrecisionTime]
RETURNS [--microseconds:-- Microseconds] =
INLINE BEGIN
Measured clock time was 2*32.2 ns => 644/10000 = 161/2500 usec/cycle
Compute slowly to avoid overflow and do rounding.
RETURN[
(LONG[161]*(pt/LONG[2500]))
+ ( LONG[161]*(pt MOD LONG[2500])+LONG[2500/2] )/LONG[2500] ];
END;
StartDoradoCounters:
PROCEDURE [CounterDescriptor] =
MACHINE CODE BEGIN PrincOps.zMISC, 240B END;
ReadDoradoCounters:
PROCEDURE [CounterVectorPtr] =
MACHINE CODE BEGIN PrincOps.zMISC, 241B END;
StopDoradoCounters:
PROCEDURE =
MACHINE CODE BEGIN PrincOps.zMISC, 242B END;
CounterVector:
TYPE =
MACHINE
DEPENDENT
RECORD [
A(0): MACHINE DEPENDENT RECORD [low(0): LONG CARDINAL, high(2): CARDINAL],
B(3): MACHINE DEPENDENT RECORD [low(0): LONG CARDINAL, high(2): CARDINAL] ];
ZeroCounterVector: CounterVector = [[0,0],[0,0]];
CounterVectorPtr: TYPE = LONG POINTER TO CounterVector;
ASelection:
TYPE =
MACHINE
DEPENDENT {
true, hold, procRef, ifuJump, miss, bpa, bpc, bpe };
BSelection:
TYPE =
MACHINE
DEPENDENT {
true, hold, ifuRef, ifuNrdy, miss, bpb, bpc, bpd };
allA, allB, doA, doB: BOOLEAN = TRUE;
emuOnlyA, emuOnlyB, notIS: BOOLEAN = FALSE;
CounterDescriptor:
TYPE =
MACHINE
DEPENDENT
RECORD [
instrSet: BOOLEAN,
ignoreBits123: [0..7],
enableA, enableB: BOOLEAN,
ignoreBits67: [0..3],
aSelects: ASelection,
allTasksA: BOOLEAN,
bSelects: BSelection,
allTasksB: BOOLEAN ];
EmuCycles: CounterDescriptor = [notIS,0,doA,doB,0,true,emuOnlyA,true,allB];