Bug 45612 - Time profiling not working on VS15
Summary: Time profiling not working on VS15
Status: RESOLVED DUPLICATE of bug 51485
Alias: None
Product: Profiler
Classification: Xamarin
Component: Android ()
Version: unspecified
Hardware: PC Windows
: High normal
Target Milestone: (C9)
Assignee: Jose Miguel Torres
URL:
Depends on:
Blocks:
 
Reported: 2016-10-18 07:18 UTC by Dima
Modified: 2017-02-02 19:08 UTC (History)
9 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 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 DUPLICATE of bug 51485

Description Dima 2016-10-18 07:18:11 UTC
Time profiling not working for latest versions of profiler, from 0.34 to 0.38.
The column "Running Time" is mostly 0. Even after using "heavy" method, that takes most of time, several times it still displayed - Running Time 0.

Using:
Windows 8,
Visual Studion 15, Update 3,
Xamarin 4.2.0
Xamarin Profiler 0.38
Comment 1 Rodrigo Moya 2016-10-18 08:14:52 UTC
Can you please share the resulting MLPD (File->Save as after you've profiled the app)?
Comment 2 Dima 2016-10-18 10:17:27 UTC
MLPD file:
https://drive.google.com/open?id=0B8G2dAyGiey0eHk0UjdLRl8xVUU

After some research I noticed that the information of profiler is not always updated. After using some (not always same) action it might to take 20-30 seconds untill show and update this action in Profiler.
In this file I used search action - RecordListViewModel:search, but it's not even displayed in profiler.
Comment 3 Rodrigo Moya 2016-10-19 13:10:30 UTC
I see you are using '1000' as the sample cycle frequency, which was the old default we had, so can you change it (in the app's preferences) to 100 and see if it gets any better?

This is the mprof-report output on that MLPD, and indeed seems we're getting too few samples, which probably is because of the '1000' value in sample cycle frequency.

Mono log profiler data
	Profiler version: 1.0
	Data version: 13
	Arguments: log:heapshot=1gc,noalloc,nocalls,maxframes=8,sample=cycles/1000,,output=#21
	Architecture: x86
	Operating system: linux
	Mean timer overhead: 550 nanoseconds
	Program startup: Tue Oct 18 11:54:15 2016
	Program ID: 22220
	Server listening on: 49230

JIT summary
	Compiled methods: 7730
	Generated code size: 1905286
	JIT helpers: 16677
	JIT helpers code size: 1917279

GC summary
	GC resizes: 0
	Max heap size: 0
	Object moves: 251396
	Gen0 collections: 7, max time: 25481us, total time: 87178us, average: 12454us
	GC handles weak: created: 633, destroyed: 358, max: 579
	GC handles weaktrack: created: 1944, destroyed: 454, max: 1490
	GC handles normal: created: 2, destroyed: 0, max: 2

Statistical samples summary
	Sample type: cycles
	Unmanaged hits:    2548 (98.8%)
	Managed hits:        32 ( 1.2%)
	Unresolved hits:    223 ( 8.6%)
	  Hits      % Method name
	  1927  74.69 syscall
	   107   4.15 clock_gettime
	    93   3.60 gettimeofday
	    25   0.97 read
	     9   0.35 mono_metadata_type_hash
	     9   0.35 pthread_mutex_lock
	     7   0.27 fstatat
	     6   0.23 pthread_mutex_unlock
	     6   0.23 strcmp
	     5   0.19 Java.Interop.JniEnvironment/Object:AllocObject (Java.Interop.JniObjectReference)
	     5   0.19 mono_metadata_decode_row_col
	     5   0.19 memcpy
	     5   0.19 _ZN3art11ScopedCheck18CheckVirtualMethodEP8_jobjectP10_jmethodID
	     4   0.16 System.Security.Cryptography.RijndaelManagedTransform:Dec (int*,int*,int*,int*,int*,int*)
	     4   0.16 memset
	     4   0.16 strlen
	     4   0.16 _ZN3art6mirror5Class25FindDeclaredVirtualMethodERKNS_11StringPieceES4_
	     4   0.16 artQuickToInterpreterBridge
	     4   0.16 mono_metadata_get_inflated_signature
	     4   0.16 madvise
	     3   0.12 System.Threading.Timer/Scheduler:SchedulerThread ()
	     3   0.12 __epoll_pwait
	     3   0.12 pthread_mutex_trylock
	     3   0.12 mono_class_enum_basetype
	     3   0.12 mono_metadata_decode_row
	     3   0.12 mono_error_init
	     3   0.12 pthread_mutex_unlock
	     3   0.12 sched_yield
	     3   0.12 pread64
	     3   0.12 munmap
	     3   0.12 pthread_mutex_lock
	     3   0.12 __ioctl

 So please try again after changing it to 100.
Comment 4 Dima 2016-10-20 05:55:06 UTC
I don't have any "sample cycle frequency" in Profiler options. What I have is: 
Tools -> Options -> Sampling:
1. Samples per Second: 10
2. Max Frames: 8
3. Call Depth: 100

I think what you mean is Samples per Second. I set it to 10000 and this is what I got:
https://drive.google.com/open?id=0B8G2dAyGiey0UGNzWFB0WF9OZzQ

In profiler search toolbar I entered "search" string and noticed that some of actions are 0 running time. Also some actions still missing and appears in profiler only after using them several times.
Comment 5 Rodrigo Moya 2016-10-20 08:42:44 UTC
Yes, the label is wrong, sorry. We have it fixed internally and will be released publicly soon, but what that value is referring to is the interval between samples, so if you set it to 10,000 you'll get many less samples, as between samples it would wait 10,000 microseconds.

With 10,000, you get even less samples than before:

Statistical samples summary
	Sample type: cycles
	Unmanaged hits:   12014 (98.9%)
	Managed hits:       132 ( 1.1%)
	Unresolved hits:    557 ( 4.6%)
	  Hits      % Method name
	 10128  83.39 syscall
	   537   4.42 clock_gettime
	   254   2.09 gettimeofday
	   112   0.92 read
	    20   0.16 madvise
	    13   0.11 Mono.Globalization.Unicode.SimpleCollator:GetContraction (string,int,int,Mono.Globalization.Unicode.Contraction[])
	    13   0.11 fstatat

So whatever the label says, please set it to 100 and try again.
Comment 6 Dima 2016-10-20 10:01:33 UTC
It seems like changing this parametr makes no difference.

Search action still not visible here:
https://drive.google.com/open?id=0B8G2dAyGiey0YWlLcGozeFVNSTQ

After waiting about 20 seconds and doing nothing in application I got this:
https://drive.google.com/open?id=0B8G2dAyGiey0R2pUd0tXZGEwUmM
Comment 7 Rodrigo Moya 2016-10-20 11:13:53 UTC
In both runs, you're still using 1000 for 'sample cycle frequency':

ardones:profiler rodrigo$ mprof-report ~/Public/sampling100.mlpd | grep Arguments
	Arguments: log:heapshot=2000ms,noalloc,nocalls,maxframes=8,sample=cycles/1000,,output=#21
ardones:profiler rodrigo$ mprof-report ~/Public/sampling100_2.mlpd | grep Arguments
	Arguments: log:heapshot=2000ms,noalloc,nocalls,maxframes=8,sample=cycles/1000,,output=#21

so please make sure you change it in the preferences dialog before starting to profile.
Comment 8 Dima 2016-10-20 11:18:10 UTC
What I see in Profiler options:
Samples per Second: 100
Comment 9 Rodrigo Moya 2016-10-20 11:28:33 UTC
can you check in regedit.exe, what the value of SamplesPerSecond key in HKEY_CURRENT_USER\SOFTWARE\Xamarin\Profiler is after having changed the setting?
Comment 10 Rodrigo Moya 2016-10-20 12:07:42 UTC
Ok, this is a bug we have, already fixed internally, but not on the build you have, so:

* change the setting to 100 in the options dialog
* exit the profiler
* start profiling again as before

The bug is that the options dialog was not saving the changes.
Comment 11 Dima 2016-10-23 06:27:20 UTC
It seems that this parameter has no affect, still have same issue after changing it to 100.

https://drive.google.com/open?id=0B8G2dAyGiey0cjJ4TnBmTlJ3SE0
Comment 12 Dima 2016-11-07 09:42:35 UTC
Is there something new for this bug?
Currently I can't use the profiler but I very need to.
Comment 13 Prashant manu 2016-11-10 08:55:33 UTC
@Rodrigo, I have checked this issue with Profiler v1.0.0-12 and getting same issue after setting 'sample cycle frequency' to 100.

Profiler Log: https://gist.github.com/Asimk360/3db62bc0df5f5333ce5d8d4286c03337
Screencast: http://www.screencast.com/t/6O4vsguezABk
Comment 14 Rodrigo Moya 2016-11-10 09:43:43 UTC
@Prashant you are not getting '0 ms', there is one node in the call tree that has 5k ms
Comment 15 Rodrigo Moya 2016-12-21 09:42:43 UTC
Dima, is it working better with the 1.0.x profiler versions?
Comment 16 Dima 2016-12-25 14:23:57 UTC
In fact it is not. Still has '0 ms' issue.
In addition:
1. Profiler stacks in Time Profile mode from time to time and I have to start profiling from scratch.
2. On image time of Time Profiler total time and total time of profiler are different.

Image:
https://drive.google.com/open?id=0B8G2dAyGiey0UFFNeVUwMXlnRFU
Mlpd file:
https://drive.google.com/open?id=0B8G2dAyGiey0Z082a0gwcVFRN2c
Comment 17 Dima 2016-12-25 14:50:14 UTC
Sorry, I put wrong mlpd.

'0 ms' issue is still reproduced. 
Some of records has '0 ms' and some of them has > 0 values.

Image:
https://drive.google.com/open?id=0B8G2dAyGiey0dVM4R1pjay1saUU
Mlpd file:
https://drive.google.com/open?id=0B8G2dAyGiey0QnFCUU5jWDNKc2M
Comment 18 Rodrigo Moya 2017-02-02 19:08:16 UTC
Ok, this is showing at least some data, so it looks a lot like the runtime profiler is not dumping its samples buffer or not giving us enough samples.

I'll mark it as duplicated of bug #51485

*** This bug has been marked as a duplicate of bug 51485 ***