Generated Ids have timestamps from the past

[stuart-beattie]

The stopwatch is declared/instantiated as a static variable.

So it wont actually be started until it is referenced.

This results in timestamps that are marked back in time. The elapsed time is only measured after the stopwatch starts and the stopwatch only starts after the first call to CreateId().

Initializing with a call to CreateId on process startup as a workaround.

[RobThree]

Can you please give an example / testcase so I can reproduce?

This is how I tested:

Console.WriteLine($"Time is now: {DateTime.Now}");
var g = new IdGenerator(0);
var shiftbits = g.MaskConfig.GeneratorIdBits + g.MaskConfig.SequenceBits;
var offset = g.TimeSource.Epoch.ToLocalTime();

Console.WriteLine($"Waiting 10 seconds...");
Thread.Sleep(1000 * 10);

var id = g.CreateId();
Console.WriteLine($"Time is now: {DateTime.Now}, generating ID...");
Console.WriteLine($"Generated id: {id}");

var date = offset + TimeSpan.FromMilliseconds(id >> shiftbits);
Console.WriteLine($"Extracted timestamp: {date}");

And this is my output:

Time is now: 19-2-2020 14:36:59
Waiting 10 seconds...
Time is now: 19-2-2020 14:37:09, generating ID...
Generated id: 679682892149817344
Extracted timestamp: 19-2-2020 14:37:09

As you can see, the generator is instantiated at 14:36:59, an ID is generated at 14:37:09 and when I 'extract' the timestamp from the ID I get that exact value?

[stuart-beattie]

Thanks for getting back on this.

I have just tried your code and I get this following output...

Time is now: 19/02/2020 14:11:24
Waiting 10 seconds...
Time is now: 19/02/2020 14:11:35, generating ID...
Generated id: 679691514317635584
Extracted timestamp: 19/02/2020 14:11:25 +00:00

[stuart-beattie]

Running in a .net core 3.1 console app

[RobThree]

Hmmm. appears to be a difference between referencing the IDGen project and using the NuGet package and between release/debug builds. Your initial reasoning is sound and your suggested workaround works. I'll look into fixing this.

Build	Project Reference	NuGet package
Debug	✔️	❌
Release	❌	❌

Out of curiosity: why are you 'extracting' the timestamp from the generated ID's? Even though it's documented how an ID is generated, you're supposed to treat is as a "blob" 😉

[stuart-beattie]

Ah I wasnt, its just we had two nodes populating records in a shared database table, using this component to generate the ids. Fetching the records, ordering by id and then ordering by creation date yielded different results (despite the clocks being synced). Took me a while to work it out :)

[RobThree]

That must've been a pain to debug, I bet! Sorry 'bout that! I'll make sure this gets fixed; not sure how yet (I could call CreateID() just before the end of the ctor but that's ugly and may have unintentional side-effects...). I'm going to think about this. Suggestions welcome!

[stuart-beattie]

You could try adding a static constructor to the StopwatchTimeSource class, and instantiating the StopWatch there

[RobThree]

I just noticed Stopwatch.Start() "starts or resumes" a stopwatch. So I could just call _sw.Start() from the StopwatchTimeSource ctor I guess. And then I could initialize the _sw field with just new Stopwatch()...

[RobThree]

See 1417890

Build	Project Reference	NuGet package (2.1)
Debug	✔️	✔️
Release	✔️	✔️

That seems to fix it. I'll create and release a new NuGet package soon. Thanks for reporting, working and thinking with me on this one!

[stuart-beattie]

Great! no problem, thanks.

[RobThree]

Will be in 2.1 release soon to be released.

🎉 Yay! See version 2.1 now also on NuGet along with the new IdGen.Configuration package 🎉