Way to get aggregate timings?

[johnrom]

Note: Duplicate of #178 , which was (in my mind) closed without resolution

Just wondering if there is a "correct" way to get aggregate timings. Note that I'm using .net core console only. If the answer is "there is no correct way", I'd be interested in creating a PR for it. The following is an ideal example of what I'm trying to achieve:

using (_profiler.Step("Doing a collection of repeated work")) 
using (var aggregateTimer1 = _profiler.CreateAggregateTimer("Doing part 1")) 
using (var aggregateTimer2 = _profiler.CreateAggregateTimer("Doing part 2")) 
{
    foreach (var listItem in myList) {
        using (aggregateTimer1.Step()) {
            DoPart1(listItem);
        }
        using (aggregateTimer2.Step()) {
            DoPart2(listItem);
        }
    }
}

_profiler.Stop();
_logger.LogInformation(_profiler.RenderPlainText());

Intended Result:

Total Time = 28,256.8ms
> Doing a collection of repeated work = 28,249.4ms
>> Aggregate: Doing part 1 = 11,185.9ms
>> Aggregate: Doing part 2 = 14,185.9ms

[LeonidVasilyev]

There is multiple things you can do. One options is to use custom timings, they are grouped by category by default:

using (_profiler.Step("Doing a collection of repeated work"))
{
    foreach (var listItem in myList)
    {
        using (_profiler.CustomTiming("Doing part 1", commandString: string.Empty))
        {
            DoPart1(listItem);
        }
        using (_profiler.CustomTiming("Doing part 2", commandString: string.Empty))
        {
            DoPart2(listItem);
        }
    }
}

Generated report:

SERVER at 26.11.2018 13:46:22
 MiniProfiler = 61,5ms
> Doing a collection of repeated work = 58,6ms (Doing part 1 = 8ms in 10 cmds) (Doing part 2 = 1,6ms in 10 cmds)

But this may not be the best solution in terms of instrumentation overhead if you have a big list. Maybe you can do first processing step for all items first, and then proceed with second step:

using (_profiler.Step("Doing a collection of repeated work"))
{
    using (_profiler.Step("Doing part 1"))
    {
        foreach (var listItem in myList)
        {
            DoPart1(listItem);
        }
    }
    using (_profiler.Step("Doing part 2"))
    {
        foreach (var listItem in myList)
        {
            DoPart2(listItem);
        }
    }
}

Generated report:

SERVER at 26.11.2018 13:52:45
 MiniProfiler = 8,5ms
> Doing a collection of repeated work = 5,3ms
>> Doing part 1 = 2,3ms
>> Doing part 2 = 2,8ms

Or you can roll you own MiniProfiler extension method.

[johnrom]

I definitely wouldn't duplicate the loop in order to profile. I didn't realize that the CustomTiming would combine in that way, so that's definitely helpful! I do wish it displayed similar to a step by default. I'll use the extension method posted in the previous issue if there is no interest in making it a part of the API.

[LeonidVasilyev]

Please note that I am not a MiniProfiler developer and I take no part in API design decision.

One other option is to use Stopwatch instances and set Timing.DurationMilliseconds property explicitly:

using (var repeatedWork = _profiler.Step("Doing a collection of repeated work"))
using (var aggregateTiming1 = new Timing(_profiler, repeatedWork, "Doing part 1"))
using (var aggregateTiming2 = new Timing(_profiler, repeatedWork, "Doing part 2"))
{
    var sw1 = new Stopwatch();
    var sw2 = new Stopwatch();
    try
    {
        foreach (var listItem in myList)
        {
            sw1.Start();
            DoPart1(listItem);
            sw1.Stop();

            sw2.Start();
            DoPart2(listItem);
            sw2.Stop();
        }
    }
    finally
    {
        aggregateTiming1.DurationMilliseconds = sw1.ElapsedMilliseconds;
        aggregateTiming2.DurationMilliseconds = sw2.ElapsedMilliseconds;
    }
}

Generated report:

SERVER at 26.11.2018 15:37:17
 MiniProfiler = 324,5ms
> Doing a collection of repeated work = 319,1ms
>> Doing part 1 = 106ms
>> Doing part 2 = 209ms

[johnrom]

That's a really nice option, thank you! Ultimately, the purpose of this issue is to establish if there is interest in adding a standardized way to achieve this to the MiniProfiler API, instead of individual developers maintaining their own way to get these performance metrics. It does seem that the CustomTiming API technically accomplishes this task on its own, so maybe it would be as simple as adding some direction in the documentation to use the CustomTiming API for aggregation as well as categorization.

However, if there is a large performance overhead to creating these various CustomTimings thousands of times, maybe it would be useful to reuse timings that persist in Head via an Extension method that is added to the API similar to:

https://stackoverflow.com/questions/9757591/mvc-mini-profiler-manually-adding-step

[NickCraver]

While there aren't extension methods for it (given the care is so rare), this is doable today. Here's how you'd go about it:

void Main()
{
    var profiler = MiniProfiler.StartNew();
    var myList = new List<string> { "A", "B", "C", "D" };
    using (var parent = profiler.Step("Doing a collection of repeated work"))
    {
        var aggregateTimer1 = new Timing(profiler, parent, "Doing part 1");
        var aggregateTimer2 = new Timing(profiler, parent, "Doing part 2");
        foreach (var listItem in myList)
        {
            using (new Timing(profiler, aggregateTimer1, listItem))
            {
                Method1(listItem);
            }
            using (new Timing(profiler, aggregateTimer2, listItem))
            {
                Method2(listItem);
            }
        }
    }

    profiler.Stop();
    Console.WriteLine(profiler.RenderPlainText());
}

public void Method1(string name) => Thread.Sleep(30);
public void Method2(string name) => Thread.Sleep(60);

The output then looks like this:

CRAVERTOP at 12/1/2018 4:00:06 PM
 MiniProfiler = 366.6ms
> Doing a collection of repeated work = 366.6ms
>> Doing part 1 = 366.6ms
>>> A = 30.5ms
>>> B = 30.8ms
>>> C = 30.8ms
>>> D = 30.8ms
>> Doing part 2 = 366.6ms
>>> A = 60.8ms
>>> B = 60.8ms
>>> C = 60.8ms
>>> D = 60.8ms

Is that close enough to what you're trying to achieve? The problem with arbitrary starting and stopping of a timing is the position in the linear-time relative tree ceases to make sense. With child timings split out when they actually happens, there's no magic. If we want more flexible (magic) way to summarize, I think that should remain custom and it requires a distortion of reality to achieve doing so.

Thoughts? If this works, I'll add it as a sample to the Misc project that's racking some of these up :)

[johnrom]

@NickCraver Thanks for your solution! I'm not sure I would classify this case as "rare" since one cannot know the frequency of usage of something that doesn't yet exist. I've almost always found reasons across many projects and languages for wanting to profile this type of information, always resorting to context clues or a manual step-through instead of being able to leverage a built-in profiler method. This is doable, but perhaps not ideal.

Is there a way to hide or average "A, B, C, D" without having to re-create the plaintext template? For me, that information can get in the way when it's not explicitly needed, especially over thousands or millions of iterations. I understand that the concept of a linear-time relative tree breaks down when working with cyclic timing. However, I think in cyclic scenarios, a different representation of the subtree within an interval of linear time could be more useful for debugging in scenarios where the repetition becomes the bottleneck. I'm not familiar with the nomenclature of these types of datasets, so apologies for making one up, but I'd say there's a valid yet different subtree that could be used in these circumstances.

// linear tree
Root = 1ms
> A = 1ms
> AA = 1ms
> B = 1ms
> BA = 1ms
> C = 5ms
// cyclic subtree - condensed
>> CA (aggregate) x 2 = 4ms (2ms avg)
// CAA, CAB present in the order declared in the repeated code
>>> CAA x 2 (avg) = 1ms
>>> CAB x 2 (avg) = 1ms
// cyclic subtree - expanded
>> CA1 = 2ms
>>> CAA = 1ms
>>> CAB = 1ms
>> CA2 = 2ms
>>> CAA = 1ms
>>> CAB = 1ms
// back to linear time
>> CB = 1ms

I think there is a correct way to implement this that is universally useful (though maybe not exactly the way above), which is why I am ultimately requesting a new feature as opposed to updated documentation.

[NickCraver]

@johnrom Sure, we can't know for sure, but we have to determine things based on the data we have. In almost 7 years, it's been requested once (this time) - so as a maintainer, I have to think it's rare. The built-in bits are an intentional API design to register actual time including absolute bounds in the tree and where items are. What's requested here is most of a "whatever I want inside a step" time. For those cases, custom timings do exist though still their start and end times would be meaningless as you're losing time between recordings.

If you want to do this without actual detail or accuracy with respect to timelines, I suggest a custom timing that you just build and append is the way to go - if the drawbacks of an inaccurate start and end time that doesn't match duration are acceptable to you. I can't think of anything this would break, but it's possible the UI doesn't handle it in some way.

[johnrom]

@NickCraver I actually linked to a separate issue that was opened, but closed, requesting a similar thing and solving it via a custom extension.

I understand the need to register actual time. I suppose that my inclination is that you can both record actual time while correlating separate timings into categorized data, and that this can be a universally useful feature. You can disagree, and mark this is a wontfix if that is what the team thinks is best. I think the custom timing solution would do well enough, but for some reason the display of it is all on a single line when printing plaintext. Here's a contrived example:

>>> Adding and updating customers and attributes = 7,719.4ms (Checking for Existing Customer = 151.7ms in 2051 cmds) (Updating First Names = 42.9ms in 2051 cmds) (Updating Last Names = 44.2ms in 2051 cmds) (Updating Usernames = 25.4ms in 2051 cmds) (Updating Billing Address = 38ms in 2051 cmds) (Updating Shipping Address = 27.1ms in 2051 cmds) (Updating Favorite Color = 33ms in 2051 cmds) (Updating Phone Number = 35.5ms in 2051 cmds) (Updating Other Data = 32.6ms in 2051 cmds) (Updating Much Other Data = 208.4ms in 2051 cmds) (Updating Even More Data = 52.5ms in 2051 cmds)

I suppose at the bare minimum having each parenthetical item on a newline would be enough, although being able to switch between a condensed version and a version that actually shows each iteration would be ideal, for debugging when a single iteration is causing a hold-up.

[boukeversteegh]

In my project, I also need to figure out which part of a loop takes the most time.

Looping twice is not an option for me because it impacts performance, so I need something as proposed here.

The following solution worked for me, and could be used as a copy-paste snippets for others in the same situation:

Re-usable step / aggregate timings implementation

public static class MiniProfilerExtensions
{
    public static SubTiming SubStep(this Timing timer, string name)
        => timer != null ? new SubTiming(MiniProfiler.Current, timer, name) : null;
}

public class SubTiming : Timing
{
    private readonly Stopwatch stopwatch;

    public SubTiming(MiniProfiler profiler, Timing parent, string name, decimal? minSaveMs = null) :
        base(profiler, parent, name, minSaveMs) => stopwatch = new Stopwatch();

    public void Start() => stopwatch.Start();

    public new void Stop()
    {
        stopwatch.Stop();
        DurationMilliseconds = stopwatch.ElapsedMilliseconds;
    }
}

How to use

void SomeMethod() {
    using var step = MiniProfiler.Current?.Step("Processing Loop");
    // define aggregates, timer will not start yet.
    var stepA = step.SubStep("Processing Type A");
    var stepB = step.SubStep("Processing Type B");

    foreach (var item in items) {
         if (item.Type == ItemType.A) {
              stepA.Start(); // start and stop timer manually inside the loop.
              ProcessA(item);
              stepA.Stop();
         }
         if (item.Type == ItemType.B) {
              stepB.Start();
              ProcessB(item);
              stepB.Stop();
         }
    }
}

Output

>> Processing Loop 231.3ms
>>>> Processing Type A 210.5ms
>>>> Processing Type B 29.6ms