Debugger Command 25,007 - Timers

This command packet is processed only by Fieldpine PosGreen (Windows). It returns the internal timers recording how long certain operations have been taking inside the system. These timers are only held in memory and are reset when the process ends.

DATS Reply Packet Structure

Field#	Field Name	Units	Description
108	TimerName		Common name for this timer
109	TimerId		Internal Id for this timer. An internal id does not change once allocated to a timing area
120	OutOfControl	1/0
121	TotalSamples	Number	The number of samples that have been taken
122	Minimum	mS	The smallest sample observed.
123	Maximum	mS	The largest sample observed
124	Average	mS	Average of all samples. Value is = sum(all-samples) / TotalSamples
125	StdDev	mS	Standard deviation of samples
126	Quartile1	mS
127	Quartile2	mS
128	Quartile3	mS
129	OutOfControlMask	BitMask
130	Raw	mS	A list of some of the most recent values, newest first

The precision of the timers is typically around 10-18mS, as typically the code is using GetTickCount(). This is sufficient for the timers as they are only a broad overview. You should not try to over analyse timer values that are not at least 3 times the value of this precision without fully understanding the statistical implications.

Example

<?xml version="1.0" encoding="UTF-8" standalone="yes" ?> 
<DATS>
  <Opcode>25007</Opcode> 
  <ProcessId>3472</ProcessId> 
  <DATS>
    <TimerId>120</TimerId> 
    <TimerName>SaleCreate</TimerName> 
    <OutOfControl>0</OutOfControl> 
    <TotalSamples>4</TotalSamples> 
    <Minimum>125.000000</Minimum> 
    <Maximum>500.000000</Maximum> 
    <Average>250.000000</Average> 
    <StdDev>176.776695</StdDev> 
    <OutOfControlMask>0</OutOfControlMask> 
    <Quartile1>125.000000</Quartile1> 
    <Quartile2>250.000000</Quartile2> 
    <Quartile3>500.000000</Quartile3> 
    <Raw>125.000000</Raw> 
    <Raw>125.000000</Raw> 
    <Raw>250.000000</Raw> 
    <Raw>500.000000</Raw> 
  </DATS>
</DATS>

SaleCreate Timer

This timer records how long the system took to create a new sale in the database. This timer is a leading indicator of general system issues. While the values are highly system specific, a PC using a local harddrive typically sees average timers of less than 50mS. The example below is a debug machine running full code analysis and many extra features enabled. Network systems and ODBC databases cannot easily be compared.

To investigate deeper why a SaleCreate Timer might be slower than you wish, enable trace file and search for the following line after creating a sale. (line breaks below for readability)

30639,0,0,23/08/2016 07:21:17,Flow(120), 
	1605160412=0,
	1300160412=0,
	1603160412=0,
	1559160412=16,
	1558160412=31,
	1557160412=31,
	1556160412=31,
	1555160412=47,
	1551160412=47,
	1550160412=47,
	1549160412=109,
	1548160412=141

This trace line shows the timer at each step of the SaleCreate operation. The first number is the flow point and the second is the elapsed milliseconds from start to reach that point. The flow points can be used to isolate the operation the POS has just performed.

• The trace line shows the longest delay happened at "1549160412=109" This took 109-47= 62mS. (+/- around 16mS precision)
• Using the flow point number, see either Flow_Reference or lookup this single value online Flow=1549160412
• The flow documentation says "PriceBand determined and applied, Pre Printing completed, Stocktake setup (if stocktake mode), SaleMachines executed"