Merge pull request #198 from tvjames/master

Diagnostic tool to track IRedisClient instances handed out by IRedisClientsManager

Author: mythz

src/ServiceStack.Redis/ServiceStack.Redis.csproj

@@ -167,6 +167,10 @@
     <Compile Include="ShardedConnectionPool.cs" />
     <Compile Include="ShardedRedisClientManager.cs" />
     <Compile Include="Support\ConsistentHash.cs" />
+    <Compile Include="Support\Diagnostic\InvokeEventArgs.cs" />
+    <Compile Include="Support\Diagnostic\TrackingFrame.cs" />
+    <Compile Include="Support\Diagnostic\TrackingRedisClientProxy.cs" />
+    <Compile Include="Support\Diagnostic\TrackingRedisClientsManager.cs" />
     <Compile Include="Support\Locking\IDistributedLock.cs" />
     <Compile Include="Support\OptimizedObjectSerializer.cs" />
     <Compile Include="Support\Queue\ISequentialData.cs" />

src/ServiceStack.Redis/Support/Diagnostic/InvokeEventArgs.cs

@@ -0,0 +1,18 @@
+using System;
+using System.Reflection;
+
+namespace ServiceStack.Redis.Support.Diagnostic
+{
+    /// <summary>
+    /// Provides access to the method reflection data as part of the before/after event
+    /// </summary>
+    public class InvokeEventArgs : EventArgs
+    {
+        public MethodInfo MethodInfo { get; private set; }
+
+        public InvokeEventArgs(MethodInfo methodInfo)
+        {
+            MethodInfo = methodInfo;
+        }
+    }
+}

src/ServiceStack.Redis/Support/Diagnostic/TrackingFrame.cs

@@ -0,0 +1,36 @@
+using System;
+
+namespace ServiceStack.Redis.Support.Diagnostic
+{
+    /// <summary>
+    /// Stores details about the context in which an IRedisClient is allocated. 
+    /// </summary>
+    public class TrackingFrame : IEquatable<TrackingFrame>
+    {
+        public Guid Id { get; set; }
+
+        public Type ProvidedToInstanceOfType { get; set; }
+
+        public DateTime Initialised { get; set; }
+
+        public bool Equals(TrackingFrame other)
+        {
+            if (ReferenceEquals(null, other)) return false;
+            if (ReferenceEquals(this, other)) return true;
+            return Id.Equals(other.Id);
+        }
+
+        public override bool Equals(object obj)
+        {
+            if (ReferenceEquals(null, obj)) return false;
+            if (ReferenceEquals(this, obj)) return true;
+            if (obj.GetType() != this.GetType()) return false;
+            return Equals((TrackingFrame)obj);
+        }
+
+        public override int GetHashCode()
+        {
+            return Id.GetHashCode();
+        }
+    }
+}

src/ServiceStack.Redis/Support/Diagnostic/TrackingRedisClientProxy.cs

@@ -0,0 +1,56 @@
+using System;
+using System.Reflection;
+using System.Runtime.Remoting.Messaging;
+using ServiceStack.Logging;
+
+namespace ServiceStack.Redis.Support.Diagnostic
+{
+    /// <summary>
+    /// Dynamically proxies access to the IRedisClient providing events for before & after each method invocation 
+    /// </summary>
+    public class TrackingRedisClientProxy : System.Runtime.Remoting.Proxies.RealProxy
+    {
+        private static readonly ILog Logger = LogManager.GetLogger(typeof(TrackingRedisClientProxy));
+
+        private readonly IRedisClient redisClientInstance;
+        private readonly Guid id;
+
+        public TrackingRedisClientProxy(IRedisClient instance, Guid id)
+            : base(typeof(IRedisClient))
+        {
+            this.redisClientInstance = instance;
+            this.id = id;
+        }
+
+        public event EventHandler<InvokeEventArgs> BeforeInvoke;
+        public event EventHandler<InvokeEventArgs> AfterInvoke;
+
+        public override IMessage Invoke(IMessage msg)
+        {
+            // Thanks: http://stackoverflow.com/a/15734124/211978
+
+            var methodCall = (IMethodCallMessage)msg;
+            var method = (MethodInfo)methodCall.MethodBase;
+
+            try
+            {
+                if (this.BeforeInvoke != null)
+                {
+                    this.BeforeInvoke(this, new InvokeEventArgs(method));
+                }
+                var result = method.Invoke(this.redisClientInstance, methodCall.InArgs);
+                if (this.AfterInvoke != null)
+                {
+                    this.AfterInvoke(this, new InvokeEventArgs(method));
+                }
+
+                return new ReturnMessage(result, null, 0, methodCall.LogicalCallContext, methodCall);
+            }
+            catch (TargetInvocationException e)
+            {
+                Logger.Error("Reflection exception when invoking target method", e);
+                return new ReturnMessage(e.InnerException, msg as IMethodCallMessage);
+            }
+        }
+    }
+}

src/ServiceStack.Redis/Support/Diagnostic/TrackingRedisClientsManager.cs

@@ -0,0 +1,136 @@
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
+using System.Reflection;
+using System.Runtime.CompilerServices;
+using System.Threading;
+using ServiceStack.Caching;
+using ServiceStack.Logging;
+
+namespace ServiceStack.Redis.Support.Diagnostic
+{
+    /// <summary>
+    /// Tracks each IRedisClient instance allocated from the IRedisClientsManager logging when they are allocated and disposed. 
+    /// Periodically writes the allocated instances to the log for diagnostic purposes.
+    /// </summary>
+    public class TrackingRedisClientsManager : IRedisClientsManager
+    {
+        private static readonly ILog Logger = LogManager.GetLogger(typeof(TrackingRedisClientsManager));
+
+        private readonly HashSet<TrackingFrame> trackingFrames = new HashSet<TrackingFrame>();
+        private readonly IRedisClientsManager redisClientsManager;
+
+        public TrackingRedisClientsManager(IRedisClientsManager redisClientsManager)
+        {
+            if (redisClientsManager == null)
+            {
+                throw new ArgumentNullException("redisClientsManager");
+            }
+
+            this.redisClientsManager = redisClientsManager;
+            Logger.DebugFormat("Constructed");
+
+            var timer = new Timer(state => this.DumpState());
+            timer.Change(TimeSpan.FromSeconds(30), TimeSpan.FromMinutes(1));
+        }
+
+        public void Dispose()
+        {
+            Logger.DebugFormat("Disposed");
+            this.redisClientsManager.Dispose();
+        }
+
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        public IRedisClient GetClient()
+        {
+            // get calling instance
+            var callingStackFrame = new StackFrame(1, true);
+            var callingMethodType = callingStackFrame.GetMethod();
+
+            return TrackInstance(callingMethodType, "GetClient", this.redisClientsManager.GetClient());
+        }
+
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        public IRedisClient GetReadOnlyClient()
+        {
+            // get calling instance
+            var callingMethodType = new StackFrame(1, true).GetMethod();
+
+            return TrackInstance(callingMethodType, "GetReadOnlyClient", this.redisClientsManager.GetReadOnlyClient());
+        }
+
+        public ICacheClient GetCacheClient()
+        {
+            Logger.DebugFormat("GetCacheClient");
+            return this.redisClientsManager.GetCacheClient();
+        }
+
+        public ICacheClient GetReadOnlyCacheClient()
+        {
+            Logger.DebugFormat("GetReadOnlyCacheClient");
+            return this.redisClientsManager.GetReadOnlyCacheClient();
+        }
+
+        private IRedisClient TrackInstance(MethodBase callingMethodType, string method, IRedisClient instance)
+        {
+            // track
+            var frame = new TrackingFrame()
+            {
+                Id = Guid.NewGuid(),
+                Initialised = DateTime.Now,
+                ProvidedToInstanceOfType = callingMethodType.DeclaringType,
+            };
+            lock (this.trackingFrames)
+            {
+                this.trackingFrames.Add(frame);
+            }
+
+            // proxy
+            var proxy = new TrackingRedisClientProxy(instance, frame.Id);
+            proxy.BeforeInvoke += (sender, args) =>
+            {
+                if (string.Compare("Dispose", args.MethodInfo.Name, StringComparison.InvariantCultureIgnoreCase) != 0)
+                {
+                    return;
+                }
+                lock (this.trackingFrames)
+                {
+                    this.trackingFrames.Remove(frame);
+                }
+                var duration = DateTime.Now - frame.Initialised;
+
+                Logger.DebugFormat("{0,18} Disposed {1} released from instance of type {2} checked out for {3}", method, frame.Id, frame.ProvidedToInstanceOfType.FullName, duration);
+            };
+
+            Logger.DebugFormat("{0,18} Tracking {1} allocated to instance of type {2}", method, frame.Id, frame.ProvidedToInstanceOfType.FullName);
+            return proxy.GetTransparentProxy() as IRedisClient;
+        }
+
+        private void DumpState()
+        {
+            Logger.InfoFormat("Dumping currently checked out IRedisClient instances");
+            var inUseInstances = new Func<TrackingFrame[]>(() =>
+            {
+                lock (this.trackingFrames)
+                {
+                    return Enumerable.ToArray(this.trackingFrames);
+                }
+            }).Invoke();
+
+            var summaryByType = inUseInstances.GroupBy(x => x.ProvidedToInstanceOfType.FullName);
+            foreach (var grouped in summaryByType)
+            {
+                Logger.InfoFormat("{0,60}: {1,-9} oldest {2}", grouped.Key, grouped.Count(),
+                    grouped.Min(x => x.Initialised));
+            }
+
+            foreach (var trackingFrame in inUseInstances)
+            {
+                Logger.DebugFormat("Instance {0} allocated to {1} at {2} ({3})", trackingFrame.Id,
+                    trackingFrame.ProvidedToInstanceOfType.FullName, trackingFrame.Initialised,
+                    trackingFrame.ProvidedToInstanceOfType.FullName);
+            }
+        }
+    }
+}