Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

eliminated allocations with StandardOutWriter #1881

Merged
merged 1 commit into from
Apr 14, 2016
Merged

eliminated allocations with StandardOutWriter #1881

merged 1 commit into from
Apr 14, 2016

Conversation

Aaronontheweb
Copy link
Member

Found some memory leaks in Helios which revolve around the use of delegates with context closures - realized it might explain some of the memory leak reports we've had around logging in Akka.NET. Found some code inside the StandardOutWriter that uses delegates similarly and profiled it.

Added NBench.PerformanceCounters to get some more detailed metrics.

@Aaronontheweb
Copy link
Member Author

Ok, made some changes to StandardOutWriter for comparison....

Before

Akka.Tests.Performance.Util.StandardOutWriterMemoryBenchmark+StressTestStandardOutWriter

Testing to see if the design of the StandardOutWriter produces allocations
4/14/2016 2:53:56 AM

System Info

NBench=NBench, Version=0.2.1.0, Culture=neutral, PublicKeyToken=null
OS=Microsoft Windows NT 6.2.9200.0
ProcessorCount=4
CLR=4.0.30319.42000,IsMono=False,MaxGcGeneration=2
WorkerThreads=32767, IOThreads=4

NBench Settings

RunMode=Throughput, TestMode=Measurement
NumberOfIterations=13, MaximumRunTime=00:00:01

Data

Totals

Metric Units Max Average Min StdDev
TotalBytesAllocated bytes 1,145,416.00 1,145,416.00 1,145,416.00 0.00
TotalCollections [Gen0] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen1] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen2] collections 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# of Pinned Objects:NBench.Runner objects 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# Bytes in all Heaps:NBench.Runner bytes 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# GC Handles:NBench.Runner handles 0.00 0.00 0.00 0.00
[Counter] StandardOutWrites operations 4,207.00 4,207.00 4,207.00 0.00

Per-second Totals

Metric Units / s Max / s Average / s Min / s StdDev / s
TotalBytesAllocated bytes 2,578,576.37 2,085,873.78 93,081.68 686,096.72
TotalCollections [Gen0] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen1] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen2] collections 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# of Pinned Objects:NBench.Runner objects 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# Bytes in all Heaps:NBench.Runner bytes 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# GC Handles:NBench.Runner handles 0.00 0.00 0.00 0.00
[Counter] StandardOutWrites operations 9,470.86 7,661.21 341.88 2,519.97

Raw Data

TotalBytesAllocated

Run # bytes bytes / s ns / bytes
1 1,145,416.00 1,986,843.03 503.31
2 1,145,416.00 2,557,736.97 390.97
3 1,145,416.00 2,419,719.32 413.27
4 1,145,416.00 93,081.68 10,743.25
5 1,145,416.00 1,906,905.87 524.41
6 1,145,416.00 2,578,576.37 387.81
7 1,145,416.00 2,511,639.80 398.15
8 1,145,416.00 2,537,498.13 394.09
9 1,145,416.00 2,423,057.78 412.70
10 1,145,416.00 2,556,672.22 391.13
11 1,145,416.00 1,564,631.68 639.13
12 1,145,416.00 1,834,819.24 545.01
13 1,145,416.00 2,145,177.05 466.16

TotalCollections [Gen0]

Run # collections collections / s ns / collections
1 0.00 0.00 576,500,500.00
2 0.00 0.00 447,824,000.00
3 0.00 0.00 473,367,300.00
4 0.00 0.00 12,305,492,800.00
5 0.00 0.00 600,667,300.00
6 0.00 0.00 444,204,800.00
7 0.00 0.00 456,043,100.00
8 0.00 0.00 451,395,800.00
9 0.00 0.00 472,715,100.00
10 0.00 0.00 448,010,500.00
11 0.00 0.00 732,067,500.00
12 0.00 0.00 624,266,400.00
13 0.00 0.00 533,949,400.00

TotalCollections [Gen1]

Run # collections collections / s ns / collections
1 0.00 0.00 576,500,500.00
2 0.00 0.00 447,824,000.00
3 0.00 0.00 473,367,300.00
4 0.00 0.00 12,305,492,800.00
5 0.00 0.00 600,667,300.00
6 0.00 0.00 444,204,800.00
7 0.00 0.00 456,043,100.00
8 0.00 0.00 451,395,800.00
9 0.00 0.00 472,715,100.00
10 0.00 0.00 448,010,500.00
11 0.00 0.00 732,067,500.00
12 0.00 0.00 624,266,400.00
13 0.00 0.00 533,949,400.00

TotalCollections [Gen2]

Run # collections collections / s ns / collections
1 0.00 0.00 576,500,500.00
2 0.00 0.00 447,824,000.00
3 0.00 0.00 473,367,300.00
4 0.00 0.00 12,305,492,800.00
5 0.00 0.00 600,667,300.00
6 0.00 0.00 444,204,800.00
7 0.00 0.00 456,043,100.00
8 0.00 0.00 451,395,800.00
9 0.00 0.00 472,715,100.00
10 0.00 0.00 448,010,500.00
11 0.00 0.00 732,067,500.00
12 0.00 0.00 624,266,400.00
13 0.00 0.00 533,949,400.00

[PerformanceCounter] .NET CLR Memory:# of Pinned Objects:NBench.Runner

Run # objects objects / s ns / objects
1 0.00 0.00 576,500,500.00
2 0.00 0.00 447,824,000.00
3 0.00 0.00 473,367,300.00
4 0.00 0.00 12,305,492,800.00
5 0.00 0.00 600,667,300.00
6 0.00 0.00 444,204,800.00
7 0.00 0.00 456,043,100.00
8 0.00 0.00 451,395,800.00
9 0.00 0.00 472,715,100.00
10 0.00 0.00 448,010,500.00
11 0.00 0.00 732,067,500.00
12 0.00 0.00 624,266,400.00
13 0.00 0.00 533,949,400.00

[PerformanceCounter] .NET CLR Memory:# Bytes in all Heaps:NBench.Runner

Run # bytes bytes / s ns / bytes
1 0.00 0.00 576,500,500.00
2 0.00 0.00 447,824,000.00
3 0.00 0.00 473,367,300.00
4 0.00 0.00 12,305,492,800.00
5 0.00 0.00 600,667,300.00
6 0.00 0.00 444,204,800.00
7 0.00 0.00 456,043,100.00
8 0.00 0.00 451,395,800.00
9 0.00 0.00 472,715,100.00
10 0.00 0.00 448,010,500.00
11 0.00 0.00 732,067,500.00
12 0.00 0.00 624,266,400.00
13 0.00 0.00 533,949,400.00

[PerformanceCounter] .NET CLR Memory:# GC Handles:NBench.Runner

Run # handles handles / s ns / handles
1 0.00 0.00 576,500,500.00
2 0.00 0.00 447,824,000.00
3 0.00 0.00 473,367,300.00
4 0.00 0.00 12,305,492,800.00
5 0.00 0.00 600,667,300.00
6 0.00 0.00 444,204,800.00
7 0.00 0.00 456,043,100.00
8 0.00 0.00 451,395,800.00
9 0.00 0.00 472,715,100.00
10 0.00 0.00 448,010,500.00
11 0.00 0.00 732,067,500.00
12 0.00 0.00 624,266,400.00
13 0.00 0.00 533,949,400.00

[Counter] StandardOutWrites

Run # operations operations / s ns / operations
1 4,207.00 7,297.48 137,033.63
2 4,207.00 9,394.32 106,447.35
3 4,207.00 8,887.39 112,518.97
4 4,207.00 341.88 2,925,004.23
5 4,207.00 7,003.88 142,778.06
6 4,207.00 9,470.86 105,587.07
7 4,207.00 9,225.01 108,401.02
8 4,207.00 9,319.98 107,296.36
9 4,207.00 8,899.65 112,363.94
10 4,207.00 9,390.40 106,491.68
11 4,207.00 5,746.74 174,011.77
12 4,207.00 6,739.11 148,387.54
13 4,207.00 7,879.02 126,919.28

@Aaronontheweb
Copy link
Member Author

After

Akka.Tests.Performance.Util.StandardOutWriterMemoryBenchmark+StressTestStandardOutWriter

Testing to see if the design of the StandardOutWriter produces allocations
4/14/2016 3:26:09 AM

System Info

NBench=NBench, Version=0.2.1.0, Culture=neutral, PublicKeyToken=null
OS=Microsoft Windows NT 6.2.9200.0
ProcessorCount=4
CLR=4.0.30319.42000,IsMono=False,MaxGcGeneration=2
WorkerThreads=32767, IOThreads=4

NBench Settings

RunMode=Throughput, TestMode=Measurement
NumberOfIterations=13, MaximumRunTime=00:00:01

Data

Totals

Metric Units Max Average Min StdDev
TotalBytesAllocated bytes 850,504.00 850,504.00 850,504.00 0.00
TotalCollections [Gen0] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen1] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen2] collections 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# of Pinned Objects:NBench.Runner objects 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# Bytes in all Heaps:NBench.Runner bytes 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# GC Handles:NBench.Runner handles 0.00 0.00 0.00 0.00
[Counter] StandardOutWrites operations 4,803.00 4,803.00 4,803.00 0.00

Per-second Totals

Metric Units / s Max / s Average / s Min / s StdDev / s
TotalBytesAllocated bytes 1,885,937.36 1,376,697.98 589,527.53 470,900.70
TotalCollections [Gen0] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen1] collections 0.00 0.00 0.00 0.00
TotalCollections [Gen2] collections 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# of Pinned Objects:NBench.Runner objects 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# Bytes in all Heaps:NBench.Runner bytes 0.00 0.00 0.00 0.00
[PerformanceCounter] .NET CLR Memory:# GC Handles:NBench.Runner handles 0.00 0.00 0.00 0.00
[Counter] StandardOutWrites operations 10,650.34 7,774.54 3,329.20 2,659.29

Raw Data

TotalBytesAllocated

Run # bytes bytes / s ns / bytes
1 850,504.00 1,173,571.76 852.10
2 850,504.00 1,787,771.41 559.36
3 850,504.00 1,885,937.36 530.24
4 850,504.00 589,527.53 1,696.27
5 850,504.00 738,658.92 1,353.80
6 850,504.00 1,462,386.33 683.81
7 850,504.00 1,787,010.00 559.59
8 850,504.00 603,055.84 1,658.22
9 850,504.00 1,283,260.51 779.27
10 850,504.00 1,827,411.52 547.22
11 850,504.00 1,706,013.44 586.16
12 850,504.00 1,413,524.30 707.45
13 850,504.00 1,638,944.77 610.15

TotalCollections [Gen0]

Run # collections collections / s ns / collections
1 0.00 0.00 724,714,100.00
2 0.00 0.00 475,734,200.00
3 0.00 0.00 450,971,500.00
4 0.00 0.00 1,442,687,500.00
5 0.00 0.00 1,151,416,400.00
6 0.00 0.00 581,586,400.00
7 0.00 0.00 475,936,900.00
8 0.00 0.00 1,410,323,800.00
9 0.00 0.00 662,768,000.00
10 0.00 0.00 465,414,600.00
11 0.00 0.00 498,533,000.00
12 0.00 0.00 601,690,400.00
13 0.00 0.00 518,933,900.00

TotalCollections [Gen1]

Run # collections collections / s ns / collections
1 0.00 0.00 724,714,100.00
2 0.00 0.00 475,734,200.00
3 0.00 0.00 450,971,500.00
4 0.00 0.00 1,442,687,500.00
5 0.00 0.00 1,151,416,400.00
6 0.00 0.00 581,586,400.00
7 0.00 0.00 475,936,900.00
8 0.00 0.00 1,410,323,800.00
9 0.00 0.00 662,768,000.00
10 0.00 0.00 465,414,600.00
11 0.00 0.00 498,533,000.00
12 0.00 0.00 601,690,400.00
13 0.00 0.00 518,933,900.00

TotalCollections [Gen2]

Run # collections collections / s ns / collections
1 0.00 0.00 724,714,100.00
2 0.00 0.00 475,734,200.00
3 0.00 0.00 450,971,500.00
4 0.00 0.00 1,442,687,500.00
5 0.00 0.00 1,151,416,400.00
6 0.00 0.00 581,586,400.00
7 0.00 0.00 475,936,900.00
8 0.00 0.00 1,410,323,800.00
9 0.00 0.00 662,768,000.00
10 0.00 0.00 465,414,600.00
11 0.00 0.00 498,533,000.00
12 0.00 0.00 601,690,400.00
13 0.00 0.00 518,933,900.00

[PerformanceCounter] .NET CLR Memory:# of Pinned Objects:NBench.Runner

Run # objects objects / s ns / objects
1 0.00 0.00 724,714,100.00
2 0.00 0.00 475,734,200.00
3 0.00 0.00 450,971,500.00
4 0.00 0.00 1,442,687,500.00
5 0.00 0.00 1,151,416,400.00
6 0.00 0.00 581,586,400.00
7 0.00 0.00 475,936,900.00
8 0.00 0.00 1,410,323,800.00
9 0.00 0.00 662,768,000.00
10 0.00 0.00 465,414,600.00
11 0.00 0.00 498,533,000.00
12 0.00 0.00 601,690,400.00
13 0.00 0.00 518,933,900.00

[PerformanceCounter] .NET CLR Memory:# Bytes in all Heaps:NBench.Runner

Run # bytes bytes / s ns / bytes
1 0.00 0.00 724,714,100.00
2 0.00 0.00 475,734,200.00
3 0.00 0.00 450,971,500.00
4 0.00 0.00 1,442,687,500.00
5 0.00 0.00 1,151,416,400.00
6 0.00 0.00 581,586,400.00
7 0.00 0.00 475,936,900.00
8 0.00 0.00 1,410,323,800.00
9 0.00 0.00 662,768,000.00
10 0.00 0.00 465,414,600.00
11 0.00 0.00 498,533,000.00
12 0.00 0.00 601,690,400.00
13 0.00 0.00 518,933,900.00

[PerformanceCounter] .NET CLR Memory:# GC Handles:NBench.Runner

Run # handles handles / s ns / handles
1 0.00 0.00 724,714,100.00
2 0.00 0.00 475,734,200.00
3 0.00 0.00 450,971,500.00
4 0.00 0.00 1,442,687,500.00
5 0.00 0.00 1,151,416,400.00
6 0.00 0.00 581,586,400.00
7 0.00 0.00 475,936,900.00
8 0.00 0.00 1,410,323,800.00
9 0.00 0.00 662,768,000.00
10 0.00 0.00 465,414,600.00
11 0.00 0.00 498,533,000.00
12 0.00 0.00 601,690,400.00
13 0.00 0.00 518,933,900.00

[Counter] StandardOutWrites

Run # operations operations / s ns / operations
1 4,803.00 6,627.44 150,887.80
2 4,803.00 10,095.97 99,049.39
3 4,803.00 10,650.34 93,893.71
4 4,803.00 3,329.20 300,372.16
5 4,803.00 4,171.38 239,728.59
6 4,803.00 8,258.45 121,088.15
7 4,803.00 10,091.67 99,091.59
8 4,803.00 3,405.60 293,633.94
9 4,803.00 7,246.88 137,990.42
10 4,803.00 10,319.83 96,900.81
11 4,803.00 9,634.27 103,796.17
12 4,803.00 7,982.51 125,273.87
13 4,803.00 9,255.51 108,043.70

@Aaronontheweb
Copy link
Member Author

I wasn't able to collect any PerformanceCounter metrics due to petabridge/NBench#105, so I can't prove if there was a memory leak or not.

Writing to the Console will naturally use some memory, so that's most of the allocation.

However, we were also allocating a fairly large number of delegates while calling this, which is why the previous metric

Metric Units Max Average Min StdDev
TotalBytesAllocated bytes 1,145,416.00 1,145,416.00 1,145,416.00 0.00

Is now

Metric Units Max Average Min StdDev
TotalBytesAllocated bytes 850,504.00 850,504.00 850,504.00 0.00

Aaronontheweb
Aaronontheweb reviewed Apr 14, 2016
View reviewed changes
src/core/Akka/Util/StandardOutWriter.cs
{
WriteToConsole(() => Console.Write(message), foregroundColor, backgroundColor);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Caused an allocation; removed.

@Aaronontheweb
added benchmark to illustrate potential memory leak with StandardOutW…
7bda483 
…riter

eliminated allocations inside StandardOutWriter
Aaronontheweb
Aaronontheweb reviewed Apr 14, 2016
View reviewed changes
src/core/Akka/Util/StandardOutWriter.cs
{
WriteToConsole(() => Console.WriteLine(message), foregroundColor, backgroundColor);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Caused an allocation; removed.

@Aaronontheweb Aaronontheweb changed the title added benchmark to illustrate potential memory leak / allocations with StandardOutWriter eliminated allocations with StandardOutWriter Apr 14, 2016
@Danthar Danthar merged commit c2dfb83 into akkadotnet:dev Apr 14, 2016
@Danthar
Copy link
Member

Danthar commented Apr 14, 2016

Looks ok, Runs ok. :shipit:

@Aaronontheweb Aaronontheweb deleted the logger-profiling branch April 14, 2016 14:55
This was referenced Apr 26, 2016
Merged
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@Aaronontheweb @Danthar