Bug 51485 - Time profiler: Running time is always 0
Summary: Time profiler: Running time is always 0
Alias: None
Product: Runtime
Classification: Mono
Component: Profiler ()
Version: 4.8.0 (C9)
Hardware: Macintosh Mac OS
: Normal normal
Target Milestone: Future Cycle (TBD)
Assignee: Alex Rønne Petersen
: 45612 ()
Depends on:
Reported: 2017-01-12 15:43 UTC by Christophe Oosterlynck
Modified: 2017-08-26 23:53 UTC (History)
9 users (show)

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

Example profile log with 0ms (4.64 MB, application/octet-stream)
2017-01-12 15:43 UTC, Christophe Oosterlynck

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:

Description Christophe Oosterlynck 2017-01-12 15:43:10 UTC
Created attachment 19304 [details]
Example profile log with 0ms

When profiling on most of my devices (e.g. Nexus 5 and Samsung Galaxy S7) the running time mentioned by the time profiler is always 0ms for every method. On a Huawei P6 the running time is reported correctly.

When changing the "Sample cycle frequency" from 1 to 100 it does sometimes start working.


Visual Studio for Mac Preview
Version Preview 2 (7.0 build 560)
Installation UUID: 14ce014a-9f28-4189-ac59-2358db326f0a
	Mono 4.8.0 (mono-4.8.0-branch/f5fbc32) (64-bit)
	GTK+ 2.24.23 (Raleigh theme)

	Package version: 408000344


Version: 1.1.2
Location: /Applications/Xamarin Profiler.app/Contents/MacOS/Xamarin Profiler

Apple Developer Tools
Xcode 8.2 (11766)
Build 8C38

Version: (Visual Studio Enterprise)
Hash: 62816dd
Branch: master
Build date: 2016-11-15 06:24:02-0500

Version: (Visual Studio Enterprise)
Android SDK: /Users/christophe/Library/Developer/Xamarin/android-sdk-macosx
	Supported Android versions:
		4.0.3 (API level 15)
		4.1   (API level 16)
		4.2   (API level 17)
		4.4   (API level 19)
		5.0   (API level 21)
		5.1   (API level 22)
		6.0   (API level 23)
		7.0   (API level 24)
		7.1   (API level 25)

SDK Tools Version: 25.2.2
SDK Platform Tools Version: 24.0.4
SDK Build Tools Version: 23.0.2

Java SDK: /usr
java version "1.8.0_101"
Java(TM) SE Runtime Environment (build 1.8.0_101-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.101-b13, mixed mode)

Android Designer EPL code available here:

Version: (Visual Studio Enterprise)

Build Information
Release ID: 700000560
Git revision: 21714a71933f78242fea5b184a64f78bd5b11560
Build date: 2016-12-05 11:02:52-05
Xamarin addins: 6ef9b840f7003f55bc17782a901086305e96d290
Build lane: monodevelop-vNext-preview

Operating System
Mac OS X 10.12.1
Darwin Christophes-MacBook-Pro.local 16.1.0 Darwin Kernel Version 16.1.0
    Thu Oct 13 21:26:57 PDT 2016
    root:xnu-3789.21.3~60/RELEASE_X86_64 x86_64
Comment 1 Rodrigo Moya 2017-01-20 22:58:13 UTC
@alexrp see the difference Christophe sees depending on the device, could it be why we see some users reporting this and others seeing it working correctly?

The attached MLPD indeed doesn't contain any sample at all, which explains the '0ms' in all methods.
Comment 2 Alex Rønne Petersen 2017-01-22 15:41:28 UTC
OK, I think I know what's wrong. If we look at the counters for the profiler, we can see that TYPE_SAMPLE_HIT events are in fact being written to a log buffer:

> $ mprof-report --reports=counters --counters-sort=category --verbose test.mlpd
> ... snip ...
>                 Event: Sample hits: [type: UInt, unit: Raw, variance: <unknown>]
>                         0:00:00:01.000 : 4
>                         0:00:00:02.001 : 12
>                         0:00:00:03.004 : 20
>                         0:00:00:04.006 : 38
>                         0:00:00:05.008 : 61
>                         0:00:00:06.010 : 75
> ... snip ...

(The low amount of samples is because the app was presumably mostly idle and you're running with the default sampling mode, sampling-process, which only samples when there's CPU activity.)

The question, of course, is why they aren't showing up in the MLPD when all sorts of other events are showing up just fine (including counter samples, which are written in a very similar fashion to TYPE_SAMPLE_HIT events, from the helper thread). I *think* what's happening is that the 75 sample events are not enough to make the sample dumping thread decide to flush its log buffer. Each log buffer is 64k in size and a sample event structure (the one used internally in the profiler, not the one in the format) is 60 bytes in size (kinda tiny since you're using maxframes=8). Of course, 75 * 60 is nowhere near enough to make the sample dumping thread flush its log buffer.

This isn't normally a problem because apps that actually do a significant amount of work will produce a ton of samples, so the sample dumping thread flushes its log buffer all the time. Also, on normal shutdown, the sample dumping thread flushes its log buffer unconditionally, so any leftover samples won't be lost. This is all well and good for batch applications (servers, compilers, what have you), but clearly isn't ideal for GUI apps that tend to idle between work. Further, mobile apps often don't shut down cleanly like on desktop, so samples are likely to be lost if the sample dumping thread's log buffer isn't flushed regularly.

@Christophe: You can verify my hypothesis by simply making the app do some artificial work, like calling Thread.SpinWait (100) in a loop.

If my hypothesis turns out to be true, the fix is fairly simple: The profiler should just flush the sample dumping thread's log buffer every second just like what's done for the helper thread. Well, it should probably do that anyway.
Comment 3 Rodrigo Moya 2017-02-02 18:24:15 UTC
Moving to runtime profiler then. On the profiler UI side, we're investigating about using sampling-real (and offering a UI to switch between one or the other)
Comment 4 Rodrigo Moya 2017-02-02 19:08:16 UTC
*** Bug 45612 has been marked as a duplicate of this bug. ***
Comment 5 Alex Rønne Petersen 2017-08-26 23:53:28 UTC
This should be fixed in Mono 5.6.