MiniProfiler RavenDB integration

MiniProfilerRavenDBIntegration.cs

using Newtonsoft.Json;
using Newtonsoft.Json.Linq;
using Raven.Client.Documents;
using Raven.Client.Documents.Session;
using StackExchange.Profiling;
using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Diagnostics;
using System.IO;
using System.IO.Compression;
using System.Linq;
using System.Net.Http;
using System.Reflection;
using System.Security.Policy;
using System.Text;

namespace finstat
{
    public static class MiniProfilerRavenDBIntegration
    {
        private static HttpDiagnosticSourceSubscriber _diagSubscriber;
        private static HashSet<Assembly> _stackTraceAssemblies = new HashSet<Assembly>(new[] {
            Assembly.Load("your_project_assembly1"),
            Assembly.Load("your_project_assembly2"),
            Assembly.Load("your_project_assembly3"),
            Assembly.GetExecutingAssembly()
        });
        public static void AttachTo(DocumentStore store)
        {

            if (store == null)
                return;
            if (_diagSubscriber == null)
            {
                _diagSubscriber = new HttpDiagnosticSourceSubscriber(new HttpClientDiagnosticObserver(_stackTraceAssemblies));
            }
            _diagSubscriber.RegisterStore(store);
            store.OnSessionCreated += TrackSession;
            store.AfterDispose += AfterDispose;
        }

        private static void TrackSession(object sender, SessionCreatedEventArgs e)
        {
            var profiler = MiniProfiler.Current;
            using (var timing = profiler.CustomTiming("RavenDB", $"Session {e.Session.Id} created for {e.Session.DatabaseName}", "Session", includeStackTrace: false))
            {
                if (timing != null)
                {
                    timing.StackTraceSnippet = GetStackInfo(_stackTraceAssemblies);
                }
            }
        }

        private static void AfterDispose(object sender, EventArgs e)
        {
            var store = sender as DocumentStore;
            if (store != null)
            {
                store.OnSessionCreated -= TrackSession;
                store.AfterDispose -= AfterDispose;
            }
        }
        internal static string GetStackInfo(HashSet<Assembly> stackTraceAssemblies, int stackDept = 3)
        {
            StackTrace st = new StackTrace(true);
            var stackPath = new StringBuilder();
            var usedStackDebt = 0;
            string previousMethodHash = null;
            for (int i = 2; i < st.FrameCount; i++)
            {
                // Note that high up the call stack, there is only
                // one stack frame.
                StackFrame sf = st.GetFrame(i);
                var method = sf.GetMethod();
                var lineNumber = sf.GetFileLineNumber();
                if (method.DeclaringType != null)
                {
                    var className = method.DeclaringType.FullName.Split('+', 2)[0]
                                    // remove namespace
                                    .Replace(method.DeclaringType.Namespace ?? "ignore_this_pattern", null)
                                    .Trim('.');
                    var methodName = method.Name.Split('>', 2)[0].Trim('<', '>');
                    // break stack trace on run internal
                    if (className == "ExecutionContext" && methodName == "RunInternal")
                    {
                        break;
                    }
                    if (stackTraceAssemblies.Contains(method.DeclaringType.Assembly))
                    {
                        // fix names for async calls
                        if (method.Name == "MoveNext")
                        {
                            className = method.DeclaringType.DeclaringType.FullName.Split('+', 2)[0]
                                // remove namespace
                                .Replace(method.DeclaringType.DeclaringType.Namespace, null)
                                .Trim('.');
                            methodName = method.DeclaringType.Name.Split('>', 2)[0].Trim('<', '>');
                        }
                        if (usedStackDebt < stackDept || className.Contains("Controller"))
                        {
                            // exclude following conditions
                            if (className.EndsWith("Middleware"))
                            {
                                continue;
                            }
                            var methodHash = className + methodName;
                            if (methodHash != previousMethodHash)
                            {
                                if (stackPath.Length > 0) stackPath.Insert(0, " > ");
                                stackPath.Insert(0, $"{className}.{methodName}:{lineNumber}");
                                previousMethodHash = methodHash;
                                ++usedStackDebt;
                            }
                        }
                    }
                }
            }
            return stackPath.ToString();
        }
    }

    /// <summary>
    /// This is http diagnostic observer to attach to all http requests from this app
    /// </summary>
    public sealed class HttpClientDiagnosticObserver : IObserver<KeyValuePair<string, object>>
    {
        public HttpClientDiagnosticObserver(IEnumerable<Assembly> stackTraceAssemblies)
        {
            _stackTraceAssemblies = new HashSet<Assembly>(stackTraceAssemblies);
        }
        private static ConcurrentDictionary<HttpRequestMessage, CustomTiming> _Requests = new ConcurrentDictionary<HttpRequestMessage, CustomTiming>();
        private static IList<(string database, string url, DocumentStore store)> _registeredStores = new List<(string database, string url, DocumentStore store)>();
        private readonly HashSet<Assembly> _stackTraceAssemblies;

        public void OnCompleted()
        {
        }

        public void OnError(Exception error)
        {
        }

        /// <summary>
        /// Register store to have info about info about url format and deserialization for content
        /// </summary>
        public void RegisterStore(DocumentStore store)
        {
            foreach (var baseUrl in store.Urls)
            {
                _registeredStores.Add((database: store.Database, url: baseUrl, store: store));
            }
        }

        public void OnNext(KeyValuePair<string, object> value)
        {
            var profiler = MiniProfiler.Current;
            switch (value.Key)
            {
                case "System.Net.Http.HttpRequestOut.Start":
                    var startRequest = (HttpRequestMessage)value.Value.GetType().GetProperty("Request").GetValue(value.Value, null);

                    // create timing
                    var startTiming = profiler.CustomTiming(
                            // if request is in pattern of registered store
                            _registeredStores.Any(x => startRequest.RequestUri.AbsoluteUri.StartsWith($"{x.url}/databases/{x.database}/")) ? "RavenDB" : "Http",
                            $"Url: {startRequest.RequestUri} started", "Request", includeStackTrace: false);
                    // get related stack
                    if (startTiming != null)
                    {
                        startTiming.StackTraceSnippet = MiniProfilerRavenDBIntegration.GetStackInfo(_stackTraceAssemblies);
                    }
                    // register reguest timing
                    _Requests.TryAdd(startRequest, startTiming);
                    break;
                case "System.Net.Http.HttpRequestOut.Stop":
                    var endRequest = (HttpRequestMessage)value.Value.GetType().GetProperty("Request").GetValue(value.Value, null);
                    var endResponse = (HttpResponseMessage)value.Value.GetType().GetProperty("Response").GetValue(value.Value, null);
                    // get timing for registered requests
                    CustomTiming timing;
                    _Requests.TryRemove(endRequest, out timing);
                    if (timing != null)
                    {
                        // mark timing as completed, to get proper duration
                        timing.FirstFetchCompleted();
                        if (endResponse != null)
                        {
                            // check if request is to registered stores
                            DocumentStore locatedStore = _registeredStores.Where(x => endRequest.RequestUri.AbsoluteUri.StartsWith($"{x.url}/databases/{x.database}/")).Select(x => x.store).FirstOrDefault();
                            if (locatedStore != null)
                            {
                                // stack trace broken by interceptor use db info instead
                                timing.StackTraceSnippet = $"DB [{locatedStore.Database}] at {endRequest.RequestUri.Authority}: {timing.StackTraceSnippet}";
                                var contentRaw = endResponse.Content.ReadAsStringAsync().Result;
                                // log load multi (lazy calls)
                                if (endRequest.RequestUri.AbsolutePath.Contains("/multi_get") && endRequest.Method == System.Net.Http.HttpMethod.Post)
                                {
                                    timing.ExecuteType = "MULTI";
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}:";
                                    // deserialize request commands
                                    var requestRaw = UnGzip(endRequest.Content.ReadAsByteArrayAsync().Result);
                                    var requests = JsonConvert.DeserializeObject<JObject>(requestRaw);
                                    // deserialize result of call
                                    var content = JsonConvert.DeserializeObject<JObject>(contentRaw);
                                    if (content != null)
                                    {
                                        int position = 0;
                                        // iterate over result and pair commands with results
                                        foreach (var result in content["Results"])
                                        {
                                            var query = requests["Requests"][position];
                                            string queryCommand = query["Query"].Value<string>();

                                            if (queryCommand.StartsWith("?queryHash="))
                                            {
                                                queryCommand = query["Content"]["Query"].Value<string>();
                                                var queryParams = query["Content"]["QueryParameters"];
                                                if (queryParams != null)
                                                {
                                                    queryCommand += $"\n{queryParams}";
                                                }
                                            }
                                            // something wrong
                                            if (result["StatusCode"].Value<int>() == 500)
                                            {
                                                timing.CommandString += $"\n{position}: {queryCommand}: !!!Failed request!!!";
                                            }
                                            // some result => try to get info about commmand
                                            else if (query.Type != JTokenType.Null)
                                            {
                                                var durationData = result["Result"].Type != JTokenType.Null ? result["Result"]["DurationInMs"] : null;
                                                string duration = durationData != null ? $" in {TimeSpan.FromMilliseconds(durationData.Value<int>())}" : null;
                                                timing.CommandString += $"\n{position}. [{result["StatusCode"]}]{duration}: {queryCommand}";
                                            }
                                            // nothing => aggresive cache
                                            else
                                            {
                                                timing.CommandString += $"\n{position}: {queryCommand}: Agressive cache";
                                            }
                                            ++position;

                                        }
                                    }
                                }
                                // log load single
                                else if (endRequest.RequestUri.AbsolutePath.EndsWith("/docs"))
                                {
                                    timing.ExecuteType = "LOAD";
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}: {endRequest.RequestUri.Query}";
                                }
                                // log store
                                else if (endRequest.RequestUri.AbsolutePath.EndsWith("/bulk_docs"))
                                {
                                    timing.ExecuteType = "STORE";
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}:";
                                    var requestRaw = UnGzip(endRequest.Content.ReadAsByteArrayAsync().Result);
                                    var request = JsonConvert.DeserializeObject<JObject>(requestRaw);
                                    int position = 0;
                                    foreach (var command in request["Commands"])
                                    {
                                        string collection = null;
                                        if (command["Document"] == null)
                                        {
                                            timing.ExecuteType = command["Type"].Value<string>();
                                        }
                                        else
                                        {
                                            collection = command["Document"].Type != JTokenType.Null && command["Document"]["@metadata"].Type != JTokenType.Null ? command["Document"]["@metadata"]["@collection"].Value<string>() : null;
                                        }
                                        timing.CommandString += $"\n{position}: {collection} ['{command["Id"]}']";
                                    }
                                }
                                // log stream
                                else if (endRequest.RequestUri.AbsolutePath.EndsWith("/streams/queries"))
                                {
                                    timing.ExecuteType = "STREAM";
                                    var requestRaw = UnGzip(endRequest.Content.ReadAsByteArrayAsync().Result);
                                    var request = JsonConvert.DeserializeObject<JObject>(requestRaw);
                                    string queryCommand = request["Query"].Value<string>();
                                    var queryParams = request["QueryParameters"];
                                    if (queryParams != null)
                                    {
                                        queryCommand += $"\n{queryParams}";
                                    }
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}: {queryCommand}";
                                }
                                // log single query
                                else if (endRequest.RequestUri.AbsolutePath.EndsWith("/queries"))
                                {
                                    timing.ExecuteType = "QUERY";
                                    var requestRaw = UnGzip(endRequest.Content.ReadAsByteArrayAsync().Result);
                                    var request = JsonConvert.DeserializeObject<JObject>(requestRaw);
                                    string queryCommand = request["Query"].Value<string>();
                                    var queryParams = request["QueryParameters"];
                                    if (queryParams != null)
                                    {
                                        queryCommand += $"\n{queryParams}";
                                    }
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}: {queryCommand}";
                                }
                                // log client configuration
                                else if (endRequest.RequestUri.AbsolutePath.EndsWith("/configuration/client"))
                                {
                                    timing.ExecuteType = "CLIENT";
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}: client configuration";
                                }
                                // log single query
                                else if (endRequest.RequestUri.AbsolutePath.EndsWith("/indexes/terms"))
                                {
                                    timing.ExecuteType = "TERMS";
                                    var queryCommand = endRequest.RequestUri.Query;
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}: {queryCommand}";
                                }
                                else
                                {
                                    timing.ExecuteType = "UNKNOWN";
                                    timing.CommandString = $"[{endResponse.StatusCode} - {HumanizeBytes(contentRaw.Length)}] in {TimeSpan.FromMilliseconds(Convert.ToInt64(timing.FirstFetchDurationMilliseconds ?? 0))}: not recognized command";
                                }

                            }
                            else
                            {
                                timing.CommandString += $"\nResult: {endResponse.StatusCode}";
                            }
                        }
                        else
                        {
                            timing.CommandString += "\nNo response";
                        }
                        ((IDisposable)timing).Dispose();
                    }
                    break;
            }
        }
        /// <summary>
        /// Helper function to ungzip content
        /// </summary>
        private static string UnGzip(byte[] bytes)
        {
            using (var msi = new MemoryStream(bytes))
            using (var mso = new MemoryStream())
            {
                using (var gs = new GZipStream(msi, CompressionMode.Decompress))
                {
                    gs.CopyTo(mso);
                }

                return Encoding.UTF8.GetString(mso.ToArray());
            }
        }
        /// <summary>
        /// Bytes in human format
        /// </summary>
        private static string HumanizeBytes(long? byteCount)
        {
            if (byteCount == null)
            {
                return "unknown";
            }
            string[] suf = { "B", "KB", "MB", "GB", "TB", "PB", "EB" }; //Longs run out around EB
            if (byteCount == 0)
                return "0" + suf[0];
            long bytes = Math.Abs(byteCount.Value);
            int place = Convert.ToInt32(Math.Floor(Math.Log(bytes, 1024)));
            double num = Math.Round(bytes / Math.Pow(1024, place), 1);
            return (Math.Sign(byteCount.Value) * num).ToString(System.Globalization.CultureInfo.InvariantCulture) + suf[place];
        }
    }

    /// <summary>
    /// Http diagnostic subscriber
    /// </summary>
    public class HttpDiagnosticSourceSubscriber : IObserver<DiagnosticListener>, IDisposable
    {
        private readonly HttpClientDiagnosticObserver parent;
        private readonly IDisposable allListenersSubscription;
        private IDisposable sourceSubscription;
        private bool disposed = false;

        /// <summary>
        /// Register store to have info about info about url format and deserialization for content
        /// </summary>
        public void RegisterStore(DocumentStore store)
        {
            parent.RegisterStore(store);
        }

        /// <summary>
        /// Use this function to attach Http diagnostic observer
        /// </summary>
        internal HttpDiagnosticSourceSubscriber(HttpClientDiagnosticObserver parent)
        {
            this.parent = parent;
            allListenersSubscription = DiagnosticListener.AllListeners.Subscribe(this);
        }

        /// <summary>
        /// This method gets called once for each existing DiagnosticListener when this
        /// DiagnosticListener is added to the list of DiagnosticListeners
        /// (<see cref="DiagnosticListener.AllListeners"/>). This method
        /// will also be called for each subsequent DiagnosticListener that is added to
        /// the list of DiagnosticListeners.
        /// <seealso cref="IObserver{T}.OnNext(T)"/>
        /// </summary>
        /// <param name="value">The DiagnosticListener that exists when this listener was added to
        /// the list, or a DiagnosticListener that got added after this listener was added.</param>
        public void OnNext(DiagnosticListener value)
        {
            if (value != null)
            {
                if (value.Name == "HttpHandlerDiagnosticListener")
                {
                    sourceSubscription = value.Subscribe(parent, (Predicate<string>)null);
                }
            }
        }

        /// <summary>
        /// Notifies the observer that the provider has finished sending push-based notifications.
        /// <seealso cref="IObserver{T}.OnCompleted()"/>
        /// </summary>
        public void OnCompleted()
        {
        }

        /// <summary>
        /// Notifies the observer that the provider has experienced an error condition.
        /// <seealso cref="IObserver{T}.OnError(Exception)"/>
        /// </summary>
        /// <param name="error">An object that provides additional information about the error.</param>
        public void OnError(Exception error)
        {
        }

        /// <summary>
        /// IDisposable implementation.
        /// </summary>
        public void Dispose()
        {
            Dispose(true);
            GC.SuppressFinalize(this);
        }

        /// <summary>
        /// IDisposable implementation.
        /// </summary>
        /// <param name="disposing">The method has been called directly or indirectly by a user's code.</param>
        protected virtual void Dispose(bool disposing)
        {
            if (!disposed)
            {
                if (disposing)
                {
                    if (sourceSubscription != null)
                    {
                        sourceSubscription.Dispose();
                    }

                    if (allListenersSubscription != null)
                    {
                        allListenersSubscription.Dispose();
                    }
                }

                disposed = true;
            }
        }
    }
}

Startup.cs

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
  ...
  var documentStore = new DocumentStore
  {
  ...
  }
  if (env.IsDevelopment())
  {
      MiniProfilerRavenDBIntegration.AttachTo(documentStore);
      MiniProfilerRavenDBIntegration.AttachTo(documentStore1);
      MiniProfilerRavenDBIntegration.AttachTo(documentStore2);
      MiniProfilerRavenDBIntegration.AttachTo(documentStoreN);
  }
}