Slow TTFB (server response time) #1711

18 Answer(s)

• 

  0

  maliming created 3 years ago

  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.

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  @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?

  Save Cancel
• 

  0

  alper created 3 years ago

  Support Team Director

  try to disable Redis if you have not done.

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  @albert Redis is already disabled

  Save Cancel
• 

  0

  alper created 3 years ago

  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

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  @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.

  Save Cancel
• 

  0

  alper created 3 years ago

  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

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  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.

  Save Cancel
• 

  0

  alper created 3 years ago

  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.

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  _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?

  Save Cancel
• 

  0

  alper created 3 years ago

  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.

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  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.

  Save Cancel
• 

  0

  alper created 3 years ago

  Support Team Director

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

  Save Cancel
• 

  0

  alper created 3 years ago

  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.

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  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.

  Save Cancel
• 

  0

  alper created 3 years ago

  Support Team Director

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

  Save Cancel
• 

  0

  alexander.nikonov created 3 years ago

  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<PagedResultDto<LookupItemDto<int>>> GetOwnerAsync([FromRoute] string languageCode = null)
      {
          return new PagedResultDto<LookupItemDto<int>> { Items = new List<LookupItemDto<int>>(), TotalCount = 0 };
      }
  

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

  

  Save Cancel
• 

  0

  alper created 3 years ago

  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.

  Save Cancel