0

My Android Xamarin Forms App is exhibiting a 10 to 30 second lag when creating a ViewModel/View and pushing the View to the modal stack at runtime.

The application is receiving a deep link successfully, but then experiences a considerable performance lag when trying to show the desired view.

The same application executing on IOS does not have this lag.

Looking at the logs and code, the lag happens at the line I've marked with '***' below, after MT2 but before MT3 log entries.

I have been experimenting with Device.BeginInvokeOnMainThread to see if it makes the problem better or worse, but have seen no effect for this issue.

Any idea what the perf hangup might be? Is TCPOptimizer part of the problem? In case it's relevant, I've been executing the code on two different Samsung S8's.

Code

protected override async void OnAppLinkRequestReceived(Uri uri)
{
    //Aside:  I would rather use System.Web.HttpUtility to parse this query string, but it seems I can't in an Xam PCL.

    //Pattern:
    //my.app.deeplink://<command>?<params>
    //Examples:                             
    //  Deep Linking Web Navigation:
    //      my.app.deeplink://webnav?url=/ns/products/product/?id=1234&param1=value1&param2=value2
    //  Deep Linking Native Navigation:
    //      my.app.deeplink://view?name=SettingsPageView&param1=value1&param2=value2

    try
    {
        m_oLogging.LogInfo("OnAppLinkRequestReceived: " + uri.ToString());

        NavigationManager.DeepLinkCommand oDeepCmd = NavigationManager.ParseDeepLink(uri);

        switch (oDeepCmd)
        {
            case NavigationManager.DeepLinkCommand.invalid:
                m_oLogging.LogInfo("Deep Link deemed invalid.  Doing nothing.");
                break;

            case NavigationManager.DeepLinkCommand.webnav:
                //Query expected to be like:    ?url=/ns/products/product/?id=1234&param1=value1&param2=value2

                string szUri = uri.Query;
                Uri oParsedURI = WebNavigationManager.URLS.ParseDeepLinkUri(szUri);
                string szURL = oParsedURI.ToString();

                m_oLogging.LogInfo(string.Format("Proceeding with webnav to [{0}].", szURL));
                App oApp = ((App)Application.Current);

                WebNavigationManager.Instance.NavigateToURL(szURL);

                break;

            case NavigationManager.DeepLinkCommand.view:
                //Query like:    ?name=SettingsPageView&param1=value1&param2=value2

                string szView = uri.Query.Split('=')[1].Split('&')[0];
                string szViewTypeName = string.Empty;
                switch (szView)
                {
                    case "SettingsPageView":
                        szViewTypeName = typeof(SettingsPageView).Name;
                        break;
                    default:
                        //Try to dynamically present the named view.
                        szViewTypeName = "my.app.namespace." + szView;
                        break;
                }

                if (ViewIsAlreadyLoaded(szViewTypeName))
                {
                    //I'm already at that page, so chill!
                    m_oLogging.LogInfo(string.Format("View [{0}] is already loaded in one of the stacks.  No need to load it again or duplicate it.", szViewTypeName));
                }
                else
                {
                    m_oLogging.LogInfo(string.Format("Proceeding with presenting view [{0}].", szViewTypeName));
                    switch (szView)
                    {
                        case "SettingsPageView":

                            //There is nothing modal right now, or there is, but the top of the stack isn't the settings page.
                            m_oLogging.LogInfo(string.Format("Pushing known view modally: '{0}'", szViewTypeName));
                            Device.BeginInvokeOnMainThread(() =>
                            {
                                m_oLogging.LogInfo(string.Format("Pushing known view modally (MT1): '{0}'", szViewTypeName));
                                IViewModel oSPVM = new SettingsPageViewModel();
                                m_oLogging.LogInfo(string.Format("Pushing known view modally (MT2): '{0}'", szViewTypeName));
***                             BaseView oSPV = new SettingsPageView(oSPVM);
                                m_oLogging.LogInfo(string.Format("Pushing known view modally (MT3): '{0}'", szViewTypeName));
                                MainPage.Navigation.PushModalAsync(oSPV, false);
                                m_oLogging.LogInfo(string.Format("Pushed known view modally (MT4): '{0}'", szViewTypeName));
                            });
                            m_oLogging.LogInfo(string.Format("Pushed known view modally: '{0}'", szViewTypeName));
                            break;

                        default:

                            //Try to dynamically present the named view.
                            var vViewModel = Activator.CreateInstance(Type.GetType(szViewTypeName + "Model"));
                            if (vViewModel != null)
                            {
                                var vView = Activator.CreateInstance(Type.GetType(szViewTypeName), vViewModel);
                                if (vView != null)
                                {
                                    m_oLogging.LogInfo(string.Format("Pushing dynamic view modally: '{0}'", szViewTypeName));
                                    Device.BeginInvokeOnMainThread(async() => await MainPage.Navigation.PushModalAsync(vView as Page, false));
                                    m_oLogging.LogInfo(string.Format("Pushed dynamic view modally: '{0}'", szViewTypeName));
                                }
                            }
                            break;
                    }
                }
                break;
        }
    }
    catch (Exception oExc)
    {
        m_oLogging.LogError(oExc.Message);
    }


    base.OnAppLinkRequestReceived(uri);
}

Runtime Debugging content

08-01 15:14:59.023 I/MyApp   (29249): OnAppLinkRequestReceived: my.package.name://view/?name=SettingsPageView&ampAction=Clicked
08-01 15:14:59.030 I/MyApp   (29249): Proceeding with presenting view [SettingsPageView].
08-01 15:14:59.031 I/MyApp   (29249): Pushing known view modally: 'SettingsPageView'
08-01 15:14:59.031 I/MyApp   (29249): Pushed known view modally: 'SettingsPageView'
Thread started:  #17
08-01 15:14:59.079 D/Mono    (29249): [0xb7190920] worker starting
08-01 15:14:59.153 D/ViewRootImpl@3c0476fMainActivity: Relayout returned: oldFrame=[0,0][1080,2220] newFrame=[0,0][1080,2220] result=0x7 surface={isValid=true -1281830912} surfaceGenerationChanged=true
08-01 15:14:59.153 D/ViewRootImpl@3c0476fMainActivity: mHardwareRenderer.initialize() mSurface={isValid=true -1281830912} hwInitialized=true
08-01 15:14:59.162 I/MyApp   (29249): Pushing known view modally (MT1): 'SettingsPageView'
Resolved pending breakpoint at 'SettingsPageViewModel.cs:25,1' to bool app.namespace.name.SettingsPageViewModel.get_PreferencePushService () [0x00001].
Resolved pending breakpoint at 'SettingsPageViewModel.cs:38,1' to bool app.namespace.name.SettingsPageViewModel.get_PreferencePushDelivery () [0x00001].
Resolved pending breakpoint at 'SettingsPageViewModel.cs:51,1' to bool app.namespace.name.SettingsPageViewModel.get_PreferencePushPromotion () [0x00001].
08-01 15:14:59.340 I/MyApp   (29249): Pushing known view modally (MT2): 'SettingsPageView'
08-01 15:14:59.488 D/Mono    (29249): DllImport searching in: '__Internal' ('(null)').
08-01 15:14:59.488 D/Mono    (29249): Searching for 'java_interop_jnienv_call_static_object_method'.
08-01 15:14:59.488 D/Mono    (29249): Probing 'java_interop_jnienv_call_static_object_method'.
08-01 15:14:59.488 D/Mono    (29249): Found as 'java_interop_jnienv_call_static_object_method'.

#############################[ 3 seconds of lag ]


08-01 15:15:02.826 D/TcpOptimizer(29249): [my.package.name] Full closed: sid=125, tcpi_state=8


#############################[ 1 second of lag ]


08-01 15:15:03.830 D/TcpOptimizer(29249): [my.package.name] Full closed: sid=130, tcpi_state=8
Thread finished:  #15
The thread 'Unknown' (0xf) has exited with code 0 (0x0).


#############################[ 26 seconds of lag ]


08-01 15:15:29.177 I/System.out(29249): (HTTPLog)-Static: isSBSettingEnabled false
08-01 15:15:29.177 I/System.out(29249): (HTTPLog)-Static: isSBSettingEnabled false
08-01 15:15:29.179 I/MyApp   (29249): CustomerID: (known) e3ecf5c1-3920-4cc9-ad08-0c1b2145db2b  ( <-- this code runs while data is being read from the viewmodel for the view )
08-01 15:15:29.186 I/System.out(29249): (HTTPLog)-Static: isSBSettingEnabled false
08-01 15:15:29.187 I/System.out(29249): (HTTPLog)-Static: isSBSettingEnabled false
08-01 15:15:29.188 I/System.out(29249): (HTTPLog)-Static: isSBSettingEnabled false
08-01 15:15:29.188 I/System.out(29249): (HTTPLog)-Static: isSBSettingEnabled false
Thread started:  #18
08-01 15:15:29.285 D/Mono    (29249): Assembly Loader probing location: '/Users/builder/data/lanes/4009/3a62f1ea/source/monodroid/builds/install/mono-armv7/lib/app.namespace.name.resources.dll'.
08-01 15:15:29.285 D/Mono    (29249): Assembly Loader probing location: '/Users/builder/data/lanes/4009/3a62f1ea/source/monodroid/builds/install/mono-armv7/lib/app.namespace.name.resources.exe'.
08-01 15:15:29.291 D/Mono    (29249): Assembly Loader probing location: '/storage/emulated/0/Android/data/my.package.name/files/.override/en-US/app.namespace.name.resources.dll'.
08-01 15:15:29.364 I/MyApp   (29249): Pushing known view modally (MT3): 'SettingsPageView'
08-01 15:15:29.428 W/art     (29249): JNI RegisterNativeMethods: attempt to register 0 native methods for md5b60ffeb829f638581ab2bb9b1a7f4f3f.LabelRenderer
08-01 15:15:29.646 W/art     (29249): JNI RegisterNativeMethods: attempt to register 0 native methods for md5b6ed58bdd2dc5ff75bde29ef5e42d6e8.ExtendedSwitchRenderer
08-01 15:15:30.001 I/MyApp   (29249): Pushed known view modally (MT4): 'SettingsPageView'
08-01 15:15:30.002 I/Choreographer(29249): Skipped 1851 frames!  The application may be doing too much work on its main thread.
08-01 15:15:30.111 D/ScrollView(29249):  onsize change changed 
08-01 15:15:30.189 D/ViewRootImpl@3c0476fMainActivity: MSG_WINDOW_FOCUS_CHANGED 1
08-01 15:15:30.189 D/ViewRootImpl@3c0476fMainActivity: mHardwareRenderer.initializeIfNeeded()#2 mSurface={isValid=true -1281830912}
08-01 15:15:30.229 V/InputMethodManager(29249): Starting input: tba=android.view.inputmethod.EditorInfo@cf0b2ac nm : my.package.name ic=null
08-01 15:15:30.230 I/InputMethodManager(29249): [IMM] startInputInner - mService.startInputOrWindowGainedFocus
08-01 15:15:30.231 D/InputTransport(29249): Input channel constructed: fd=160
08-01 15:15:30.233 D/InputMethodManager(29249): HSI from window - flag : 0 Pid : 29249
08-01 15:15:30.252 W/IInputConnectionWrapper(29249): reportFullscreenMode on inexistent InputConnection
08-01 15:15:38.190 D/Mono    (29249): [0xb7190920] worker finishing
Thread finished:  #17
The thread 'Unknown' (0x11) has exited with code 0 (0x0).
08-01 15:15:41.995 D/TcpOptimizer(29249): [my.package.name] Full closed: sid=171, tcpi_state=8
08-01 15:15:49.902 D/ViewRootImpl@3c0476fMainActivity: MSG_RESIZED_REPORT: frame=Rect(0, 0 - 1080, 2220) ci=Rect(0, 72 - 0, 144) vi=Rect(0, 72 - 0, 144) or=1
08-01 15:15:49.972 D/ViewRootImpl@3c0476fMainActivity: Relayout returned: oldFrame=[0,0][1080,2220] newFrame=[0,0][1080,2220] result=0x1 surface={isValid=true -1281830912} surfaceGenerationChanged=false
08-01 15:15:51.378 D/ViewRootImpl@3c0476fMainActivity: MSG_WINDOW_FOCUS_CHANGED 0
08-01 15:15:54.111 D/ViewRootImpl@3c0476fMainActivity: MSG_WINDOW_FOCUS_CHANGED 1
08-01 15:15:54.111 D/ViewRootImpl@3c0476fMainActivity: mHardwareRenderer.initializeIfNeeded()#2 mSurface={isValid=true -1281830912}
08-01 15:16:09.240 D/Mono    (29249): [0xbf27c920] worker finishing
Thread finished:  #10
The thread 'Unknown' (0xa) has exited with code 0 (0x0).

Any assistance is appreciated!

Curtis Herrick
  • 145
  • 1
  • 11

1 Answers1

0

After further research, I found that the view I was creating had a label that was bound to a property on its viewmodel, which in turn was returning a value from a 3rd party SDK. The SDK was slow to respond to this simple property-get in some scenarios.

The fix was to use this pattern to read this value using async await:

private string m_szCustomerID = null;
public string CustomerID
{
    get
    {
        if (m_szCustomerID == null)
        {
            m_oLogging.LogInfo("Fetching CustomerID Async");
            FetchCustomerID();
        }
        m_oLogging.LogInfo("Returning: " + (m_szCustomerID == null ? "NULL": m_szCustomerID));
        return m_szCustomerID;
    }
    set
    {
        if (value != m_szCustomerID)
        {
            m_szCustomerID = value;
            m_oLogging.LogInfo("CustomerID new value: " + (m_szCustomerID == null ? "NULL" : m_szCustomerID));
            NotifyPropertyChanged();
        }
    }
}

private async void FetchCustomerID()
{
    string szVal = null;
    szVal = await m_oSDK.AsyncCustomerID;

    if (szVal == null)
    {
        szVal = "(unknown) " + await m_oSDK.AsyncInstallID; 
    }
    else
    {
        szVal = "(known) " + szVal;
    }
    CustomerID = szVal;
}

One link I found helpful was: How to call an async method from a getter or setter?

In the spirit of sharing, I'll share a class I find handy for isolating performance problems:

LoggedSection Tool - A simple class I coded to help find the timing issues is as follows:

//IDisposable is a Try/Finally if you look at it using Ildasm.exe.
//Using it here provides some convenient info gathered without a lot of overhead while the code being logged is executing.
public class LoggedSection : IDisposable
{
    private ILogging m_iLogger = null;
    private string m_szSpanDescription;
    private string m_szCallerMemberName;
    private string m_szFilePath;
    private DateTime m_dtStart;
    private Guid m_oGuid;
    private List<MileStone> m_oMileStones = null;

    private class MileStone
    {
        private string m_szMileStone;
        private DateTime m_dtWhen;

        public MileStone(string szWhat)
        {
            m_szMileStone = szWhat;
            m_dtWhen = DateTime.Now;
        }

        public string What
        {
            get
            {
                return m_szMileStone;
            }
        }

        public DateTime When
        {
            get
            {
                return m_dtWhen;
            }
        }
    }

    public LoggedSection(ILogging iLogger, string szSpanDescription = "", [CallerMemberName] string szCallerMemberName = "", [CallerFilePath] string szFilePath = null)
    {
        m_oGuid = Guid.NewGuid();
        m_dtStart = DateTime.Now;
        m_iLogger = iLogger;
        m_szSpanDescription = szSpanDescription;
        m_szCallerMemberName = szCallerMemberName;
        m_szFilePath = szFilePath;
        m_iLogger.LogInfo(string.Format("At: {3} Span ID '{2}' Name '{0}' Started in [{1}].", 
            m_szSpanDescription, m_szCallerMemberName, m_oGuid.ToString(), m_dtStart.ToString(TIME_FORMAT)), 
            m_szCallerMemberName, m_szFilePath);
    }

    public void AddMileStone(string szMileStone)
    {
        if (m_oMileStones == null) m_oMileStones = new List<MileStone>();
        m_oMileStones.Add(new MileStone(szMileStone));
    }

    private const string TIME_FORMAT = "hh:mm:ss.fff";    

    public void Dispose()
    {
        DateTime dtNow = DateTime.Now;
        try
        {
            if (m_oMileStones != null)
            {
                DateTime dtLastStone = m_dtStart;
                int iStone = 1;
                foreach (MileStone oStone in m_oMileStones)
                {
                    m_iLogger.LogInfo(string.Format("At: {8} Span ID '{4}' Name '{0}' MileStone #{7} '{5}' in [{1}].{2} TIME ELAPSED: {3} MS INTO SPAN    {6} MS since last Milestone",
                        m_szSpanDescription, m_szCallerMemberName, System.Environment.NewLine, (oStone.When - m_dtStart).TotalMilliseconds, m_oGuid.ToString(), oStone.What, (oStone.When - dtLastStone).TotalMilliseconds, iStone, oStone.When.ToString(TIME_FORMAT)),
                        m_szCallerMemberName, m_szFilePath);
                    dtLastStone = oStone.When;
                    iStone++;
                }
            }

            m_iLogger.LogInfo(string.Format("At: {5} Span ID '{4}' Name '{0}' Finished in [{1}].{2} TIME ELAPSED: {3} MS",
                m_szSpanDescription, m_szCallerMemberName, System.Environment.NewLine, (dtNow - m_dtStart).TotalMilliseconds, m_oGuid.ToString(), dtNow.ToString(TIME_FORMAT)),
                m_szCallerMemberName, m_szFilePath);
        }
        catch(Exception oExc)
        {
            try
            {
                m_iLogger.LogError("An exception occurred in LoggedSection: " + oExc.Message, m_szCallerMemberName, m_szFilePath);
            }
            catch { }
        }
    }
}

Logger class Code aka iLogger above

public void LogError(string szError, [CallerMemberName] string szMember = null, [CallerFilePath] string szFilePath = null)
{
    Log.Error(APP, FormatLog(szError, szMember, szFilePath));
}

public void LogInfo(string szInfo, [CallerMemberName] string szMember = null, [CallerFilePath] string szFilePath = null)
{
    Log.Info(APP, FormatLog(szInfo, szMember, szFilePath));
}

public void LogWarning(string szWarning, [CallerMemberName] string szMember = null, [CallerFilePath] string szFilePath = null)
{
    Log.Warn(APP, FormatLog(szWarning, szMember, szFilePath));
}

private string FormatLog(string szInfo, string szMember, string szFilePath)
{
    return string.Format("{4}{3}{0}{3}{1}{3}{2}{3}{4}{3}", 
        (szFilePath == null ? string.Empty : "File [" + szFilePath + "]"),
        (szMember == null ? string.Empty : "Member [" + szMember + "]"),
                                    szInfo,
                                    System.Environment.NewLine,
                                    "-----------------------------------------");
}

Logged Section Class Example usage

using (LoggedSection oLogSec = new LoggedSection(m_oLogging, string.Format("Pushing known view modally: '{0}'", szViewTypeName)))
{
    oLogSec.AddMileStone("Creating ViewModel SettingsPageViewModel");
    IViewModel oSPVM = new SettingsPageViewModel();
    oLogSec.AddMileStone(string.Format("Creating View {0}", szViewTypeName));
    BaseView oSPV = new SettingsPageView(oSPVM);
    oLogSec.AddMileStone(string.Format("Pushing View {0}", szViewTypeName));
    MainPage.Navigation.PushModalAsync(oSPV, false);
    oLogSec.AddMileStone(string.Format("Pushed View {0}", szViewTypeName));
}

The results seen in the output window at runtime are helpful, as each milestone is correlatable with the logged section by simply using Find on the Guid value, and it also puts out the timing into the section, as well as the timing since the last milestone.

For this problem, a handful of LoggedSections added to the code helped narrow down where the performance issue was pretty quickly.

Curtis Herrick
  • 145
  • 1
  • 11