The Database Managers, Inc.

Contact The Database Managers, Inc.


Use an RSS enabled news reader to read these articles.Use an RSS enabled news reader to read these articles.

DataFlex Decompiler
Page 5

Timing an Event in DataFlex

by Curtis Krauskopf

Using SYSDATE for Microsecond Timing

With some clever tinkering, we now have the tools to be able to have SYSDATE and SYSDATE4 tell us (indirectly) in what fraction of a second an event happened. This technique is so accurate that it is able to tell me, within 40 microseconds (0.000040 seconds), how long an event took.

In delay.src, I showed how we could synchronize the start of an event with the beginning of a second. Since we have the program's execution synchronized with the system clock, we can use that to our advantage by incrementing a counter during an entire second. That will tell us how many times the counter can be incremented on that hardware (based on its CPU and the DataFlex runtime that is executing).

Once we have that information, we can then let the event that we're really interested in timing happen. When that finishes, we increment a different counter to count the amount of time that remained in the second after the event finished. Subtracting that number from the number of increments in a whole second will tell us what fraction of a second the event consumed.

Here's a diagram of this whole process:

This diagram shows the following events:

Second Event
:06
The program starts at some fraction of a second after the system clock rolled over to the sixth second in the minute. The program immediately enters a wait loop that repeats until the clock rolls over to :07.
:07
The program calibrates itself by incrementing an integer for an entire second. This tells us how many times an integer can be incremented per second.
:08

The event being measured starts. In this example, it also stops in the same second, but that's not necessary. The event could stop in any second and the rest of this process would remain the same (and just as accurate).

After the event stops, we immediately enter a loop that increments a different integer. The number of incrementations that are made before the next second (:09) tells us how much time was left after the event finished.

:09

At :09, the loop that increments the second integer finishes and we can report the results.

The equation to calculate the fraction of a second used by the event is in equation #1:

(1) amount_used  =    calibration - post_event
calibration

In equation 1, both calibration and post_event are the number of integer incrementations completed in the appropriate phases. calibration is incremented during an entire second to calibrate the number of integer increments that can happen per second. post_event is incremented immediately after the event being timed has finished. post_event indicates how much time was left in the second that the event stopped.

As an example, let's say that the calibration phase incremented an integer 25,000 times. After the event, let's say that the second integer (post_event) incremented 4,000 times. The fraction of a second used by the event is in equation #2:

(2) amount_used  =    25000 - 4000
25000
   =  0.84 seconds

A DataFlex program that demonstrates this concept is:

// accurate.src
// by Curtis Krauskopf at www.decompile.com
//
// This program shows how to make SYSDATE4 detect
// fractions of a second.  On a 1 Ghz Dell computer
// running DataFlex 3.1d, I'm able to get a
// resolution of 40 microseconds.
//
//

date today
integer hour minute second start

date before after
integer before_hour before_minute before_second
integer after_hour after_minute after_second

integer calibration
integer finish_ticks

// First phase:  Initialize all variables
move 0 to calibration
move 0 to finish_ticks


// Second phase:  enter a loop that waits until
// the second on the system clock changes.
sysdate4 today hour minute start
repeat
  sysdate4 today hour minute second
until start ne second


// Execution and the system clock are now synchronized.
// Enter a loop that increments a counter for an
// entire second.
repeat
  sysdate4 before before_hour before_minute before_second
  increment calibration
until before_second NE second


// Now that we have calibrated the number of integer
// increments per second, we can test how long our
// event takes:
showln "Press any key to stop the test."
string akey 1
inkey akey


// The event if finished, but we need to record the
// amount of time that is left in this second.
sysdate4 after after_hour after_minute after_second
repeat
  sysdate4 today hour minute second
  increment finish_ticks
until after_second NE second


// Now we can report how long the event took:
show   "Calibration recorded " calibration
showln " increments per second."
showln
show   "The event had " finish_ticks
showln " increments before the second changed."
showln
show   "The event took "

number before_time   // Accumulated number of seconds
number after_time

move (integer(before) * 3600 * 24) to before_time
move (before_time + (before_hour * 3600)) to before_time
move (before_time + (before_minute * 60)) to before_time
move (before_time + (before_second)) to before_time

move (integer(after) * 3600 * 24) to after_time
move (after_time + (after_hour * 3600)) to after_time
move (after_time + (after_minute * 60)) to after_time
move (after_time + (after_second)) to after_time

show (after_time - before_time)

// Fractional numbers converted to strings in DataFlex have
// a leading 0.  This block converts the result (a number)
// to a string and then removes the leading "0"
string result
move (number(calibration) - finish_ticks / calibration) to result
replace "0." in result with "."
show result
showln " seconds."

showln
showln
showln "Press any key to continue."

inkey akey

The output for this program looks like this:

Press any key to stop the test.
Calibration recorded 25211 increments per second.

The event had 20344 increments before the second changed.

The event took 4.19305065 seconds.

Press any key to continue.

On a Windows system, if you run the program several times (remember the rules of thumb when testing event timing on a computer), you might have noticed something odd. The calibration value reported in each test run might be different!

Here are some snapshots of four test runs on my system running DataFlex 3.1d:

The event had 24753 increments before the second changed.

The event had 24164 increments before the second changed.

The event had 24507 increments before the second changed.

The event had 25619 increments before the second changed.

The problem is that the Windows operating system is stealing timeslices from the program. If I boot to MS-Dos and run the same test program, I get calibration results that are only a few increments from each other.

Go Back to Page: 1 2 3 4

Copyright 2003 The Database Managers, Inc.

DataFlex: Tips | Freeware | WebApp Server | Books | Links
Services | Programming | Contact Us | Recent Updates

Send feedback to: