Problem profiling MVC application with async actions

JonSmith

Hi,

I am profiling an MVC application which uses async actions extensively. Problem is I get very strange results.

The timing of the await action inside the MVC action has a 'silly' time, e.g. it says it has taken seconds of time while the Chrome Network profiler said the action took 15ms. In addition the time shown seems to increase with every call to that action, e.g. call n might say it took 21,500 ms n+1 said it took 64,000 ms. Subsequent async actions after the first async action can show as zero time.

Also I know it does database calls via Entity Framework, but I don't see any SQL database calls after the initial check of the database migration table. After startup I have called a method that has never been called before but don't see any database accesses. It is a small test database, but I am accessing records not looked at any time before this method call so I don't see how they might be cached.

I am running ANTS profiler 9.0 at the highest level of profiling. It says it has detected async mode and my timing options are CPU time, milliseconds. I zoom into a specific section

Jon Smith

JonSmith

Further to this post I took the trouble to change a specific part of the MVC code to NOT use async. When I did that then a) the timings were sensible and b) I could see the database accesses. Going back to async gave wrong timing and no access to database calls.

Alex B

Hi Jon,

I think you may need to use the Async Mode available in ANTS Performance Profiler (View > Async Mode). Here is documentation about Async Mode in the call tree and Async and the call graph. You will also need to ensure the Profile with Async Awareness is enabled in the advanced options.

Please have a look at this documentation and let me know if that helps or if you need any further assistance!

Kind regards,
Alex

JonSmith

Hi Alex,

Sorry in the delay in getting back to you but I had other work I needed to press on with.

I have looked at your suggestions and the documentation. I am definitely have View->Async Mode ticked and the advanced setting has 'Profile with Async awareness' ticked. I also swapped to wall-clock timing, ms.

Problem is I still have the same problem, i.e.
1) The Time to await reads as 75,897 ms (for instance) for the call to the Detail view, but Chrome developer said the call finished in 30 ms (Load was 308ms)
2) I don't get any database calls listed in ANTS view, i.e. if i select 'Database calls' in the View dropdown list is says 'No SQL queries were recorded ... etc.'

The application is an MVC5 web app running the action below. The GetRenderLabelGroupAsync method which has a couple of database calls, both using Async.

        public async Task<ActionResult> Details(int labelGroupId, IGenericActionsDbContext db)
        {
            var status = await RenderSetupDto.GetRenderLabelGroupAsync(db, labelGroupId, false);
            if (status.IsValid) 
                   return View(status.Result);

            //else error, so set status and return to index page
            TempData["Status"] = status;
            return RedirectToAction("Index");
        }

I have Isolated the call by leaving plenty of time before and after it. Also, as I said in my last post, I took the trouble to convert it all to sync and ANTS worked perfectly.

What on earth am I doing wrong?

Alex B

Hi Jon,

Is 75k ms wall-clock time and is the 30ms from Chrome cpu or wall-clock? I just want to make sure they're measuring the same thing.

Also, please try turning off the "Adjust timings to compensate for overhead added by the profiler" advanced option and profile using "Only methods with source" or less profiling mode.

For the database calls, can you please try profiling the async version with the "Profile with Async awareness" option turned off and see if the database calls are captured then?

Kind regards,
Alex

JonSmith

Hi Alex,

Thanks for getting back to me and sorry for the delay my end - on a project at the moment so have to fit this in at the weekend.

Firstly I have taken screenshots but there doesn't seem to be any way to attach them to a post. If you go to my web site at http://www.thereformedprogrammer.net/ (didn't want to put my email in post!) and send me your email I can email you the screenshots.

Anyway, onto your questions:

1) The timings in ANTs are wall-clock milliseconds and are typically > 10,000ms . The chrome timing are from the developer tools->Network page and the time I have quoted is the total time that Chrome was waiting for the page, typically 50ms (note: the page contains all the database accesses - none are done by Ajax at the moment).

2) I turned off "Adjust timings to compensate for overhead added by the profiler" advanced option and it made no difference to the timings.

3) I turned off the "Profile with Async awareness" option and I still could not see the database accesses. I also tried turning off Async Mode in the the View, but that did not reveal the database access either.

So, no joy there at all.

sallgeud

I'm seeing the exact same issue. However, when I turn off every single advanced option, the times begin to seem more reasonable and nearer to accurate.

JonSmith

Hi sallgeud,

I have been talking directly with RedGate via their support desk. It does look like there is something funny going on with async timings and they are working on it.

On the logging the database access it seems that isn't supported in async mode currently.

Jon

jrg

SQL calls from ExecuteReaderAsync, ExecuteXmlReaderAsync, ExecuteNonQueryAsync, ExecuteDbDataReaderAsync and ExecuteScalarAsync are now captured by ANTS Performance Profiler.