Have a look at this simple DateTime example
Hello,
I could not follow the mechanism of the CLR how it updates the DateTime.Now property.
The following code should demonstrate my intention:
Code:
[STAThread]
static void Main(string[] args)
{
for(int i=0;i<10;++i)
{
DateTime dt = DateTime.Now;
Console.WriteLine("before the loop: ".PadRight(20,' ') + dt.Second + ":" + dt.Millisecond);
for(int n=0; n<1000000; ++n);
dt = DateTime.Now;
Console.WriteLine("after the loop: ".PadRight(20,' ') + dt.Second + ":" + dt.Millisecond);
}
}
The result of the output is:
Code:
before the loop: 33:905
after the loop: 33:921
before the loop: 33:921
after the loop: 33:921
before the loop: 33:921
after the loop: 33:921
before the loop: 33:921
after the loop: 33:937
before the loop: 33:937
after the loop: 33:937
before the loop: 33:937
after the loop: 33:937
before the loop: 33:937
after the loop: 33:952
before the loop: 33:952
after the loop: 33:952
before the loop: 33:952
after the loop: 33:952
before the loop: 33:952
after the loop: 33:952
My questions are:
Why dosen't the milliseconds change on every step?
Are there other approaches?
Thanks
woodz
Re: Have a look at this simple DateTime example
Quote:
Originally Posted by woodz
Why dosen't the milliseconds change on every step?
That is because the loop executes quickly on the system. This is the reason why you don't see the milliseconds being elapsed
Quote:
Originally Posted by woodz
Are there other approaches?
That would depend on what you are trying to do. You could even try using Environment.TickCount. This should be a better approach.
Re: Have a look at this simple DateTime example
Well,
I am not sure whether seeing elapsed milliseconds depends on the "quickley" executed loop.
I tried the following to see any changes:
Code:
static void Main(string[] args)
{
for(int i=0;i<10;++i)
{
Console.WriteLine("before the loop: ".PadRight(20,' ') + Environment.TickCount);
for(int n=0; n<1000000; ++n);
Console.WriteLine("after the loop: ".PadRight(20,' ') + Environment.TickCount);
for(int n=0; n<1000000; ++n);
}
}
output is:
Code:
before the loop: 18151125
after the loop: 18151125
before the loop: 18151140
after the loop: 18151140
before the loop: 18151140
after the loop: 18151140
before the loop: 18151156
after the loop: 18151156
before the loop: 18151156
after the loop: 18151171
before the loop: 18151171
after the loop: 18151171
before the loop: 18151187
after the loop: 18151187
before the loop: 18151187
after the loop: 18151203
before the loop: 18151203
after the loop: 18151203
before the loop: 18151218
after the loop: 18151218
That tells us using Environment.TickCount has the same result as using DateTime.
Then I tried this:
Code:
static void Main(string[] args)
{
for(int i=0;i<10;++i)
{
Console.WriteLine("before the loop: ".PadRight(20,' ') + Environment.TickCount);
Thread.Sleep(10);
Console.WriteLine("after the loop: ".PadRight(20,' ') + Environment.TickCount);
Thread.Sleep(10);
}
}
output is:
Code:
before the loop: 18423656
after the loop: 18423671
before the loop: 18423687
after the loop: 18423687
before the loop: 18423703
after the loop: 18423718
before the loop: 18423734
after the loop: 18423734
before the loop: 18423750
after the loop: 18423765
before the loop: 18423765
after the loop: 18423781
before the loop: 18423796
after the loop: 18423796
before the loop: 18423812
after the loop: 18423828
before the loop: 18423828
after the loop: 18423843
before the loop: 18423859
after the loop: 18423875
The outcome of this is, sleeping for 10ms delivers better results but worse performance. My intention ist not to go to bed on every step.
Finally the best results are reched when sleeping at lest for 30ms:
Code:
static void Main(string[] args)
{
for(int i=0;i<10;++i)
{
Console.WriteLine("before the loop: ".PadRight(20,' ') + Environment.TickCount);
Thread.Sleep(30);
Console.WriteLine("after the loop: ".PadRight(20,' ') + Environment.TickCount);
Thread.Sleep(30);
}
}
the output:
Code:
before the loop: 18979171
after the loop: 18979203
before the loop: 18979234
after the loop: 18979265
before the loop: 18979296
after the loop: 18979328
before the loop: 18979359
after the loop: 18979390
before the loop: 18979406
after the loop: 18979437
before the loop: 18979468
after the loop: 18979515
before the loop: 18979546
after the loop: 18979578
before the loop: 18979609
after the loop: 18979640
before the loop: 18979671
after the loop: 18979703
before the loop: 18979718
after the loop: 18979750
My pristine intention is building a frame logger that logs incomming Frames from a CAN (Controller Area Network) Card. Received frames are handled by a callback function of the driver. If you don't know about the CAN BUS it doesn't mater. You can imagine logging lines of text to a file and give each line a timestamp. Here is an example of my log file:
Code:
W: 17:25:24.640 790h 8d d1h 04h 00h 1ch ffh ffh ffh ffh Q....... Write Hmf Sequence 1 on Adr 1ch - 1fh
R: 17:25:24.655 (15:25:24.629) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:25:24.655 790h 8d d1h 04h 00h 20h ffh ffh ffh ffh Q....... Write Hmf Sequence 1 on Adr 20h - 23h
R: 17:25:24.671 (15:25:24.644) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:25:24.671 790h 8d d1h 04h 00h 24h ffh ffh ffh ffh Q..$.... Write Hmf Sequence 1 on Adr 24h - 27h
R: 17:25:24.671 (15:25:24.654) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:25:24.687 790h 8d d1h 04h 00h 28h ffh ffh ffh ffh Q..(.... Write Hmf Sequence 1 on Adr 28h - 2bh
R: 17:25:24.687 (15:25:24.669) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:25:24.702 790h 8d d1h 04h 00h 2ch ffh ffh ffh ffh Q..,.... Write Hmf Sequence 1 on Adr 2ch - 2fh
R: 17:25:24.702 (15:25:24.684) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:25:24.702 790h 8d d1h 04h 00h 30h ffh ffh ffh ffh Q..0.... Write Hmf Sequence 1 on Adr 30h - 33h
R: 17:25:24.718 (15:25:24.694) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:25:24.718 790h 8d d1h 04h 00h 34h ffh ffh ffh ffh Q..4.... Write Hmf Sequence 1 on Adr 34h - 37h
R: 17:25:24.734 (15:25:24.709) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:25:24.734 790h 8d d1h 04h 00h 38h ffh ffh ffh ffh Q..8.... Write Hmf Sequence 1 on Adr 38h - 3bh
If we look at the timestmps we can recognize the same behaviour as we have seen at the above simulation with the loops. The timestamps in Braces come from the driver and are always correct. The way from sending or receiving a Frame and bring it to the file is driven by an event. On any Frame I notify any observers which are intersted on it. The invokation over the event delegate ist asynchronous. So formatting to text and write to the file ist executed in a seperate thread. It seems that time needed for this is short enough to sometimes see no changes of the milliseconds.
My questions are:
How can I workaround the problem without sleeping? I cannot sleep. If I do the entries of the logfile appear confused. Like this:
Code:
W: 17:21:58.093 790h 8d d1h 04h 00h 1ch ffh ffh ffh ffh Q....... Write Hmf Sequence 1 on Adr 1ch - 1fh
W: 17:21:58.124 790h 8d d1h 04h 00h 20h ffh ffh ffh ffh Q....... Write Hmf Sequence 1 on Adr 20h - 23h
R: 17:21:58.093 (15:21:56.550) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:21:58.124 790h 8d d1h 04h 00h 24h ffh ffh ffh ffh Q..$.... Write Hmf Sequence 1 on Adr 24h - 27h
R: 17:21:58.109 (15:21:56.560) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:21:58.155 790h 8d d1h 04h 00h 28h ffh ffh ffh ffh Q..(.... Write Hmf Sequence 1 on Adr 28h - 2bh
R: 17:21:58.124 (15:21:56.570) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:21:58.155 790h 8d d1h 04h 00h 2ch ffh ffh ffh ffh Q..,.... Write Hmf Sequence 1 on Adr 2ch - 2fh
R: 17:21:58.124 (15:21:56.585) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:21:58.171 790h 8d d1h 04h 00h 30h ffh ffh ffh ffh Q..0.... Write Hmf Sequence 1 on Adr 30h - 33h
W: 17:21:58.187 790h 8d d1h 04h 00h 34h ffh ffh ffh ffh Q..4.... Write Hmf Sequence 1 on Adr 34h - 37h
R: 17:21:58.155 (15:21:56.595) 791h 8d d1h ffh 02h 70h 01h 00h 00h 00h Q..p....
W: 17:21:58.187 790h 8d d1h 04h 00h 38h ffh ffh ffh ffh Q..8.... Write Hmf Sequence 1 on Adr 38h - 3bh
Thanks in advance
WOODZ
Re: Have a look at this simple DateTime example
Quote:
Originally Posted by woodz
Code:
[STAThread]
static void Main(string[] args)
{
for(int i=0;i<10;++i)
{
DateTime dt = DateTime.Now;
Console.WriteLine("before the loop: ".PadRight(20,' ') + dt.Second + ":" + dt.Millisecond);
for(int n=0; n<1000000; ++n);
dt = DateTime.Now;
Console.WriteLine("after the loop: ".PadRight(20,' ') + dt.Second + ":" + dt.Millisecond);
}
}
I believe that the for loop will be erased by the compiler. It is a useless loop and the optimizer of the compiler could eliminate that. Maybe that explains your behavior on the time counter. You should have a look at the IL Code for the loop. Maybe there is no one. ;)
Re: Have a look at this simple DateTime example
You need to make a call to unmanaged code to get greater than 15ms resolution. The tickcount you was using was based on windows rather than the cpu...
Code:
using System;
using System.Runtime.InteropServices;
using System.Collections.Generic;
using System.Text;
namespace ConsoleApplication1
{
class Program
{
[DllImport("Kernel32.dll")]
private static extern bool QueryPerformanceCounter(
out long lpPerformanceCount);
[DllImport("Kernel32.dll")]
private static extern bool QueryPerformanceFrequency(
out long lpFrequency);
[STAThread]
static void Main(string[] args)
{
long startTime, stopTime;
long freq;
QueryPerformanceFrequency(out freq);
for (int i = 0; i < 10; ++i)
{
QueryPerformanceCounter(out startTime);
Console.WriteLine("before the loop: ".PadRight(20, ' ') + startTime / (double)freq + 's');
for (int n = 0; n < 1000000; ++n) ;
QueryPerformanceCounter(out stopTime);
Console.WriteLine("after the loop: ".PadRight(20, ' ') + stopTime / (double)freq + 's');
}
Console.ReadKey();
}
}
}
a nice class for the above is here:
http://www.codeproject.com/csharp/hi...timercshar.asp
Re: Have a look at this simple DateTime example
very nice *io*,
what I still want know, the CLR comes with a PerformanceCounter class too. Can I use it to solve the problem as you did with PInvoke?
@torrud
maybe you are right. But Thred.Sleep(...) should make the delay but solves not my problem. Thank you for this tip! I never considered this.
Thanks
woodz
Re: Have a look at this simple DateTime example
I found a more accurate solution:
http://www.codeproject.com/csharp/highresclock.asp
A precise clock, which can mesure points not only spans.
Maybye someone is interested.
Woodz
