Forum Visual Studio

Announcement:

The Xamarin Forums have officially moved to the new Microsoft Q&A experience. Microsoft Q&A is the home for technical questions and answers at across all products at Microsoft now including Xamarin!

To create new threads and ask questions head over to Microsoft Q&A for .NET and get involved today.

Guidelines required on Xamarin time profiler

Hi, I tried Xamarin time profiler for profiling a xamarin android application. But the results seem to be weird. I profiled the following code snippet.

void TestMethod()
    {
        //Stopwatch stopwatch = new Stopwatch();
        //stopwatch.Start();
        for (int i = 0; i < 5; i++)
        {
            Thread.Sleep(2000);
        }
        //stopwatch.Stop();
        //Console.WriteLine("Time for testmethod(): " + stopwatch.ElapsedMilliseconds);
    }

The stopwatch.ElapsedMilliseconds outputs "10002ms" but when I check it in xamarin profiler it displays "4.90s". Why is this difference? What exactly xamarin profiler is capturing?

Instead of using Thread.Sleep, I even tried following code snippet. Still there is a huge difference between what I could see in profiler and the output from stopwatch.ElapsedMilliseconds.

void TestMethod()
    {
        //Stopwatch stopwatch = new Stopwatch();
        //stopwatch.Start();
        for (int i = 0; i < 1000000; i++)
        {
            Console.WriteLine("Test output");
        }
        //stopwatch.Stop();
        //Console.WriteLine("Time for testmethod(): " + stopwatch.ElapsedMilliseconds);
    }

Note: I'm using xamarin profiler beta version 1.6.1.483. Also tried stable version 1.6.0.27. Result was not what I expected.

Posts

  • RodrigoMoyaRodrigoMoya ESXamarin Team Xamurai

    Sampling in runtime profiler samples the profiled app at regular intervals, while the stopwatch class calculates the exact time from .Start to .Stop, given the system's clock. That time between the .Start and .Stop calls might be have been spent in other threads, for instance, or, because of the app being busy, samples might have been emitted at smaller intervals, for instance.

    So, Xamarin.Profiler calculates, given the sample interval and the number of samples received for that method, a guess of how much time was spent on that method, so it's never 100% exact.

    On the other hand, the difference seems indeed big enough to justify looking at it, so, could you share the full source code of the app, or is just adding that TestMethod to a simple Console app enough to see the issue?

  • GeethaThangamGeethaThangam USMember ✭✭

    Thanks for your reply RodrigoMoya. Can you please explain what do you mean by "number of samples received for that method" here?

  • GeethaThangamGeethaThangam USMember ✭✭
    edited March 2018

    To answer your question, I have used the sample app given in the Xamarin profiler documentation "Walkthrough - Using the Xamarin profiler / AsyncImageAndroid"

    I have just changed few lines of code in MainActivity.cs. I replaced image uri and called TestMethod() in the beginning of the downloadAsync().

    void TestMethod()
    {
        //Stopwatch stopwatch = new Stopwatch();
        //stopwatch.Start();
        for (int i = 0; i < 5; i++)
        {
            Thread.Sleep(2000);
        }
        //stopwatch.Stop();
        //Console.WriteLine("Time for testmethod(): " + stopwatch.ElapsedMilliseconds);
    }
    
    void TestMethod1()
    {
        Stopwatch stopwatch = new Stopwatch();
        stopwatch.Start();
        for (int i = 0; i < 1000000; i++)
        {
            Console.WriteLine("Test output");
        }
        stopwatch.Stop();
        Console.WriteLine("Time for testmethod(): " + stopwatch.ElapsedMilliseconds);
    }
    
    async void downloadAsync(object sender, System.EventArgs ea)
    {
        TestMethod();       //Newly added line
        //TestMethod1();    //Newly added line
        webClient = new WebClient();
        var url = new Uri(<some image url>);    // Adding image url, not allowing me to post this reply
        byte[] bytes = null;
    
        // No changes in the remaining code.
    }
    

    I don't have the data for previous profiler session. I have started a new profiler session and added the data as follows.

    Data1:
    Time captured using Stopwatch inside the "TestMethod()" is "10003ms".
    Time captured using Stopwatch and TestMethod() for "webClient.DownloadDataTaskAsync(url);" is "1884ms".
    Combining both -> 10003ms + 1884ms = 11887ms
    Xamarin Profiler data, Refer image -> Sample_Thread_Sleep.PNG

    Data2:
    Time captured using Stopwatch inside the "TestMethod1" is "28111ms".
    Time captured using Stopwatch and TestMethod1() for "webClient.DownloadAsync(url);" is "1821ms".
    Combining both -> 28111ms + 1821ms = 29932ms
    Xamarin Profiler data, Refer image -> Sample_process_code.PNG

  • RodrigoMoyaRodrigoMoya ESXamarin Team Xamurai

    @GeethaThangam said:
    Thanks for your reply RodrigoMoya. Can you please explain what do you mean by "number of samples received for that method" here?

    the Mono profiler emits samples for $whatever method, so the times displayed in the Xamarin.Profiler are based on the number of samples emitted for that specific method and its callees.

  • RodrigoMoyaRodrigoMoya ESXamarin Team Xamurai

    @RodrigoMoya said:

    @GeethaThangam said:
    Thanks for your reply RodrigoMoya. Can you please explain what do you mean by "number of samples received for that method" here?

    the Mono profiler emits samples for $whatever method, so the times displayed in the Xamarin.Profiler are based on the number of samples emitted for that specific method and its callees.

    So, if the runtime profiler is set to sample 1000 times a second your app, that code you're measuring will probably get N samples per second, so if the app has been running for 30 seconds,, and that code got, for instance, 400 samples per second, you would see, in the Xamarin profiler, 400ms * 30 = 12000ms, which is not the same as the real time used for your code between the stopwatch's Start/End operations.

    Of course, the calculation is a bit more complex, as 30 seconds of real time don't mean 30 seconds of CPU time, and even though the runtime profiler is set to sample every millisecond, we might not get exactly 1000 samples per second,, but you get the idea.

Sign In or Register to comment.