Starting Thread seems slow

ledragonledragon Member ✭✭✭

Hi,

I have a scenario where I have multiple HTTP connections to make simulataneously. It's been performing the requests very slowly so I've added a few log messages to the Output Window:

[0:] OPOCDebug 10:50:08.818: ViewJobViewModel SyncJob RFIs Add Task Start
[0:] OPOCDebug 10:50:08.833: SyncManager HandleExistingRfis Start
Thread started: #36
[0:] OPOCDebug 10:50:10.344: ViewJobViewModel SyncJob RFIs Add Task End
[0:] OPOCDebug 10:50:10.461: ViewJobViewModel SyncJob ExistingImageBanks Add Task Start
[0:] OPOCDebug 10:50:10.503: SyncManager HandleExistingImageBanks Start
[0:] OPOCDebug 10:50:10.606: RfiSyncService UpdateToServerAsync: 1.3395597s
Resolved pending breakpoint at 'RfiService.cs:207,1' to void OPOC.Prism.Standard.Data.Database.RfiService.d__9.MoveNext () [0x00142].
[0:] OPOCDebug 10:50:11.129: RfiSyncService UpdateToLocalAsync: 0.4949528s
[0:] OPOCDebug 10:50:11.156: SyncManager HandleExistingRfis End
Thread started: #37
[0:] OPOCDebug 10:50:12.033: ViewJobViewModel SyncJob ExistingImageBanks Add Task End
[0:] OPOCDebug 10:50:12.368: ViewJobViewModel SyncJob NewImageBanks Add Task Start
[0:] OPOCDebug 10:50:12.445: SyncManager HandleNewImageBanks Start
[0:] OPOCDebug 10:50:12.482: ImageBankSyncService UpdateToServerAsync: 1.9132596s
Resolved pending breakpoint at 'ImageBankService.cs:159,1' to void OPOC.Prism.Standard.Data.Database.ImageBankService.d__7.MoveNext () [0x00142].
[0:] OPOCDebug 10:50:13.078: ViewJobViewModel SyncJob NewImageBanks Add Task End
[0:] OPOCDebug 10:50:13.091: ViewJobViewModel SyncJob Pre Try
[0:] OPOCDebug 10:50:13.109: ViewJobViewModel SyncJob Pre WhenAll
[0:] OPOCDebug 10:50:13.508: ImageBankSyncService UpdateToLocalAsync: 0.9988966s
[0:] OPOCDebug 10:50:13.532: SyncManager HandleExistingImageBanks End
[0:] OPOCDebug 10:50:14.377: ImageBankSyncService AddBulkToServerAsync: 1.9011344s
Resolved pending breakpoint at 'ImageBankService.cs:255,1' to void OPOC.Prism.Standard.Data.Database.ImageBankService.d__10.MoveNext () [0x001cc].
[0:] OPOCDebug 10:50:14.763: ImageBankSyncService UpdateBulkLocalIdAsync: 0.3374065s
[0:] OPOCDebug 10:50:15.120: SyncManager HandleNewImageBanks End
[0:] OPOCDebug 10:50:15.144: ViewJobViewModel SyncJob Post WhenAll
[0:] OPOCDebug 10:50:15.294: ViewJobViewModel SyncJob Finally Start
[0:] OPOCDebug 10:50:15.887: ViewJobViewModel SyncJob Pre Check Dirty09-21 10:50:15.859 D/[email protected]MainActivity: dispatchDetachedFromWindow

I realise that there's not much to go on without code but does anyone have any pointers as to why it appears that the time to start a Thread is so long?

See the gaps here:

[0:] OPOCDebug 10:50:08.833: SyncManager HandleExistingRfis Start
Thread started: #36
[0:] OPOCDebug 10:50:10.344: ViewJobViewModel SyncJob RFIs Add Task End

And

[0:] OPOCDebug 10:50:11.156: SyncManager HandleExistingRfis End
Thread started: #37
[0:] OPOCDebug 10:50:12.033: ViewJobViewModel SyncJob ExistingImageBanks Add Task End

Answers

  • LeonLuLeonLu Member, Xamarin Team Xamurai

    First of all, please reduce the number of HTTP Requests, if it could become faster, if not, we should focus on the network quality, use wireshark to monitor the network package.

    Did you open one thread, then make Multiple HTTP Requests in this thread? If so, please do not put Multiple HTTP Requests in one thread.

    Here is a case about Multiple HTTP Requests that make the app slow down, you can refer to following link.
    https://stackoverflow.com/questions/23824178/xamarin-multiple-http-requests-slow-down-the-app

  • ledragonledragon Member ✭✭✭
    edited September 23

    @LeonLu Hi there,

    Thanks for the reply. Yes, I saw that post on my Google roundtrips but his issues are more to do with what he does with the responses that the Http performance no?...I've check the Network Quality and API performance and it's neither of these.

    I'm using Tasks.

    I've moved on a little with testing and my best guess is my main issue is with Refit and HttpClient.

    [0:] OPOCDebug 07:59:32.338: ApiService createClient Start
    [0:] OPOCDebug 07:59:32.358: ApiService createClient Duration: 0.0036197s
    [0:] OPOCDebug 07:59:32.366: ApiService createClient End

    Thread started: #45
    Thread started: #46
    Thread started: #47
    Thread started: #48
    Thread started: #49
    Thread started: #50
    Thread started: #51
    Thread started: #52
    Thread started: #53

    [0:] 2.1/5.1 OPOCDebug 07:59:33.487: RfiSyncService UpdateToServerAsync Start
    [0:] 4.1 OPOCDebug 07:59:33.613: IssuesSyncService AddBulkToServerAsync Start
    [0:] 6.1 OPOCDebug 07:59:33.659: RfiSyncService AddBulkToServerAsync Start
    [0:] 4.2 OPOCDebug 07:59:33.696: IssuesSyncService AddBulkToServerAsync Http Start

    09-22 19:59:34.139 I/.telerik.OPOCv(18820): Explicit concurrent copying GC freed 79983(4MB) AllocSpace objects, 12(288KB) LOS objects, 57% free, 4MB/10MB, paused 282us total 46.039ms

    [0:] 2.2/5.2 OPOCDebug 07:59:34.146: RfiSyncService UpdateToServerAsync Http Start
    [0:] 4.2.1 OPOCDebug 07:59:34.157: ApiManager CreateIssues Start
    [0:] 8.1 OPOCDebug 07:59:34.165: TextCategorySyncService AddBulkToServerAsync Start
    [0:] OPOCDebug 07:59:34.197: ApiService createClient Start
    [0:] 8.2 OPOCDebug 07:59:34.218: TextCategorySyncService AddBulkToServerAsync Http Start
    [0:] 2.2.1 OPOCDebug 07:59:34.227: ApiManager SaveRFIs Start
    [0:] OPOCDebug 07:59:34.249: ApiService createClient Start
    [0:] 8.2.1 OPOCDebug 07:59:34.282: ApiManager CreateTextCategories Start
    [0:] OPOCDebug 07:59:34.318: ApiService createClient Start
    [0:] OPOCDebug 07:59:34.350: ApiService createClient Duration: 0.1340778s
    [0:] 6.2 OPOCDebug 07:59:34.369: RfiSyncService AddBulkToServerAsync Http Start
    [0:] OPOCDebug 07:59:34.369: ApiService createClient End
    [0:] 6.2.1 OPOCDebug 07:59:34.411: ApiManager CreateRFIs Start
    [0:] OPOCDebug 07:59:34.428: ApiService createClient Start
    [0:] OPOCDebug 07:59:34.461: ApiService createClient Duration: 0.1120231s
    [0:] OPOCDebug 07:59:34.461: ApiService createClient Duration: 0.0197268s
    [0:] OPOCDebug 07:59:34.461: ApiService createClient Duration: 0.1790279s
    [0:] OPOCDebug 07:59:34.499: ApiService createClient End
    [0:] OPOCDebug 07:59:34.482: ApiService createClient End
    [0:] OPOCDebug 07:59:34.532: ApiService createClient End
    [0:] 10.1 OPOCDebug 07:59:34.682: ImageBankSyncService AddBulkToServerAsync Start - ImageBank Count: 13

    09-22 19:59:34.864 I/.telerik.OPOCv(18820): Explicit concurrent copying GC freed 23001(1045KB) AllocSpace objects, 2(48KB) LOS objects, 64% free, 3MB/9MB, paused 288us total 40.883ms
    09-22 19:59:34.961 I/.telerik.OPOCv(18820): Explicit concurrent copying GC freed 1198(53KB) AllocSpace objects, 0(0B) LOS objects, 64% free, 3MB/9MB, paused 182us total 29.658ms
    Thread started: #4

    [0:] 8.2.2 OPOCDebug 07:59:34.964: ApiManager CreateTextCategories Duration: 0.6470063s AddTextCategory: 0.1989716
    [0:] 8.2.3 OPOCDebug 07:59:35.048: ApiManager CreateTextCategories End
    [0:] 8.3 OPOCDebug 07:59:35.092: TextCategorySyncService AddBulkToServerAsync Http End
    [0:] 8.4 OPOCDebug 07:59:35.178: TextCategorySyncService AddBulkToServerAsync Duration: 0.9814299s
    [0:] 8.5 OPOCDebug 07:59:35.197: TextCategorySyncService AddBulkToServerAsync End

    09-22 19:59:35.411 I/.telerik.OPOCv(18820): Explicit concurrent copying GC freed 5(31KB) AllocSpace objects, 0(0B) LOS objects, 64% free, 3MB/9MB, paused 419us total 52.227ms

    [0:] 10.2 OPOCDebug 07:59:35.470: ImageBankSyncService AddBulkToServerAsync Http Start
    [0:] 10.2.1 OPOCDebug 07:59:35.504: ApiManager CreateImageBanks Start
    [0:] OPOCDebug 07:59:35.528: ApiService createClient Start
    [0:] OPOCDebug 07:59:35.575: ApiService createClient Duration: 0.0172813s
    [0:] OPOCDebug 07:59:35.597: ApiService createClient End

    09-22 19:59:35.938 I/.telerik.OPOCv(18820): Explicit concurrent copying GC freed 3(16KB) AllocSpace objects, 0(0B) LOS objects, 64% free, 3MB/9MB, paused 202us total 31.713ms

    [0:] 4.2.1 OPOCDebug 07:59:37.548: ApiManager CreateIssues Duration: 3.3516558s AddIssues: 1.036015
    [0:] 4.2.2 OPOCDebug 07:59:37.588: ApiManager CreateIssues End
    [0:] 4.3 OPOCDebug 07:59:37.753: IssuesSyncService AddBulkToServerAsync Http End

    09-22 19:59:38.034 I/.telerik.OPOCv(18820): Explicit concurrent copying GC freed 3(31KB) AllocSpace objects, 0(0B) LOS objects, 64% free, 3MB/9MB, paused 336us total 59.839ms

    [0:] 4.4 OPOCDebug 07:59:38.064: IssuesSyncService AddBulkToServerAsync Duration: 4.4369492s
    [0:] 4.5 OPOCDebug 07:59:38.163: IssuesSyncService AddBulkToServerAsync End
    [0:] 6.2.2 OPOCDebug 07:59:38.322: ApiManager CreateRFIs Duration: 3.8938436s CreateRfis: 1.629258
    [0:] 6.2.3 OPOCDebug 07:59:38.418: ApiManager CreateRFIs End
    [0:] 6.3 OPOCDebug 07:59:38.572: RfiSyncService AddBulkToServerAsync Http End
    [0:] 6.4 OPOCDebug 07:59:38.661: RfiSyncService AddBulkToServerAsync Duration: 4.9862344s
    [0:] 6.5 OPOCDebug 07:59:38.946: RfiSyncService AddBulkToServerAsync End
    [0:] 10.2.2 OPOCDebug 07:59:44.388: ApiManager CreateImageBanks Duration: 8.8598781s AddImageBank: 3.1106314
    [0:] 10.2.3 OPOCDebug 07:59:44.457: ApiManager CreateImageBanks End
    [0:] 10.3 OPOCDebug 07:59:44.486: ImageBankSyncService AddBulkToServerAsync Http End
    [0:] 10.4 OPOCDebug 07:59:44.592: ImageBankSyncService AddBulkToServerAsync Duration: 9.8940845s
    [0:] 10.5 OPOCDebug 07:59:44.614: ImageBankSyncService AddBulkToServerAsync End
    [0:] 2.2.2 OPOCDebug 07:59:47.141: ApiManager SaveRFIs Duration: 12.8986348s SaveRfis: 1.0895118
    [0:] 2.2.3 OPOCDebug 07:59:47.169: ApiManager SaveRFIs End
    [0:] 2.3/5.3 OPOCDebug 07:59:47.195: RfiSyncService UpdateToServerAsync Http End
    [0:] 2.4/5.4 OPOCDebug 07:59:47.274: RfiSyncService UpdateToServerAsync Duration: 13.7617301s
    [0:] 2.5/5.5 OPOCDebug 07:59:47.295: RfiSyncService UpdateToServerAsync End

    Above I've added timer values for the duration of the Refit Requests and the duration the API to took to provide a response.

    eg.
    [0:] 2.2.2 OPOCDebug 07:59:47.141: ApiManager SaveRFIs Duration: 12.8986348s SaveRfis: 1.0895118

    Xamarin Forms logged 12.89sec whereas the API only took 1.08sec.

    Hard to understand why!

    public async Task<HttpResponseMessage> SaveRFIs(List<RFIDto> rfis)
        {
            Debug.Write($"OPOCDebug {DateTime.Now.ToString("hh:mm:ss.fff")}: ApiManager SaveRFIs Start");
    
            Stopwatch stopwatch = new Stopwatch();
            stopwatch.Start();
    
            try
            {
                var cancellationTokenSource = new CancellationTokenSource();
    
                //var task = RemoteRequestAsync<HttpResponseMessage>(_rfiApi.GetApi(Priority.UserInitiated, sendProgress).SaveRFIs(rfis, cancellationTokenSource.Token));
                var task = _api.GetApi(Priority.UserInitiated).SaveRFIs(rfis, cancellationTokenSource.Token);
    
                runningTasks.Add(task.Id, cancellationTokenSource);
    
                var result = await task;
    
                stopwatch.Stop();
                Debug.Write($"OPOCDebug {DateTime.Now.ToString("hh:mm:ss.fff")}: ApiManager SaveRFIs Duration: {stopwatch.Elapsed.TotalSeconds}s");
    
                Debug.Write($"OPOCDebug {DateTime.Now.ToString("hh:mm:ss.fff")}: ApiManager SaveRFIs End");
    
                return result;
            }
            catch (Exception ex)
            {
                throw;
            }
        }
    

    GetApi runs the following:

    Debug.Write($"OPOCDebug {DateTime.Now.ToString("hh:mm:ss.fff")}: ApiService createClient Start");
    
                Stopwatch stopwatch = new Stopwatch();
                stopwatch.Start();
    
                var client = new HttpClient(priority)
                {
                    BaseAddress = new Uri(apiBaseAddress),
                //    //Timeout = TimeSpan.FromSeconds(5) // TODO Change this for Live
                };
    
                if (authToken != null) client.DefaultRequestHeaders.Authorization = new AuthenticationHeaderValue("Bearer", authToken);
    
                var restService = RestService.For<T>(client);
    
                stopwatch.Stop();
                Debug.Write($"OPOCDebug {DateTime.Now.ToString("hh:mm:ss.fff")}: ApiService createClient Duration: {stopwatch.Elapsed.TotalSeconds}s");
    
                Debug.Write($"OPOCDebug {DateTime.Now.ToString("hh:mm:ss.fff")}: ApiService createClient End");
    
                return restService;
    

    All the requests follow this pattern

  • ledragonledragon Member ✭✭✭

    I'm basically following this pattern:

    https://github.com/CrossGeeks/RefitXamarinFormsSample

  • LeonLuLeonLu Member, Xamarin Team Xamurai

    Did you try to move HttpClient global scope and initialize them within the constructor, HttpClient is reused over multiple requests like this link.

    https://www.reddit.com/r/csharp/comments/54iygj/httpclients_sendasync_is_very_slow_not_a_proxy/

    Because HttpClient have a ”Warm-up period“, I test it everytime, this ”Warm-up period“ will cost 1-2 sceconds to warm_up.

  • ledragonledragon Member ✭✭✭

    @LeonLu Thanks for sticking with this and the above link...I think the slowness maybe down to multiple garbage collections as I'm looping through multiple images and converting to base64.

    See this post:

    https://forums.xamarin.com/discussion/170339/loop-through-multiple-images-to-convert-to-base64-to-http-post-garbage-collection#latest

  • JohnHardmanJohnHardman GBUniversity mod

    @ledragon said:
    @LeonLu Thanks for sticking with this and the above link...I think the slowness maybe down to multiple garbage collections as I'm looping through multiple images and converting to base64.

    See this post:

    https://forums.xamarin.com/discussion/170339/loop-through-multiple-images-to-convert-to-base64-to-http-post-garbage-collection#latest

    I have answered re. garbage collection on that other thread, but regarding Http @LeonLu is correct that you should usually try to reuse a single HttpClient instance where possible.

Sign In or Register to comment.