 |
|
 |
I've been messing with DateTime.Now and SQL Server for a long time. A trigger should store the most precise/accurate time when fired, the datetime/datetime2 field was also part of the primary key. When called multiple times in a row, the trigger started throwing "duplicate key" messages. It drove me nuts and I could not find a proper solution until I found your class. You are my hero James: thank you very much
:respect:
|
|
|
|
 |
|
 |
I really like this and I intend to use this it. I have a Windows system that's hardware synchronized to local GPS hardware and it's annoying that I can't get any better accuracy than 16ms. This at least provides high-resoultion timestamps for the kinding of timing that needs to be performed. Question about your code, since the StopWatch.Frequency is a constant why do you constantly adjust this frequency when resyncing? i.e., the following code:
s - immutable._s_observed) * _clockTickFrequency * 2) / (t.Ticks - immutable._t_observed.Ticks + t.Ticks + t.Ticks - t_base_new.Ticks - immutable._t_observed.Ticks
|
|
|
|
 |
|
 |
Hi Mr. Carroll,
The value returned by Stopwatch.Frequency is an approximation (with only about 4 significant digits) of the clock frequency at which your CPU operates.
Discovery of the true clock frequency of your CPU is, in a sense, the core purpose of DateTimePrecise.
DateTimePrecise does not simply use the measured frequency of (clock cycles during time period / time period), however. It is constrained by a continuity requirement, so it uses a frequency that will asymptotically approach the measured frequency.
|
|
|
|
 |
|
 |
Hey, I think the above mentioned line is generating a bug:
I've got a 'divide by zero' exception on the following line:
return immutable._t_base.AddTicks( ((s - immutable._s_observed)*_clockTickFrequency) /(immutable._stopWatchFrequency));
and immutable._stopWatchFrequency might have initialized to zero because of:
_immutable = new DateTimePreciseSafeImmutable( t, t_base_new, s, ((s - immutable._s_observed)*_clockTickFrequency*2) / (t.Ticks - immutable._t_observed.Ticks + t.Ticks + t.Ticks - t_base_new.Ticks - immutable._t_observed.Ticks) );
I haven't dig much into it, how would you suggest fixing it?
|
|
|
|
 |
|
 |
Hey? any solution for the divide by zero exception?
|
|
|
|
 |
|
 |
Hi shlomiw,
Thanks for the bug report, I've not seen that bug yet.
That's odd, and it's hard to see how that could happen.
In order for immutable._stopWatchFrequency to be zero, the fourth argument to the DateTimePreciseSafeImmutable constructor has to be zero. In order for that argument to be zero, either _clockTickFrequency has to be zero, or (s - immutable._s_observed) has to be zero. _clockTickFrequency is constant. (s - immutable._s_observed) must be greater than _synchronizePeriodStopwatchTicks, because of the "if" condition at the top of the get accessor. _synchronizePeriodStopwatchTicks must be greater than zero, as long as the synchronizePeriodSeconds argument to the DateTimePrecise constructor is greater than zero. I assume you're not passing a negative value for synchronizePeriodSeconds.
Have you seen this exception thrown more than once? Could you break into the debugger when you see it, and tell me what the values of all the variables are?
|
|
|
|
 |
|
 |
Hi James,
I use your DateTimePrecise quite a lot in my server (and it's great!), though this bug happened something like twice. It's extremely rare and I can't reproduce it. I'm not passing a negative value for synchronizePeriodSeconds.
I'm not sure either how it was zero, but we have to prevent it somehow, please tell what would be the best way to do it because I can't afford to let it happen next time on the production server...
Next time it will happen - I promise to give you all the information I can.
Many thanks! Shlomi
|
|
|
|
 |
|
 |
Hi shlomiw,
Try making the construction of a new DateTimePreciseSafeImmutable conditional:
if ((s - immutable._s_observed) * _clockTickFrequency > 0) { _immutable = new DateTimePreciseSafeImmutable( t, t_base_new, s, ((s - immutable._s_observed) * _clockTickFrequency * 2) / (t.Ticks - immutable._t_observed.Ticks + t.Ticks + t.Ticks - t_base_new.Ticks - immutable._t_observed.Ticks) } else { // print to an error log or to debug the values of s, t, _clockTickFrequency, t.Ticks, t_base_new, t_base_new.Ticks, immutable._t_observed, immutable._t_base, immutable._s_observed, immutable._stopWatchFrequency }
Even if you don't do the error log printing, this should fix your production code, I hope, by skipping the construction of a new DateTimePreciseSafeImmutable if it would be constructed with a zero stopWatchFrequency.
If you do the error log printing, please let me know what you find.
|
|
|
|
 |
|
 |
Thanks James!
I've added what you said, and also put the Log. whenever it'll occur - I'll post the log results.
Thanks again! Shlomi
|
|
|
|
 |
|
 |
yep - got it! (it happened only today after a long time that it didn't happen)
it happened many times in a period of time.
here are the Logs: (hope you'll figure it out)
04 Nov 2008 13:20:30,082 [13] WARN Common - Avoided DivideByZero . debug: s=1706502946672, t=11/04/2008 11:20:30, _clockTickFrequency=10000000, t.Ticks=633613944300822787, t_base_new=11/04/2008 11:06:04, t_base_new.Ticks=633613935645633599, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:30,113 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1706564087720, t=11/04/2008 11:20:30, _clockTickFrequency=10000000, t.Ticks=633613944301135287, t_base_new=11/04/2008 11:06:04, t_base_new.Ticks=633613935645920454, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:30,441 [13] WARN Common - Avoided DivideByZero . debug: s=1707260291104, t=11/04/2008 11:20:30, _clockTickFrequency=10000000, t.Ticks=633613944304416537, t_base_new=11/04/2008 11:06:04, t_base_new.Ticks=633613935649186827, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:30,535 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1707477335696, t=11/04/2008 11:20:30, _clockTickFrequency=10000000, t.Ticks=633613944305354037, t_base_new=11/04/2008 11:06:05, t_base_new.Ticks=633613935650205134, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:30,926 [13] WARN Common - Avoided DivideByZero . debug: s=1708317461544, t=11/04/2008 11:20:30, _clockTickFrequency=10000000, t.Ticks=633613944309260287, t_base_new=11/04/2008 11:06:05, t_base_new.Ticks=633613935654146747, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:30,941 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1708340477656, t=11/04/2008 11:20:30, _clockTickFrequency=10000000, t.Ticks=633613944309416537, t_base_new=11/04/2008 11:06:05, t_base_new.Ticks=633613935654254731, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:31,082 [13] WARN Common - Avoided DivideByZero . debug: s=1708647402072, t=11/04/2008 11:20:31, _clockTickFrequency=10000000, t.Ticks=633613944310822787, t_base_new=11/04/2008 11:06:05, t_base_new.Ticks=633613935655694727, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:31,097 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1708655496424, t=11/04/2008 11:20:31, _clockTickFrequency=10000000, t.Ticks=633613944310979037, t_base_new=11/04/2008 11:06:05, t_base_new.Ticks=633613935655732703, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:31,441 [13] WARN Common - Avoided DivideByZero . debug: s=1709394611528, t=11/04/2008 11:20:31, _clockTickFrequency=10000000, t.Ticks=633613944314416537, t_base_new=11/04/2008 11:06:05, t_base_new.Ticks=633613935659200405, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:31,441 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1709402060488, t=11/04/2008 11:20:31, _clockTickFrequency=10000000, t.Ticks=633613944314416537, t_base_new=11/04/2008 11:06:05, t_base_new.Ticks=633613935659235353, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:31,754 [13] WARN Common - Avoided DivideByZero . debug: s=1710078563120, t=11/04/2008 11:20:31, _clockTickFrequency=10000000, t.Ticks=633613944317541537, t_base_new=11/04/2008 11:06:06, t_base_new.Ticks=633613935662409296, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:31,769 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1710087828920, t=11/04/2008 11:20:31, _clockTickFrequency=10000000, t.Ticks=633613944317697787, t_base_new=11/04/2008 11:06:06, t_base_new.Ticks=633613935662452768, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:32,051 [13] WARN Common - Avoided DivideByZero . debug: s=1710705419616, t=11/04/2008 11:20:32, _clockTickFrequency=10000000, t.Ticks=633613944320510287, t_base_new=11/04/2008 11:06:06, t_base_new.Ticks=633613935665350315, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:32,051 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1710710193488, t=11/04/2008 11:20:32, _clockTickFrequency=10000000, t.Ticks=633613944320510287, t_base_new=11/04/2008 11:06:06, t_base_new.Ticks=633613935665372712, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:39,097 [13] WARN Common - Avoided DivideByZero . debug: s=1725706708592, t=11/04/2008 11:20:39, _clockTickFrequency=10000000, t.Ticks=633613944390979037, t_base_new=11/04/2008 11:06:13, t_base_new.Ticks=633613935735731769, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:20:39,097 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1725713495856, t=11/04/2008 11:20:39, _clockTickFrequency=10000000, t.Ticks=633613944390979037, t_base_new=11/04/2008 11:06:13, t_base_new.Ticks=633613935735763612, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:04,129 [13] WARN Common - Avoided DivideByZero . debug: s=1779048461752, t=11/04/2008 11:21:04, _clockTickFrequency=10000000, t.Ticks=633613944641291537, t_base_new=11/04/2008 11:06:38, t_base_new.Ticks=633613935985994939, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:04,129 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1779055340520, t=11/04/2008 11:21:04, _clockTickFrequency=10000000, t.Ticks=633613944641291537, t_base_new=11/04/2008 11:06:38, t_base_new.Ticks=633613935986027212, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:30,785 [13] WARN Common - Avoided DivideByZero . debug: s=1835873951136, t=11/04/2008 11:21:30, _clockTickFrequency=10000000, t.Ticks=633613944907854037, t_base_new=11/04/2008 11:07:05, t_base_new.Ticks=633613936252602733, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:30,785 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1835879561144, t=11/04/2008 11:21:30, _clockTickFrequency=10000000, t.Ticks=633613944907854037, t_base_new=11/04/2008 11:07:05, t_base_new.Ticks=633613936252629053, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:41,519 [13] WARN Common - Avoided DivideByZero . debug: s=1858752105024, t=11/04/2008 11:21:41, _clockTickFrequency=10000000, t.Ticks=633613945015197787, t_base_new=11/04/2008 11:07:15, t_base_new.Ticks=633613936359940024, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:41,519 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1858758178416, t=11/04/2008 11:21:41, _clockTickFrequency=10000000, t.Ticks=633613945015197787, t_base_new=11/04/2008 11:07:15, t_base_new.Ticks=633613936359968519, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:50,410 [13] WARN Common - Avoided DivideByZero . debug: s=1877689301784, t=11/04/2008 11:21:50, _clockTickFrequency=10000000, t.Ticks=633613945104104037, t_base_new=11/04/2008 11:07:24, t_base_new.Ticks=633613936448787552, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:50,410 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1877700102944, t=11/04/2008 11:21:50, _clockTickFrequency=10000000, t.Ticks=633613945104104037, t_base_new=11/04/2008 11:07:24, t_base_new.Ticks=633613936448838228, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:57,457 [13] WARN Common - Avoided DivideByZero . debug: s=1892711772896, t=11/04/2008 11:21:57, _clockTickFrequency=10000000, t.Ticks=633613945174572787, t_base_new=11/04/2008 11:07:31, t_base_new.Ticks=633613936519268386, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415 04 Nov 2008 13:21:57,472 [Worker #16] WARN Common - Avoided DivideByZero . debug: s=1892742257160, t=11/04/2008 11:21:57, _clockTickFrequency=10000000, t.Ticks=633613945174729037, t_base_new=11/04/2008 11:07:31, t_base_new.Ticks=633613936519411409, immutable._t_observed=11/04/2008 11:11:15, immutable._t_base=11/04/2008 11:11:15, immutable._s_observed=524020673112, immutable._stopWatchFrequency=2131426415
|
|
|
|
 |
|
 |
Thanks for the data, shlomiw!
I now know what's going on: you've got an arithmetic overflow.
Based on the values of s and immutable._s_observed, it looks to me like eight minutes have passed since the first error you got and the last time that you called DateTimePrecise.Now. If you wait 8 minutes between calls to DateTimePrecise.Now, then the difference between the high-frequency clock samples becomes too large. When ((s - immutable._s_observed) * _clockTickFrequency * 2) is evaluated, it overflows into a negative number, that's how a negative value was being passed into the DateTimePreciseSafeImmutable constructor.
There are other reasons why DateTimePrecise is not good if you're only going to be sampling the time every 8 minutes. Because DateTimePrecise has no background thread, it only synchronizes itself when you call into it. If you only call it every eight minutes, you will find that DateTimePrecise.Now is much less accurate than DateTime.Now (even when it doesn't have arithmetic overflow problems). DateTimePrecise is more accurate the more often you call it, and it is intended for applications which have to sample the time at least a few hundred times per second.
Judging by your debug output, it looks like you have some application that lies dormant for a while, and then suddenly has to take lots of time samples very quickly, so unfortunately, your usage pattern is exactly the pattern that exposes the limitations of DateTimePrecise. 
I think the easiest solution for you is to make sure that you're calling DateTimePrecise.Now at least once every ten seconds. You may need to create a special background thread for this purpose.
P.S. To force an arithmetic overflow to throw an exception in C#, put a checked {} block around the operation that may overflow.
|
|
|
|
 |
|
 |
Hey James!
Thanks, I understand your point. I think you should add this important comment in your code  I'll arrange that the DateTimePrecise.Now will be called at-least every 10 seconds.
P.S. you judged my application correctly 
best of luck! Shlomi
|
|
|
|
 |
|
 |
You can increase the 8 min error window by applying a little algebra to the equations. (X*Y)/Z == (X/Z)*Y so the problem calculation can be done as (long)(((double)((s - immutable._s_observed) / immutable._stopWatchFrequency))* ((double)_clockTickFrequency))
if you do the division as long then you will lose accuracy so you need to do the whole thing as floating point numbers and then convert the result to long. The same change can be done when the _stopWatchFrequency is recalculated.
This should extend the 8 min window to days or even years.
|
|
|
|
 |
|
|
 |
|
 |
You're welcome, shlomiw. Let me know how it goes.
|
|
|
|
 |
|