Telemetry API

[galvesribeiro]

Following @sergeybykov advices, I'm using this PR to push #992 changes progressively.

[tsibelman]

Hi @galvesribeiro I want to comment on a metric telemetry interface, from my experience you need some additional methods, you have counters where you want to add or remove deltas and not just to set values in addition you have a special use case for tracking timings, it possible to accomplish this with a single TrackMetric method but I think it much more convenient to distinguish between all these cases, so here is is my suggestion:

public interface IMetricTelemetryConsumer : ITelemetryConsumer
{
    void TrackMetric(string name, double value, IDictionary<string, string> properties = null);

    void TrackMetric(string name, TimeSpan value, IDictionary<string, string> properties = null);

    void IncrementMetric(string name);

    void IncrementMetric(string name, double value);

    void DecrementMetric(string name);

    void DecrementMetric(string name, double value);
}

[galvesribeiro]

@tsibelman I would say, you beat me :)

The previous unified interface has all those exact methods! When I had it split, those methods weren't moved!

Thanks for the feedback, just added them.

[tsibelman]

Another more radical change is instead of having all the methods on the TraceLogger class is to have one property that returns a MetricTelemetry object like this

public override MetricTelemetry Metric {  get;   }

The class implementation something like this:

public class MetricTelemetry {

    private static ConcurrentBag<ITelemetryConsumer> TelemetryProviders { get; set; }

    public void Track(string name, double value, IDictionary<string, string> properties = null)
    {
        if(TelemetryProviders != null)
            TelemetryProviders.OfType<IMetricTelemetryConsumer>().AsParallel().ForAll(tc => tc.TrackMetric(name, value, properties));
    }

    public void Track(string name, TimeSpan value, IDictionary<string, string> properties = null)
    {
        if (TelemetryProviders != null)
            TelemetryProviders.OfType<IMetricTelemetryConsumer>().AsParallel().ForAll(tc => tc.TrackMetric(name, value, properties));
    }

    public void Increment(string name)
    {
        if (TelemetryProviders != null)
            TelemetryProviders.OfType<IMetricTelemetryConsumer>().AsParallel().ForAll(tc => tc.IncrementMetric(name));
    }

    public void Increment(string name, double value)
    {
        if (TelemetryProviders != null)
            TelemetryProviders.OfType<IMetricTelemetryConsumer>().AsParallel().ForAll(tc => tc.IncrementMetric(name, value));
    }

    public void Decrement(string name)
    {
        if (TelemetryProviders != null)
            TelemetryProviders.OfType<IMetricTelemetryConsumer>().AsParallel().ForAll(tc => tc.DecrementMetric(name));
    }

    public void Decrement(string name, double value)
    {
        if (TelemetryProviders != null)
            TelemetryProviders.OfType<IMetricTelemetryConsumer>().AsParallel().ForAll(tc => tc.DecrementMetric(name, value));
    }
}

This way the logger class will be a bit cleaner and I think from user perspective calling log.Metric.Increment("Metr"); in more readable and discovarable that log.IncrementMetric("Metr")

[galvesribeiro]

@tsibelman If you look at the whole #992 thread, I had at the beginning suggested a new API. I don't feel so happy with keeping the current Logger and TraceLogger with the Telemetry stuff on it. I rather prefer to rewrite it. In other hand, @sergeybykov and @jason-bragg has a point on keep those classes as is today to keep backward-compatibility.

I would say that we first should start as they suggested keeping the telemetry methods on the Logger class but later on, we can have another developer-facing API and slowly deprecate the old logger as @sergeybykov mentioned before.

Even your suggestion on keep log.Metric.XXX() is something that I don't like. As I stated on the initial issue, Log is something, APM/Telemetry is something else that happens to also have Log/Trace. Maybe its a naming confusion and we can just rename/refactor it later.

[tsibelman]

@galvesribeiro I understand what you saying I was thinking that my aproach could be a compromise what would not disrupt the original API but will make an step into direction you want to go by providing a reusable class that could be easily detached from logging implementation in the future and moved into appropiate place.

Also did you looked into existing orleans implementation of varios metrics counters I think it not directly atached to logs, and would need to be refactored as well.

[galvesribeiro]

@tsibelman yes I understand. Right now I'm finishing implementing 3 telemetry consumers: ConsoleTelemetryConsumer, TraceTelemetryConsumer, FileTelemetryConsumer.

Those are already implemented as LogWriters and I changed the original ones to Forward all the write operations to those new Consumers on the APM API so we don't need to change the public interface of Logger/TraceLogger as @sergeybykov suggested and break anything.

After that, we have grounds to make changes on it with less impact IMHO.

[galvesribeiro]

Added the final commit of the basic API. Several weird errors System.CannotUnloadAppDomainException: Error while unloading appdomain. (Exception from HRESULT: 0x80131015) are thrown even if the test itself is pass and this is being investigated on #1034. We are blocked for now until it is fixed.

[sergeybykov]

We implicitly default to Orleans.dll?

[galvesribeiro]

The current implementation does. Just made it similar. Will remove that.

[gabikliot]

We of course do need both the lock and the flush in the log writer.
It is indeed thread safe (it is safe to use it from multiple threads), but the lines appeared intermixed without the lock (the write is not atomic).
The manual flush was also important to allow interactive debugging experience. I think I remember that we observed the auto flush was not to flush fast enough.

I would refrain from bundling changing the internal implementation here from adding the new telemetry APIs. If you want to change/optimize/improve the impl., separate it in another PR.
Also, by renaming those classes and moving them into separate files it is much harder now to compare the old and new impl.

[gabikliot]

why that was removed?

[galvesribeiro]

It just moved its implementation to a ConsoleTelemetryConsumer to avoid just boilerplate code forwarding to the new API(and to follow @sergeybykov comment #1026 (diff)). The idea is to keep the public interface as is for the developer.

[gabikliot]

It looks to me you changed a lot of how the existing logger used to work, and I can't really easily say if it is comparable or not, since files changed, but it appears it is not.
I thought the goal of this PR was to add telemetry tracing. Maybe also refactor the old code to use the same new APIs. But why change the behavior?

[galvesribeiro]

@gabikliot OK. For some reason (maybe my git noobish) some changes here weren't pushed. The message formatting that was previously on the LogWriters.cs was encapsulated inside another utility class and is used by the default trace/log consumers.

The Severity was the only type that was moved to remove the "dependency" on the Logger class.

I tought we agreed that the public interface of the Logger and TraceLogger class for now, should be kept and the internal implementation is what should change in order to make the first step to the new Telemetry API.

There wasn't behaviour change. The log output and usage still the same from the developer point of view. It is just "processed" by the new APIs instead of the old ILogConsumer ones.

Ok, so lets set the goals again:

1. Introduce the new Telemetry APIs by adding interfaces so people can create providers for any kind of APM/Telemetry/Log tool by spliting the contracts on small separate interfaces.
2. Instead of create a new public facing interface to push logs/telemetry, for now, add the methods to push data on the current Logger abstract class so developers would make use of it without break any code from the developer's perspective.
3. Forward all the calls from TraceLogger/Logger classes to push logs to the new API on the Consumers.
4. Create 3 basic providers that will behave as the current Trace, File and Console writers and those providers will be bundled on Orleans.dll as the previous ones are today.

I'll commit the missing stuff along with the changes on the lock as you suggested.

The only thing I now missed is the call to the old ILogConsumer's registered on that old collection that was made before. People would probably have custom consumers based on this interface for now. So, when we talk about Trace/Log, I should forward the messages to there as well to avoid them to break. Will add that on this commit so they can continue working on it. Everything new we should encourage people to use the new APIs.

I have a 4 hours drive now, as soon as I get back, will make those changes and submit the PR

Thanks for the feedback.

[sergeybykov]

Why WriteUsage()?

[galvesribeiro]

Just made so it got diff colors for diff messages. But ok, if you want I can change it.

[sergeybykov]

Remove this?

[sergeybykov]

Overall, I don't see any significant problem here.

[sergeybykov]

We definitely need a lock here. It races and throws in functional tests.

Exc level 0: System.IndexOutOfRangeException: Probable I/O race condition detected while copying memory. The I/O package is not thread safe by default. In multithreaded applications, a stream must be accessed in a thread-safe way, such as a thread-safe wrapper returned by TextReader's or TextWriter's Synchronized methods. This also applies to classes like StreamWriter and StreamReader.
at System.Buffer.InternalBlockCopy(Array src, Int32 srcOffsetBytes, Array dst, Int32 dstOffsetBytes, Int32 byteCount)
at System.IO.StreamWriter.Write(Char[] buffer, Int32 index, Int32 count)
at Orleans.Runtime.FileTelemetryConsumer.TrackTrace(String message) in c:\Builds\5877\Orleans\sbykov-Orleans-VSO-BVT-GH-Func\src\src\Orleans\Telemetry\Consumers\FileTelemetryConsumer.cs:line 25
at Orleans.Runtime.TraceLogger.TrackTrace(String message, Severity severity) in c:\Builds\5877\Orleans\sbykov-Orleans-VSO-BVT-GH-Func\src\src\Orleans\Logging\TraceLogger.cs:line 1147
at Orleans.Runtime.TraceLogger.WriteLogMessage(Int32 errorCode, Severity sev, String format, Object[] args, Exception exception) in c:\Builds\5877\Orleans\sbykov-Orleans-VSO-BVT-GH-Func\src\src\Orleans\Logging\TraceLogger.cs:line 814
at Orleans.Runtime.TraceLogger.Info(ErrorCode errorCode, String format, Object[] args) in c:\Builds\5877\Orleans\sbykov-Orleans-VSO-BVT-GH-Func\src\src\Orleans\Logging\TraceLogger.cs:line 636
at Orleans.Runtime.SystemStatus.set_Current(SystemStatus value) in c:\Builds\5877\Orleans\sbykov-Orleans-VSO-BVT-GH-Func\src\src\Orleans\Runtime\SystemStatus.cs:line 51
at Orleans.Runtime.Silo.Terminate(Boolean gracefully) in c:\Builds\5877\Orleans\sbykov-Orleans-VSO-BVT-GH-Func\src\src\OrleansRuntime\Silo\Silo.cs:line 660
at Orleans.Runtime.Silo.Shutdown()

[sergeybykov]

I'm running a perf test with rebuilt Halo grains for just in case.

There are a couple of build warning. Could you please fix them.

Warning 1 Ambiguous reference in cref attribute: 'FormatLogMessage'. Assuming 'Orleans.Runtime.TraceParserUtils.FormatLogMessage(Orleans.Runtime.Severity, Orleans.Runtime.TraceLogger.LoggerType, string, string, System.Net.IPEndPoint, System.Exception, int)', but could have also matched other overloads including 'Orleans.Runtime.TraceParserUtils.FormatLogMessage(System.DateTime, Orleans.Runtime.Severity, Orleans.Runtime.TraceLogger.LoggerType, string, string, System.Net.IPEndPoint, System.Exception, int)'. C:\GitHub\sergeybykov\Orleans\src\Orleans\Telemetry\TraceParserUtils.cs 43 28 Orleans
Warning 2 Ambiguous reference in cref attribute: 'FormatLogMessage'. Assuming 'Orleans.Runtime.TraceParserUtils.FormatLogMessage(Orleans.Runtime.Severity, Orleans.Runtime.TraceLogger.LoggerType, string, string, System.Net.IPEndPoint, System.Exception, int)', but could have also matched other overloads including 'Orleans.Runtime.TraceParserUtils.FormatLogMessage(System.DateTime, Orleans.Runtime.Severity, Orleans.Runtime.TraceLogger.LoggerType, string, string, System.Net.IPEndPoint, System.Exception, int)'. C:\GitHub\sergeybykov\Orleans\src\Orleans\Telemetry\TraceParserUtils.cs 43 28 Orleans

[sergeybykov]

Perf is fine. This is ready to merge when these two warning are fixed.

[sergeybykov]

Thank you, @galvesribeiro!

[galvesribeiro]

Thank you @sergeybykov for accept this suggestion. Let's now move to the real part... Implement the Consumers 😄

[sergeybykov]

@galvesribeiro Go for it!

[veikkoeeva]

@galvesribeiro Thanks and bows. 👍 Go get'em tiger, grr! 👯

[gabikliot]

Great contribution! Thank you @galvesribeiro !