NET6 - Stopwatch.ElapsedMilliseconds returns wrong result when using monoVM on linux-arm

[michaldobrodenka]

Description

Results seem to be 100x bigger.

Reproduction Steps

I was testing minimal Thread.Sleep() time with following program:

Stopwatch sw = new Stopwatch();

while(true)
{
    sw.Restart();
    Thread.Sleep(1);
    sw.Stop();
    Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")} - Elapsed {sw.ElapsedMilliseconds}");
}

deployed with
dotnet publish -r linux-arm -p:PublishTrimmed=True -p:TrimMode=Link --self-contained true -c Release -f net6.0 -o bin\dotnet\mono -p:UseMonoRuntime=true - for monoVM

and
dotnet publish -r linux-arm -p:PublishTrimmed=True -p:TrimMode=Link --self-contained true -c Release -f net6.0 -o bin\dotnet - for default dotnet runtime

Expected behavior

Expected to return number of milliseconds elapsed.

Actual behavior

100x elapsed millisecods for mono VM.

On screenshot first part is using monoVM, second default dotnet runtime.

Regression?

No response

Known Workarounds

No response

Configuration

No response

Other information

Tested on 32bit linux-arm on Yocto linux

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[michaldobrodenka]

seems to be fine on win-x64 platform with mono:

[Clockwork-Muse]

Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss")} - Elapsed {sw.ElapsedMilliseconds}");
but the output is:
2021-11-15 16:45:44.775 - Elapsed 15

You don't have a fractional specifier in your format string, so are you sure the code being run is the code currently written (yes, I've seen your other issue).

[michaldobrodenka]

Sorry, should be:
Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")} - Elapsed {sw.ElapsedMilliseconds}");

To be sure I'm going to retest it.

[MichalPetryka]

You probably should use sw.Elapsed.TotalMiliseconds in order to get more accurate values.

[michaldobrodenka]

You probably should use sw.Elapsed.TotalMiliseconds in order to get more accurate values.
@MichalPetryka

sw.Elapsed.TotalMiliseconds results are also *100.

while(true)
{
    sw.Restart();
    Thread.Sleep(1);
    sw.Stop();
    Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")} - Elapsed {sw.ElapsedMilliseconds} - Total {sw.Elapsed.TotalMilliseconds}");
}

result (linux-arm, monoVM):

2021-11-16 09:44:32.8389687 - Elapsed 113 - Total 113.1042
2021-11-16 09:44:32.8403993 - Elapsed 113 - Total 113.7333
2021-11-16 09:44:32.8418021 - Elapsed 113 - Total 113.9958
2021-11-16 09:44:32.8432352 - Elapsed 114 - Total 114.5292

There are about 750 lines per second, so it's about 1-1.5ms for each line, but reported value is between 100-150

[michaldobrodenka]

DateTime.Millisecond return correct value.

Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")} - {DateTime.Now.Millisecond}ms - Elapsed {sw.ElapsedMilliseconds} - Total {sw.Elapsed.TotalMilliseconds}");

result in:

2021-11-16 10:46:06.9695772 - 969ms - Elapsed 110 - Total 110.4625
2021-11-16 10:46:06.9708808 - 970ms - Elapsed 110 - Total 110.2084
2021-11-16 10:46:06.9721416 - 972ms - Elapsed 109 - Total 109.8917
2021-11-16 10:46:06.9734647 - 973ms - Elapsed 109 - Total 109.7291
2021-11-16 10:46:06.9747487 - 974ms - Elapsed 110 - Total 110.5334

[michaldobrodenka]

Maybe problem is with comething like CurrentCulture/Calendar Ticks per second or something like that.

[Clockwork-Muse]

Maybe problem is with comething like CurrentCulture/Calendar Ticks per second or something like that.

Unlikely, culture shouldn't be accessed for the stopwatch calculations.

The most likely culprit is that the resolution translation code has an issue (in at least the windows APIs, timers return a tick count and a value giving the resolution).

The other possibility is that whatever clock the stopwatch is using for timings just has a really bad resolution? DateTime(Offset) and StopWatch use different mechanisms to get "time" (since for one you want potentially updated wall-clock time, and for the other you just want an elapsed time), so it's possible that your hardware is providing a poor timing clock. What hardware are you deploying this on?

[michaldobrodenka]

The other possibility is that whatever clock the stopwatch is using for timings just has a really bad resolution? DateTime(Offset) and StopWatch use different mechanisms to get "time" (since for one you want potentially updated wall-clock time, and for the other you just want an elapsed time), so it's possible that your hardware is providing a poor timing clock. What hardware are you deploying this on?

Device is embedded board with Allwinner H3 board (Nano pi core). I tried it with mono 6.6 which I have on the system also and it seems ok:

Program:

using System;
using System.Diagnostics;
using System.Threading;

namespace StopwatchTestFW
{
    internal class Program
    {
        static void Main(string[] args)
        {
            Stopwatch sw = new Stopwatch();

            while (true)
            {
                sw.Restart();
                Thread.Sleep(1);
                sw.Stop();
                Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")} - {DateTime.Now.Millisecond}ms - Elapsed {sw.ElapsedMilliseconds} - Total {sw.Elapsed.TotalMilliseconds}");
            }
        }
    }
}

NET5 - ok
NET6 - default runtime - ok
Mono 6.6 & net FW 4.50 Exe - ok
NET6 - MonoVM - bug

[michaldobrodenka]

Problem is already in Ticks:

2021-11-17 09:21:31.1446956 - 144ms - Elapsed 141 - Total 141.3125 - in ticks 1413125
2021-11-17 09:21:31.1463332 - 146ms - Elapsed 143 - Total 143.2875 - in ticks 1432875

So 1.4ms - 1432875Ticks

Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")} - {DateTime.Now.Millisecond}ms - Elapsed {sw.ElapsedMilliseconds} - Total {sw.Elapsed.TotalMilliseconds} - in ticks {sw.ElapsedTicks}");

Tagging subscribers to this area:
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

Results seem to be 100x bigger.

Reproduction Steps

I was testing minimal Thread.Sleep() time with following program:

Stopwatch sw = new Stopwatch();

while(true)
{
    sw.Restart();
    Thread.Sleep(1);
    sw.Stop();
    Console.WriteLine($"{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")} - Elapsed {sw.ElapsedMilliseconds}");
}

deployed with
dotnet publish -r linux-arm -p:PublishTrimmed=True -p:TrimMode=Link --self-contained true -c Release -f net6.0 -o bin\dotnet\mono -p:UseMonoRuntime=true - for monoVM

and
dotnet publish -r linux-arm -p:PublishTrimmed=True -p:TrimMode=Link --self-contained true -c Release -f net6.0 -o bin\dotnet - for default dotnet runtime

Expected behavior

Expected to return number of milliseconds elapsed.

Actual behavior

100x elapsed millisecods for mono VM.

On screenshot first part is using monoVM, second default dotnet runtime.

Regression?

No response

Known Workarounds

No response

Configuration

No response

Other information

Tested on 32bit linux-arm on Yocto linux

Author:	michaldobrodenka
Assignees:	-
Labels:	untriaged, area-VM-meta-mono
Milestone:	-