{"id":138,"date":"2014-06-26T09:31:50","date_gmt":"2014-06-26T07:31:50","guid":{"rendered":"http:\/\/ingeniarius.net\/blog\/?p=138"},"modified":"2014-07-11T10:06:49","modified_gmt":"2014-07-11T08:06:49","slug":"logging-entity-framework-6-queries-to-azure-tables","status":"publish","type":"post","link":"https:\/\/ingeniarius.net\/blog\/2014\/06\/logging-entity-framework-6-queries-to-azure-tables\/","title":{"rendered":"Logging Entity Framework 6 queries to Azure Tables"},"content":{"rendered":"

I wrote about Semantic Logging (SL) in MVC and after watching Rowan Miller`s video from Tech Ed 2014 <\/a>I decided to implement logging Entity Framework 6 queries to Azure Tables with EventSource (aka Semantic Logging \/ Structured Logging).<\/p>\n

 <\/p>\n

Motivation for logging Entity Framework 6 queries to Azure Tables<\/h2>\n

By MHO the motivation behind every logging system must include :<\/p>\n

    \n
  1. Finding and removing bugs which improves QoS and reduces Dev\/Ops time to resolve an issue.<\/li>\n
  2. Good structured log which enables a less proficient programmers to solve the problem. Better support devs => higher ops. costs.<\/li>\n
  3. Proactive response – get into action long before the client gets to you. Or even better – you call the client first.<\/li>\n
  4. Measuring and optimizing performance of your app. As Mark Simms and Chris Clayton say<\/a> that “premature optimization is the root of all evil.<\/strong>” is not so relevant when designing clod apps.<\/li>\n<\/ol>\n

    <\/p>\n

    <\/h2>\n

    Explanation<\/h2>\n

    Why so much “maintenance cost”? Because “maintenance cost” is the source of most of the cost of a big app and lowering it as much as possible is a key feature. That is why I consider the logging to be a key feature for every working program. When you do not have good logging ( and documentation ) in case of a failure or a bug you have to rely on the knowledge, of the internals of the application, that is inside the head of a few (some times just one) of your best developers which will not be around for 15 years probably. And 10+ years is the minimum lifespan of enterprise apps that I have encountered so far – desktop or web based.<\/p>\n

    What are the benefits of using EventSource for logging Entity Framework queries to Azure Tables compared to writing to file like in the video?<\/p>\n

    Why I do not like the idea of a log.txt?<\/p>\n

      \n
    1. Writing to log.txt places a file on each instance which makes it troublesome to get all the files from all instances and then combine them.<\/li>\n
    2. You have to first combine all the files from all your instances before you even start searching for particular queries.<\/li>\n
    3. You do not have structured logs but a bulk of text which makes searching cumbersome.<\/li>\n
    4. Searching through big txt log files is not a pleasure at all – wastes time of the administrator\/developer\/ops guy.<\/li>\n
    5. You have to do this every time you want to get all the logs and search for a problem or else.<\/li>\n
    6. You can not easily start SQL Profiler on Web Role. (On all your web roles? :))<\/span><\/li>\n
    7. I have personally used NLog for logging with a txt for web apps but when you go to multiple instances with great volume – it starts to become a burden rather then help.<\/li>\n<\/ol>\n

      Why I do like the idea of EventSource (ETW) with Azure Tables?<\/p>\n

        \n
      1. You have everything in one place right away.<\/li>\n
      2. You have it structured. For example – InstanceId, Query, Time, etc, …. however you like it.<\/li>\n
      3. You have tools to quickly and conveniently search Azure Tables. My favorite is Cerebrata\/RegGate Azure Management Studio<\/a>. But there are others free alternatives like Azure Storage Explorer<\/a><\/li>\n
      4. EventSource uses ETW<\/a> which is asynchronous and very fast. Why bother about that? Watch this video where\u00a0Mark Simms and Chris Clayton<\/a> explain such a case where the synchrony of the logging framework was overlooked. Simms advises against Log4Net or other logging libraries which can not log asynchronously.<\/li>\n
      5. If you use separate storage account for diagnostics (aka logging) you will hardly hit the limit of Azure Table – up to 20,000 per second.<\/a><\/li>\n<\/ol>\n

         <\/p>\n

        Implementation<\/h2>\n

        Without further ado lets get to the code.<\/p>\n

        First the not so interesting part – The DbContext and DbSets to work with :<\/p>\n

        public class ProductContext : DbContext\r\n{\r\n    public DbSet<Category> Categories { get; set; }\r\n    public DbSet<Product> Products { get; set; }\r\n    public DbSet<Supplier> Suppliers { get; set; }\r\n}\r\n\r\npublic class Category\r\n{\r\n   public int CategoryId { get; set; }\r\n   public string Name { get; set; }\r\n\r\n   public virtual ICollection<Product> Products { get; set; }\r\n}\r\n\r\npublic class Product\r\n{\r\n    public int ProductId { get; set; }\r\n    public string Name { get; set; }\r\n    public int CategoryId { get; set; }\r\n    public virtual Category Category { get; set; }\r\n}\r\n\r\npublic class Supplier\r\n{\r\n   [Key]\r\n   public string SupplierCode { get; set; }\r\n   public string Name { get; set; }\r\n}<\/pre>\n
        Now the logger itself :<\/p>\n
        public class EfLogger : EventSource, IEfLogger\r\n{\r\n    public static class Keywords\r\n    {\r\n        \/\/ only powers of 2 -> 1,2,4,8,16,32,64,128\r\n        public const EventKeywords All = (EventKeywords)2048;\r\n    }\r\n\r\n    public void LogQuery(string query)\r\n    {\r\n        LogQueryInternal(query);\r\n    }\r\n\r\n    [Event(100, Keywords = Keywords.All,Level = EventLevel.LogAlways)]\r\n    private void LogQueryInternal(string query)\r\n    {\r\n        if (this.IsEnabled())\r\n        {\r\n                WriteEvent(100, query);\r\n        }\r\n    }\r\n}\r\n\r\npublic interface IEfLogger\r\n{\r\n    void LogQuery(string query);\r\n}<\/pre>\n
        Why bother with the interface? You are probably going to drop it via DI<\/a> into your DbContext builder. I still have doubts about how to implement logging because it is a cross cutting concern as explained by M. Seeman in his book<\/a>: Drop it in over DI? Hide it behind static method? Mark the class with some passive attribute<\/a>? Implement it as a Castle Windsor Dynamic Proxy Interceptor<\/a>? It depends on the app \ud83d\ude42<\/p>\n
        Now the logger setup :<\/p>\n
        public class LoggerContainer\r\n{\r\n   private static readonly List<EventListener> Listeners = new List<EventListener>();\r\n\r\n    public static void SetupEntityFrameworkListener(IEfLogger efLogger)\r\n    {\r\n        try\r\n        {\r\n            EventSourceAnalyzer.InspectAll((EventSource)efLogger);\r\n        }\r\n        catch (EventSourceAnalyzerException eventSourceAnalyzerException)\r\n        {\r\n            string errorMsg = string.Format(\r\n                        \"Critical configuration error during event sources inspection. Exception Message : {0} StackTrace :{1} \",\r\n                        eventSourceAnalyzerException.Message,\r\n                        eventSourceAnalyzerException.StackTrace);\r\n            EventLog.WriteEntry(\"Event Sources Initialization\", errorMsg, EventLogEntryType.Error);\r\n        }\r\n        var listener = WindowsAzureTableLog.CreateListener(\r\n\"EfLog\",  \r\nConfigurationSettings.AppSettings[\"DiagnosticsConnectionString\"],\r\n\"EfLog\"\r\n);\r\n        Listeners.Add(listener);\r\n\r\n        listener.EnableEvents(\r\n            (EventSource)efLogger,\r\n            EventLevel.Informational,\r\n            EfLogger.Keywords.All);\r\n    }\r\n\r\n    public static void DisposeEventListener()\r\n    {\r\n        foreach (var eventListener in Listeners)\r\n        {\r\n           eventListener.Dispose();\r\n        }\r\n    }\r\n}<\/pre>\n
        Now a screenshot of the results :<\/p>\n
        \"Cerebrata<\/a>
        Cerebrata Table Broser – EntityFramework Log<\/figcaption><\/figure>\n
        You can download the source code here<\/a>. Do not forget to restore NuGet packages and build.<\/p>\n
         <\/p>\n
        Resources<\/h2>\n
          \n
        1. http:\/\/msdn.microsoft.com\/en-us\/data\/dn469464.aspx<\/a><\/li>\n
        2. http:\/\/blog.oneunicorn.com\/2013\/05\/08\/ef6-sql-logging-part-1-simple-logging\/<\/a><\/li>\n
        3. http:\/\/channel9.msdn.com\/Events\/Build\/2014\/3-633<\/a><\/li>\n
        4. http:\/\/jpreecedev.com\/2013\/11\/13\/exploring-logging-in-entity-framework-6\/<\/a><\/li>\n
        5. http:\/\/ppe.blogs.msdn.com\/b\/windowsazure\/archive\/2012\/11\/02\/windows-azure-s-flat-network-storage-and-2012-scalability-targets.aspx<\/a><\/li>\n
        6. http:\/\/stackoverflow.com\/questions\/14443081\/azure-table-storage-transaction-limitations<\/a><\/li>\n<\/ol>\n","protected":false},"excerpt":{"rendered":"
          I wrote about Semantic Logging (SL) in MVC and after watching Rowan Miller`s video from Tech Ed 2014 I decided to implement logging Entity Framework 6 queries to Azure Tables with EventSource (aka Semantic Logging \/ Structured Logging).   Motivation for logging Entity Framework 6 queries to Azure Tables By MHO the motivation behind every… Continue reading Logging Entity Framework 6 queries to Azure Tables<\/span><\/a><\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[8,16,15],"tags":[],"aioseo_notices":[],"_links":{"self":[{"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/posts\/138"}],"collection":[{"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/comments?post=138"}],"version-history":[{"count":36,"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/posts\/138\/revisions"}],"predecessor-version":[{"id":169,"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/posts\/138\/revisions\/169"}],"wp:attachment":[{"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/media?parent=138"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/categories?post=138"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/ingeniarius.net\/blog\/wp-json\/wp\/v2\/tags?post=138"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}