Merge pull request #4025 from jtattermusch/csharp_perf_instrumentation

Add simple profiling instrumentation for C#

8 files changed, 135 insertions, 73 deletions

diff --git a/src/csharp/Grpc.Core/Internal/AsyncCall.cs b/src/csharp/Grpc.Core/Internal/AsyncCall.cs
index 800462c854..e3ecc47282 100644
--- a/src/csharp/Grpc.Core/Internal/AsyncCall.cs
+++ b/src/csharp/Grpc.Core/Internal/AsyncCall.cs
@@ -39,6 +39,7 @@ using System.Threading;
 using System.Threading.Tasks;
 using Grpc.Core.Internal;
 using Grpc.Core.Logging;
+using Grpc.Core.Profiling;
 using Grpc.Core.Utils;
 
 namespace Grpc.Core.Internal
@@ -87,6 +88,9 @@ namespace Grpc.Core.Internal
         /// </summary>
         public TResponse UnaryCall(TRequest msg)
         {
+            var profiler = Profilers.ForCurrentThread();
+
+            using (profiler.NewScope("AsyncCall.UnaryCall"))
             using (CompletionQueueSafeHandle cq = CompletionQueueSafeHandle.Create())
             {
                 byte[] payload = UnsafeSerialize(msg);
@@ -104,24 +108,26 @@ namespace Grpc.Core.Internal
                 }
 
                 using (var metadataArray = MetadataArraySafeHandle.Create(details.Options.Headers))
+                using (var ctx = BatchContextSafeHandle.Create())
                 {
-                    using (var ctx = BatchContextSafeHandle.Create())
-                    {
-                        call.StartUnary(ctx, payload, metadataArray, GetWriteFlagsForCall());
-                        var ev = cq.Pluck(ctx.Handle);
+                    call.StartUnary(ctx, payload, metadataArray, GetWriteFlagsForCall());
+
+                    var ev = cq.Pluck(ctx.Handle);
 
-                        bool success = (ev.success != 0);
-                        try
+                    bool success = (ev.success != 0);
+                    try
+                    {
+                        using (profiler.NewScope("AsyncCall.UnaryCall.HandleBatch"))
                         {
                             HandleUnaryResponse(success, ctx.GetReceivedStatusOnClient(), ctx.GetReceivedMessage(), ctx.GetReceivedInitialMetadata());
                         }
-                        catch (Exception e)
-                        {
-                            Logger.Error(e, "Exception occured while invoking completion delegate.");
-                        }
+                    }
+                    catch (Exception e)
+                    {
+                        Logger.Error(e, "Exception occured while invoking completion delegate.");
                     }
                 }
-
+                    
                 // Once the blocking call returns, the result should be available synchronously.
                 // Note that GetAwaiter().GetResult() doesn't wrap exceptions in AggregateException.
                 return unaryResponseTcs.Task.GetAwaiter().GetResult();
@@ -329,27 +335,35 @@ namespace Grpc.Core.Internal
 
         private void Initialize(CompletionQueueSafeHandle cq)
         {
-            var call = CreateNativeCall(cq);
-            details.Channel.AddCallReference(this);
-            InitializeInternal(call);
-            RegisterCancellationCallback();
+            using (Profilers.ForCurrentThread().NewScope("AsyncCall.Initialize"))
+            { 
+                var call = CreateNativeCall(cq);
+
+                details.Channel.AddCallReference(this);
+                InitializeInternal(call);
+                RegisterCancellationCallback();
+            }
         }
 
         private INativeCall CreateNativeCall(CompletionQueueSafeHandle cq)
         {
-            if (injectedNativeCall != null)
-            {
-                return injectedNativeCall;  // allows injecting a mock INativeCall in tests.
-            }
+            using (Profilers.ForCurrentThread().NewScope("AsyncCall.CreateNativeCall"))
+            { 
+                if (injectedNativeCall != null)
+                {
+                    return injectedNativeCall;  // allows injecting a mock INativeCall in tests.
+                }
 
-            var parentCall = details.Options.PropagationToken != null ? details.Options.PropagationToken.ParentCall : CallSafeHandle.NullInstance;
+                var parentCall = details.Options.PropagationToken != null ? details.Options.PropagationToken.ParentCall : CallSafeHandle.NullInstance;
 
-            var credentials = details.Options.Credentials;
-            using (var nativeCredentials = credentials != null ? credentials.ToNativeCredentials() : null)
-            {
-                return details.Channel.Handle.CreateCall(environment.CompletionRegistry,
-                    parentCall, ContextPropagationToken.DefaultMask, cq,
-                    details.Method, details.Host, Timespec.FromDateTime(details.Options.Deadline.Value), nativeCredentials);
+                var credentials = details.Options.Credentials;
+                using (var nativeCredentials = credentials != null ? credentials.ToNativeCredentials() : null)
+                {
+                    var result = details.Channel.Handle.CreateCall(environment.CompletionRegistry,
+                                 parentCall, ContextPropagationToken.DefaultMask, cq,
+                                 details.Method, details.Host, Timespec.FromDateTime(details.Options.Deadline.Value), nativeCredentials);
+                    return result;
+                }
             }
         }
 
@@ -385,33 +399,37 @@ namespace Grpc.Core.Internal
         /// </summary>
         private void HandleUnaryResponse(bool success, ClientSideStatus receivedStatus, byte[] receivedMessage, Metadata responseHeaders)
         {
-            TResponse msg = default(TResponse);
-            var deserializeException = success ? TryDeserialize(receivedMessage, out msg) : null;
-
-            lock (myLock)
+            using (Profilers.ForCurrentThread().NewScope("AsyncCall.HandleUnaryResponse"))
             {
-                finished = true;
+                TResponse msg = default(TResponse);
+                var deserializeException = success ? TryDeserialize(receivedMessage, out msg) : null;
 
-                if (deserializeException != null && receivedStatus.Status.StatusCode == StatusCode.OK)
+                lock (myLock)
                 {
-                    receivedStatus = new ClientSideStatus(DeserializeResponseFailureStatus, receivedStatus.Trailers);
+                    finished = true;
+
+                    if (deserializeException != null && receivedStatus.Status.StatusCode == StatusCode.OK)
+                    {
+                        receivedStatus = new ClientSideStatus(DeserializeResponseFailureStatus, receivedStatus.Trailers);
+                    }
+                    finishedStatus = receivedStatus;
+
+                    ReleaseResourcesIfPossible();
+
                 }
-                finishedStatus = receivedStatus;
 
-                ReleaseResourcesIfPossible();
-            }
+                responseHeadersTcs.SetResult(responseHeaders);
 
-            responseHeadersTcs.SetResult(responseHeaders);
+                var status = receivedStatus.Status;
 
-            var status = receivedStatus.Status;
+                if (!success || status.StatusCode != StatusCode.OK)
+                {
+                    unaryResponseTcs.SetException(new RpcException(status));
+                    return;
+                }
 
-            if (!success || status.StatusCode != StatusCode.OK)
-            {
-                unaryResponseTcs.SetException(new RpcException(status));
-                return;
+                unaryResponseTcs.SetResult(msg);
             }
-
-            unaryResponseTcs.SetResult(msg);
         }
 
         /// <summary>
diff --git a/src/csharp/Grpc.Core/Internal/AsyncCallBase.cs b/src/csharp/Grpc.Core/Internal/AsyncCallBase.cs
index 3e2c57c9b5..953f61aa1e 100644
--- a/src/csharp/Grpc.Core/Internal/AsyncCallBase.cs
+++ b/src/csharp/Grpc.Core/Internal/AsyncCallBase.cs
@@ -41,6 +41,7 @@ using System.Threading.Tasks;
 
 using Grpc.Core.Internal;
 using Grpc.Core.Logging;
+using Grpc.Core.Profiling;
 using Grpc.Core.Utils;
 
 namespace Grpc.Core.Internal
@@ -167,16 +168,19 @@ namespace Grpc.Core.Internal
         /// </summary>
         protected bool ReleaseResourcesIfPossible()
         {
-            if (!disposed && call != null)
+            using (Profilers.ForCurrentThread().NewScope("AsyncCallBase.ReleaseResourcesIfPossible"))
             {
-                bool noMoreSendCompletions = sendCompletionDelegate == null && (halfcloseRequested || cancelRequested || finished);
-                if (noMoreSendCompletions && readingDone && finished)
+                if (!disposed && call != null)
                 {
-                    ReleaseResources();
-                    return true;
+                    bool noMoreSendCompletions = sendCompletionDelegate == null && (halfcloseRequested || cancelRequested || finished);
+                    if (noMoreSendCompletions && readingDone && finished)
+                    {
+                        ReleaseResources();
+                        return true;
+                    }
                 }
+                return false;
             }
-            return false;
         }
 
         protected abstract bool IsClient
@@ -228,7 +232,10 @@ namespace Grpc.Core.Internal
 
         protected byte[] UnsafeSerialize(TWrite msg)
         {
-            return serializer(msg);
+            using (Profilers.ForCurrentThread().NewScope("AsyncCallBase.UnsafeSerialize"))
+            {
+                return serializer(msg);
+            }
         }
 
         protected Exception TrySerialize(TWrite msg, out byte[] payload)
@@ -247,15 +254,20 @@ namespace Grpc.Core.Internal
 
         protected Exception TryDeserialize(byte[] payload, out TRead msg)
         {
-            try
-            {
-                msg = deserializer(payload);
-                return null;
-            } 
-            catch (Exception e)
+            using (Profilers.ForCurrentThread().NewScope("AsyncCallBase.TryDeserialize"))
             {
-                msg = default(TRead);
-                return e;
+                try
+                {
+                
+                    msg = deserializer(payload);
+                    return null;
+             
+                }
+                catch (Exception e)
+                {
+                    msg = default(TRead);
+                    return e;
+                }
             }
         }
 
diff --git a/src/csharp/Grpc.Core/Internal/CallSafeHandle.cs b/src/csharp/Grpc.Core/Internal/CallSafeHandle.cs
index 0be7a4dd3a..ddeedebd11 100644
--- a/src/csharp/Grpc.Core/Internal/CallSafeHandle.cs
+++ b/src/csharp/Grpc.Core/Internal/CallSafeHandle.cs
@@ -34,6 +34,7 @@ using System.Diagnostics;
 using System.Runtime.InteropServices;
 using Grpc.Core;
 using Grpc.Core.Utils;
+using Grpc.Core.Profiling;
 
 namespace Grpc.Core.Internal
 {
@@ -131,8 +132,11 @@ namespace Grpc.Core.Internal
 
         public void StartUnary(BatchContextSafeHandle ctx, byte[] payload, MetadataArraySafeHandle metadataArray, WriteFlags writeFlags)
         {
-            grpcsharp_call_start_unary(this, ctx, payload, new UIntPtr((ulong)payload.Length), metadataArray, writeFlags)
-                .CheckOk();
+            using (Profilers.ForCurrentThread().NewScope("CallSafeHandle.StartUnary"))
+            {
+                grpcsharp_call_start_unary(this, ctx, payload, new UIntPtr((ulong)payload.Length), metadataArray, writeFlags)
+                    .CheckOk();
+            }
         }
 
         public void StartClientStreaming(UnaryResponseClientHandler callback, MetadataArraySafeHandle metadataArray)
diff --git a/src/csharp/Grpc.Core/Internal/ChannelSafeHandle.cs b/src/csharp/Grpc.Core/Internal/ChannelSafeHandle.cs
index d270d77526..5f9169bcb2 100644
--- a/src/csharp/Grpc.Core/Internal/ChannelSafeHandle.cs
+++ b/src/csharp/Grpc.Core/Internal/ChannelSafeHandle.cs
@@ -32,6 +32,7 @@ using System;
 using System.Runtime.InteropServices;
 using System.Threading;
 using System.Threading.Tasks;
+using Grpc.Core.Profiling;
 
 namespace Grpc.Core.Internal
 {
@@ -84,13 +85,16 @@ namespace Grpc.Core.Internal
 
         public CallSafeHandle CreateCall(CompletionRegistry registry, CallSafeHandle parentCall, ContextPropagationFlags propagationMask, CompletionQueueSafeHandle cq, string method, string host, Timespec deadline, CredentialsSafeHandle credentials)
         {
-            var result = grpcsharp_channel_create_call(this, parentCall, propagationMask, cq, method, host, deadline);
-            if (credentials != null)
+            using (Profilers.ForCurrentThread().NewScope("ChannelSafeHandle.CreateCall"))
             {
-                result.SetCredentials(credentials);
+                var result = grpcsharp_channel_create_call(this, parentCall, propagationMask, cq, method, host, deadline);
+                if (credentials != null)
+                {
+                    result.SetCredentials(credentials);
+                }
+                result.SetCompletionRegistry(registry);
+                return result;
             }
-            result.SetCompletionRegistry(registry);
-            return result;
         }
 
         public ChannelState CheckConnectivityState(bool tryToConnect)
diff --git a/src/csharp/Grpc.Core/Internal/CompletionQueueSafeHandle.cs b/src/csharp/Grpc.Core/Internal/CompletionQueueSafeHandle.cs
index f7a3471bb4..9de2bc7950 100644
--- a/src/csharp/Grpc.Core/Internal/CompletionQueueSafeHandle.cs
+++ b/src/csharp/Grpc.Core/Internal/CompletionQueueSafeHandle.cs
@@ -31,6 +31,7 @@
 using System;
 using System.Runtime.InteropServices;
 using System.Threading.Tasks;
+using Grpc.Core.Profiling;
 
 namespace Grpc.Core.Internal
 {
@@ -70,7 +71,10 @@ namespace Grpc.Core.Internal
 
         public CompletionQueueEvent Pluck(IntPtr tag)
         {
-            return grpcsharp_completion_queue_pluck(this, tag);
+            using (Profilers.ForCurrentThread().NewScope("CompletionQueueSafeHandle.Pluck"))
+            {
+                return grpcsharp_completion_queue_pluck(this, tag);
+            }
         }
 
         public void Shutdown()
diff --git a/src/csharp/Grpc.Core/Internal/Enums.cs b/src/csharp/Grpc.Core/Internal/Enums.cs
index 185098160b..b0eab2001b 100644
--- a/src/csharp/Grpc.Core/Internal/Enums.cs
+++ b/src/csharp/Grpc.Core/Internal/Enums.cs
@@ -102,6 +102,9 @@ namespace Grpc.Core.Internal
         /* Realtime clock */
         Realtime,
 
+        /* Precise clock good for performance profiling. */
+        Precise,
+
         /* Timespan - the distance between two time points */
         Timespan
     }
diff --git a/src/csharp/Grpc.Core/Internal/MetadataArraySafeHandle.cs b/src/csharp/Grpc.Core/Internal/MetadataArraySafeHandle.cs
index 31b834c979..ed1bd24498 100644
--- a/src/csharp/Grpc.Core/Internal/MetadataArraySafeHandle.cs
+++ b/src/csharp/Grpc.Core/Internal/MetadataArraySafeHandle.cs
@@ -31,6 +31,7 @@
 using System;
 using System.Runtime.InteropServices;
 using System.Threading.Tasks;
+using Grpc.Core.Profiling;
 
 namespace Grpc.Core.Internal
 {
@@ -66,14 +67,17 @@ namespace Grpc.Core.Internal
             
         public static MetadataArraySafeHandle Create(Metadata metadata)
         {
-            // TODO(jtattermusch): we might wanna check that the metadata is readonly 
-            var metadataArray = grpcsharp_metadata_array_create(new UIntPtr((ulong)metadata.Count));
-            for (int i = 0; i < metadata.Count; i++)
+            using (Profilers.ForCurrentThread().NewScope("MetadataArraySafeHandle.Create"))
             {
-                var valueBytes = metadata[i].GetSerializedValueUnsafe();
-                grpcsharp_metadata_array_add(metadataArray, metadata[i].Key, valueBytes, new UIntPtr((ulong)valueBytes.Length));
+                // TODO(jtattermusch): we might wanna check that the metadata is readonly 
+                var metadataArray = grpcsharp_metadata_array_create(new UIntPtr((ulong)metadata.Count));
+                for (int i = 0; i < metadata.Count; i++)
+                {
+                    var valueBytes = metadata[i].GetSerializedValueUnsafe();
+                    grpcsharp_metadata_array_add(metadataArray, metadata[i].Key, valueBytes, new UIntPtr((ulong)valueBytes.Length));
+                }
+                return metadataArray;
             }
-            return metadataArray;
         }
 
         /// <summary>
diff --git a/src/csharp/Grpc.Core/Internal/Timespec.cs b/src/csharp/Grpc.Core/Internal/Timespec.cs
index daf85d5f61..38fc067d9f 100644
--- a/src/csharp/Grpc.Core/Internal/Timespec.cs
+++ b/src/csharp/Grpc.Core/Internal/Timespec.cs
@@ -239,6 +239,19 @@ namespace Grpc.Core.Internal
             }
         }
 
+        /// <summary>
+        /// Gets current timestamp using <c>GPRClockType.Precise</c>.
+        /// Only available internally because core needs to be compiled with 
+        /// GRPC_TIMERS_RDTSC support for this to use RDTSC.
+        /// </summary>
+        internal static Timespec PreciseNow
+        {
+            get
+            {
+                return gprsharp_now(GPRClockType.Precise);
+            }
+        }
+
         internal static int NativeSize
         {
             get