If you're encountering performance issues with your Web Application, one of the first things you should be doing is finding the hot spots: what are the places in code where a lot of time is spent and why?  Hopefully, you will uncover an inefficiency which can be optimized and optimizing a hot spot is likely to have a significant effect on the overall performance.

For this purpose, so-called profilers exist which can give you great insight in where the time is spent and help you quickly drill down to the lower levels to find the hot spots. However, if for whatever reason you cannot deploy such a profiler on an ill-performing system and your Web Application is based on DXA.NET, there is a poor man's approach to getting similar insights, using the built-in tracing functionality. This procedure is not nearly as user-friendly as with a full-blown profiler, but I want to show you it can be done with a bit of perseverance.

Enable DXA tracing by setting the DXA log level to TRACE in Log.config.

This will output detailed method entry/exit tracing in the DXA log file (which is configured in Log.config), including the time each method took.

Because of the level of detail, trace logging will have significant performance impact and will quickly result in a huge log file. Therefore it should be enabled only temporarily for analysis purposes. Furthermore, analysis of the trace will quickly become challenging because of the sheer amount of tracing information.  However,  PowerShell's Select-Strings cmdlet (alias: sls) is your friend here;  this is PowerShell's equivalent of Unix grep.

For example: to quickly find methods which took longer than one second:

sls "Duration: \d{4}" site.log

This will output all lines which contain the text "Duration: " followed by at least four digits (and since duration is output in milliseconds, this means one second or more).

site.log:1053:2017-01-18 21:36:21,265 [1] DEBUG -   ContextServiceClaimsProvider..cctor() exit. Duration: 1308 ms.
site.log:1064:2017-01-18 21:36:21,281 [1] DEBUG - SiteConfiguration.InitializeProviders() exit. Duration: 1397 ms.
site.log:1551:2017-01-18 21:36:22,937 [17] DEBUG -       Localization.LoadStaticContentItem() exit. Duration: 1098 ms.
site.log:1568:2017-01-18 21:36:23,000 [17] DEBUG -     Localization.Load() exit. Duration: 1229 ms.
site.log:1569:2017-01-18 21:36:23,000 [17] DEBUG -   CdApiLocalizationResolver.ResolveLocalization() exit. Duration: 1452 ms.
site.log:1571:2017-01-18 21:36:23,000 [17] DEBUG - CustomStaticContentModule.BeginRequest() exit. Duration: 1456 ms.
site.log:2201:2017-01-18 21:36:25,656 [17] DEBUG -   CustomProvider.GetPageModel() exit. Duration: 1793 ms.
site.log:2203:2017-01-18 21:36:25,656 [17] DEBUG - CustomPageController.Page() exit. Duration: 1807 ms.
site.log:2698:2017-01-18 21:36:29,281 [17] DEBUG -               DefaultModelBuilder.BuildEntityModel() exit. Duration: 2452 ms.
site.log:2709:2017-01-18 21:36:29,328 [17] DEBUG -             DefaultModelBuilder.BuildEntityModel() exit. Duration: 2507 ms.
site.log:2710:2017-01-18 21:36:29,328 [17] DEBUG -           ModelBuilderPipeline.CreateEntityModel() exit. Duration: 2507 ms.
site.log:2711:2017-01-18 21:36:29,328 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 2516 ms.
site.log:3301:2017-01-18 21:36:30,562 [17] DEBUG -               DefaultModelBuilder.BuildEntityModel() exit. Duration: 1036 ms.
site.log:3312:2017-01-18 21:36:30,593 [17] DEBUG -             DefaultModelBuilder.BuildEntityModel() exit. Duration: 1067 ms.
site.log:3313:2017-01-18 21:36:30,593 [17] DEBUG -           ModelBuilderPipeline.CreateEntityModel() exit. Duration: 1067 ms.
site.log:3314:2017-01-18 21:36:30,593 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 1091 ms.
site.log:4089:2017-01-18 21:36:32,781 [17] DEBUG -               DefaultModelBuilder.BuildEntityModel() exit. Duration: 1840 ms.
site.log:4100:2017-01-18 21:36:32,812 [17] DEBUG -             DefaultModelBuilder.BuildEntityModel() exit. Duration: 1869 ms.
site.log:4101:2017-01-18 21:36:32,812 [17] DEBUG -           ModelBuilderPipeline.CreateEntityModel() exit. Duration: 1870 ms.
site.log:4102:2017-01-18 21:36:32,812 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 1890 ms.
site.log:4111:2017-01-18 21:36:33,031 [17] DEBUG -       HtmlHelperExtensions.DxaEntity() exit. Duration: 6901 ms.
site.log:4112:2017-01-18 21:36:33,031 [17] DEBUG -     HtmlHelperExtensions.DxaEntities() exit. Duration: 6901 ms.
site.log:4113:2017-01-18 21:36:33,031 [17] DEBUG -   HtmlHelperExtensions.DxaRegion() exit. Duration: 6904 ms.
site.log:4114:2017-01-18 21:36:33,031 [17] DEBUG - HtmlHelperExtensions.DxaRegion() exit. Duration: 6904 ms.

Note that the output lines start with the file name and line number; useful to lookup the line in the entire log file to get some context.

Also note that the number in brackets is the thread ID and the indentation reflects the nesting of method calls (for a given thread). With multiple concurrent threads outputting traces, indentation may look like a mess. A useful thing to do is to isolate the tracing for a single thread we want to analyze further. In the above example, it makes sense to zoom in on thread 17. Let's create a separate log file for this thread only:

sls "\[17\]" site.log > thread17.log

Now we have a thread17.log file with only the debug/trace output for thread 17. If we open this file in a text editor, we should see the nesting of the method calls from the indentation.  Note that durations aggregate: the duration of a calling method includes the durations of the methods it has called. To find hot spots, the innermost methods which take a long time are most interesting.

For example, let's zoom on the DefaultProvider.GetEntityModel method which took more that 2.5 seconds on one occasion:

sls "DefaultProvider\.GetEntityModel" thread17.log

Result:

thread17.log:389:site.log:1911:2017-01-18 21:36:24,906 [17] DEBUG -     DefaultProvider.GetEntityModel("75159-78432", 849 ('English')) entry.
thread17.log:695:site.log:2200:2017-01-18 21:36:25,656 [17] DEBUG -     DefaultProvider.GetEntityModel() exit. Duration: 751 ms.
thread17.log:788:site.log:2293:2017-01-18 21:36:26,172 [17] DEBUG -         DefaultProvider.GetEntityModel("108922-78444", 849 ('English')) entry.
thread17.log:823:site.log:2327:2017-01-18 21:36:26,453 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 280 ms.
thread17.log:824:site.log:2328:2017-01-18 21:36:26,453 [17] DEBUG -         DefaultProvider.GetEntityModel("66820-78444", 849 ('English')) entry.
thread17.log:854:site.log:2357:2017-01-18 21:36:26,515 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 51 ms.
thread17.log:863:site.log:2366:2017-01-18 21:36:26,531 [17] DEBUG -         DefaultProvider.GetEntityModel("61761-78398", 849 ('English')) entry.
thread17.log:897:site.log:2399:2017-01-18 21:36:26,593 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 62 ms.
thread17.log:898:site.log:2400:2017-01-18 21:36:26,593 [17] DEBUG -         DefaultProvider.GetEntityModel("61761-79617", 849 ('English')) entry.
thread17.log:943:site.log:2444:2017-01-18 21:36:26,672 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 82 ms.
thread17.log:944:site.log:2445:2017-01-18 21:36:26,687 [17] DEBUG -         DefaultProvider.GetEntityModel("73287-347", 849 ('English')) entry.
thread17.log:950:site.log:2451:2017-01-18 21:36:26,797 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 119 ms.
thread17.log:951:site.log:2452:2017-01-18 21:36:26,797 [17] DEBUG -         DefaultProvider.GetEntityModel("73287-78398", 849 ('English')) entry.
thread17.log:969:site.log:2470:2017-01-18 21:36:26,812 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 13 ms.
thread17.log:970:site.log:2471:2017-01-18 21:36:26,812 [17] DEBUG -         DefaultProvider.GetEntityModel("73287-93876", 849 ('English')) entry.
thread17.log:1229:site.log:2711:2017-01-18 21:36:29,328 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 2516 ms.
thread17.log:1230:site.log:2712:2017-01-18 21:36:29,328 [17] DEBUG -         DefaultProvider.GetEntityModel("108462-78398", 849 ('English')) entry.
thread17.log:1248:site.log:2730:2017-01-18 21:36:29,359 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 21 ms.
thread17.log:1249:site.log:2731:2017-01-18 21:36:29,359 [17] DEBUG -         DefaultProvider.GetEntityModel("108462-79617", 849 ('English')) entry.
thread17.log:1289:site.log:2770:2017-01-18 21:36:29,421 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 68 ms.
thread17.log:1290:site.log:2771:2017-01-18 21:36:29,421 [17] DEBUG -         DefaultProvider.GetEntityModel("108462-79618", 849 ('English')) entry.
thread17.log:1330:site.log:2810:2017-01-18 21:36:29,468 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 49 ms.
thread17.log:1331:site.log:2811:2017-01-18 21:36:29,468 [17] DEBUG -         DefaultProvider.GetEntityModel("71674-78398", 849 ('English')) entry.
thread17.log:1349:site.log:2829:2017-01-18 21:36:29,500 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 24 ms.
thread17.log:1350:site.log:2830:2017-01-18 21:36:29,500 [17] DEBUG -         DefaultProvider.GetEntityModel("71674-79901", 849 ('English')) entry.
thread17.log:1871:site.log:3314:2017-01-18 21:36:30,593 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 1091 ms.
thread17.log:1872:site.log:3315:2017-01-18 21:36:30,593 [17] DEBUG -         DefaultProvider.GetEntityModel("75138-78398", 849 ('English')) entry.
thread17.log:1895:site.log:3338:2017-01-18 21:36:30,656 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 63 ms.
thread17.log:1896:site.log:3339:2017-01-18 21:36:30,656 [17] DEBUG -         DefaultProvider.GetEntityModel("75138-79617", 849 ('English')) entry.
thread17.log:1941:site.log:3383:2017-01-18 21:36:30,750 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 92 ms.
thread17.log:1942:site.log:3384:2017-01-18 21:36:30,750 [17] DEBUG -         DefaultProvider.GetEntityModel("75138-79618", 849 ('English')) entry.
thread17.log:1998:site.log:3438:2017-01-18 21:36:30,890 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 154 ms.
thread17.log:1999:site.log:3439:2017-01-18 21:36:30,890 [17] DEBUG -         DefaultProvider.GetEntityModel("71122-78398", 849 ('English')) entry.
thread17.log:2012:site.log:3452:2017-01-18 21:36:30,921 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 23 ms.
thread17.log:2013:site.log:3453:2017-01-18 21:36:30,921 [17] DEBUG -         DefaultProvider.GetEntityModel("71122-79901", 849 ('English')) entry.
thread17.log:2697:site.log:4102:2017-01-18 21:36:32,812 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 1890 ms.    

Note that the result lines now contain line numbers both in thread17.log and in the original site.log.

From these results, we can see the DefaultProvider.GetEntityModel parameters for the call which is so slow:

thread17.log:970:site.log:2471:2017-01-18 21:36:26,812 [17] DEBUG -         DefaultProvider.GetEntityModel("73287-93876", 849 ('English') entry.
thread17.log:1229:site.log:2711:2017-01-18 21:36:29,328 [17] DEBUG -         DefaultProvider.GetEntityModel() exit. Duration: 2516 ms    

Note that DefaultProvider.GetEntityModel is called by a controller in order to get the DXA Entity Model for a given Dynamic Component Presentation. In this case: the DCP for Component tcm:849-73287 rendered with CT tcm:849-93876-32.

Now we have zoomed in enough to go back to the log file itself, or better the log file for thread 17:  goto line 970 to find the method entry.  You can now see what called the method (above; lower indent) and what the method calls (below; higher indent; don't look past line 1229, because that is where the method exit is).