Add YARP Telemetry instrumentation #501

MihaZupan · 2020-10-29T16:30:10Z

Contributes to #158

Removes IOperationLogger and associated glue
Adds a Microsoft.ReverseProxy EventSource and the related HttpProxy/StreamCopier instrumentation
Adds public ProxyStage enum

Marked some open questions with TODO or PR REVIEW comments.

MihaZupan · 2020-10-29T17:08:34Z

The failing tests are the timing tests. They're flaky, I will figure out how to make those more stable.

src/ReverseProxy/Service/Proxy/HttpProxy.cs

src/ReverseProxy/Service/Proxy/StreamCopier.cs

src/ReverseProxy/Telemetry/ProxyStage.cs

Tratcher · 2020-10-29T22:06:29Z

src/ReverseProxy/Telemetry/ProxyTelemetry.cs

+        [Event(3, Level = EventLevel.Informational)]
+        public void ProxyStage(ProxyStage stage)
+        {
+            if (IsEnabled(EventLevel.Informational, EventKeywords.All))


Should ProxyStage and ContentTransferring use EventLevel.Verbose?

We could change the EventLevel for these, or we could also think about introducing Keyword flags for allowing more granular control over which events we fire.

I don't believe we will reach a significant number of ProxyStage values either, so even those could be made into flags instead, allowing users to have fine-grained control over exactly which events they actually care about.

src/ReverseProxy/Telemetry/ProxyStage.cs

test/ReverseProxy.Tests/Service/Proxy/StreamCopierTests.cs

davidfowl · 2020-11-02T14:02:37Z

src/ReverseProxy/Microsoft.ReverseProxy.csproj

@@ -5,6 +5,7 @@
    <TargetFrameworks>net5.0;netcoreapp3.1</TargetFrameworks>
    <OutputType>Library</OutputType>
    <RootNamespace>Microsoft.ReverseProxy</RootNamespace>
+    <AllowUnsafeBlocks>true</AllowUnsafeBlocks>


EventSource 😢

src/ReverseProxy/Utilities/MonotonicTimer.cs

Tratcher

Much better

src/ReverseProxy/Service/Proxy/HttpProxy.cs

src/ReverseProxy/Telemetry/ProxyTelemetry.cs

src/ReverseProxy/Telemetry/ProxyStage.cs

src/ReverseProxy/Telemetry/ProxyTelemetry.cs

Tratcher · 2020-11-02T17:15:54Z

src/ReverseProxy/Utilities/IUptimeClock.cs

    /// </summary>
    internal interface IUptimeClock
    {
        long TickCount { get; }
+
+        long GetStopwatchTimestamp();


Suggested change

long GetStopwatchTimestamp();

// See Stopwatch.GetTimestamp

long Timestamp { get; }

I wanted to be very explicit about what it is to avoid more confusion.

For example TickCount is in ms while Timestamp is in whatever frequency the underlying Stopwatch is

Does IUptimeClock also need to expose the frequency?

I don't see the need for it, this is just an internal abstraction over fetching time so that we can have stable tests.

If we wanted a cleaner API I think we should just expose a TimeSpan - we don't right now to save a few instructions on repeated conversions.

src/ReverseProxy/Utilities/MonotonicTimer.cs

src/ReverseProxy/Middleware/ProxyInvokerMiddleware.cs

src/ReverseProxy/Telemetry/ProxyTelemetry.cs

src/ReverseProxy/Service/Proxy/StreamCopier.cs

Tratcher · 2020-11-03T16:22:58Z

And yes, renaming the clock abstraction to IClock makes sense.

src/ReverseProxy/Service/Proxy/StreamCopier.cs

Tratcher · 2020-11-03T18:37:10Z

src/ReverseProxy/Service/Proxy/StreamCopier.cs

+                            // PR REVIEW:
+                            // Should this event be logged on failure as well (instead of XContentTransferStop)?


Yes? It might be good to know how much content transferred before the failure. Instead of XContentTransferStop? Don't you still need start/stop pairs? Would you need to do both ContentTransferred and XContentTransferStop?

Right now we log XContentTransferStart and XContentTransferStop ProxyStage events in try/finally.

If we were to log ContentTransferred on failure as well, there'd be no need to have the Stop ProxyStage event.

Ok, try it.

alnikola

A couple of comments, but overall it definitely looks good.

alnikola · 2020-11-04T16:51:38Z

src/ReverseProxy/Service/Proxy/ProxyError.cs

@@ -6,7 +6,7 @@ namespace Microsoft.ReverseProxy.Service.Proxy
    /// <summary>
    /// Errors reported when proxying a request to the destination.
    /// </summary>
-    public enum ProxyError
+    public enum ProxyError : int


Do we really need this? We don't specify the enum base type explicitly in other places.

Just being really explicit about the backing type, as we can't change it in the future.

alnikola · 2020-11-04T16:55:16Z

src/ReverseProxy/Service/Proxy/StreamCopier.cs

        {
            _ = input ?? throw new ArgumentNullException(nameof(input));
            _ = output ?? throw new ArgumentNullException(nameof(output));

+            var telemetryEnabled = ProxyTelemetry.Log.IsEnabled();


Can the linker recognize this pattern and trim the code when telemetry is disabled? As far as I remember, in the networking telemetry we made those checks directly in the if clauses.

If it recognizes telemetryEnabled can't change, maybe?

We're not doing IsEnabled checks inline in any product code here (YARP), which is the same pattern AspNetCore uses. Personally I prefer the readability of that approach over doing IsEnabled checks everywhere - it moves that responsibility onto the EventSource.

In general, I don't think we care too much about how trimmed down this package is?

IsEnabled is runtime state, right? The linker is a compile time operation and shouldn't apply in this scenario. The Jitter is the one that would be optimizing for the true/false code paths at runtime, and it can do that regardless of how you structure it.

Using telemetryEnabled is simpler than repeating ProxyTelemetry.Log.IsEnabled(); in each if.

It is a runtime check, but the linker has an option to remove EventSource code entirely by stubbing out EventSource.IsEnabled() to be const false and then removing unreachable code.

Using telemetryEnabled is simpler than repeating ProxyTelemetry.Log.IsEnabled(); in each if.

I agree. In this case it's also a question about correctness, as IsEnabled() can start returning true once we're already in the method and we could then work with invalid timing data (e.g. never setting the initial time/time between events)

alnikola · 2020-11-04T16:57:17Z

src/ReverseProxy/Service/Proxy/StreamCopier.cs

+                {
+                    ProxyTelemetry.Log.ProxyStage(isRequest ? ProxyStage.RequestContentTransferStart : ProxyStage.ResponseContentTransferStart);
+
+                    stopwatchTicksBetweenTransferringEvents = Stopwatch.Frequency; // 1 second


Hmm. Should not it be exposed via IClock interface too? AFAIK, we agreed on adding a Resolution or Frequency property there.

See #501 (comment), I don't think it's needed

alnikola · 2020-11-04T17:00:30Z

src/ReverseProxy/Service/Proxy/StreamCopier.cs

+
+            static long StopwatchTicksToDateTimeTicks(long stopwatchTicks)
+            {
+                var dateTimeTicksPerStopwatchTick = (double)TimeSpan.TicksPerSecond / Stopwatch.Frequency;


The same question as above about a direct access to Stopwatch.Frequency.

alnikola · 2020-11-04T17:01:19Z

src/ReverseProxy/Telemetry/ProxyStage.cs

+
+namespace Microsoft.ReverseProxy.Telemetry
+{
+    internal enum ProxyStage : int


Do we need an explicit base type here?

alnikola · 2020-11-04T17:06:24Z

test/ReverseProxy.Tests/Service/Proxy/StreamCopyHttpContentTests.cs

@@ -25,7 +26,7 @@ public async Task CopyToAsync_InvokesStreamCopier()
            var source = new MemoryStream(sourceBytes);
            var destination = new MemoryStream();

-            var sut = new StreamCopyHttpContent(source, autoFlushHttpClientOutgoingStream: false, CancellationToken.None);
+            var sut = new StreamCopyHttpContent(source, autoFlushHttpClientOutgoingStream: false, new Clock(), CancellationToken.None);


Is there a plan to add telemetry verification here as well?

We're just delegating to StreamCopier inside, which is already tested, so duplicating that here seems redundant.

Is there another scenario you see that should be covered?

src/ReverseProxy/Telemetry/ProxyTelemetry.cs

ManickaP · 2020-11-06T09:15:58Z

src/ReverseProxy/Telemetry/ProxyTelemetry.cs

+                    DisplayName = "Requests Started",
+                };
+
+                _startedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-started-rate", this, () => Volatile.Read(ref _startedRequests))


How does this work? It says the counter contains requests per seconds but it's reading the same value as "requests-started" counter. Is there any computational magic behind IncrementingPollingCounter?

Yes, IncrementingPollingCounter has an internal field for last-value that it substracts, so it only reports the change in the last interval.

ManickaP · 2020-11-06T09:20:31Z

src/ReverseProxy/Service/Proxy/StreamCopier.cs

@@ -22,28 +25,68 @@ internal static class StreamCopier
        /// Based on <c>Microsoft.AspNetCore.Http.StreamCopyOperationInternal.CopyToAsync</c>.
        /// See: <see href="https://github.com/dotnet/aspnetcore/blob/080660967b6043f731d4b7163af9e9e6047ef0c4/src/Http/Shared/StreamCopyOperationInternal.cs"/>.
        /// </remarks>
-        public static async Task<(StreamCopyResult, Exception)> CopyAsync(Stream input, Stream output, CancellationToken cancellation)
+        public static async Task<(StreamCopyResult, Exception)> CopyAsync(bool isRequest, Stream input, Stream output, IClock clock, CancellationToken cancellation)


Should we rename StreamCopier to something that would tie it together with HttpProxy?
It shouldn't be used for anything else than copying proxy contents now, if I understand this change properly.

It shouldn't be used for anything else than copying proxy contents now, if I understand this change properly.

Correct.

Should we rename StreamCopier

It's also going to be using Pipes in the future, so maybe just ContentCopier?
I can make the change in a future PR if we want to change the name

I like the ContentCopier name! But I don't insist on changing it here in this PR, we can do it later.

ManickaP

LGTM

Add YARP Telemetry instrumentation

9617aa6

MihaZupan added this to the YARP 1.0.0-preview7 milestone Oct 29, 2020

MihaZupan requested review from halter73, Tratcher, ManickaP and alnikola October 29, 2020 16:30

Merge master

b3cc9ea

Tratcher reviewed Oct 29, 2020

View reviewed changes

MihaZupan added 3 commits November 2, 2020 11:34

Remove StreamCopier duplication

81002da

Rename InvokerSendAsync ProxyStage to SendAsync

4cf7d4b

Inline ProxyAsync telemetry into the core method

9d5acdb

davidfowl reviewed Nov 2, 2020

View reviewed changes

MihaZupan added 3 commits November 2, 2020 15:42

Change ProxyStage visibility to internal

6829762

Use IUptimeClock to improve Telemetry test stability

b866d92

Make internal UptimeClock class sealed

65fee89

MihaZupan commented Nov 2, 2020

View reviewed changes

src/ReverseProxy/Utilities/MonotonicTimer.cs Outdated Show resolved Hide resolved

Tratcher reviewed Nov 2, 2020

View reviewed changes

Remove dead code

5849f7c

davidfowl reviewed Nov 3, 2020

View reviewed changes

src/ReverseProxy/Middleware/ProxyInvokerMiddleware.cs Show resolved Hide resolved

davidfowl reviewed Nov 3, 2020

View reviewed changes

src/ReverseProxy/Telemetry/ProxyTelemetry.cs Outdated Show resolved Hide resolved

MihaZupan added 2 commits November 3, 2020 14:47

Set EventSource name from ctor instead of attribute

902489b

Rename ResponseUpgradeStart to ResponseUpgrade

d906d9d

Tratcher reviewed Nov 3, 2020

View reviewed changes

src/ReverseProxy/Service/Proxy/StreamCopier.cs Outdated Show resolved Hide resolved

MihaZupan added 4 commits November 3, 2020 18:45

Make ProxyFailed an event, remove ID args from ProxyStart

9ed69c0

Add ProxyInvoke event

990ee0b

Rename IUptimeClock to IClock

9d89f78

Add ProxyStart/Failed/Stop tests

ef59934

Tratcher reviewed Nov 3, 2020

View reviewed changes

alnikola reviewed Nov 4, 2020

View reviewed changes

MihaZupan added 3 commits November 5, 2020 11:43

Log ContentTransfered on Copy failure

df4ed1a

Add ProxyInvoke test

b6df2df

Merge master

24c0b0b

Tratcher approved these changes Nov 6, 2020

View reviewed changes

ManickaP reviewed Nov 6, 2020

View reviewed changes

Add missing Requests Started increment

6c237a4

ManickaP approved these changes Nov 6, 2020

View reviewed changes

MihaZupan merged commit 0a5ae94 into microsoft:master Nov 6, 2020

This was referenced Jan 12, 2021

Redesign/remove IOperationLogger #115

Closed

E2E logging coverage #158

Closed

Write Telemetry docs #676

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add YARP Telemetry instrumentation #501

Add YARP Telemetry instrumentation #501

MihaZupan commented Oct 29, 2020

MihaZupan commented Oct 29, 2020

Tratcher Oct 29, 2020

MihaZupan Nov 2, 2020 •

edited

Loading

davidfowl Nov 2, 2020

Tratcher left a comment

Tratcher Nov 2, 2020

MihaZupan Nov 2, 2020

Tratcher Nov 2, 2020

MihaZupan Nov 3, 2020

Tratcher commented Nov 3, 2020

Tratcher Nov 3, 2020

MihaZupan Nov 3, 2020

Tratcher Nov 3, 2020

MihaZupan Nov 5, 2020

alnikola left a comment

alnikola Nov 4, 2020

MihaZupan Nov 5, 2020

alnikola Nov 4, 2020

MihaZupan Nov 5, 2020

Tratcher Nov 5, 2020 •

edited

Loading

MihaZupan Nov 5, 2020 •

edited

Loading

alnikola Nov 4, 2020

MihaZupan Nov 5, 2020

alnikola Nov 4, 2020

alnikola Nov 4, 2020

alnikola Nov 4, 2020

MihaZupan Nov 5, 2020

ManickaP Nov 6, 2020

MihaZupan Nov 6, 2020

ManickaP Nov 6, 2020

MihaZupan Nov 6, 2020

ManickaP Nov 6, 2020

davidfowl Nov 6, 2020

ManickaP left a comment

	long GetStopwatchTimestamp();
	// See Stopwatch.GetTimestamp
	long Timestamp { get; }

		// PR REVIEW:
		// Should this event be logged on failure as well (instead of XContentTransferStop)?

Add YARP Telemetry instrumentation #501

Add YARP Telemetry instrumentation #501

Conversation

MihaZupan commented Oct 29, 2020

MihaZupan commented Oct 29, 2020

Choose a reason for hiding this comment

MihaZupan Nov 2, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Tratcher left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Tratcher commented Nov 3, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alnikola left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Tratcher Nov 5, 2020 • edited Loading

Choose a reason for hiding this comment

MihaZupan Nov 5, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ManickaP left a comment

Choose a reason for hiding this comment

MihaZupan Nov 2, 2020 •

edited

Loading

Tratcher Nov 5, 2020 •

edited

Loading

MihaZupan Nov 5, 2020 •

edited

Loading