Skip to content

Instantly share code, notes, and snippets.

@vlko

vlko/MiniProfilerRavenDBIntegration.cs

Created December 21, 2021 18:03
Show Gist options
  • Save vlko/708c046c547c6684c547154ebaa74f1f to your computer and use it in GitHub Desktop.
Save vlko/708c046c547c6684c547154ebaa74f1f to your computer and use it in GitHub Desktop.
Download ZIP
MiniProfiler RavenDB integration
Raw
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;
}
}
}
}
Raw
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);
}
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment