Recent posts about LINQ and related topics - Page 1 by ThinqLinq

Reactive Translator for RxJs

For several years, I’ve been demonstrating using Reactive Extensions to handle taking user input and providing real time translations into multiple languages. This code sample has been so popular that even Soma posted an example using the Bing translator in his introducing Rx post. In most cases, they only issue a single request or issue multiple individual requests for multiple languages. To add a bit of fun to my demo, I decided to spice it up a bit and turn the list of destination languages into another observable that I can join with as well. I’ve had this sample available in my Rx downloads for some time including one for RxJs, but haven’t updated them to newer versions (curently 2.2.2) until now. I figured it was about time that I shared my version.

To begin, let’s create a UI. We’ll keep it simple to allow us to focus on the code that comes later:

    <input type="text" id="TextToTranslate" size="80" />

    <div id="output">
    </div>

As they say at Staples, “That was easy.”

Next comes the fun part. Before you can do anything though, you do need to sign up to get a free Bing App ID. I’m not going to share mine Winking smile. Once you have that, your ready to code. But what are we going to do in our code? This example combines three observable sequences: User key presses, destination languages, and service request/responses. In order to work with the observables and to make it easy to work with our DOM, we need to start by importing two JavaScript libraries: jQuery and Rx (we only need the rx.lite.js version for this example).

    <script type="text/javascript" src="Scripts/jquery-2.1.0.js"></script>
    <script type="text/javascript" src="Scripts/rx.lite.js"></script>

Of our three observables, the second one is the easiest, so let’s get it out of the way first. To turn an array of languages into an observable sequence, we use the fromArray generator on a simple JavaScript array.

var destLanguages = ["de", "es", "zh-CHT", "fr", "it", "ar", "ht", "tlh"];
var languagesObs = Rx.Observable.fromArray(destLanguages);

With that out of the way, Let’s take a look at how we are going to issue the service requests to Bing and turn them into an observable stream. We’ll use the jQuery ajax method to issue our request to the Bing translator using jsonp and pass in the required app id, destination language (to), source language (I speak American English, so ‘from’ is ‘en-us’) and the text we want to translate (text). We can then use JavaScript promise to access this invoker and use RxJs’s fromPromise to turn it into an observable stream that returns the string result.

var translate = function (text, lang) {
    var p = { appId: appId, to: lang, from: 'en-us', text: text };
    var promise = $.ajax({
        url: 'http://api.microsofttranslator.com/V2/Ajax.svc/Translate',
        data: p,
        dataType: 'jsonp',
        jsonp: 'oncomplete',
    }).promise();
    return Rx.Observable.fromPromise(promise);
};

Now that we have these two observables, we need to wire this up with the user’s key presses. Instead of going on and on about each step, here’s the code in it’s glory detail annotated with what each line is doing.

// Get the keypresses
var textInputDetected = Rx.Observable.fromEvent($("#TextToTranslate"), 'keyup')
    // Wait for 1/2 second to see if they're still typing
    .throttle(500)
    // They're done typing. Clear the last output
    .do(function (_) { $("#output").empty(); })
    // Get the input string
    .select(function () { return $("#TextToTranslate").val(); })
    // If it's the same as the last one, don't re-issue the request
    .distinctUntilChanged()
    // Merge the search string with the list of languages
   .selectMany(function (text) {
        return languagesObs.select(function (t1) { return { source: text, dest: t1 }; });
    })
    // Call the service passing the source string and destination language
   .selectMany(function (sourceDest) {
       return translate(sourceDest.source, sourceDest.dest)
            // Return the destination language and translated result from the service
            .select(function (result) { return { dest: sourceDest.dest, translation: result }; });
    });

d = textInputDetected.subscribe(function (x) {
        // Add the result to the list
        $("#output").append(x.dest + ' : ' + x.translation + '<br />');
    },
    function (err) {
        // In case of an error, show the error
        $("#output").append(err + '<br />')
    });

We start by getting the keyup events for the input textbox and turning that into an observable stream (using fromEvent). This is an expensive service operation, so we throttle the request for 1/2 of a second before continuing to let the user finish typing. There’s no reason to send each keypress through the translator. The do method allows us to cause side effects, in this case to clear the last translated results if any exist. We then transform (using select or map) the result to get the user’s supplied text and pass that as the resulting stream. Similar to throttle, we also want to make sure that the user hasn’t just entered the same value twice which would result in the same translation results. We optimize our requests by not reissuing the request using distinctUntilChanged.

The fun stuff comes next. Here we start to merge our observables using selectMany (or flatMap) to match up the input text with the observable list of destination languages. Once we have that, we selectMany again, this time passing in the source string and destination language into the translate method that returns the observable string result and based on that result, we project out the result along with the enclosing destination language.

To conclude, we subscribe to the end observable stream and either append the result to the output list in the case of onNext, or append the error message for onError. Since this is set up over observables, the user can just start typing another string and the process will react to the request all over again. To put this all together, here is the complete code. Remember to get your AppId before you use it because the one I’m showing here won’t work.

    <input type="text" id="TextToTranslate" size="80" />

    <div id="output">
    </div>

    <script type="text/javascript" src="Scripts/jquery-2.1.0.js"></script>
    <script type="text/javascript" src="Scripts/rx.lite.js"></script>
    <script type="text/javascript">
        var appId = "GetYoursAt http://www.bing.com/developers/appids.aspx";
        var destLanguages = ["de", "es", "zh-CHT", "fr", "it", "ar", "ht", "he", "ja", "ko", "no", "ru", "th", "tlh"];

        (function ($) {

            var translate = function (text, lang) {
                var p = { appId: appId, to: lang, from: 'en-us', text: text };
                var promise = $.ajax({
                    url: 'http://api.microsofttranslator.com/V2/Ajax.svc/Translate',
                    data: p,
                    dataType: 'jsonp',
                    jsonp: 'oncomplete',
                }).promise();
                return Rx.Observable.fromPromise(promise);
            };

            // Turn the language array into a cold observable for the selectMany below
            var languagesObs = Rx.Observable.fromArray(destLanguages);

            // Get the keypresses
            var textInputDetected = Rx.Observable.fromEvent($("#TextToTranslate"), 'keyup')
                // Wait for 1/2 second to see if they're still typing
                .throttle(500)
                // They're done typing. Clear the last output
                .do(function (_) { $("#output").empty(); })
                // Get the input string
                .select(function () { return $("#TextToTranslate").val(); })
                // If it's the same as the last one, don't re-issue the request
                .distinctUntilChanged()
                // Merge the search string with the list of languages
                .selectMany(function (text) {
                    return languagesObs.select(function (t1) { return { source: text, dest: t1 }; });
                })
                // Call the service passing the source string and destination language
                .selectMany(function (sourceDest) {
                    return translate(sourceDest.source, sourceDest.dest)
                        // Return the destination language and translated result from the service
                        .select(function (result) { return { dest: sourceDest.dest, translation: result }; });
                });

            d = textInputDetected.subscribe(function (x) {
                    // Add the result to the list
                    $("#output").append(x.dest + ' : ' + x.translation + '<br />');
                },
                function (err) {
                    // In case of an error, show the error
                    $("#output").append(err + '<br />')
                });
            
        })(jQuery);

    </script>

Thinq you can improve on this sample, let me know.

Posted on - Comment
Categories: RxJs - JavaScript - Rx -

Tools and Apps

Now that I’ve been at Slalom Consulting for 3 years, it’s about time for a hardware refresh. In preparation for that, and inspired by the recent list by Rocky Lhotka of top Win8/RT apps, I thought I would share the list of software/tools that I have found indispensible over the last several years creating software for customers. This is by no means as extensive as the impressive list of tools that Scott Hanselman puts out each year. A while back, I published a list of LINQ tools if you’re looking for some of those.

This list is primarily intended as a list to help me when I build my next laptop and offered here in case you find it helpful as well. It is by no means an endorsement of any specific product and I’m not paid to publish any of these. Feel free to add to this list in the comments as I may well have forgotten something along the way.

System apps and tools

Windows Home Server I use this to seamlessly backup all of the computers on my home network. It’s saved my rear multiple times and makes trying out new builds of Windows and other applications a painless task. I’m still using the original version and it’s been grinding along smoothly for years now.
Windows Live Writer The best tool I’ve found for offline creating/editing of blog posts. So great, I’m using it to write this post.
Paint.Net Impressive free image editor that includes many of the features of Photoshop without the license costs. Includes multiple layers and special effects.
WinDirStat Do you ever wander what’s taking up so much space on your drives? WinDirStat is a nifty way to visualize your space usage and can break it down by folder/file type/etc. It’s an easy way to find those screen capture videos, vhd images, and audio files that can get scattered around the drive over time.
TouchFreeze This simple utility blocks the annoying mouse jump that can happen if your thumb accidently brushes the touchpad while typing.
Syncfusion Metrostudio Over 2500 metro-style icon templates that are free (in exchange for giving them your email address that they will use to spam up) and customizable either as XAML or png images. I’ve used these a number of times when needing an icon for a customer and changed the colors to match their brand.
FileZilla The best free FTP client I’ve found yet.
EasyBCD GUI to manage your boot image. Helps out in a pinch when the boot sector gets corrupted or you want to configure dual boot to a VHD image for testing new OS images. It has a free non-commercial version as well as a minimal cost commercial version.
Oracle VirtualBox Free virtual machine tool. I’ve found this to be lighter weight and easier to configure than HyperV or VmWare. I’m sure there are features that it doesn’t include, but so far I haven’t had the need for the bigger tools except for running the Windows Phone emulator which does require HyperV.
ProcessMonitor Low level debugging tool for when you want to see in minute detail what your drives are doing. The information that it provides can be overwhelming, but I’ve found it useful for tracking down pesky file not found issues where a system is looking for a file in a different path than where it actually exists.
Metrotwit This has been my go-to twitter client for years. Unfortunately due to Twitter’s access token limit, they recently announced that they will no longer support new users or upgrades. I may have to switch back to Tweetdeck or Tweetium once the new computer comes but wanted to leave this on my list in tribute to the app that was.
Foxit Reader Much smaller and faster than Adobe Reader. Handles 95% of my pdf reading needs with less overhead.

Development Tools

Visual Studio The best development IDE out there. I spend most of my time working in the .Net world, but have had to work with a couple others including Eclipse and am much happier and productive with VS than the other tools.
SQL Server Management Tools These are the tools for working with SQL Server including SSMS/ SSDT/ SQL Profiler and Tuning Advisor.
LINQPad Any time I want to test out some code snippets but don’t want to crank up a new project and build a UI, I reach out for LINQ Pad. We liked it so much that we published all of the LINQ in Action samples for you to use in LinqPad.
ILSpy Although not as full featured as the no longer free Reflector, I reach out to the open-source .NET assembly browser and decompiler, ILSpy whenever I want to know how a .Net DLL works under the covers and I don’t have access to the original source code.
WebMatrix If I’m doing a simple site and don’t need the full Visual Studio experience, I often reach out to the free WebMatrix as a web development sandbox.
Dependency Walker This simple tool lets you check the project dependencies of compiled modules which is helpful when trying to understand how existing systems are constructed so that we can try to extend them with additional functionality.
Tortoise SVN If I’m doing work for a client that uses SVN as their source repository, I often use this to integrate the source repository directly into windows explorer.
GitHub for Windows The easiest way to get started with GitHub on Windows computers without the need to fumble around with the command line.
Fiddler Anytime I need to sniff web requests or test services, Fiddler is my tool of choice. Not only are you able to see the requests and responses, but you can easily create new ones by dragging a previous request to the compose tab and modifying the URI/header/footers to meet your needs and issue the request directly without needing to mess with a browser.
WinMerge Often I need to compare files or directories to merge them between different versions. There are a number of diffing tools, but this one lets you quickly diff and merge them.

Visual Studio Extensions

I typically do not install many extensions including the popular CodeRush, Resharper, or JustCode because I’m frequently giving presentations and attendees often are more focused on the plug in tools that I’m using than the task at hand. As a result, I typically use a cleaner install of Visual Studio with just a handful of useful tools.

Nuget If you’re using Visual Studio and haven’t heard of Nuget, you’ve probably been living under a bridge for the last couple of years. NuGet is the way to manage external packages for your applications. Increasingly, parts of .Net including MVC, Entity Framework, Web API, and others are being distributed through NuGet rather than as part of large .Net version upgrades. It’s a must have extension for Visual Studio at this point.
Web Essentials Adds extensions into the web tools (including Html, javascript, css) that they couldn’t fit into the typical product cycles. There are versions for 2010, 2012, and 2013.
Chutzpah Test Runner Visual Studio plug in that allows you to run JavaScript QUnit, Jasmine, and Mocha unit tests the same way you run your MSTest/XUnit tests for .Net code—directly within Visual Studio. Also allows you to debug the JavaScript unit tests quickly and easily.
CssCop Integrates the CSSLint style checker into Visual Studio to help writing better CSS catching common errors that affect browser compatibility.
Azure SDK Tools and SDK’s for working with Azure services.
Fody Simple tool to weave code into your build process. In particular, I use this to add INotifyPropertyChanged events into POCO classes.
Posted on - Comment
Categories: Visual Studio -

Left Outer Joins in LINQ with Entity Framework

As I spend more time reviewing code with clients and on public forums, I’m constantly seeing cases where people have issues with Outer joins in LINQ and the various flavors of LINQ. In this post, I’m going to look at a couple options from a syntax perspective that you can use to make working with outer joins easier with LINQ. Naturally, we have a much deeper discussion of outer joins in our book that you’re welcome to dig into as well.

Typically, if you do a join in LINQ, it will perform an inner join where it only returns the records that contain results in both sides of the evaluation (in both tables). If a child table doesn’t have a record for a parent row, that result will be excluded. Consider the case in Northwind where an Order record exists, but there are no order detail lines. The following LINQ query won’t return that record as part of its result set:

from o in Orders
join od in OrderDetails on o.OrderID equals od.OrderID
select new {o, od}

This translates into the following SQL statement (Note to DBA’s that are concerned by the * below: EF does list the individual columns in the actual SQL. I’m reducing them to * for the purposes of this post to focus on the join clauses):

SELECT 
    [Extent1].*, [Extent2.*
FROM  [dbo].[Orders] AS [Extent1]
    INNER JOIN [dbo].[OrderDetails] AS [Extent2] ON [Extent1].[OrderID] = [Extent2].[OrderID]

If you want to include the orders regardless of whether it has any detail lines, you would need to turn this inner join into an outer join using the DefaultIfEmpty extension method. LINQ only supports left outer joins. If you want a right outer join, you need to flip the logic of your query to turn it into a left outer join. In order to use the DefaultIfEmpty, you typically need to push the joined set into a temporary value first and then select from it using the DefaultIfEmpty method:

from o in Orders
join innerOD in OrderDetails on o.OrderID equals innerOD.OrderID into Inners
from od in Inners.DefaultIfEmpty()
select new {o, od}

This generates the expected LEFT outer join as shown below:

SELECT 
    [Extent1].*, [Extent2].*
FROM  [dbo].[Orders] AS [Extent1]
    LEFT OUTER JOIN [dbo].[OrderDetails] AS [Extent2] ON [Extent1].[OrderID] = [Extent2].[OrderID]
The problem that I have with this is that the syntax seems overly verbose to accomplish this change. As is often the case, Microsoft often gives multiple ways to accomplish the same goal. One method that I’ve started to find helpful is to revert to more of an ANSI 82 style syntax where the joins were accomplished in a where clause instead of a join clause. By mixing and matching the LINQ query comprehensions and lambda syntax, we can restate the above query as follows:
from o in Orders
from od in OrderDetails
    .Where(details => o.OrderID == details.OrderID)
    .DefaultIfEmpty()
select new {o, od}

If we check the SQL, we can see that this generates the same SQL as the more verbose version above. Often when I’m doing this in application code, I’ll put the where and DefaultIfEmpty on the same line to let me focus on what I’m fetching from, not how I’m joining them unless I need to focus on that.

There is an issue with using this syntax when joining nullable values or strings. Since the where statement doesn’t know about the cardinality relationship (1-Many, 0-1 – Many, etc), Entity Framework adds an additional check where the nullable value is not null to allow for join cases where both sides have a null value. Changing our query to use Northwind’s Customers and Orders which joins on the string CustomerID values, we can write the following LINQ query which is nearly identical to the one we created before for Orders and OrderDetails:

from c in Customers
from o in Orders
    .Where (o => o.CustomerID == c.CustomerID)
    .DefaultIfEmpty()
select new {c, o};

This results in the following SQL statement.

SELECT 
    1 AS [C1], 
    [Extent1].*, [Extent2}.*
    FROM  [dbo].[Customers] AS [Extent1]
    LEFT OUTER JOIN [dbo].[Orders] AS [Extent2] ON ([Extent2].[CustomerID] = [Extent1].[CustomerID])
       AND ([Extent2].[CustomerID] IS NOT NULL)

Note that in this case, we have an additional clause checking for Extent2.CustomerID IS NOT NULL. This may seem innocuous, but I have found in at least one case for the query execution to be significantly slower due to the use of an index scan rather than an index seek caused by this clause. Here you have to be careful when crafting your queries and monitor performance even more carefully to avoid performance bottlenecks unnecessarily.

While this version works better, I still prefer to use associations rather than joins to think about the problem from more of an object graph perspective rather than set based operations. As long as you have a natural association between the entities I much prefer using the associations to navigate through than to have to worry about building out the joins manually each time. We can restate our join even more simply as follows using associations:

from o in Orders
from od in o.Order_Details.DefaultIfEmpty()
select new {o, od}

Note that if you omit the DefaultIfEmpty clause, you would get an Inner join rather than left outer join.

If you have other ways of creating outer joins in LINQ that you prefer, let me know what you thinq.

Posted on - Comment
Categories: C# - Entity Framework - LINQ -

Custom Logging with Entity Framework EF6

Coming from LINQ to SQL, I’ve long been a fan of its logging simplicity where you just set the context.log to a stream (console.out) to see the stream of sql statements being issued to the database. Prior to EF6, this has been a rather frustrating omission that has finally been rectified with EF 6. Now, you can log SQL statements just as simply, but with a slightly different implementation. In EF, you set the DbContext’s Database.Log property to an Action delegate that takes a string as input parameter. Thus to log requests to the Diagnostics Trace implementation, you simply set the following:

context.Database.Log = Sub(val) Diagnostics.Trace.WriteLine(val)

This is fine as long as you are willing to accept the default logging implementation. If you want to customize the log output, things get a bit trickier. In my example, I only want to log the calling method and elapsed time that the query took to execute. I’m not as concerned in my current need for the SQL string, but that is easily included as I’ll point out below.

To start, I need to set the calling method from my code that I’ll be able to access in the logging implementation. Since the calling code is actually in ASP.Net Web API calls returning IQueryables, and the database is not being executed until long after my application code has completed. I need to explicitly identify the application calling method rather than the last method from the call stack which would otherwise be one of the Web API internal methods. To handle this and centralize my set-up logic for the context, I’ll create a factory method which configures the context and use that instead of relying on the context’s constructor. Thanks to partial classes, I can extend the generated entity class and include this new property and factory constructor. To make matters even easier, I’ll take advantage of the CallerMemberName attribute to automatically pull the member name from the method that is calling the factory.

Public Class NorthwindEfEntities

    Public Shared Function ContextFactory(<CallerMemberName> Optional memberName As String = "") As NorthwindEfEntities
        Dim context = New NorthwindEfEntities()
        context.CallingMethod = memberName
        context.Database.Log = Sub(val) Diagnostics.Trace.WriteLine(val)
        Return context
    End Function

    Public Property CallingMethod As String

End Class

Now, to create the context we call this new ContextFactory method, but don’t pass the memberName explicitly. The compiler will add that for us automatically.

    Public Function GetCustomers() As IQueryable(Of DTO.DtoCustomer)
        cn = NorhwindEfEntities.ContextFactory
        ' Do some amazing query and return it.
   End Function

Now that we’ve set up the logger, we need to customize the output that is generated. To do this, we need to add a new class that derives from DatabaseLogFormatter (in the System.Data.Entity.Infrastructure.Interception namespace). If you don’t have this namespace, you may need to upgrade to EF6 on order to access the logging functionality. Since the base class doesn’t have a default parameterless constructor, we need to make a new one and simply delegate to the base implementation. With that out of the way, we can supply our own logging. The base implementation gives us hooks to the following interception points.

Method Description
LogCommand Writes the SQL Statement to the action implementation prior to executing the statement
LogResult Writes when the SQL statement has completed
LogParameter Writes the parameter(s) used in the query
Executing/Executed Called before and after the database request is made
NonQueryExecuting/NonQueryExecuted Called for queries that don’t return results (insert/update/delete and non-result return stored procedures)
ReaderExecuting/ReaderExecuted Called for queries that return tabular data results (select)
ScalarExecuting/ScalarExecuted Called for queries that return single value results (user defined functions)
Write Base write implementation that each of the loggers use to format the output.

As stated before in our example, we want to write a log entry when the command completes including the calling method name and execution time. To do this we need to perform the following adjustments to the base implementation: 1) suppress logging the SQL statements in the LogCommand method by simply creating a noop and not delegating to the base implementation, and 2) replace the default result log information with our custom output in the LogResult method. To get the elapsed time, we directly leverage the Stopwatch property of the base class. Here then is our new custom formatter.

Imports System.Data.Entity.Infrastructure.Interception
Imports System.Data.Entity

Public Class CustomDbLogFormatter
    Inherits DatabaseLogFormatter

    Public Sub New(context As DbContext, writeAction As Action(Of String))
        MyBase.New(context, writeAction)
    End Sub

    Public Overrides Sub LogCommand(Of TResult)(command As Common.DbCommand, interceptionContext As DbCommandInterceptionContext(Of TResult))
        'MyBase.LogCommand(Of TResult)(command, interceptionContext)
    End Sub

    Public Overrides Sub LogResult(Of TResult)(command As Common.DbCommand, interceptionContext As DbCommandInterceptionContext(Of TResult))

        Dim context = interceptionContext.DbContexts.OfType(Of NorthwindEfEntities).FirstOrDefault()
        If context IsNot Nothing Then
            Trace.WriteLine(context.CallingMethod + " Completed in " + Stopwatch.ElapsedMilliseconds.ToString)
        End If
   
    End Sub
End Class

One step remains in order for this new logging implementation to take effect. We need to register the custom logger in our solution. To do this manually in code, we create a new class and derive from DbConfiguration. Then in the constructor, call the base class’s SetDatabaseLogFormatter to set the formatter to our new CustomDbLogFormatter. For more information on configuring the logging via your config file rather than in code, see AJ Vicker’s post today on EF 6.1 turning on SQL logging without recompiling your app.

Public Class LogConfiguration
    Inherits DbConfiguration

    Public Sub New()
        SetDatabaseLogFormatter(Function(context, action) New CustomDbLogFormatter(context, action))
    End Sub
End Class

Naturally, the value that we are outputting is just an example, you’re free to make your logging as complex as you want given these basic building blocks. For more details, make sure to read the EF team’s posts on the logging implementation.

Posted on - Comment
Categories: Entity Framework - VB Dev Center -

Logging ASP.Net WebApi elapsed time for IQueryables

I’ve recently been doing a fair amount of work with exposing queryable structures using ASP.Net Web API. In a nutshell, Web API allows you to expose not only the data from a service request, but also the query structure that can be extended. By default, the Web API scaffolding generates Get(id), Get, Post, Put and Delete methods. Of these, the most interesting, from a query perspective, is the Get method that returns a list of values:

    Public Function GetCustomers() As IEnumerable(Of Customer)
        Dim query = cn.Customers
        Return query
    End Function

By returning the default IEnumerable, the database will return everything that matches the service query definition and the consuming application isn’t able to customize this view to meet their needs. If you apply a couple changes, you can enable much greater service flexibility and allow customers to access your resources the way they want rather than just the way you originally intended. Of course with great power comes great responsibility. To make our GetCustomers method queryable, we simply change the output type from IEnumerable to IQueryable.

    Public Function GetCustomers() As IQueryable(Of Customer)
        Dim query = cn.Customers
        Return query
    End Function

In addition, we need to enable the query support for Web API in the Web Api Config’s Register method in the App_Start folder:

Public Module WebApiConfig
    Public Sub Register(ByVal config As HttpConfiguration)
        ' Web API configuration and services

        ' Web API routes
        config.MapHttpAttributeRoutes()

        config.Routes.MapHttpRoute(
            name:="DefaultApi",
            routeTemplate:="api/{controller}/{id}",
            defaults:=New With {.id = RouteParameter.Optional}
        )
        config.EnableQuerySupport()
        
    End Sub
End Module

Now, if we run the service, we can not only get the full list of Customers, but also add querying options like filter (where), orderby, top, skip, etc. For example, the following query gets the first two customers from London ordered by the Company Name. For a complete list of the various url query options, refer to the OData Query Specification URI Convention page.

http://localhost:17413/api/Customer?$filter=City%20eq%20'London'&$orderby=CompanyName&$top=2

Now, how does this fit with the question of logging the requests? If we were to use a traditional logging mechanism, we could just wrap the beginning and end of the service request with a timer and output the difference.

    Public Function GetCustomers() As IQueryable(Of DTO.DtoCustomer)
        Dim sw = New Stopwatch
        sw.Start()

        Dim query = cn.Customers
        sw.Stop()
        System.Diagnostics.Trace.WriteLine("GetCustomers completed in " + sw.ElapsedMilliseconds.ToString)

        Return query
    End Function

This outputs the result: “GetCustomers completed in 1”. Why is the time to execute so short? Remember that with LINQ, the database request is deferred until the results are iterated over (GetEnumerator). In the case of an IQueryable with WebAPI, the query isn’t executed until after our code has returned the base query and WebAPI has had a chance to add on any query parameters that the user supplied. We no longer have access to the query pipeline to hook into, right?

Adding tracing

Not exactly, Mike Wasson pointed out that there is a TraceWriter implementation that you can leverage and extend to hook into the Web API pipeline. For more information, see his article on Tracing in ASP.Net Web API.

In our example, we can output all of the tracing messages as follows. One thing to watch here is that the Kind and Operation are not set until the traceAction is executed, thus you need to execute the action prior to logging the details.

Imports System.Web.Http.Tracing Imports System.Diagnostics Public Class ServiceTracer Implements ITraceWriter Public Sub Trace(request As Net.Http.HttpRequestMessage,
category As String,
level As System.Web.Http.Tracing.TraceLevel,
traceAction As Action(Of TraceRecord)) Implements ITraceWriter.Trace

Dim rec = New TraceRecord(request, category, level) traceAction(rec) System.Diagnostics.Trace.WriteLine(String.Format("{0} - {1} {2} - {3}", category, level, rec.Kind, rec.Operation)) End Sub End Class

We then need to register this implementation with the WebAPI configuration (again in WebApiConfig):

Public Module WebApiConfig
    Public Sub Register(ByVal config As HttpConfiguration)
        ' Web API configuration and services

        ' Web API routes
        config.MapHttpAttributeRoutes()

        config.Routes.MapHttpRoute(
            name:="DefaultApi",
            routeTemplate:="api/{controller}/{id}",
            defaults:=New With {.id = RouteParameter.Optional}
        )
        config.EnableQuerySupport()
        config.Services.Replace(GetType(ITraceWriter), New ServiceTracer)

    End Sub
End Module

If we run our solution again and access our service, we should see the following in the output window:

System.Web.Http.Request - Info  Begin - 
System.Web.Http.Controllers - Info  Begin - SelectController
System.Web.Http.Controllers - Info  End - SelectController
System.Web.Http.Controllers - Info  Begin - CreateController
System.Web.Http.Controllers - Info  Begin - Create
System.Web.Http.Controllers - Info  End - Create
System.Web.Http.Controllers - Info  End - CreateController
System.Web.Http.Controllers - Info  Begin - ExecuteAsync
System.Web.Http.Action - Info  Begin - SelectAction
System.Web.Http.Action - Info  End - SelectAction
System.Web.Http.ModelBinding - Info  Begin - ExecuteBindingAsync
System.Web.Http.ModelBinding - Info  End - ExecuteBindingAsync
System.Web.Http.Filters - Info  Begin - OnActionExecutingAsync
System.Web.Http.Filters - Info  End - OnActionExecutingAsync
System.Web.Http.Action - Info  Begin - InvokeActionAsync
System.Web.Http.Action - Info  Begin - ExecuteAsync
System.Web.Http.Action - Info  End - ExecuteAsync
System.Net.Http.Formatting - Info  Begin - Negotiate
System.Net.Http.Formatting - Info  Begin - GetPerRequestFormatterInstance
System.Net.Http.Formatting - Info  End - GetPerRequestFormatterInstance
System.Net.Http.Formatting - Info  End - Negotiate
System.Web.Http.Action - Info  End - InvokeActionAsync
System.Web.Http.Filters - Info  Begin - OnActionExecutedAsync
System.Web.Http.Filters - Info  End - OnActionExecutedAsync
System.Web.Http.Controllers - Info  End - ExecuteAsync
System.Web.Http.Request - Info  End - 
System.Net.Http.Formatting - Info  Begin - WriteToStreamAsync
System.Net.Http.Formatting - Info  End - WriteToStreamAsync
System.Web.Http.Controllers - Info  Begin - Dispose
System.Web.Http.Controllers - Info  End - Dispose

Boy, that’s a lot of information, but not quite what we want. If you scan through this list, you can see that WebAPI essentially gives us hooks before and after each operation that it does, including selecting the controller from the request URI, serializing any input/body parameters, executing the service, getting the output formatter, formatting the output, and writing the response. In our case, all we want is to log which method was called and how long it took to execute. Instead of wrapping a stopwatch around the beginning and end of our query definition as we did before, we need to find the time difference between the beginning and end of the service request. Given the trace list above, we can see that we can catch the begin SelectAction operation and the corresponding End Dispose operation and log that.

For the solution, we need to set-up a list of TraceRecord objects that we can use to correlate the start and end operations. We’ll use a private items variable to track the start requests. In the write trace method, we can check the Kind and Operation to add the record for the Begin of the SelectAction operation. We also check for the End Dispose operation to write the timings. In the end method, we need to find the item based on the supplied RequestId. (Remember, WebAPI may have multiple service requests executing simultaneously with a single trace writer instance, so you have to take care to get the correct start and end.) The TraceRecord already has a convenient TimeStamp property which is set when the traceAction is executed.  We simply calculate the difference between the start and end timestamps to output the total execution time. After we output the log record, we make sure to remove the starting trace record from the items list to clean up after ourselves. Below is our revised implementation of the trace writer to log the total execution time for the request.

Public Class ServiceTracer Implements ITraceWriter Dim items As New List(Of TraceRecord) Public Sub Trace(request As Net.Http.HttpRequestMessage,
category As String,
level As System.Web.Http.Tracing.TraceLevel,
traceAction As Action(Of TraceRecord)) Implements ITraceWriter.Trace

Dim rec = New TraceRecord(request, category, level) traceAction(rec) WriteTrace(rec) End Sub Private Sub WriteTrace(rec As TraceRecord) If rec.Kind = TraceKind.Begin AndAlso rec.Operation = "SelectAction" Then items.Add(rec) End If If rec.Kind = TraceKind.End AndAlso rec.Operation = "Dispose" Then WriteServiceEnd(rec) End If End Sub Private Sub WriteServiceEnd(rec As TraceRecord) Dim start = items.Find(Function(r) r.RequestId = rec.RequestId) If rec.Request IsNot Nothing AndAlso start IsNot Nothing Then System.Diagnostics.Trace.WriteLine(String.Format("{0} - {1}: elapsedTime={2}", Now, rec.Request.RequestUri.PathAndQuery, (rec.Timestamp - start.Timestamp).TotalMilliseconds)) items.Remove(start) End If End Sub End Class

Posted on - Comment
Categories: Entity Framework -