Sunday, November 10, 2013

Tetris in SSMS - Part 1

Part of my "hacker nature" is to find creative and unusual ways to do things.  This expands my creative thinking and teaches me deeper concepts about the tools and languages I use.  Today I had the idea of trying to implement the game of Tetris in SQL Server, specifically through the use of SSMS. Tetris is sort of my go-to game for a creative challenge, having made a Tetris clone in Excel once already.

It's not so hard as it may sound if you break it down.  The key components of a game are as follows:

  • Output
  • Input
  • Logic
  • Data Storage
Output, data storage, and logical processing are pretty straightforward in SQL Server.  The tricky part is input - as well as getting interactive output rather than just static results from a query.  I'll start by attacking the latter - a means of interactive and dynamic output.  Instead of using SQL-based output, I'm going to use text output, by using the "Results to Text" option in SSMS.  Then getting interactive output means using print statements to display the current state of the game.

How do you update the state of the game?  You can simply print out a bunch of blank lines to shift everything up, and then reprint the next state.  To get timer-based event loop, use the WAITFOR command to introduce a half-second or so delay between frames.  If you do this, you will find a problem - the output doesn't display immediately.  Even if you print a bunch of output, do a WAITFOR, print more output, WAITFOR again, and then finally some output and finish the query, you'll see that nothing displays until the entire query is finished processing.  There is a trick to flush the output buffer - by raising a level-0 error:

raiserror('',0,1) with nowait --to flush the buffer
waitfor delay '00:00:10'      --pause for 10 seconds

This basically solves the problem of output - create a continuous loop that prints out the board state and has a delay.  The downside is an ever-growing output buffer which may eventually crash SSMS once it reaches the limit of available memory.  You may have to restart the output cycle from time to time to prevent reaching this limit.

Getting input is quite a bit trickier.  I explored a number of different options, including running queries in a separate tab, and using macros.  The best solution I've come up with is to have an entirely separate SSMS window open for input (works best with multiple monitors), so that you can interact with the second session while leaving the output screen running constantly.  To get somewhat interactive input, I've opted to make use of the Query Shortcuts feature, found in Tools -> Options -> Environment -> Keyboard -> Query Shortcuts.  This allows you to define something like a macro, in the form of a SQL command that runs when you hit the predefined key CTRL+1 through 9.

The key inputs for Tetris are moving the piece left, right, and down, dropping the piece to the bottom, and rotating left and right.  This would require a total of 6 macros, which can be handled by 6 stored procedures to implement the logic.  If the game state is stored in a table which is shared by the two SSMS sessions, then the output will update live as the macros are executed.  All that remains is to implement the logic for displaying the game and processing the input.  I will leave that for Part 2.

Happy Programming!

Saturday, November 9, 2013

What happens with Path System Variable is too long?

Nothing is more disconcerting than an error message when attempting to use basic Windows features.  I was greeted this morning by an error when trying to open SSMS 2012 after I just installed it: "Exception has been thrown by target of an invocation."  Googling the error didn't return much helpful information except to suggest that I needed to adjust my PATH system environment variable.  So I decided the next best thing would be to review my path variable.

In Windows 7, the standard way I get to environment variables is through the "Advanced System Settings" option in Computer -> Properties:


Imagine my surprise when I get this instead: "Windows cannot find '%windir%\system32\systempropertiesadvanced.exe'. Make sure you typed the name correctly, and then try again."  What!?  Did I corrupt my Windows 7 installation again and I have to start all over?  Thankfully, no.

Turns out, the root cause was my installation of SSMS 2012 put the length of the PATH variable just above the maximum limit.  When the PATH variable is too long, it stops resolving %PATH% properly, as well as any other environment variable.  I could test this by literally going to Command Prompt and typing "echo %PATH%."  The result coming back was "%PATH%" instead of expanding the environment variable as it normally would.

To get it working, I manually went directly to the path %windir%\system32\systempropertiesadvanced.exe, by navigating to c:\windows (%windir%) in Windows Explorer.  I could open the program from there, go to the PATH editor, and remove all the extra junk to make the variable a more manageable length.  Once I did that, my "Advanced System Settings" started working again, as did SSMS 2012.  Crisis averted!

Happy programming!

Wednesday, September 25, 2013

The Power of Indexes

Indexing is one of those things that a developer seems to forget about, because it seems to be a "DBA"-role for maintaining the database.  After a week of performance tuning of our cloud application, I am convinced that indexing should be a key part of the my process for any performance analysis.  There are a couple of simple ways to find appropriate indexes for your database to address the low-hanging fruit of poor database performance.  The process looks something like this:
  1. Identify slow performing queries in your application.
  2. Develop a SQL script containing test queries that are consistently low performance.
  3. Execute the script in SSMS using the option to include the Execution Plan.
  4. Review & apply suggested indexes, and retest again.
The first step can be done in multiple ways.  My favorites are to use timing code like I posted previously, or to use System DMV's (Dynamic Management Views) to identify the most expensive queries.  You can also use a tool like SQL Profiler to capture SQL traffic and timings, although this method can be challenging to apply practically because of excessive traffic "noise".
Here is one such example to find expensive queries:
SELECT TOP 10 SUBSTRING(qt.TEXT, (qs.statement_start_offset/2)+1,
((CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(qt.TEXT)
ELSE qs.statement_end_offset
END - qs.statement_start_offset)/2)+1),
qs.execution_count,
qs.total_logical_reads, qs.last_logical_reads,
qs.total_logical_writes, qs.last_logical_writes,
qs.total_worker_time,
qs.last_worker_time,
qs.total_elapsed_time/1000000 total_elapsed_time_in_S,
qs.last_elapsed_time/1000000 last_elapsed_time_in_S,
qs.last_execution_time,
qp.query_plan
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) qp
ORDER BY qs.total_logical_reads DESC -- logical reads
-- ORDER BY qs.total_logical_writes DESC -- logical writes
-- ORDER BY qs.total_worker_time DESC -- CPU time
The result is a list of queries and the time (in microseconds) that the query typically takes to execute.  A rule of thumb I used is infrequent queries taking more than a couple seconds should be analyzed, as well as frequent queries taking more than about 100 ms for a high-performance, low-latency application.  These requirements will vary depending on the needs of your application.
Once you identify a query to review, use these highlighted options in SSMS to include the Execution Plan and Client Statistics for good data to analyze the query:

With luck, the Execution Plan will provide a clue as to the reason for the poor performance.  Reading execution plans is a whole other topic which is worth researching in and of itself.  If you have a clear need for an index, and you have a good test set, SSMS 2012 will suggest an index at the top of the window which you can click to generate the script.  Running this script will apply the index, and allow you to retest and see if the query performance is improved.  Using this method we found 7-8 indexes that improved the overall performance of our application by about 10-15%.

While indexing a database is a good way to quickly improve performance with large amounts of data, there are a few caveats to keep in mind:
  • An index must be maintained, which means INSERT/UPDATE queries will have a slight performance impact for each index.  This trade-off must be weighed carefully with each index, so at least one performance test should include real-world traffic patterns.
  • There is no replacement for good programming practices.  It is better to fix chattiness in your application or cache often-used data rather than just use indexing to make the queries faster.  For instance, using the wrong algorithm in your application can have a much more severe impact on performance than using a slow query.
Happy programming!

Friday, September 13, 2013

Friday TIP: Switch Application By Name

I have for awhile been searching for a program that would allow me to manage all my open windows – as I typically have anywhere from 30-40 windows open on any given day.  The most frustrating thing was eyeing over the icons trying to find a certain window, and can’t seem to find it.  So enter some new tools for switching to open program by name:

  • Switcher – Adds a new shortcut Windows+~ that pulls up an overlay with a grid of screenshots of open windows, sorted by most often active.  Also, you can start typing, and it will search windows by name.  Downside: Requires Windows Aero to be activated, and it is somewhat graphic/cpu intense.  Probably not going to work well on a laptop.
  • ENSO Launcher – Replaces your CAPS Lock as a shortcut to a popup window where you can type various commands (if you’re like me and hardly ever use CAPs lock anyway, it’s not a big deal to lose this key).  You can type “go abcd” where abcd is part of the name of an open window.  As you type a smart-list dynamically populates with closest matches, and you simply press Enter to switch to the application.



I have both installed, and I’m quickly preferring ENSO Launcher because it is less graphic intense and more performant.

Wednesday, September 11, 2013

Performance Tuning C#.Net Code

If you've developed a project with any level of complexity, you have surely run into the problem of needing to do performance optimization.  You've got too many calls to the database; or your inner loops are inefficient; or you need to convert some large arrays into dictionary lookups, etc.  As it happens, my project this week has been to optimize the performance of some functionality for creating records in a cloud-based system that live synchronizes every update with a second database.

The most complicated calls in this system involve what we call "business logic".  A record update made in the cloud system is synchronized to the back-end database (via web-service call), and then there are other records in related tables that are automatically updated as well (think of a trigger), and those changes are sent back.  On top of that, if new records in related tables are being created, the ID values of those new records have to be sent in a second web service call to keep record ID's in sync.  For some of our larger customers, this entire two-way communication process from end-to-end has been taking upwards of a couple of minutes to execute, which is not acceptable to them or to us.

So how to approach a problem like this, where you have a performance issue in a complex system composed of many moving parts in separate locations?  A couple of basic rules come to mind, like the old mantra "Premature optimization is the root of all evil" (Donald Knuth).  Basically, we must first measure the code to determine what is in need of optimization, because it is very often not in the place you intuitively think it is.  The simplest way to measure code performance in .NET is to make use of the DateTime and TimeSpan classes.

var start = DateTime.Now;
DoCode();
var end = DateTime.Now;
var msElapsed = (end - start).TotalMilliseconds;

Console.WriteLine("Execution Time: " + msElapsed + " ms");
One nice thing about the DateTime API as shown above is a natural conversion to TimeSpan's by subtracting one DateTime from another.  This gives us the time difference, or total time elapsed in the code, to a pretty high accuracy in milliseconds (+/- 20 ms in my experience).  As you can imagine, your code can get pretty cluttered as you litter it with these timing calls.  So to simplify a little, I developed a set of helper methods to do performance timings:
private string _indent = "";
private DateTime _lastEvent = DateTime.Now;
public void LogTimingMessage(string method, string message, bool includeElapsedTime = true, TimeSpan? eventElapsed = null)
{
 var eventTime = DateTime.Now;
 var logFormat = "{0} ({1})-{2}{3}:{4}";
 if (includeElapsedTime) logFormat += " ({5} ms)";
 if (eventElapsed == null) eventElapsed = eventTime - _lastEvent;
 var log = string.Format(logFormat, TimeElapsed, eventTime, _indent, method, message, eventElapsed.Value.TotalMilliseconds);
 Console.WriteLine(log);
 _logging += log + "\n";
}

public void LogTimingVariable(string method, string variable, string value)
{
 var message = string.Format("{0}={1}", variable, value);
 LogTimingMessage(method, message);
}

public T LogTimingTask<T>(string method, string taskDescription, Func<T> Task)
{
 _indent += "\t";
 var start = DateTime.Now;
 var result = Task();
 var end = DateTime.Now;
 _indent = _indent.Substring(0, _indent.Length - 1);
 LogTimingMessage(method, "Task " + taskDescription, eventElapsed:(end - start));
 return result;
}

public void LogTimingTask(string method, string taskDescription, Action Task)
{
 LogTimingTask<bool>(method, taskDescription, () => { Task(); return true; });
}

public void LogTimingStart(string method)
{
 LogTimingMessage(method, "Start");
}

public void LogTimingEnd(string method)
{
 LogTimingMessage(method, "End", eventElapsed:DateTime.Now - Start);
}
The basic idea is that every call to a Log method prints out a message of how much time has elapsed since the last Log call.  Furthermore, you can wrap groups of code or method calls, and it will time execution of that group of code, as well as indent inner calls to show the nature of inner vs. outer timings.  Perhaps a real-world example usage will demonstrate what I mean:
var createResult = LoggingContext.Current.LogTimingTask("API.CreateEmployeeChangeSet", "Create Employee", () =>
 {
   return APIMethods.CreateEmployee(ee, depInfo, wage, recordId, (SetupContext context, int employeeId) =>
   {
    //Common.LogMessage((DateTime.Now - start).TotalMilliseconds.ToString() + " ms", "APIMethods.CreateEmployee");

    var innerStart = DateTime.Now;
    var companyCode = ee.CompanyCode;

    var emp = LoggingContext.Current.LogTimingTask("API.CreateEmployeeChangeSet", "Get Employee", () =>
     {
       return context.GetEmployee(employeeId);
     });
    //Common.LogMessage((DateTime.Now - innerStart).TotalMilliseconds.ToString() + " ms", "context.GetEmployee");
    innerStart = DateTime.Now;

    var resolver = LoggingContext.Current.LogTimingTask("API.CreateEmployeeChangeSet", "Build Indexed Resolver", () =>
     {
       return new IndexedCompanySnapshotForeignKeyMapper(context, companyCode);
     });

    //Common.LogMessage((DateTime.Now - innerStart).TotalMilliseconds.ToString() + " ms", "IndexedCompanySnapshotForeignKeyMapper");
    innerStart = DateTime.Now;


    var locationId = LoggingContext.Current.LogTimingTask("API.CreateEmployeeChangeSet", "Resolve Location Id", () =>
     {
      return resolver.ResolveLocationId(companyCode).Id;
     });

    var cpobjs = LoggingContext.Current.LogTimingTask("API.CreateEmployeeChangeSet", "emp.AsEnumerable", () =>
     {
      return emp.AsEnumerable(EmployeeFlag.All, false).ToList();
     });

    var hrobjs = LoggingContext.Current.LogTimingTask("API.CreateEmployeeChangeSet", "Convert cpobjs", () =>
     {
      return cpobjs.Select(c => { var hrobj = HRObjectUtility.Convert(c, resolver); hrobj.LocationId = locationId; return hrobj; }).ToList();
     });

    csi = new ChangeSetInfo();
    csi.Inserts = cpobjs;
    csi.HRInserts = hrobjs;
    csi.Updates = new List<HRObject>() { HREmployee.Convert(emp, resolver, EmployeeFlag.None) };
    csi.Updates[0].LocationId = locationId;
    csi.Deletes = new List<HRObject>();

    return true;
   }
  );
 }
);

The output looks something like this:
00:00:00.2260226 (9/6/2013 2:44:32 PM)-API.CreateEmployeeChangeSet:Start (226.0226 ms)
00:00:02.5132513 (9/6/2013 2:44:34 PM)-  APIMethods.CreateEmployee:Task wrapper.CreateEmployee (2224.2224 ms)
00:00:02.5302530 (9/6/2013 2:44:34 PM)-  APIMethods.CreateEmployee:Task context.InsertTranslationID (17.0017 ms)
00:00:02.5622562 (9/6/2013 2:44:34 PM)-  APIMethods.CreateEmployee:Task context.SubmitChanges (32.0032 ms)
00:00:03.2523252 (9/6/2013 2:44:35 PM)-  API.CreateEmployeeChangeSet:Task Get Employee (688.0688 ms)
00:00:06.2986298 (9/6/2013 2:44:38 PM)-  API.CreateEmployeeChangeSet:Task Build Indexed Resolver (3046.3046 ms)
00:00:06.3156315 (9/6/2013 2:44:38 PM)-  API.CreateEmployeeChangeSet:Task Resolve Location Id (17.0017 ms)
00:00:06.3206320 (9/6/2013 2:44:38 PM)-  API.CreateEmployeeChangeSet:Task emp.AsEnumerable (5.0005 ms)
00:00:06.3766376 (9/6/2013 2:44:38 PM)-  API.CreateEmployeeChangeSet:Task Convert cpobjs (56.0056 ms)
00:00:06.4176417 (9/6/2013 2:44:38 PM)-  APIMethods.CreateEmployee:Task context.AddEmployeeUpdateRecord (30.003 ms)
00:00:06.5426542 (9/6/2013 2:44:38 PM)-API.CreateEmployeeChangeSet:Task Create Employee (6316.6316 ms)
00:00:06.9636963 (9/6/2013 2:44:39 PM)-API.CreateEmployeeChangeSet:Task APIMethods.ProcessChangeSet (421.0421 ms)
00:00:06.9636963 (9/6/2013 2:44:39 PM)-API.CreateEmployeeChangeSet:End (6963.6963 ms)
At a glance it is fairly obvious which methods need the most attention - the "APIMethods.CreateEmployee" call which takes about 2.2 seconds, and the "Build Indexed Resolver" step, which takes about 3 seconds by itself.  With this data analysis in hand, I know where to focus my attention to get the biggest return on performance.

Happy programming!

Friday, August 23, 2013

An Error? Carry on anyway!

Lately I've had to do a lot of development in our core internal application which is responsible for managing data flow between our clients systems and our network.  This system also coordinates data for some of our 3rd-party partner integrations, such as Pay-as-you-Go Worker's Compensation.  Multiple times throughout any day, a number of scheduled tasks are run which imports data into databases, downloads and processes XML files, generates and uploads more XML files, and other similar large-scale data processing tasks.

So you'd think a system at this core level should be well-designed, right?  Wrong!  There are a number of faults in the architecture of this system, but by far the most blatant is a pattern called "Exception? Won't happen!"  It's the most pernicious of them all because it results in a number of complex, hard-to-debug data defects:

  • Data partially processed, or processed incorrectly and has to be manually rolled back.
  • Files that are generated, but not uploaded properly.
  • Multiple day's worth of data just "missing" from generated files.
Here's what the pattern looks like in a nut-shell:

Try
  PrepareData()
Catch ex As Exception
  LogException(ex)
End Try

Try
  GenerateFile()
Catch ex As Exception
  LogException(ex)
End Try

Try
  ArchiveData()
Catch ex As Exception
  LogException(ex)
End Try

Try
  UploadFile()
Catch ex As Exception
  LogException(ex)
End Try

At first glance you might think there's nothing wrong - the developer has wisely adding exception handling and logging to the system to make sure errors can be detected and reviewed.  The problem comes if something does indeed fail.  For example, what happens if "UploadFile()" process fails?  Well, the first three processes will have already finished and been committed.  The data has been archived permanently, but the generated file never got uploaded to the 3rd-party network.  That means they will never receive the data, and we will never send it again because it's been marked "complete"!  Apparently the developer assumed that "nothing could go wrong".

Resolving this defect can be a little time-consuming, but definitely worth it. I generally approach it this way:

  1. Wrap all sub-steps in some sort of transaction.
  2. Pass the same transaction to each method.
  3. If the entire process (work unit) is successful, commit the transaction at the end.
  4. If anything fails on any step, roll the entire process back, including deleting any temp files that were partially created.
  5. Everything is left in a consistent state then for another try in the next processing cycle.
Just for fun, here's another gem from the same code-base that occurred while stepping through with the debugger in Visual Studio (the highlighted line is the next statement to execute):



Happy programming!

Friday, August 16, 2013

Windows Azure RDP

So the other day I was looking for a good solution to managing multiple RDP windows. In a normal day I will be working with up to 10 different RDP sessions at once, and it gets annoying managing all those icons on the taskbar.  After hunting around and comparing a few different products, I settled with Terminals, which is an open-source RDP session manager hosted on CodePlex.  My ideal RDP manager would have the following core properties:

  • Has good connection management - groups, saved credentials, etc.
  • Captures special keys correctly (Windows key, Alt+Tab, Ctrl+Shift+Esc, etc.)
  • Supports Windows Azure
Terminals comes close, because it handles the first two very well, but unfortunately, it does not support Windows Azure.  However, since it is open-source and written in C#.Net, I thought I would just modify it myself to add support.

If you've worked with Windows Azure, you'll be familiar with the Connect link at the bottom of the Azure Portal when viewing information about a service instance.  That link gives you an .RDP file to download which can be used to connect to the instance.  If you type in the public instance name (name.cloudapp.net) into an RDP session without going through the .RDP file download, you'll quickly discover that it doesn't work.  So what is different about generating the .RDP file directly from the portal?

When you open the file, there is a special property value unique to Windows Azure that is required for the connection.  Without it, you get no response whatsoever, and no idea why your connection is not working.  I guess that's a security feature by design in Azure.  Here's an example file (with values redacted):

full address:s:subdomain.cloudapp.net
username:s:bobbytest
LoadBalanceInfo:s:Cookie: mstshash=subdomain#subdomain_IN_0
You'll notice there is a special value called "LoadBalanceInfo" which is not present on typical RDP sessions.  So I added the property to the UI of the Terminals program and modified all the places that generate RDP sessions to make use of the property as well.  However, every time I would try to connect, still no response.  After doing a little research, I became convinced that I was just missing a small detail and WireShark (network capture software) would provide the answer.

With WireShark I quickly discovered exactly what the issue was - my strings were getting sent over the wire as UTF-16, which means every character was 2 bytes.  Here is an example of what the TCP conversation dump looks like:

C.o.o.k.i.e.:. .m.s.t.s.h.a.s.h.=.s.u.b.d.o.m.a.i.n.#.s.u.b.d.o.m.a.i.n._.I.N._.0.

The dots in between each character are 0-byte characters making up the other half of the 2-byte unicode characters.  Since the class being used for the RDP connections is an ActiveX component provided by Microsoft, actually modifying the class was out of the question.  But there is a way - re-encode the string as UTF-8 by squishing two characters together into each 2-byte character.  It becomes a really weird string if you try to interpret as UTF-16 (the default in .NET), but the ActiveX class which reads as 1-byte characters works beautifully:

var b = Encoding.UTF8.GetBytes(temp);
var newLBI = Encoding.Unicode.GetString(b);

The only catch to this solution is that if the original string has an odd number of characters, the last character will still be a 0-byte and be rejected.  Simple solution is to pad with an extra space at the end, which seems to work okay.  Add to that the requirement that LoadBalanceInfo always be suffixed by "\r\n", and the full working solution is below:

var temp = LoadBalanceInfo;
if (temp.Length % 2 == 1) temp += " ";
temp += "\r\n";
var b = Encoding.UTF8.GetBytes(temp);
var newLBI = Encoding.Unicode.GetString(b);

Magically, it works!  I created and uploaded a patch that adds support for Windows Azure to the Terminals website, so you can try it for yourself.  Happy programming!