Unable to print query using Miniprofiler

Question

I have integrated Entity Framework and CodeFirstStoredProc library in my project. I want to log the queries executed by both the libraries. Previously I was using Database.Log delegate provided by EF but as I want to log query from other libraries also, I decided to integrated Miniprofiler for the same.

I used below code to get the query log in result variable:

MiniProfilerEF6.Initialize();
        MiniProfiler.StartNew("Test");
        using (MiniProfiler.Current.Step("Level 1"))
        {
            DbConnection spConnection = new System.Data.SqlClient.SqlConnection(ConfigurationManager.ConnectionStrings["DefaultConnection"].ConnectionString);
            ProfiledDbConnection profileSpConnection = new ProfiledDbConnection(spConnection, MiniProfiler.Current);
            using (EfDataContext db = new EfDataContext(profileSpConnection))
            {
                List<Domain.PersonEntity> data = db.Persons.ToList();
            }
            using (StoredProcedureContext db = new StoredProcedureContext(profileSpConnection))
            {
                List<GetPersonResult> data = db.GetPerson.CallStoredProc(new Domain.GetPersonParameter { IsActive = true }).ToList<GetPersonResult>();
            }
            string result = MiniProfiler.Current.RenderPlainText();
        }
        MiniProfiler.Current.Stop();

I expected the output query with all the details but unfortunately I am getting below result:

Manprit-PC at 11/15/2018 2:24:27 PM
 Test = ms
> Level 1 = ms (sql = 45ms in 12 cmds)

Am I missing something for the implementation?

Answer 1

This is just how current version of MiniProfilerExtensions.RenderPlainText() renders custom timing information. Custom timings are created using CustomTiming() rather then Step(), they typically are sort of leaf measurements in a MiniProfiler hierarchy such as database interaction or HTTP requests.

You can easily customize rendering process and render verbose information about custom timings:

SERVER at 23.11.2018 09:00:00
 MiniProfiler = 48,3[ms]
> Foo = 35,6ms (sql = 24,8[ms] in 1 cmd) (http = 4,7[ms] in 1 cmd)
   sql 24,8[ms] +16,9[ms] SELECT * FROM Foo
   http 4,7[ms] +41,8[ms] GET http://foo.bar

Example implementation:

using StackExchange.Profiling;
using StackExchange.Profiling.Internal;
...
public static string CustomRenderPlainText(this MiniProfiler profiler, bool htmlEncode = false)
{
    if (profiler == null) return string.Empty;

    var text = StringBuilderCache.Get()
        .Append(htmlEncode ? WebUtility.HtmlEncode(Environment.MachineName) : Environment.MachineName)
        .Append(" at ")
        .Append(DateTime.UtcNow)
        .AppendLine();

    var timings = new Stack<Timing>();
    timings.Push(profiler.Root);

    while (timings.Count > 0)
    {
        var timing = timings.Pop();

        text.AppendFormat("{0} {1} = {2:###,##0.##}[ms]",
            new string('>', timing.Depth),
            htmlEncode ? WebUtility.HtmlEncode(timing.Name) : timing.Name,
            timing.DurationMilliseconds);

        if (timing.HasCustomTimings)
        {
            // TODO: Customize this code block.

            // Custom timings grouped by category. Collect all custom timings in a list.
            var customTimingsFlat = new List<KeyValuePair<string, CustomTiming>>(capacity: timing.CustomTimings.Sum(ct => ct.Value.Count));
            foreach (var pair in timing.CustomTimings)
            {
                var type = pair.Key;
                var customTimings = pair.Value;

                customTimingsFlat.AddRange(pair.Value.Select(ct => KeyValuePair.Create(type, ct)));
                text.AppendFormat(" ({0} = {1:###,##0.##}[ms] in {2} cmd{3})",
                    type,
                    customTimings.Sum(ct => ct.DurationMilliseconds),
                    customTimings.Count,
                    customTimings.Count == 1 ? string.Empty : "s");
            }

            foreach (var pair in customTimingsFlat.OrderBy(kvp => kvp.Value.StartMilliseconds))
            {
                var type = pair.Key;
                var ct = pair.Value;

                text.AppendLine();
                var mainPart = string.Format("{0}{1} {2:###,##0.##}[ms] +{3:###,##0.##}[ms] ",
                                    new string(' ', timing.Depth + 2),
                                    type,
                                    ct.DurationMilliseconds,
                                    ct.StartMilliseconds);
                text.Append(mainPart);
                // Shift command text to closer to the command for better readability.
                var prefix = new string(' ', mainPart.Length);
                string cmdLine = null;
                using (var reader = new StringReader(ct.CommandString))
                {
                    while ((cmdLine = reader.ReadLine()) != null)
                    {
                        text.Append(cmdLine);
                        if (reader.Peek() == -1 && profiler.Options.ExcludeStackTraceSnippetFromCustomTimings)
                        {
                            break;
                        }
                        text.AppendLine();
                        text.Append(prefix);
                    }
                }

                if (profiler.Options.ExcludeStackTraceSnippetFromCustomTimings)
                {
                    continue;
                }
                text.Append(ct.StackTraceSnippet);
            }
        }

        text.AppendLine();

        if (timing.HasChildren)
        {
            var children = timing.Children;
            for (var i = children.Count - 1; i >= 0; i--) timings.Push(children[i]);
        }
    }

    return text.ToStringRecycle();
}

Also note that by default in order to render MiniProfiler report with all timings you need to call Stop() first. You can customize this too by calculating timings so far in a report.