Bug 36327 - Profiler outputs: "time went backwards"
Summary: Profiler outputs: "time went backwards"
Status: RESOLVED INVALID
Alias: None
Product: Runtime
Classification: Mono
Component: Tools ()
Version: 4.2.0 (C6)
Hardware: PC Linux
: --- normal
Target Milestone: ---
Assignee: Alex Rønne Petersen
URL:
Depends on:
Blocks:
 
Reported: 2015-11-28 14:22 UTC by Josip Bakic
Modified: 2015-12-08 19:10 UTC (History)
3 users (show)

Tags:
Is this bug a regression?: ---
Last known good build:

Notice (2018-05-24): bugzilla.xamarin.com is now in read-only mode.

Please join us on Visual Studio Developer Community and in the Xamarin and Mono organizations on GitHub to continue tracking issues. Bugzilla will remain available for reference in read-only mode. We will continue to work on open Bugzilla bugs, copy them to the new locations as needed for follow-up, and add the new items under Related Links.

Our sincere thanks to everyone who has contributed on this bug tracker over the years. Thanks also for your understanding as we make these adjustments and improvements for the future.


Please create a new report on GitHub or Developer Community with your current version information, steps to reproduce, and relevant error messages or log files if you are hitting an issue that looks similar to this resolved bug and you do not yet see a matching new report.

Related Links:
Status:
RESOLVED INVALID

Description Josip Bakic 2015-11-28 14:22:22 UTC
Hi!

The profiler outputs the message "time went backwards" many times, then eventually blocks and I have to kill it. It has not been working on my machine for some time, since a version 3.x, but this is a new way of failing. I presume my system is the problem, but I have no idea what to do.

The profiled program is a small console app targetting .NET 4, running sometimes single-, sometimes multi-threaded code. The source is available on GitHub, if needed - https://github.com/jbakic/Shielded - the ConsoleTests project. It's about 10x slower in certain operations since the last update (see below).

The system is Ubuntu 14.04 with the Mono PPA added.

Mono JIT compiler version 4.2.1 (Stable 4.2.1.102/6dd2d0d Thu Nov 12 09:52:44 UTC 2015)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
	TLS:           __thread
	SIGSEGV:       altstack
	Notifications: epoll
	Architecture:  amd64
	Disabled:      none
	Misc:          softdebug 
	LLVM:          supported, not enabled.
	GC:            sgen

Thank you!

Josip Bakic
Comment 1 Andi McClure 2015-12-08 16:37:29 UTC
Alex, could you look at this? I think it might be a dupe of bug #30358.
Comment 2 Alex Rønne Petersen 2015-12-08 19:10:09 UTC
Oh dear. This one is a great example of why enter/leave profiling is an absolutely horrendous default that we should get rid of in the next major Mono release (5.x).

What happens here (at least on my end) is not that the program hangs, it's that it takes *ages* to complete. This is because it's producing billions upon billions of method enter/leave events. This is the default profiling mode where we log an event to the profiler log file for every single method entry/exit in the program. It's producing so many gigabytes per minute that I had to actually redirect the output to /dev/null because I didn't have enough hard drive space for the log file:

> $ time mono "--profile=log:output=|cat>/dev/null" ConsoleTests.exe
> Testing simple proxy ops with 1000000 iterations, and repeats per trans (N) = 50
> WARM UP in 72032 ms.
> empty transactions in 8079 ms.
> 1 non-transactional read w/ returning result in 10542 ms.
> 1-read transactions in 18943 ms.
> N out-of-tr. reads in 83515 ms.
> N-reads transactions in 291430 ms.
> 1-read-1-write transactions in 71601 ms.
> 1-write transactions in 68099 ms.
> N-write transactions in 383891 ms.
> 1-write-N-reads transactions in 306253 ms.
> 1-commute transactions in 90297 ms.
> N-commute transactions in 110585 ms.
> 
> cost of empty transaction = 8.079 us
> cost of the closure in InTransaction<T> = 2.463 us
> cost of an out-of-tr. read = 1.670 us
> cost of the first read = 10.864 us
> cost of an additional read = 5.561 us
> cost of write after read = 52.658 us
> cost of the first write = 60.020 us
> cost of an additional write = 6.445 us
> cost of a read after write = 4.763 us
> cost of the first commute = 82.218 us
> cost of an additional commute = 20.726 us
> mono "--profile=log:output=|cat>/dev/null" ConsoleTests.exe  2995,85s user 36,99s system 200% cpu 25:15,77 total

This is how long it took even when discarding all the output. You can imagine how slow it would be when actually writing the data to disk. The enter/leave profiling mode is really only suited for debugging and code coverage tools. It's a very, very unfortunate default.

So, what to do? The answer is the sampling mode of the profiler:

> $ time mono --profile=log:sample ConsoleTests.exe
> Testing simple proxy ops with 1000000 iterations, and repeats per trans (N) = 50
> WARM UP in 11110 ms.
> empty transactions in 143 ms.
> 1 non-transactional read w/ returning result in 428 ms.
> 1-read transactions in 268 ms.
> N out-of-tr. reads in 671 ms.
> N-reads transactions in 2472 ms.
> 1-read-1-write transactions in 10857 ms.
> 1-write transactions in 11501 ms.
> N-write transactions in 14466 ms.
> 1-write-N-reads transactions in 12268 ms.
> 1-commute transactions in 12347 ms.
> N-commute transactions in 3325 ms.
> 
> cost of empty transaction = 0.143 us
> cost of the closure in InTransaction<T> = 0.285 us
> cost of an out-of-tr. read = 0.013 us
> cost of the first read = 0.125 us
> cost of an additional read = 0.045 us
> cost of write after read = 10.589 us
> cost of the first write = 11.358 us
> cost of an additional write = 0.061 us
> cost of a read after write = 0.015 us
> cost of the first commute = 12.204 us
> cost of an additional commute = 0.427 us
> mono --profile=log:sample ConsoleTests.exe  160,13s user 0,22s system 199% cpu 1:20,22 total

This mode is how the vast majority of profilers work, and it's the mode that we recommend using for actual performance analysis. It's the least intrusive mode and doesn't produce even remotely as much pointless data:

> $ ls -lah output.mlpd
> -rw-rw-r-- 1 alexrp alexrp 130M dec  8 19:59 output.mlpd

Note that you may have to fiddle around with sampling frequency and other such options to get the desired results, as sampling works fundamentally differently from enter/leave profiling. See `man mprof-report`.

So, closing this as NOTABUG. Feel free to reopen if you see different results than me, though.

(@Andi: Don't think this one's got much to do with #30358.)