Bad performance on Azure App Service #9009

TicosSystems created 4 years ago

Dear Asp.Net Zero Team We deploy our project into azure app services and from begging we struggled with request performance. Each request have very long execution in our opinion. We focus to optimize sql query and have some success on this field, but right now when we measure our execution we get 200ms for query but full request take 530ms for example. Where we can look for a problem. From logs its looks like that legacy code for example JwtBearer.JwtBearerHandler take 100ms and this issue only occur on app service when we running our project locally it take couple of ms. Right now we run on S1 plan. Is it to low to run asp.net zero? Some snippets from logs sorry for some doubled logs it is issue with our NLog configuration but we already check it has no impact on this problem:

Line 13543: INFO [2020-05-12 06:34:17.7041]  Microsoft.AspNetCore.Hosting.Diagnostics |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Request starting HTTP/1.1 GET https://OurDomain.com/api/services/app/Course/GetAll?Sorting=&SkipCount=0&MaxResultCount=100&Keyword=&Filters= application/json   
Line 13544: INFO [2020-05-12 06:34:17.7160]  Microsoft.AspNetCore.Hosting.Diagnostics |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Request starting HTTP/1.1 GET https://OurDomain.com/api/services/app/Course/GetAll?Sorting=&SkipCount=0&MaxResultCount=100&Keyword=&Filters= application/json   
Line 13545: INFO [2020-05-12 06:34:17.7234]  Microsoft.AspNetCore.Cors.Infrastructure.CorsService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll CORS policy execution successful.  
Line 13546: INFO [2020-05-12 06:34:17.7234]  Microsoft.AspNetCore.Cors.Infrastructure.CorsService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll CORS policy execution successful.  
Line 13547: INFO [2020-05-12 06:34:17.7657]  Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Successfully validated the token.  
Line 13548: INFO [2020-05-12 06:34:17.7691]  Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Successfully validated the token.  
Line 13549: INFO [2020-05-12 06:34:17.8594]  Microsoft.AspNetCore.Routing.EndpointMiddleware |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executing endpoint 'OurProject.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'  
Line 13550: INFO [2020-05-12 06:34:17.8654]  Microsoft.AspNetCore.Routing.EndpointMiddleware |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executing endpoint 'OurProject.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'  
Line 13551: INFO [2020-05-12 06:34:17.8654]  Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Route matched with {area = "app", action = "GetAll", controller = "Course"}. Executing controller action with signature System.Threading.Tasks.Task`1[Abp.Application.Services.Dto.PagedResultDto`1[OurProject.ReservationsSystem.Courses.Dto.CourseDto]] GetAll(OurProject.Generics.PagedAndSortedWithKeywordAndFiltersResultRequestDto) on controller OurProject.ReservationsSystem.Courses.CourseAppService (OurProject.Application).  
Line 13552: INFO [2020-05-12 06:34:17.8805]  Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Route matched with {area = "app", action = "GetAll", controller = "Course"}. Executing controller action with signature System.Threading.Tasks.Task`1[Abp.Application.Services.Dto.PagedResultDto`1[OurProject.ReservationsSystem.Courses.Dto.CourseDto]] GetAll(OurProject.Generics.PagedAndSortedWithKeywordAndFiltersResultRequestDto) on controller OurProject.ReservationsSystem.Courses.CourseAppService (OurProject.Application).  
Line 13553: DEBUG [2020-05-12 06:34:17.9276]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll START GetAll for CourseDto  
Line 13554: DEBUG [2020-05-12 06:34:17.9276]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll START CheckGetAllPermission  
Line 13555: DEBUG [2020-05-12 06:34:17.9454]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END CheckGetAllPermission and START _queryService.GetAll()  
Line 13556: DEBUG [2020-05-12 06:34:17.9568]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END _queryService.GetAll() and START ApplySorting(query, input)  
Line 13557: DEBUG [2020-05-12 06:34:17.9568]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END ApplySorting(query, input) and START ApplyKeywordSearch(query, input)  
Line 13558: DEBUG [2020-05-12 06:34:17.9568]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END ApplyKeywordSearch(query, input) and START ApplyFiltering(query, input)  
Line 13559: DEBUG [2020-05-12 06:34:17.9846]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END ApplyFiltering(query, input) and START  query.CountAsync();  
Line 13560: DEBUG [2020-05-12 06:34:18.0116]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END query.CountAsync() and START  ApplyPaging(query, input)  
Line 13561: DEBUG [2020-05-12 06:34:18.0116]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END ApplyPaging(query, input) and START  page.ToListAsync()  
Line 13562: DEBUG [2020-05-12 06:34:18.1466]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END page.ToListAsync()  
Line 13563: DEBUG [2020-05-12 06:34:18.1466]  OurProject.ReservationsSystem.Courses.CourseAppService |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll END GetAll for CourseDto Execution Time: 00:00:00.2157793  
Line 13564: INFO [2020-05-12 06:34:18.1587]  Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.  
Line 13565: INFO [2020-05-12 06:34:18.1587]  Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.  
Line 13566: INFO [2020-05-12 06:34:18.2144]  Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executed action OurProject.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application) in 330.1808ms  
Line 13567: INFO [2020-05-12 06:34:18.2221]  Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executed action OurProject.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application) in 330.1808ms  
Line 13568: INFO [2020-05-12 06:34:18.2221]  Microsoft.AspNetCore.Routing.EndpointMiddleware |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executed endpoint 'OurProject.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'  
Line 13569: INFO [2020-05-12 06:34:18.2221]  Microsoft.AspNetCore.Routing.EndpointMiddleware |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Executed endpoint 'OurProject.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'  
Line 13570: INFO [2020-05-12 06:34:18.2221]  Microsoft.AspNetCore.Hosting.Diagnostics |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Request finished in 530.7161ms 200 application/json; charset=utf-8  
Line 13571: INFO [2020-05-12 06:34:18.2381]  Microsoft.AspNetCore.Hosting.Diagnostics |1b6abeee-454c029f4f6920ae. GET https://OurDomain.com/api/services/app/Course/GetAll Request finished in 530.7161ms 200 application/json; charset=utf-8

If some additional checks needed we can provide it. We need solution for this issue.

7 Answer(s)

0

maliming created 4 years ago
Support Team

Is this the same issue? https://github.com/aspnetzero/aspnet-zero-core/issues/2925
0

TicosSystems created 4 years ago

I check table AbpUserTokens 892 records , 8 was expired I delete them but still issue is there. Can I delete all this records?
0

ismcagdas created 4 years ago
Support Team

Hi @TicosSystems,

Yes, can you delete tokens and try again ?
0

TicosSystems created 4 years ago

Indeed there is some improvement about 100ms but still. Request take 300-400ms and query execution is only 160ms, Where to look for another improvements? And to solve the problem with token the solution is to change configuration of expiration time?

Line 486: INFO [2020-05-14 15:09:26.4566] Microsoft.AspNetCore.Hosting.Diagnostics |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Request starting HTTP/1.1 GET https://OurProjectDomain/api/services/app/Course/GetAll?Sorting=&SkipCount=0&MaxResultCount=10&Keyword=&Filters= application/json
Line 487: INFO [2020-05-14 15:09:26.4566] Microsoft.AspNetCore.Hosting.Diagnostics |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Request starting HTTP/1.1 GET https://OurProjectDomain/api/services/app/Course/GetAll?Sorting=&SkipCount=0&MaxResultCount=10&Keyword=&Filters= application/json
Line 488: INFO [2020-05-14 15:09:26.4695] Microsoft.AspNetCore.Cors.Infrastructure.CorsService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll CORS policy execution successful.
Line 489: INFO [2020-05-14 15:09:26.4695] Microsoft.AspNetCore.Cors.Infrastructure.CorsService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll CORS policy execution successful.
Line 490: INFO [2020-05-14 15:09:26.5196] Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Successfully validated the token.
Line 491: INFO [2020-05-14 15:09:26.5298] Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Successfully validated the token.
Line 492: INFO [2020-05-14 15:09:26.5298] Microsoft.AspNetCore.Routing.EndpointMiddleware |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executing endpoint 'OurProject.Business.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'
Line 493: INFO [2020-05-14 15:09:26.5298] Microsoft.AspNetCore.Routing.EndpointMiddleware |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executing endpoint 'OurProject.Business.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'
Line 494: INFO [2020-05-14 15:09:26.5479] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Route matched with {area = "app", action = "GetAll", controller = "Course"}. Executing controller action with signature System.Threading.Tasks.Task1[Abp.Application.Services.Dto.PagedResultDto1[OurProject.Business.ReservationsSystem.Courses.Dto.CourseDto]] GetAll(OurProject.Generics.PagedAndSortedWithKeywordAndFiltersResultRequestDto) on controller OurProject.Business.ReservationsSystem.Courses.CourseAppService (OurProject.Application).
Line 495: INFO [2020-05-14 15:09:26.5479] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Route matched with {area = "app", action = "GetAll", controller = "Course"}. Executing controller action with signature System.Threading.Tasks.Task1[Abp.Application.Services.Dto.PagedResultDto1[OurProject.Business.ReservationsSystem.Courses.Dto.CourseDto]] GetAll(OurProject.Generics.PagedAndSortedWithKeywordAndFiltersResultRequestDto) on controller OurProject.Business.ReservationsSystem.Courses.CourseAppService (OurProject.Application).
Line 496: DEBUG [2020-05-14 15:09:26.5794] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll START GetAll for CourseDto
Line 497: DEBUG [2020-05-14 15:09:26.5895] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll START CheckGetAllPermission
Line 498: DEBUG [2020-05-14 15:09:26.5895] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END CheckGetAllPermission and START _queryService.GetAll()
Line 499: DEBUG [2020-05-14 15:09:26.5895] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END _queryService.GetAll() and START ApplySorting(query, input)
Line 500: DEBUG [2020-05-14 15:09:26.6100] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END ApplySorting(query, input) and START ApplyKeywordSearch(query, input)
Line 501: DEBUG [2020-05-14 15:09:26.6100] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END ApplyKeywordSearch(query, input) and START ApplyFiltering(query, input)
Line 502: DEBUG [2020-05-14 15:09:26.6254] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END ApplyFiltering(query, input) and START query.CountAsync();
Line 503: DEBUG [2020-05-14 15:09:26.6552] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END query.CountAsync() and START ApplyPaging(query, input)
Line 504: DEBUG [2020-05-14 15:09:26.6552] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END ApplyPaging(query, input) and START page.ToListAsync()
Line 505: DEBUG [2020-05-14 15:09:26.7402] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END page.ToListAsync()
Line 506: DEBUG [2020-05-14 15:09:26.7469] OurProject.Business.ReservationsSystem.Courses.CourseAppService |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll END GetAll for CourseDto Execution Time: 00:00:00.1573364
Line 507: INFO [2020-05-14 15:09:26.7641] Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.
Line 508: INFO [2020-05-14 15:09:26.7641] Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.
Line 509: INFO [2020-05-14 15:09:26.7641] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executed action OurProject.Business.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application) in 216.5482ms
Line 510: INFO [2020-05-14 15:09:26.7776] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executed action OurProject.Business.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application) in 216.5482ms
Line 511: INFO [2020-05-14 15:09:26.7776] Microsoft.AspNetCore.Routing.EndpointMiddleware |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executed endpoint 'OurProject.Business.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'
Line 512: INFO [2020-05-14 15:09:26.7776] Microsoft.AspNetCore.Routing.EndpointMiddleware |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Executed endpoint 'OurProject.Business.ReservationsSystem.Courses.CourseAppService.GetAll (OurProject.Application)'
Line 513: INFO [2020-05-14 15:09:26.7932] Microsoft.AspNetCore.Hosting.Diagnostics |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Request finished in 336.5918ms 200 application/json; charset=utf-8
Line 514: INFO [2020-05-14 15:09:26.7932] Microsoft.AspNetCore.Hosting.Diagnostics |365392c0-40c9de129d8ebb4d. GET https://OurProjectDomain/api/services/app/Course/GetAll Request finished in 336.5918ms 200 application/json; charset=utf-8
0
ismcagdas created 4 years ago
Support Team
Hi,

There might be different places to look but before doing that, can you try to create a raw ASP.NET Core application and execute a similar query on the database you are working ? In that way, we can understand if this is caused by AspNet Zero or ASP.NET Core.

If you think this will take time, you can try disabling some features;

https://aspnetboilerplate.com/Pages/Documents/Audit-Logging#enable-disable-by-attributes

https://aspnetboilerplate.com/Pages/Documents/Authorization#suppress-authorization

Thanks,
0

TicosSystems created 4 years ago

We had already disabled Audting also we disable UnitOfWork(isTransactional: false) for speed up query execution.
0
ismcagdas created 4 years ago
Support Team
Hi,

Thanks. So you can,

Disable Authorization, https://aspnetboilerplate.com/Pages/Documents/Authorization#suppress-authorization

You can try to create a raw ASP.NET Core application and execute a similar query on the database you are working ?

Have an answer to this question? Log in and write your answer.