Measuring natural performance in ms (miliseconds)

, , ,
1

Hi all,

Is there a way to measure the precise exectution duration of a certain codeblock in natural code with a precision of milliseconds?

As it seems, it is only possible to determine the acuracy in tenth of a second with SET TIME and *TIMD…

Regards,
Rok

2

First, a warning. *TIMD is elapsed wall clock time. You can get rather different times depending on how busy your computer is. You might want to look at *CPU-TIME, which can be a more accurate measure, and is not as dependent on when you run a timing test.

The following program shows the use of *TIMD and *CPU-TIME

  • THIS PROGRAM DEMONSTRATES HOW EXPENSIVE IT IS TO EXAMINE AN ARRAY
  • AS OPPOSED TO EXAMINE’ING A STRING.

DEFINE DATA LOCAL
1 #STRING-TABLE (50)
2 #ARRAY (A3)
2 #DUMMY (A1) INIT ALL <‘*’>
1 REDEFINE #STRING-TABLE
2 #STRING (A200)
1 #LOOP (P9)
1 #NUMBER (P3)
1 #CPU-START (P9)
1 #CPU-ELAPSED (P9)
END-DEFINE
*
INCLUDE AATITLER
INCLUDE AASETC
*
MOVE *CPU-TIME TO #CPU-START
SETTIME
FOR #LOOP = 1 TO 300000
IGNORE
END-FOR
COMPUTE #CPU-ELAPSED = *CPU-TIME - #CPU-START
WRITE 3/10 ‘CONTROL LOOP TIME==>’ *TIMD (0200) #CPU-ELAPSED
*
MOVE *CPU-TIME TO #CPU-START
SETTIME
FOR #LOOP = 1 TO 300000
EXAMINE #STRING FOR ‘X’ GIVING NUMBER #NUMBER
*
IF #NUMBER = 0
IGNORE
END-IF
END-FOR
COMPUTE #CPU-ELAPSED = *CPU-TIME - #CPU-START
WRITE 3/10 ‘STRING TIME==>’ *TIMD (0280) #CPU-ELAPSED
*
MOVE CPU-TIME TO #CPU-START
SETTIME
FOR #LOOP = 1 TO 300000
EXAMINE #ARRAY () FOR ‘X’ GIVING NUMBER #NUMBER
*
IF #NUMBER = 0
IGNORE
END-IF
END-FOR
COMPUTE #CPU-ELAPSED = *CPU-TIME - #CPU-START
WRITE 3/10 ‘ARRAY TIME==>’ *TIMD (0400) #CPU-ELAPSED
*
END

PAGE #   1                    DATE:    11/20/10
PROGRAM: EXAMIN02             LIBRARY: BOST-PER



     CONTROL LOOP TIME==>        4         43


     STRING TIME==>       18        177


     ARRAY TIME==>       24        241

Note that you get one extra digit by using CPU-TIME.

In either case, a FOR loop with an appropriate number of iterations is useful (especially for *TIMD) to smooth out the results. You can subtract the CONTROL LOOP TIME (see output above) from the STRING TIME and ARRAY time to get a more meaningful comparison.

3

Too bad that *CPU-TIME is not available in all mainframe environments, such as under CICS.

4

Correct… Under z/VSE *CPU-TIME is a constant 0!

Is there a possibility to “use” the *TIMESTMP system variable? What exactly is Machine-internal store clock value which is supposed to be returned with *TIMESTMP? If I subtract the START *TIMESTMP from the END *TIMESTMP and convert the resulting binary in decimal format - is this somehow in relation with the time, that has passed between START end END?

Regards,
Rok

5

OK got it up and working…

  1. Convert Starting *TIMESTMP TO decimal
  2. Convert Finish *TIMESTMP TO decimal
  3. Subtract Start from Finish giving RESULT
  4. Divide RESULT by 4076829030 (meassured average Duration of 1 sek in *TIMESTMP Format with SET TIME and *TIMD)

Both Test and Production machines gave the relatively stable Value of 4076829030 when messured the duration of 1 sek with *TIMD (differences in +/- 2 milliseconds).

I’ll use this for now…

6

1 Second is exactly 4.096.000.000 in STCK format (which *TIMESTMP is based on)

7

Hello Wolfgang,

grazie!:slight_smile:

8

Just fyi, you don’t have to reinvent the wheel here, in library SYSEXT you’ll find

USR2036N  Convert binary variable (B8) into numeric variable (P20)

the supplied sample will give you, for example

Convert *TIMESTMP to nano seconds using subprogram USR2036N
-----------------------------------------------------------
                                                           
Start timestamp ................... D24D5372F3DE7905       
Start timestamp in nano seconds ... 3699672869715431562    
End timestamp ..................... D24D5372F4357805       
End timestamp in nano seconds ..... 3699672869716823500    
Elapsed time in milli seconds ..... 1.391938               
                                                           
                                                           
Convert *TIMESTMP to nano seconds using copycode USR2036Z  
---------------------------------------------------------  
                                                           
Start timestamp ................... D24D5372F3DE7905       
Start timestamp in nano seconds ... 3699672869715431562    
End timestamp ..................... D24D5372F4357805       
End timestamp in nano seconds ..... 3699672869716823500    
Elapsed time in milli seconds ..... 1.391938