- ABP Framework version: v8.1.3
- UI Type: MVC
- Database System: EF Core (SQL Server)
- Tiered (for MVC) or Auth Server Separated (for Angular): yes'
- Exception message and full stack trace: there is none
- Steps to reproduce the issue: Any api call Hello, I understand mine is an open-ended and possibly ill posed question but I need some help understanding. When calling a "complex" get, with no database writing, only read queries, we have a strange phenomenon, see this log:
[18:57:28 DBG] Elapsed time: 5661 ms is the last line of code before the return statement [18:57:44 DBG] Added 0 entity changes to the current audit log [18:57:44 INF] Executing ObjectResult, writing value of type 'Volo.Abp.Application.Dtos.PagedResultDto`1[[IISCert.Certonline.BaseDto.CertificatoRinnovoDto, IISCert.Certonline.Application.Contracts, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]'. [18:57:44 INF] Executed action IISCert.Certonline.Legacy.WebCertificatoPubblicazioniAppService.GetListMantenimentiAsync (IISCert.Certonline.Application) in 21726.8956ms [18:57:44 INF] Executed endpoint 'IISCert.Certonline.Legacy.WebCertificatoPubblicazioniAppService.GetListMantenimentiAsync (IISCert.Certonline.Application)' [18:57:59 DBG] Added 0 entity changes to the current audit log [18:57:59 INF] Request finished HTTP/2 GET https://localhost:44352/api/app/web-certificato-pubblicazioni/mantenimenti?maxResultCount=50&skipCount=0&sorting=
- 200 null application/json; charset=utf-8 36749.9201ms
to be clearer, this is the end of the method:
// stop timer
watch.Stop();
var elapsedMs = watch.ElapsedMilliseconds;
Log.Debug(new StringBuilder().Append("Elapsed time: ").Append(elapsedMs).Append(" ms").ToString());
return new PagedResultDto<CertificatoRinnovoDto>(
totalCount,
result);
Almost 30 seconds pass between the watch stop at the end of the method and the avaliability of the result for the browser. What happens in this time? Is it possible to reduce it? Thank you for your answers
Enrico
3 Answer(s)
-
0
hi
How can I reproduce this case?
-
0
hi
How can I reproduce this case?
Hello, It is quite hard for me to make you test our case. In general I am interested in understanding what may be happening under the hood in those 40 seconds between the various log calls that you see. The logs are produced locally in debug mode and no other operation is running in the application other that that, as you can see there are no other endpoints being called or any other automatic log.
What may be happening that makes the "Request finished" happen almost 40 seconds after that clock calls?
-
0
hi
You can set all log levels to Verbose to see what happened.
public class Program { public async static Task<int> Main(string[] args) { Log.Logger = new LoggerConfiguration() .MinimumLevel.Verbose() .Enrich.FromLogContext() .WriteTo.Async(c => c.File("Logs/logs.txt")) .WriteTo.Async(c => c.Console()) .CreateLogger();
