Akka.Remote Performance - String.Format logging perf fix

[rogeralsing]

Fixes #1539

The log message is being formatted in the default pipeline, even if logging is not enabled.
This PR moves the message formatting into the conditionals that logs.

[Horusiath]

👍 - there are some merge conflicts to be resolved.

[Aaronontheweb]

is this the right setting?

[rogeralsing]

Yep,

//this is the line we have moved ####################################
def msgLog = s"RemoteMessage: [$payload] to [$recipient]<+[$originalReceiver] from [$sender()]"

    recipient match {

      case `remoteDaemon` ⇒
        if (UntrustedMode) log.debug("dropping daemon message in untrusted mode")
        else {
          //this is where it is consumed ####################################
          if (LogReceive) log.debug("received daemon message {}", msgLog)
          remoteDaemon ! payload
        }

[Aaronontheweb]

👍

[rogeralsing]

@Horusiath merge conflicts? its green here

[Aaronontheweb]

@rogeralsing could you rebase this on dev and re-run it so the Akka.Remote benchmarks show up?

[Aaronontheweb]

Perf from this build thus far

Akka.Remote.Tests.Performance.TestTransportRemoteMessagingThroughputSpec+OneWay

Measures the throughput of Akka.Remote over a particular transport using one-way messaging
12/14/2015 9:11:16 PM

System Info

NBench=NBench, Version=0.1.5.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=Iterations, TestMode=Measurement
NumberOfIterations=13, MaximumRunTime=00:00:01

Data

---

Totals

Metric	Units	Max	Average	Min	StdDev
TotalCollections [Gen0]	collections	7.00	6.85	6.00	0.38
TotalCollections [Gen1]	collections	0.00	0.00	0.00	0.00
TotalCollections [Gen2]	collections	0.00	0.00	0.00	0.00
[Counter] RemoteMessageReceived	operations	2,467.00	2,371.00	2,147.00	93.29

Per-second Totals

Metric	Units / s	Max / s	Average / s	Min / s	StdDev / s
TotalCollections [Gen0]	collections	7.02	6.84	5.99	0.38
TotalCollections [Gen1]	collections	0.00	0.00	0.00	0.00
TotalCollections [Gen2]	collections	0.00	0.00	0.00	0.00
[Counter] RemoteMessageReceived	operations	2,463.66	2,368.21	2,143.45	93.87

Raw Data

TotalCollections [Gen0]

Run #	collections	collections / s	ns / collections
1	7.00	6.99	143,032,242.86
2	7.00	6.98	143,171,014.29
3	7.00	6.99	143,154,700.00
4	7.00	7.02	142,376,628.57
5	7.00	6.99	143,014,000.00
6	7.00	6.99	143,138,828.57
7	7.00	6.99	143,011,185.71
8	7.00	6.99	143,108,900.00
9	7.00	6.99	143,050,757.14
10	6.00	5.99	166,881,866.67
11	7.00	6.99	143,022,057.14
12	7.00	6.99	143,138,942.86
13	6.00	5.99	166,943,016.67

TotalCollections [Gen1]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,225,700.00
2	0.00	0.00	1,002,197,100.00
3	0.00	0.00	1,002,082,900.00
4	0.00	0.00	996,636,400.00
5	0.00	0.00	1,001,098,000.00
6	0.00	0.00	1,001,971,800.00
7	0.00	0.00	1,001,078,300.00
8	0.00	0.00	1,001,762,300.00
9	0.00	0.00	1,001,355,300.00
10	0.00	0.00	1,001,291,200.00
11	0.00	0.00	1,001,154,400.00
12	0.00	0.00	1,001,972,600.00
13	0.00	0.00	1,001,658,100.00

TotalCollections [Gen2]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,225,700.00
2	0.00	0.00	1,002,197,100.00
3	0.00	0.00	1,002,082,900.00
4	0.00	0.00	996,636,400.00
5	0.00	0.00	1,001,098,000.00
6	0.00	0.00	1,001,971,800.00
7	0.00	0.00	1,001,078,300.00
8	0.00	0.00	1,001,762,300.00
9	0.00	0.00	1,001,355,300.00
10	0.00	0.00	1,001,291,200.00
11	0.00	0.00	1,001,154,400.00
12	0.00	0.00	1,001,972,600.00
13	0.00	0.00	1,001,658,100.00

[Counter] RemoteMessageReceived

Run #	operations	operations / s	ns / operations
1	2,466.00	2,462.98	406,012.04
2	2,351.00	2,345.85	426,285.45
3	2,335.00	2,330.15	429,157.56
4	2,409.00	2,417.13	413,713.74
5	2,417.00	2,414.35	414,190.32
6	2,331.00	2,326.41	429,846.33
7	2,466.00	2,463.34	405,952.27
8	2,362.00	2,357.84	424,116.13
9	2,467.00	2,463.66	405,900.00
10	2,255.00	2,252.09	444,031.57
11	2,365.00	2,362.27	423,321.10
12	2,452.00	2,447.17	408,634.83
13	2,147.00	2,143.45	466,538.47

[Aaronontheweb]

Perf from previous dev build:

Akka.Remote.Tests.Performance.TestTransportRemoteMessagingThroughputSpec+OneWay

Measures the throughput of Akka.Remote over a particular transport using one-way messaging
12/14/2015 7:31:25 PM

System Info

NBench=NBench, Version=0.1.5.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=Iterations, TestMode=Measurement
NumberOfIterations=13, MaximumRunTime=00:00:01

Data

---

Totals

Metric	Units	Max	Average	Min	StdDev
TotalCollections [Gen0]	collections	8.00	8.00	8.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
[Counter] RemoteMessageReceived	operations	2,429.00	2,411.85	2,392.00	11.01

Per-second Totals

Metric	Units / s	Max / s	Average / s	Min / s	StdDev / s
TotalCollections [Gen0]	collections	7.99	7.99	7.98	0.00
TotalCollections [Gen1]	collections	0.00	0.00	0.00	0.00
TotalCollections [Gen2]	collections	0.00	0.00	0.00	0.00
[Counter] RemoteMessageReceived	operations	2,425.01	2,407.88	2,387.57	11.62

Raw Data

TotalCollections [Gen0]

Run #	collections	collections / s	ns / collections
1	8.00	7.99	125,205,837.50
2	8.00	7.99	125,132,712.50
3	8.00	7.99	125,184,087.50
4	8.00	7.99	125,130,162.50
5	8.00	7.99	125,132,187.50
6	8.00	7.99	125,232,637.50
7	8.00	7.98	125,242,450.00
8	8.00	7.99	125,202,800.00
9	8.00	7.98	125,248,450.00
10	8.00	7.99	125,157,225.00
11	8.00	7.98	125,299,875.00
12	8.00	7.98	125,278,950.00
13	8.00	7.99	125,231,875.00

TotalCollections [Gen1]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,646,700.00
2	0.00	0.00	1,001,061,700.00
3	0.00	0.00	1,001,472,700.00
4	0.00	0.00	1,001,041,300.00
5	0.00	0.00	1,001,057,500.00
6	0.00	0.00	1,001,861,100.00
7	0.00	0.00	1,001,939,600.00
8	0.00	0.00	1,001,622,400.00
9	0.00	0.00	1,001,987,600.00
10	0.00	0.00	1,001,257,800.00
11	0.00	0.00	1,002,399,000.00
12	0.00	0.00	1,002,231,600.00
13	0.00	0.00	1,001,855,000.00

TotalCollections [Gen2]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,646,700.00
2	0.00	0.00	1,001,061,700.00
3	0.00	0.00	1,001,472,700.00
4	0.00	0.00	1,001,041,300.00
5	0.00	0.00	1,001,057,500.00
6	0.00	0.00	1,001,861,100.00
7	0.00	0.00	1,001,939,600.00
8	0.00	0.00	1,001,622,400.00
9	0.00	0.00	1,001,987,600.00
10	0.00	0.00	1,001,257,800.00
11	0.00	0.00	1,002,399,000.00
12	0.00	0.00	1,002,231,600.00
13	0.00	0.00	1,001,855,000.00

[Counter] RemoteMessageReceived

Run #	operations	operations / s	ns / operations
1	2,429.00	2,425.01	412,369.99
2	2,422.00	2,419.43	413,320.27
3	2,422.00	2,418.44	413,489.97
4	2,416.00	2,413.49	414,338.29
5	2,420.00	2,417.44	413,660.12
6	2,403.00	2,398.54	416,920.97
7	2,417.00	2,412.32	414,538.52
8	2,404.00	2,400.11	416,648.25
9	2,417.00	2,412.21	414,558.38
10	2,411.00	2,407.97	415,287.35
11	2,397.00	2,391.26	418,188.99
12	2,404.00	2,398.65	416,901.66
13	2,392.00	2,387.57	418,835.70

[Aaronontheweb]

Performance of this build is actually worse with a wider standard deviation than the previous build of the dev branch

[Aaronontheweb]

@rogeralsing double check the benchmark's Akka.Remote config settings - if Settings.Receive is on then that would explain why this actually dropped in performance.

[rogeralsing]

@Aaronontheweb I'm not following? what settings are you running the tests with?

[Aaronontheweb]

@rogeralsing read the C# code of this class https://github.com/akkadotnet/akka.net/blob/dev/src/core/Akka.Remote.Tests.Performance/RemoteMessagingThroughputSpecBase.cs

that's the base class that defines the per-transport benchmarks

[Aaronontheweb]

@rogeralsing concrete implementation for TestTransport https://github.com/akkadotnet/akka.net/blob/dev/src/core/Akka.Remote.Tests.Performance/TestTransportRemoteMessagingThroughputSpec.cs

[Aaronontheweb]

also might be worth comparing the results of the two-way spec (second method on the benchmark class), which I did not include in the comments

[rogeralsing]

1. What values am I supposed to compare here?
2. The tests are running using the broken DedicatedThreadPool, making any performance improvement of any other fix invisible by just swallowing them in noise.

[Aaronontheweb]

1. compare the counter values recorded by [Counter] RemoteMessageReceived.
2. if that's true, then this PR needs to wait until that can get fixed and we have clear signal-to-noise, because there might still be an issue that this doesn't actually solve.

[rogeralsing]

The remoting tests need way longer time to run also, I'm seeing a throughput difference of ca 30% in just error between my runs in my test apps.
Everythng between 65-95k msg/sec when running for several seconds.

Even using the TestTransport, the remoting layer is just far too indeterministic in throughput.

And never calling ToString on an object will ofc always be faster than always calling ToString on that object.
So if the tests shows something else, the tests are broken not the other way around

[rogeralsing]

The old code:

//always executed
var msgLog = string.Format("RemoteMessage: {0} to {1}<+{2} from {3}", payload, recipient, originalReceiver,sender);

if (settings.LogReceive) //defaults to false
{
  log.Debug("received daemon message [{0}]", msgLog);
}

The new code

if (settings.LogReceive)  //defaults to false
{
   //not executed
   var msgLog = string.Format("RemoteMessage: {0} to {1}<+{2} from {3}", payload, recipient, originalReceiver,sender);
  log.Debug("received daemon message [{0}]", msgLog);
}

Any argument that the original code is faster for real, and I will start pushing code with ToString statements everywhere to make it all go faster ;-)

[Aaronontheweb]

So if the tests shows something else, the tests are broken not the other way around

It shows the changes weren't a significant factor in affecting performance. Try running them locally.

[Aaronontheweb]

And if the tests are broken, then fix them. This is the standard we've picked - so learn how to use it and run with it instead of depending on home-rolled stuff. My work with them over the weekend clearly demonstrated the performance differences the resulted from changing the dispatchers.

[rogeralsing]

We are fixing them we have multiple people working on fixing the dedicated thread pool which is the main issue here.
Also, If I'm not mistaken it was me that found the issue with the dispatcher which you didnt think was the error.
No need to be anal about things, calling ToString always vs. only doing it when needed is if not measurable right now,is at least good code hygiene.

[Aaronontheweb]

No need to be anal about things, calling ToString always vs. only doing it when needed is if not measurable right now,is at least good code hygiene.

Not being anal, but we can't operate from a basis of dismissing our performance numbers when they don't concur with our understanding of what should have happened as a result of this change.

From where I'm sitting, these numbers are explained by 1 or more of the following explanations:

1. The code modified in this PR isn't actually covered by the spec - these logging statements were never called here.
2. The code modified in this PR made such an insignificant difference in the throughput of the remoting system that it couldn't be measured.
3. The NBench spec covering this code is written incorrectly and is prone to errors, like the ThreadPool draining we need to account for at the end of each spec.
4. NBench is integrated incorrectly in the build server and is reporting numbers from a previous version of Akka.Remote.
5. NBench is integrated correctly and is building correctly, but I retrieved the wrong performance reports.

What I'd like to see going forward is rather than have us dismiss all of the above and merge it anyway, let's figure out which of those options explains why the observed behavior doesn't align with the expected behavior.

The code you wrote is obviously an improvement and aligns with what the JVM does, but we need to explain and provide evidence for why it didn't have an impact on this benchmark. Does that make sense?

[Aaronontheweb]

One more possible explanation:

1. The multi-threaded nature of the Akka.Remote message pipeline isn't deterministic enough to get a clear reading, therefore we need to dial up the NumberOfIterations value to something much larger than 13.

[Aaronontheweb]

So I tried running this locally, to see if Azure's CPU throttling was to blame for some of the skew and disparity between the two tests, and this time got a convergent result:

With Change

---

Akka.Remote.Tests.Performance.TestTransportRemoteMessagingThroughputSpec+OneWay

Measures the throughput of Akka.Remote over a particular transport using one-way messaging
12/15/2015 5:57:26 PM

System Info

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

NBench Settings

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

Data

---

Totals

Metric	Units	Max	Average	Min	StdDev
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
[Counter] RemoteMessageReceived	operations	3,865.00	3,833.85	3,606.00	69.35

Per-second Totals

Metric	Units / s	Max / s	Average / s	Min / s	StdDev / s
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
[Counter] RemoteMessageReceived	operations	3,860.73	3,829.71	3,599.78	69.88

Raw Data

TotalCollections [Gen0]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,136,226.60
2	0.00	0.00	1,001,546,328.71
3	0.00	0.00	1,001,727,646.01
4	0.00	0.00	1,000,869,809.90
5	0.00	0.00	1,000,723,558.68
6	0.00	0.00	1,001,072,081.33
7	0.00	0.00	1,000,947,639.50
8	0.00	0.00	1,001,230,306.33
9	0.00	0.00	1,000,856,980.84
10	0.00	0.00	1,000,842,868.88
11	0.00	0.00	1,000,787,703.95
12	0.00	0.00	1,001,217,049.64
13	0.00	0.00	1,001,106,292.14

TotalCollections [Gen1]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,136,226.60
2	0.00	0.00	1,001,546,328.71
3	0.00	0.00	1,001,727,646.01
4	0.00	0.00	1,000,869,809.90
5	0.00	0.00	1,000,723,558.68
6	0.00	0.00	1,001,072,081.33
7	0.00	0.00	1,000,947,639.50
8	0.00	0.00	1,001,230,306.33
9	0.00	0.00	1,000,856,980.84
10	0.00	0.00	1,000,842,868.88
11	0.00	0.00	1,000,787,703.95
12	0.00	0.00	1,001,217,049.64
13	0.00	0.00	1,001,106,292.14

TotalCollections [Gen2]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,136,226.60
2	0.00	0.00	1,001,546,328.71
3	0.00	0.00	1,001,727,646.01
4	0.00	0.00	1,000,869,809.90
5	0.00	0.00	1,000,723,558.68
6	0.00	0.00	1,001,072,081.33
7	0.00	0.00	1,000,947,639.50
8	0.00	0.00	1,001,230,306.33
9	0.00	0.00	1,000,856,980.84
10	0.00	0.00	1,000,842,868.88
11	0.00	0.00	1,000,787,703.95
12	0.00	0.00	1,001,217,049.64
13	0.00	0.00	1,001,106,292.14

[Counter] RemoteMessageReceived

Run #	operations	operations / s	ns / operations
1	3,864.00	3,859.61	259,093.23
2	3,864.00	3,858.03	259,199.36
3	3,606.00	3,599.78	277,794.69
4	3,838.00	3,834.66	260,779.00
5	3,847.00	3,844.22	260,130.90
6	3,851.00	3,846.88	259,951.20
7	3,835.00	3,831.37	261,003.30
8	3,861.00	3,856.26	259,318.91
9	3,864.00	3,860.69	259,020.96
10	3,844.00	3,840.76	260,364.95
11	3,840.00	3,836.98	260,621.80
12	3,861.00	3,856.31	259,315.48
13	3,865.00	3,860.73	259,018.45

Without change

---

Akka.Remote.Tests.Performance.TestTransportRemoteMessagingThroughputSpec+OneWay

Measures the throughput of Akka.Remote over a particular transport using one-way messaging
12/15/2015 6:11:02 PM

System Info

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

NBench Settings

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

Data

---

Totals

Metric	Units	Max	Average	Min	StdDev
TotalCollections [Gen0]	collections	1.00	1.00	1.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
[Counter] RemoteMessageReceived	operations	3,776.00	3,753.15	3,654.00	32.41

Per-second Totals

Metric	Units / s	Max / s	Average / s	Min / s	StdDev / s
TotalCollections [Gen0]	collections	1.00	1.00	0.99	0.00
TotalCollections [Gen1]	collections	0.00	0.00	0.00	0.00
TotalCollections [Gen2]	collections	0.00	0.00	0.00	0.00
[Counter] RemoteMessageReceived	operations	3,771.49	3,747.69	3,635.49	36.09

Raw Data

TotalCollections [Gen0]

Run #	collections	collections / s	ns / collections
1	1.00	1.00	1,001,084,910.38
2	1.00	0.99	1,005,092,279.39
3	1.00	1.00	1,000,759,052.39
4	1.00	1.00	1,000,974,580.51
5	1.00	1.00	1,001,275,208.02
6	1.00	1.00	1,001,190,963.90
7	1.00	1.00	1,001,339,780.93
8	1.00	1.00	1,000,931,389.36
9	1.00	1.00	1,001,134,516.06
10	1.00	1.00	1,001,099,877.61
11	1.00	1.00	1,001,215,339.10
12	1.00	1.00	1,001,450,110.80
13	1.00	1.00	1,001,535,210.20

TotalCollections [Gen1]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,084,910.38
2	0.00	0.00	1,005,092,279.39
3	0.00	0.00	1,000,759,052.39
4	0.00	0.00	1,000,974,580.51
5	0.00	0.00	1,001,275,208.02
6	0.00	0.00	1,001,190,963.90
7	0.00	0.00	1,001,339,780.93
8	0.00	0.00	1,000,931,389.36
9	0.00	0.00	1,001,134,516.06
10	0.00	0.00	1,001,099,877.61
11	0.00	0.00	1,001,215,339.10
12	0.00	0.00	1,001,450,110.80
13	0.00	0.00	1,001,535,210.20

TotalCollections [Gen2]

Run #	collections	collections / s	ns / collections
1	0.00	0.00	1,001,084,910.38
2	0.00	0.00	1,005,092,279.39
3	0.00	0.00	1,000,759,052.39
4	0.00	0.00	1,000,974,580.51
5	0.00	0.00	1,001,275,208.02
6	0.00	0.00	1,001,190,963.90
7	0.00	0.00	1,001,339,780.93
8	0.00	0.00	1,000,931,389.36
9	0.00	0.00	1,001,134,516.06
10	0.00	0.00	1,001,099,877.61
11	0.00	0.00	1,001,215,339.10
12	0.00	0.00	1,001,450,110.80
13	0.00	0.00	1,001,535,210.20

[Counter] RemoteMessageReceived

Run #	operations	operations / s	ns / operations
1	3,750.00	3,745.94	266,955.98
2	3,654.00	3,635.49	275,066.31
3	3,766.00	3,763.14	265,735.28
4	3,757.00	3,753.34	266,429.22
5	3,730.00	3,725.25	268,438.39
6	3,775.00	3,770.51	265,216.15
7	3,776.00	3,770.95	265,185.32
8	3,775.00	3,771.49	265,147.39
9	3,764.00	3,759.73	265,976.23
10	3,758.00	3,753.87	266,391.67
11	3,765.00	3,760.43	265,927.05
12	3,770.00	3,764.54	265,636.63
13	3,751.00	3,745.25	267,004.85

[Aaronontheweb]

With the exception of one outlier, the performance of the code with this change has a speed advantage of roughly ~5,000 nanos per operation over the previous stable release from dev.

[Aaronontheweb]

I can dial up the NumberOfIterations and try to average out the results on Azure, and I can potentially write a version of the ForkJoinDispatcher that does some things to eliminate scheduling overhead (high thread priority and CPU pinning, which is what NBench itself does for its runner) but I'm skeptical that'd make a significant difference on this environment.