SYSTEM_CLOCK problems

Paul,

I have again come across problems using SYSTEM_CLOCK, where the clock counter still counts backwards for faster processors. My 2ghz notebook works ok but my 3.17ghz desktop does not. I would expect that all processors faster than 2ghz show the problem.

I am including a simple program which tests system_clock for 10,000 different results and stores the differences and reports the elapsed time, calculated via date_and_time. This clearly shows the difference on the faster processor. There must be an integer*4 overflow there somewhere.

!
      integer*4, parameter :: m_rate = 10000
      integer*8 count_start, rate_start, max_start,    &
                count_next, rate_next, max_next,       &
                counts(0:m_rate)
      integer*4 n_call, n_diff, i, calls(0:m_rate), values_in(8), values_out(8)
      CHARACTER DATE*8, TIME*10, ZONE*5
      real*8    dt, start, finish
!
      call DATE_AND_TIME (DATE, TIME, ZONE, VALUES_in)
      START= CPU_CLOCK@()
!
      call system_clock (count_start, rate_start, max_start)
      counts(0) = count_start
      calls(0)  = 0
!
      n_call = 0
      n_diff = 0
      do
         n_call = n_call + 1
         call system_clock (count_next, rate_next, max_next)
         if (rate_next /= rate_start) write (*,*) 'Unexpected change of rate',rate_start, rate_next
         if (max_next  /= max_start)  write (*,*) 'Unexpected change of max ',max_start,  max_next
         if (count_next == count_start) cycle
         count_start = count_next
         n_diff = n_diff + 1
         counts(n_diff) = count_next
         calls(n_diff)  = n_call
         if (n_diff >= m_rate) exit
      end do
!
      call DATE_AND_TIME (DATE, TIME, ZONE, VALUES_out)
      FINISH = CPU_CLOCK@()
!
      dt =  (( (values_out(5)-values_in(5)) )  *24 +   &    ! hours
               (values_out(6)-values_in(6))  ) *60 +   &    ! minutes
               (values_out(7)-values_in(7))                 ! seconds
      dt = dt + dble (values_out(8)-values_in(8)) * .001d0
!
      do i = 1,10      
         write (*,*) i, calls(i), counts(i), (calls(i)-calls(i-1)), (counts(i)-counts(i-1))
      end do
      write (*,*) counts(0),' incremented by one for each clock count '
      write (*,*) rate_start,' number of processor clock counts per second'
      write (*,*) max_start,' maximum value that COUNT can have'
      write (*,*) n_diff,' different calls'
      write (*,*) n_call,' total calls'
      write (*,*) dt,' elapsed seconds for',n_diff,' ticks' 
      write (*,*) (finish-start),' ticks of cpu_clock@'
      write (*,*) (finish-start)/dt/1.d9,' ticks per nano-second'
      end

Test on 1.995 ghz pc

[FTN95/Win32 Ver. 4.9.1 Copyright (c) Silverforst Ltd 1993-2006]

0011)       START= CPU_CLOCK@()
WARNING - 30: The use of CPU_CLOCK@ may cause run-time errors under Windows 
    NT, and give inaccurate results under Windows 95
    NO ERRORS, 1 WARNING  [<main program> FTN95/Win32 v4.9.1]
Creating executable: C:\\junk\\test\\lgotemp@.exe
Program entered
            1          10             51571484          10                    1
            2          38             51571485          28                    1
            3          66             51571486          28                    1
            4          93             51571487          27                    1
            5         121             51571488          28                    1
            6         148             51571489          27                    1
            7         176             51571490          28                    1
            8         204             51571491          28                    1
            9         231             51571492          27                    1
           10         259             51571493          28                    1
              51571483 incremented by one for each clock count 
                 10000 number of processor clock counts per second
   9223372036854775807 maximum value that COUNT can have
        10000 different calls
       275205 total calls
           1.00000000000     elapsed seconds for       10000 ticks
           1995111228.00     ticks of cpu_clock@
           1.99511122800     ticks per nano-second

Test on 3.167 ghz pc

[FTN95/Win32 Ver. 5.30.0 Copyright (c) Silverfrost Ltd 1993-2009]

0011)       START= CPU_CLOCK@()
WARNING - 30: The use of CPU_CLOCK@ may cause run-time errors under Windows 
    NT, and give inaccurate results under Windows 95
    NO ERRORS, 1 WARNING  [<main program> FTN95/Win32 v5.30.0]
Creating executable: c:\\temp\\lgotemp@.exe
Program entered
            1           1  9223372036518373873           1                   -1
            2          52  9223372036518373872          51                   -1
            3         113  9223372036518373871          61                   -1
            4         173  9223372036518373870          60                   -1
            5         252  9223372036518373869          79                   -1
            6         347  9223372036518373868          95                   -1
            7         443  9223372036518373867          96                   -1
            8         538  9223372036518373866          95                   -1
            9         634  9223372036518373865          96                   -1
           10         729  9223372036518373864          95                   -1
   9223372036518373874 incremented by one for each clock count 
                 10000 number of processor clock counts per second
   9223372036854775807 maximum value that COUNT can have
        10000 different calls
       950726 total calls
          0.359000000000     elapsed seconds for       10000 ticks
           1131441146.00     ticks of cpu_clock@
           3.15164664624     ticks per nano-second

ps : preview did not show the submit overflow on posting size limits

OK John I will aim to have another look at this. In fact it is still on my list of outstanding jobs.

Paul

John

I have sent you some code to test via a forum message.

Paul,

I modified your code to report some interum calculations and sent you a trace from my 1.995ghz and 3.167ghz pc's. There is a factor of 1000 different in the QueryPerformanceFrequency being provided by the 2 pc's

John

Paul,

I have taken your sample of SYSTEM_CLOCK and changed it to use real10 calculations, rather than integer8. I assume that real10 is the best precision that uses the maths register. Is this still the case with modern processors ? Kind documentation reports Real10 precision =18 and Integer*8 range =18 so there should be no comprimising accuracy.

QueryPerformanceCounter and QueryPerformanceFrequency appear to provide a reliable, fast and accurate way of estimating elapsed time.

I have written and tested new versions of system_clock and high_res_clock@ which run faster and more accurately on both my pc's, using these 2 winapi routines.

There remains a vagueness in FTN95.CHM as to what is elapsed time and processor time, as CPU appears to imply either elapsed or processor time, eg HIGH_RES_CLOCK@ or CPU_CLOCK@. Some times I want to exclude non, process time, as it is reported in windows task manager.

While CPU_CLOCK@ apears to provide the fastest and most accurate version of processor time, the winapi routine GetProcessTimes does not appear to have the same accuracy. It claims accurate to 100-nanosecond, but my use returns different values only accurate to .015 seconds. does CPU_CLOCK@ report the windows task manager interpretation of CPU Usage ? If it does, there should be a more accurate version of GetProcessTimes in winapi, or I have a mistake in my implementation of GetProcessTimes.

I have a timing test program which estimates how long 11 different routines take and what is the accuracy of the answers (how many different values are returned per second). It is surprising how the speed of different routines change relatively with different processors. The table below summarises the performance of different routines I have tested where each routine runs continually for two passes of 500,000 calls. It gets 100% cpu usage so I can't differentiate between CPU and elapsed.

Thanks for your assistance.

John

Call Description     Total time   call time  unique     min dif     max dif    accuracy
                      # seconds      mu.sec  number    # mu.sec    # mu.sec    # mu.sec
#call system_clock       10.503       0.189    9430       10.00       30.00       10.00
call cpu_time            10.500       0.234       8    15625.00    15625.00    15625.00
date_and_time            10.500       0.401      13    15000.00    16000.00    15615.38
call dclock@             10.500       0.130       4    15000.00    16000.00    15750.00
#high_res_clock@         10.503       0.204  499999        0.17       81.27        0.20
seconds_since_1980@      10.000       0.125       0        0.00        0.00        0.00
cpu_clock@ ()            10.503       0.030  499999        0.03        0.89        0.03
call getlocaltime        10.500       0.121       4    15000.00    16000.00    15500.00
call gettickcount        10.500       0.017       0        0.00        0.00        0.00
call QueryPerform        10.503       0.182  499999        0.16       87.06        0.18
GetProcessTimes          10.500       0.206       6    15625.00    15625.00    15625.00

Thanks John

As a result of your feedback I have located a bug in SYSTEM_CLOCK that will be fixed for the next release. It only occurs with very fast processors.

Paul,

I am again looking for an accurate timer of CPU time, as different from elapsed time. This helps in identifying other delays, especially disk I/O delays.

QueryPerformanceCounter, which is used in SYSTEM_CLOCK, appears to be very good to get elapsed time while 'GetProcessTimes' appears to get CPU times, but only accurate to 0.015 seconds (1/64 of a second). GetLocalTime, GetTickCount and GetProcessTimes all appear to return values that are updated by the system every 0.015 seconds.

Do you know if this accuracy can be improved to better than 0.015 seconds, by setting the system to update the available values more frequently ?

Also, what winapi does CPU_clock@ use, as it is very accurate and fast, but again appears to be an elapsed time clock ? It's frequency does not appear to be available, unlike QueryPerformanceCounter.

I would appreciate any advice you could provide.

John

Hi John

The help file documents CPU_CLOCK@ as being inline assembly code. You can use /explist to see the assembly instructions that are used.

The standard intrinsic CPU_TIME can use REAL kind 1, 2 or 3 but is based on a call to GetProcessTimes so has the limitations that you describe.

Regards

Paul