GCAllocationTick_V2 ETW events are reporting wrong allocation sizes in multithreaded application

[Temp1ar]

Assume we have a program which is allocating fixed amount of memory(~200MB) in a tight loop with portions of 200KB in multiple threads:

using System.Linq;
using System.Threading;
class Program
{
  public static void Main(string[] args)
  {
    var threadsCount = args.Any() ? int.Parse(args[0]) : 4;
    var waitHandles = new WaitHandle[threadsCount];
    int counter = 1024;
    for (int i = 0; i != threadsCount; ++i)
    {
      var waitHandle = new AutoResetEvent(false);
      var thread = new Thread(() =>
      {
        while (Interlocked.Decrement(ref counter) > 0)
        {
          var _ = new byte[200 * 1024];
        }
        waitHandle.Set();
      });
      thread.Start();
      waitHandles[i] = waitHandle;
    }
    WaitHandle.WaitAll(waitHandles);
  }
}

If I run this program on .NET Core 5 (Windows 10) with one thread I'll get 1023 events with 204 848 bytes allocated each which is expected. Sum of allocation sizes column: ~210MB (see PerfView status bar in the bottom). If I ran multiple times - I get same numbers:

However If I run this program with 4 or 8 threads, allocation sizes will start to differ and total sum will not be equal to 200MB. It fluctuates between 70(Release configuration) to 360MB. Which can't be right:

Should there be thread synchronization on this allocation size counter or synchronization is not viable option because of low overhead requirement?

[ghost]

Tagging subscribers to this area: @dotnet/gc
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Assume we have a program which is allocating fixed amount of memory(~200MB) in a tight loop with portions of 200KB in multiple threads:

using System.Linq;
using System.Threading;
class Program
{
  public static void Main(string[] args)
  {
    var threadsCount = args.Any() ? int.Parse(args[0]) : 4;
    var waitHandles = new WaitHandle[threadsCount];
    int counter = 1024;
    for (int i = 0; i != threadsCount; ++i)
    {
      var waitHandle = new AutoResetEvent(false);
      var thread = new Thread(() =>
      {
        while (Interlocked.Decrement(ref counter) > 0)
        {
          var _ = new byte[200 * 1024];
        }
        waitHandle.Set();
      });
      thread.Start();
      waitHandles[i] = waitHandle;
    }
    WaitHandle.WaitAll(waitHandles);
  }
}

If I run this program on .NET Core 5 (Windows 10) with one thread I'll get 1023 events with 204 848 bytes allocated each which is expected. Sum of allocation sizes column: ~210MB (see PerfView status bar in the bottom). If I ran multiple times - I get same numbers:

However If I run this program with 4 or 8 threads, allocation sizes will start to differ and total sum will not be equal to 200MB. It fluctuates between 70(Release configuration) to 360MB. Which can't be right:

Should there be thread synchronization on this allocation size counter or synchronization is not viable option because of low overhead requirement?

Author:	Temp1ar
Assignees:	-
Labels:	area-GC-coreclr, untriaged
Milestone:	-

[ghost]

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Assume we have a program which is allocating fixed amount of memory(~200MB) in a tight loop with portions of 200KB in multiple threads:

using System.Linq;
using System.Threading;
class Program
{
  public static void Main(string[] args)
  {
    var threadsCount = args.Any() ? int.Parse(args[0]) : 4;
    var waitHandles = new WaitHandle[threadsCount];
    int counter = 1024;
    for (int i = 0; i != threadsCount; ++i)
    {
      var waitHandle = new AutoResetEvent(false);
      var thread = new Thread(() =>
      {
        while (Interlocked.Decrement(ref counter) > 0)
        {
          var _ = new byte[200 * 1024];
        }
        waitHandle.Set();
      });
      thread.Start();
      waitHandles[i] = waitHandle;
    }
    WaitHandle.WaitAll(waitHandles);
  }
}

If I run this program on .NET Core 5 (Windows 10) with one thread I'll get 1023 events with 204 848 bytes allocated each which is expected. Sum of allocation sizes column: ~210MB (see PerfView status bar in the bottom). If I ran multiple times - I get same numbers:

However If I run this program with 4 or 8 threads, allocation sizes will start to differ and total sum will not be equal to 200MB. It fluctuates between 70(Release configuration) to 360MB. Which can't be right:

Should there be thread synchronization on this allocation size counter or synchronization is not viable option because of low overhead requirement?

Author:	Temp1ar
Assignees:	-
Labels:	area-System.Diagnostics.Tracing, untriaged
Milestone:	-

[mangod9]

I believe the events might be lossy at higher scale, but adding Tracing folks to confirm

[Temp1ar]

I believe the events might be lossy at higher scale, but adding Tracing folks to confirm

Actually the number of events are the same: 1023 and 1024. It's AllocationAmount field value is incorrect for some of them.

[Maoni0]

you have found a bug! the update of etw_allocation_running_amount is not under a lock so that's why it became inaccurate when you ran it multi-threaded. this has been this way for a long time but we don't have diagnostic tests that verify that the info we fire in ETW events is accurate. I think people who use this in general don't care a lot about the absolute accuracy - as long as it's good enough it helps them find problem they are fine with it. but this is a bug. etw_allocation_running_amount is declared as a PER_HEAP var but by the time we updated it (with an ordinary +) we already gave up the per heap lock.

we should fire this while we are still holding the lock.

[ghost]

Tagging subscribers to this area: @dotnet/gc
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Assume we have a program which is allocating fixed amount of memory(~200MB) in a tight loop with portions of 200KB in multiple threads:

using System.Linq;
using System.Threading;
class Program
{
  public static void Main(string[] args)
  {
    var threadsCount = args.Any() ? int.Parse(args[0]) : 4;
    var waitHandles = new WaitHandle[threadsCount];
    int counter = 1024;
    for (int i = 0; i != threadsCount; ++i)
    {
      var waitHandle = new AutoResetEvent(false);
      var thread = new Thread(() =>
      {
        while (Interlocked.Decrement(ref counter) > 0)
        {
          var _ = new byte[200 * 1024];
        }
        waitHandle.Set();
      });
      thread.Start();
      waitHandles[i] = waitHandle;
    }
    WaitHandle.WaitAll(waitHandles);
  }
}

If I run this program on .NET Core 5 (Windows 10) with one thread I'll get 1023 events with 204 848 bytes allocated each which is expected. Sum of allocation sizes column: ~210MB (see PerfView status bar in the bottom). If I ran multiple times - I get same numbers:

However If I run this program with 4 or 8 threads, allocation sizes will start to differ and total sum will not be equal to 200MB. It fluctuates between 70(Release configuration) to 360MB. Which can't be right:

Should there be thread synchronization on this allocation size counter or synchronization is not viable option because of low overhead requirement?

Author:	Temp1ar
Assignees:	-
Labels:	area-GC-coreclr, untriaged
Milestone:	-

[mangod9]

Thanks @Temp1ar and @Maoni0. I have moved back to the gc area.

[Maoni0]

I'll include this with my instrumentation changes.