Ends in:
2 DAYS
14 HRS
43 MIN
16 SEC
Ends in:
2 D
14 H
43 M
16 S
Open Closed

Slow TTFB (server response time) #1711


User avatar
0
alexander.nikonov created
  • ABP Framework version: v4.3.0
  • UI type: Angular
  • DB provider: EF Core
  • Tiered (MVC) or Identity Server Separated (Angular): yes

We make calls from Angular app to several HTTP hosts which reside:

  1. in production - on the same domain (different web apps) - XXX.cloudapp.azure.com/host1, XXX.cloudapp.azure.com/host2, etc.
  2. locally - on different ports: XXX.localhost:44328, XXX.localhost:44338, etc.

Gathering data from all the hosts is too slow, please have a look:

Log file analysis shows that is it not a problem of DB query which takes usually several dozens of ms, it is a server response creation itself, so looks like using alternative server cache (e.g. Redis) would not help (meanwhile we use default ABP caching):

[14:46:50 INF] Executed action method AbxEps.CentralTools.Controllers.FreeCodeValues.FreeCodeValueController.GetCumulationTypesAsync (AbxEps.CentralTools.HttpApi), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 2167.4438ms.

[14:46:51 INF] Executed endpoint 'AbxEps.CentralTools.Controllers.FreeCodeValues.FreeCodeValueController.GetCumulationsAsync (AbxEps.CentralTools.HttpApi)' info: Microsoft.EntityFrameworkCore.Infrastructure[10403] Entity Framework Core 5.0.5 initialized 'CoreDbContext' using provider 'Oracle.EntityFrameworkCore' with options: SensitiveDataLoggingEnabled QuerySplittingBehavior=SplitQuery info: Microsoft.EntityFrameworkCore.Database.Command[20101] Executed DbCommand (43ms) [Parameters=[:filter_AbxTenantId_0='17' (Nullable = true), :filter_DomainId_1='MD' (Size = 4), :filter_CodeName_2='C_FND_CUM_TYP' (Size = 50), :filter_LanguageCode_3='E' (Size = 4), :defaultLanguageCode_4='E' (Size = 4)], CommandType='Text', CommandTimeout='0'] SELECT c.C_TENANT, c.C_DOMAIN, c.C_FLD, c.C_LANGUAGE, c.C_STR, c.S_COMMENT, c.D_INS, c.C_USR_INS, c.S_TXT, c.U_CA_IMAGE, c.D_UPD, c.C_USR_UPD, c.C_NEOSKEY, c.C_NUM, c.S_TXT_INT FROM CT_CA_CD_POS c WHERE ((((((c.C_TENANT = :filter_AbxTenantId_0) AND (c.C_DOMAIN = :filter_DomainId_1))) AND (c.C_FLD = :filter_CodeName_2))) AND (((c.C_LANGUAGE = :filter_LanguageCode_3) OR (c.C_LANGUAGE = :defaultLanguageCode_4))))

I also see some gaps between numbers which form total response time above and can't figure out what those ~15 seconds are spent for:

[14:46:54 INF] Request finished HTTP/2 GET https://localhost:44328/api/ct/central-tool/free-codes/values/cumulations/en - - - 200 302 application/json;+charset=utf-8 17065.3807ms

Used Oracle DB resides on Azure cloud, but it may not contribute much to the total time either.

How to overcome this issue with TTFB? We use standard ABP layered architecture, nothing fancy.


18 Answer(s)
  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    hi

    Can you share more logs of all of the applications?

    You can set the log level to Debug to see more logs.

  • User Avatar
    0
    alexander.nikonov created

    @maliming Here are logs from both HttpApi hosts. Level was set to 'Debug': .MinimumLevel.Override("Microsoft", LogEventLevel.Debug)

    Please be aware, that this time response times are less - though, they are still too big:

    https://1drv.ms/u/s!AhWdpZddvifTtw10XrTEduNTBt8-?e=RKpfLs https://1drv.ms/u/s!AhWdpZddvifTtwzipyhO1VtNwgbF?e=3oxwaQ

    P.S. Could you please add possibility to attach log files to a message, not only images?

  • User Avatar
    0
    alper created
    Support Team Director

    try to disable Redis if you have not done.

  • User Avatar
    0
    alexander.nikonov created

    @albert Redis is already disabled

  • User Avatar
    0
    alper created
    Support Team Director

    to filter down the problem, 1 - create a new aspnet controller in your backend project 2 - create a new method in the new controller. disable auditing and authorization on this new action. 3- make a request to this new action with postman or curl or any other 3rd party ( dont use your angular client)

    4 - if it's still slow . create a new Aspnet core application from scratch and follow the steps 1-3 and write me the results

  • User Avatar
    0
    alexander.nikonov created

    @albert since I will be out for 2 weeks, I've decided to try some experiments right away. Is it essential to create a new controller? If I got you right regarding disabling auditing and authorization, I had to put the following attributes on my controller and appservice:

    [AllowAnonymous]
    [DisableAuditing]
    

    So after doing this I run existing lookup method from POSTMAN. Result is approximately the same as from Angular app before (response time varies between 4 and 16 seconds depending on how many times I run the same details page):

    Researching further... So now I have to try a new controller or new Net Core project... It will take more time.

    Here's new controller with a very simple output, no appservice used:

      [RemoteService]
        [Area("app")]
        [ControllerName("Test")]
        [Route("api/ct/central-tool/tests")]
        [AllowAnonymous]
        [DisableAuditing]
        public class TestController : AbpController
        {
            public TestController()
            {
            }
    
            [HttpGet]
            public List<int> GetPositionLookupAsync()
            {
                return new List<int>
                {
                    0, 1, 2, 3, 4, 5, 6, 7, 999, 10000 
                };
            }
        }
    

    Is this time still NOT OK? I mean it is noticeably less than previous, but this code does not use DI (getting appservice instance), does not access DB... And it is still 300+ ms... Should I proceed with a new project or should I proceed with investigating appservice code somehow?

    UPDATE: in fact I have had test solution based on ABP Framework 4.3.0. I used the same test method as above and here is the timing from Swagger (I did not manage to run it from Postman, getting some weird Invalid character in header content ["Host"] error, even though there was nothing wrong with the URL):

    Looking forward for your recommendation as to my next actions.

  • User Avatar
    0
    alper created
    Support Team Director

    GetPositionLookupAsync() takes 100ms . i think it is OK. your service provider has a 100ms lag with the empty action.

    1- add auditing and authorization attributes and report duration. 2- make a db transaction and report duration.

    we will see which step adds the overhead

  • User Avatar
    0
    alexander.nikonov created

    Here's what I've got after modifications in a test solution:

    1. when I added authorization attribute and removed audit-disabling attribute - the time did not change;
    2. when I added ABP appservice - the picture looks like this:
    
            [RemoteService]
            [Authorize]
            public class TestController : AbpController
            {
                private readonly IIdentityUserAppService _identityUserAppService;
    
                public TestController(IIdentityUserAppService identityUserAppService)
                {
                    _identityUserAppService = identityUserAppService;
                }
    
                [HttpGet]
                public async Task<PagedResultDto<string>> GetPositionLookupAsync()
                {
                    var result = await _identityUserAppService.GetListAsync(new GetIdentityUsersInput());
    
                    return new PagedResultDto<string>
                    {
                        Items = result.Items.Select(x => x.Email).ToList(),
                        TotalCount = result.Items.Count
                    };
                }
            }
    
    

    Does it look OK? Even if so - it's a test solution which uses MS SQL Server DB. Our solution uses Oracle and has a lot different functionality on top of standard test solution. Also, replacing MS SQL Server with Oracle in a test solution would take too much effort.

    So I suggest to focus on analysis of our problematic solution based on my input in the previous post: 4 sec is an approx response time with no authorization and disabled auditing (almost the same as initially reported time) and 300+ ms is response time with no appservice used. Please suggest what drill-down should I make - like posting some of our AbpModule code etc.

  • User Avatar
    0
    alper created
    Support Team Director

    _identityUserAppService.GetListAsync makes 2 DB request. one for count one for the list. and I think this duration is OK. 1.44second is acceptable with a fully featured request. Do you say it adds 300ms when you derive from AbpController? See the AbpController base class which uses Lazy properties.

  • User Avatar
    0
    alexander.nikonov created

    _identityUserAppService.GetListAsync makes 2 DB request. one for count one for the list. and I think this duration is OK. 1.44second is acceptable with a fully featured request.
    Do you say it adds 300ms when you derive from AbpController? See the AbpController base class which uses Lazy properties.

    probably i was not precise enough. what i wanted to say is that response time is approx 300ms when not using appservice - just forming test data in controller directly as shown in the code above. if i access real DB data from identityUserService (this exact ABP service is taken just in test purpose, because you know it well) - it is already 4sec which i suppose is too much, because usually it is said one request needs to take less than 1 sec. so what would you suggest?

  • User Avatar
    0
    alper created
    Support Team Director

    I agree that 4sec is too much for that appservice method. then there's a problem with the database server. can you add Dapper to your project and write a raw sql without using ABP repositories. If the duration is still long it means there's a slowness at the database server.

  • User Avatar
    0
    alexander.nikonov created

    I returned from vacation and keep on testing. I am not sure now it's a DB thing. I run API GET request from DB via appservice and TTFB was about 3-4s. Then I replaced the AbpController code which accesses DB via appservice with already mentioned above List<int> data:

            [HttpGet]
            [Route("values/module-types/{languageCode?}")]
            public virtual async Task<List<int>> GetModuleTypeAsync([FromRoute] string languageCode = null)
            {
                return new List<int>
                {
                    0, 1, 2, 3, 4, 5, 6, 7, 999, 10000
                };
                // AppService DB request is commented!!!
            }
    

    And TTFB still is 3s!

    What do you suggest? Probably it has something to do with appservice DI instantiation in AbpControllers? I tried to run it in several mins when writing to you - and the time is about 50-60ms! Another API request - with appservice engaged, run straight after this, is 200-300ms...

    So in other words - sometimes TTFS is more or less OK. But sometimes it is inacceptibly slow. I need to find a root cause. Emphasizing - everything is tested on localhost, VS 2020 / 2022.

    I took a look at the log, trying to find information for the case when TTFB was about 3s. Please have a look at this:

    2021-09-07 18:01:35.693 +03:00 [INF] Route matched with {area = "app", controller = "FixCodeValue", action = "GetModuleType", page = ""}. Executing controller action with signature System.Threading.Tasks.Task1[Volo.Abp.Application.Dtos.PagedResultDto1[AbxEps.CT.Core.Shared.LookupItemDto`1[System.Int32]]] GetModuleTypeAsync(System.String) on controller AbxEps.CentralTools.Controllers.FixCodeValues.FixCodeValueController (AbxEps.CentralTools.HttpApi). 2021-09-07 18:01:38.816 +03:00 [INF] Executing action method AbxEps.CentralTools.Controllers.FixCodeValues.FixCodeValueController.GetModuleTypeAsync (AbxEps.CentralTools.HttpApi) - Validation state: "Valid" 2021-09-07 18:01:38.996 +03:00 [INF] Executed action method AbxEps.CentralTools.Controllers.FixCodeValues.FixCodeValueController.GetModuleTypeAsync (AbxEps.CentralTools.HttpApi), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 180.5069ms.

    • about 3s between "executing controller action" and "executing action method"... What those 3s in-between were spent for? Indeed, the method execution itself took only 180ms...

    UPDATE: for better understanding, I'm attaching zipped log file, where logging level was set to "Debug". This time I tried to run my problematic Details page again. Could you please have a look at the log, probably it will give you some idea?

    https://1drv.ms/u/s!AhWdpZddvifTtxGBMcuy35NOzw31?e=fSMRYs

    On some next run, those times could be 2-3 times less (about 1.5-2sec), which is still pretty much...

    UPDATE 2: cold run today, audit and authorization is turned off - debug log displays the gap between those 2 entries:

    2021-09-08 11:31:11.624 +03:00 [DBG] Executing controller factory for controller AbxEps.CentralTools.Controllers.FreeCodeValues.FreeCodeValueController (AbxEps.CentralTools.HttpApi) 2021-09-08 11:31:13.063 +03:00 [DBG] Executed controller factory for controller AbxEps.CentralTools.Controllers.FreeCodeValues.FreeCodeValueController (AbxEps.CentralTools.HttpApi)

    What is happening in-between? Again, next run of this request takes 255ms, so could look like a DB stuff (and now the data is cached)... But yesterday I saw big time without DB query involved.

  • User Avatar
    0
    alper created
    Support Team Director

    results are not consistent. are you running the server-side on your machine or on a cloud service?

  • User Avatar
    0
    alper created
    Support Team Director

    and be aware that the first run of DI takes the longest time (initialization of services) the consistent test can be done after 2nd or 3rd request.

  • User Avatar
    0
    alexander.nikonov created

    DB resides on Azure cloud. Everything the rest - on localhost. Just in case: I won't be able to create local copy of DB if it is needed for a deeper testing. But as I already mentioned, sometimes there are unexplained lags even if I don't access DB.

  • User Avatar
    0
    alper created
    Support Team Director

    is it possible to share your project with us? info@abp.io

  • User Avatar
    0
    alexander.nikonov created

    I am sorry, but I am now allowed to share the project. What I can do is just to show some informational screendumps, send logs and separate code files... Please let me know if I can measure some additional timings somewhere, etc. Now - just some thoughts: when I use Postman to send API requests - first TTFB is large, that's right, second and further - 10 and more times decreased. That would explain DI initialization. But in real situation, when I refresh the same page in Angular app - I am getting almost the same big timings. For instance, first run ~5-6sec per lookup API request. Next run ~1.5-3sec. Next run - about the same time... Next run - attention - ~4sec again!! Even retrieving refresh tokens at IdentityServer takes ages:

    UPDATE: I've updated my controllers - removing all appservices instantiation at all. There is no DB access to retrieve data now anywhere, empty data is returned:

        [HttpGet]
        [Route("values/owners/{languageCode?}")]
        public virtual async Task&lt;PagedResultDto&lt;LookupItemDto&lt;int&gt;>> GetOwnerAsync([FromRoute] string languageCode = null)
        {
            return new PagedResultDto&lt;LookupItemDto&lt;int&gt;> { Items = new List&lt;LookupItemDto&lt;int&gt;>(), TotalCount = 0 };
        }
    

    Also, made all API calls anonymous and without audit logging. And TTFB is still unsasisfactory. Any ideas?

  • User Avatar
    0
    alper created
    Support Team Director

    @alexander from our tests, this is not related to the ABP Framework. we advise you to publish your project to a on-premise environment to make a real test without 3rd party cloud service.

Made with ❤️ on ABP v9.1.0-preview. Updated on December 02, 2024, 12:35