Runtime: [Perf][Windows_NT] Investigate the improvement/regressions on System/IO/Tests/PerfStreamWriter

[jorive]

From release/2.0.0 to release/2.1 there has been the following changes in the tests:

  WriteCharArray(writeLength: 100)         // Improved ~8%
  WriteCharArray(writeLength: 2)           // Improved ~7%
  WritePartialCharArray(writeLength: 100)  // Improved ~16%
  WritePartialCharArray(writeLength: 2)    // Regressed ~25%
  WriteString(writeLength: 2)              // Regressed ~4%

[danmosemsft]

It'd be great when we open issues like this to include relevant benchview links to get a jump start.

master
https://benchview/trendline?build_selector=latest&count=1000&aggregate=arithmeticMean&filterTail=one&filterVal=100&interval=INTERVAL_MIN_MAX&rtids=[957,1121]&archids=[23]&mpids=[1292]&cfgids=[2706]&testids=[63752,63751,63754,63753,63756,63755,60281,63059,63111,61559,61598,60271,61483,61505,61753,61745,61749]&jobid=93820&

release/2.1 (don't know how to show overlayed) -- not much to see here, it's just regressed from the start
https://benchview/trendline?build_selector=latest&count=1000&aggregate=arithmeticMean&filterTail=one&filterVal=100&interval=INTERVAL_MIN_MAX&rtids=[957]&archids=[23]&mpids=[1292]&cfgids=[2706]&testids=[63750,63752,63751,63754,63753,63756,63755,63111,61559,61598,60271,61483,61505,61753,61745,61749]&jobid=93653&

I see StreamWriter moved from CoreFX to Corelib https://github.com/dotnet/coreclr/pull/15884 but this regression was back when it was in corefx (of course not necessarily in StreamWriter.cs itself)
History there: https://github.com/dotnet/corefx/commits/c47edd1c8a3e561e5081e966b0d270fa2b345f05/src/System.Runtime.Extensions/src/System/IO/StreamWriter.cs
Which shows a large regression was fixed on 12/15, very likely by https://github.com/dotnet/corefx/commit/2e5a18aa7558a2f5f94fed3c22ba18d32a99e1ac#diff-dcd5e773943a8ee81e58444d7518cd9a by @ahsonkhan

I don't yet have a way to see data before Jan to see when we regressed originally. A large earlier change in StreamWriter was https://github.com/dotnet/corefx/commit/b272c1bde8d5d2e2b72772d2eb1f8b0496d05310?diff=split by @stephentoub. It might be interesting to bisect either side of that. @jorive is trying to help me find earlier data.

[danmosemsft]

This shows a clear view of the whole timeline (may take 30 sec to draw)
https://benchview/trendline?jobgroup=CoreFX&branchId=42&count=2000&jobtype=rolling&rtids=[957]&archids=[23]&mpids=[1292]&cfgids=[2706]&testids=[63752,63751,63754,63753,63756,63755]&

There was a large regression 11/21 but it was reversed 12/15 and is not relevant.

The regression in WritePartialCharArray(writeLength: 2) was clearly in this specific change to StreamWriter by @stephentoub. @stephentoub up to you whether this is worth investigating.
https://benchview/compare?jobid=63511&resulttypeid=957&archid=23&testid=63753&configid=2706&machinepoolid=1292&comparejobids=[63457]&
https://github.com/dotnet/corefx/compare/093e437ad7c6f765a5a787ca29d3b68ef8f92f79...dotnet:b272c1bde8d5d2e2b72772d2eb1f8b0496d05310
https://github.com/dotnet/corefx/pull/24725

The regression in WriteString(writeLength: 2) was different, on 2/27

probably arrived with the new CLR
https://github.com/dotnet/corefx/compare/b648d27cce9114fa826d16534a20bf1516a30ce7...dotnet:3471249dc6cecb57debfadd023fca87157f4ca8f
and has not been reverted to baseline since. I see an 11% regression over 2.0, this seems worth investigating.

As for the improvements listed above, there is not a clear single change. I have no reason to doubt they are not real: I don't thi9nk they are worth investigating further.

[danmosemsft]

The cause of the regression in WriteCharArray(writeLength: 2) looks like the cause of the 8.5% win in WriteCharArray(writeLength: 100).

Incidentally WriteCharArray(writeLength: 100) has regressed 11% very recently.

[danmosemsft]

We should check back on http://benchview in a few days when this has had a chance to percolate, to verify it's fixed.

[danmosemsft]

The fix has brought down most scenarios to at or better than 2.0 in both Linux and Windows. However WriteString(2) is still off -- in fact, it got worse around this time. I say around this time because although the first bad point is 4a4261, just after this fix, there were several days without datapoints and it's possible the regression was another change in this range:
https://github.com/dotnet/corefx/compare/320d57acf4dfb2326eb074f38e062637ca4dc76b...dotnet:4a42618a590fca0fb3f754f25b2cd36600775922

https://benchview/trendline?build_selector=latest&count=2000&aggregate=arithmeticMean&filterTail=one&filterVal=100&interval=INTERVAL_MIN_MAX&rtids=[957]&archids=[23]&mpids=[1292]&cfgids=[2785,2706]&testids=[63750,63752,63751,63754,63753,63756,63755]&jobid=94550&

Linux is about 230% of goal (ie 2.1) and Windows about 180% of goal

@stephentoub up to you how you priortize this. We are significantly better than goal for writing char arrays now: perhaps that's more important.

[danmosemsft]

Also worth noting in the graph is the regression on 2/27 (associated with a runtime update) was far more pronounced on Linux: and Linux does not seem to be either regressed or improved by the recent change (ie., the more recent regression seems Windows specific).

[danmosemsft]

@stephentoub is taking a quick look, if it doesn't seem obviously fixable today, we will close it.

[stephentoub]

The problem appears to be the [MethodImpl(MethodImplOptions.NoInlining)] that we put onto Write(string) at the last minute. When I remove that, throughput on this Write(twoCharString) benchmark more than doubles.

This is strange, though, as previously while Write(string) would have been inlined, the WriteCore(ReadOnlySpan<>) method it called wouldn't have been; now the WriteSpan(ReadOnlySpan<>) method it calls will be and the Write(string) won't, so there's still the same number of method calls. There must be something more intricate going on...

cc: @AndyAyersMS

[stephentoub]

The issue appears to be due to the inlining of string.AsSpan. When it gets inlined into the benchmark call site, things gets faster.

If I change this:
```C#
[MethodImpl(MethodImplOptions.NoInlining)]
public override void Write(string value)
{
WriteSpan(value, appendNewLine: false);
}

to this:
```C#
        public override void Write(string value)
        {
            WriteSpan(value.AsSpan());
        }

        [MethodImpl(MethodImplOptions.NoInlining)]
        private void WriteSpan(ReadOnlySpan<char> value)
        {
            WriteSpan(value, appendNewLine: false);
        }

the issue goes away.

The problem with that is, if Write(string value) doesn't get inlined, then we've actually made things slower by making such a change. It's an override, and it'll only be inlined in specific cases like the benchmark where the JIT is able to devirtualize it.

[stephentoub]

@AndyAyersMS, @jkotas, any suggestions on this one? I assume this ends up being related to the other issues we've seen around initialization of spans. I'd prefer not to revert back to the pre-span code for Write(string).

[AndyAyersMS]

I'll have to take a look at the codegen and see what's up.

[jkotas]

I doubt there is a way to 100% match the perf characteristics of the original code in all cases without duplication. But maybe Andy can come up with something creative...

Using ForceInline as replacement for C macro tends to get you in troubles. https://github.com/dotnet/corefx/issues/28180 is another example. I am sure that we have other places where it is problematic that we do not know about yet since we have started using ForceInline liberally.

[AndyAyersMS]

SysV ABI struct passing conventions are quite different than the Windows ABI conventions, and that often leads to perf differences. And the jit is not very good yet at using the SysV rules for best perf.

Looking at windows codegen now...

[stephentoub]

Looking at windows codegen now...

Thanks, Andy.

[AndyAyersMS]

First thing that jumps out is that
C# public static implicit operator ReadOnlySpan<char>(string value) => value != null ? new ReadOnlySpan<char>(ref value.GetRawStringData(), value.Length) : default;
is not inlined.

So calling this string conversion method and then passing the resulting span to a callee incurs some prolog overhead, as the spans returned or passed by reference require prolog zeroing. In the "fast" variant this zeroing happens in the benchmark method outside the timing loop and so doesn't impact the perf results.

In the current/slow version all this prolog cost is paid in the timed method, and for very short writes it appears the overhead is significant compared to the cost of the write.

So I guess one message here is that if parts of the timed method can be inlined then the timing results may be misleading as some of the "cost" may be effectively hoisted out of the timing loop.

I am going to try revising the benchmark to contain all the costs in the timed portion to see what the numbers say that way. Of course this same cost hoisting "benefit" can accrue to user code so it's not clear offhand if these new numbers will be any more meaningful than the ones we have now.

Also it seems likely that inlining the string->span conversion will likely be beneficial. Will look into that too.

[AndyAyersMS]

Some data from various combinations, measured locally:

StreamWriter | Benchmark | Perf |
------------: | -----------: | -----: |
current | current | 286 |
modded | current | 161 |
current | noinline | 302 |
modded | noinline | 342 |
current + string->span inlined | current | 148 |

So if we update the benchmark (via a noinline wrapper) to not allow the prolog costs to escape the timing loop, the modded version of the stream code actually appears to be a bit slower than the current version. But if we let the costs escape (as happens now) the modded version is faster.

I think we are better off leaving things as is -- the cases that can benefit from modding (or reverting the change that caused the regression) are ones that look more or less exactly like the benchmark: it must be a method that repeatedly calls Write(string) in a long-running loop on very short strings and also directly constructs the StreamReader in a way that visibly connects it to the call to Write.

[Edit: added impact of inlining the string->span conversion]

[danmosemsft]

I think we are better off leaving things as is

Thanks for the investigation, @AndyAyersMS .

[stephentoub]

[Edit: added impact of inlining the string->span conversion]

Should we make the string->span conversion AggressiveInlining? That operation is done a lot, both with AsSpan and with the implicit cast operator method.

(And thanks for looking, Andy!)

cc: @ahsonkhan

[stephentoub]

I see @AndyAyersMS already opened https://github.com/dotnet/coreclr/issues/17366. I moved it from Future to 2.1 as I think we should consider taking it for this release.

[AndyAyersMS]

Jan made the change to inline the string to span conversion and it's been picked up by CoreFx. Master perf now looking good for both Windows & Ubuntu. Note this is the version that is timing the entire operation -- no bits are escaping from the timing loop.

[danmosemsft]

Nice, good teamwork, thanks guys.