Frank Solomon
Query the sys.dm_xe_objects table, and look at the rpc_completed event row.

Using SQL Server Extended Events to debug applications

July 3, 2020 by

Introduction

Often enough, multilayer software has bugs. SQL Server Extended Events system offers tools that can help find those bugs. A bug can happen in any layer – data, logic, or presentation. To fix those bugs, it helps to see the exact parameters and values that the presentation layer sends to the data layer. As a data layer product, SQL Server Extended Events can help with this.

The Demo Application

For this article, we’ll work with a VB.net desktop application that I built for a customer. The application handles recipe management. The user sees a presentation layer that front-ends a locally hosted, completely relational SQL Server 2014 Enterprise database. First, we’ll see a bug in the Application Recipe Edit Module. Then, we’ll use the SQL Server Extended Events tool to understand and fix the bug.

The Bug

We’ll edit a recipe in the Recipe Edit module, as seen in this screenshot:

The Recipe Edit module.

In the lower right Recipe Text control, we’ll edit the recipe text, as seen in the screenshot below:

The Recipe Edit module, with a recipe text edit.

The recipe text shown here has the exact content, formatting, casing, etc. that we want. We’ll click the Save Recipe button at the lower right to save the changes. Sometime later, we’ll try to edit the recipe again. We’ll again open it in the Recipe Edit module, as seen in this screenshot:

The Recipe Edit module. The recipe text should not have all caps text.

That previous edit shows the correct text, except now the recipe text has all upper casing. We just found a bug, and we need to fix it.

Investigating the bug

The Recipe Edit module calls the UPDATE_RECIPE stored procedure to update a recipe. We can call this stored procedure in a Query Analyzer, with parameters that match this test case. First, we’ll manually roll back the recipe, with this SQL Server statement:

This screenshot shows this statement in a Query Analyzer tab:

Run a stored procedure to investigate a detected bug.

The SELECT statement at line 4 verifies the RECIPES table record rollback. This screenshot shows that the Query Analyzer rollback change worked:

The Recipe Edit module.

This screenshot runs UPDATE_RECIPE with the changes we originally wanted to make:

Run a stored procedure to directly change the recipe text in the database.

It looks like the stored procedure ran correctly. We can again look at the recipe in the Recipe Edit tool, as shown in this screenshot:

The Recipe Edit module shows that the database table edit worked.

Based on the research so far, the bug behavior shown in the third screenshot above most likely does not happen in the SQL Server data layer. We need to look outside this layer, and we’ll turn to the SQL Server Extended Events tool.

The Extended Events Tool

Microsoft offered the SQL Server Profiler tool since at least SQL Server 7. The Profiler captures SQL Server event and behavior “payloads” at a fine-grained level, and SQL developers and DBAs can use this for diagnostics. The Profiler can watch the parameter flows into the UPDATE_RECIPE stored procedure, so it would help here. However, in this article, An overview of the SQL Server Profiler, Hadi Fadlallah explained that Microsoft would eventually phase out the Profiler. As a replacement, Microsoft first released SQL Server Extended Events in SQL Server 2008. That version of SQL Server Extended Events covered fewer events compared to Profiler, and it did not have a UI. In SQL Server 2012, added a UI, and with every major release, SQL Server Extended Events design covers more events. Microsoft defines SQL Server Extended Events as “… a lightweight performance monitoring system that enables users to collect data needed to monitor and troubleshoot problems in SQL Server.” As we’ll see, it will help us solve the problem.

Build an Extended Events Session

SQL Server Extended Events system operates on “sessions.” We’ll create a new Extended Event session here. First, launch SQL Server and expand Databases. Expand the RECIPES database, and drill into Stored Procedures. We’ll focus on the UPDATE_RECIPE stored procedure, highlighted in this screenshot:

The SQL Server Object Explorer.

To build an Extended Event session, drill down to Extended Events -> Sessions in the Object Explorer, as shown below:

The SQL Server Object Explorer. Drill down to the Sessions option.

Right-click “Sessions” and drill down to New Session, as shown in this screenshot:

The SQL Server Object Explorer. Drill down to the Sessions option, and open New Session.

We could pick “New Session Wizard” here, but “New Session” seems to involve less effort to build a session. The New Session window opens, as shown in this screenshot:

Build a new session.

For this demo, we’ll focus on the General and Events pages at the upper left, starting with the General page. As we build the session, we’ll see a lot of options and choices available, but we’ll focus only on what we need. This screenshot shows the General page for the session:

First step: the New Session General page.

We named the session “UPDATE_RECIPE_session” and later on, we’ll see how to manually launch it and watch the live data on the screen. Next, we’ll configure the session at the Events page, as shown in this screenshot:

Second step: the New Session Events page.

First, we’ll pick the specific event we want in the Event library list box, although we can pick more. As of SQL Server 2014, SQL Server Extended Events covers more than 1300 events. Reference material about them might become hard to find, but as a start, we can look at the sys.dm_xe_objects table with this query:

The following screenshot shows the basic information returned about the available events:

Query the sys.dm_xe_objects table, and look at the rpc_completed event row.

In the highlighted row above, the description for rpc_completed says that it “Occurs when a remote procedure call has completed.” This looks promising because a stored procedure might count as a “remote procedure.” Other research showed that this guess is correct. Click the highlighted rpc_completed row. Then, click the circled right arrow to move this event to the Selected events list box, as shown in this screenshot:

Configure a new session.

This enables the “Configure” control at the upper right. Click it to open the event configuration options, as shown below:

The event configuration options for a new session.

Click the Filter Predicates tab, and place these values in the Event configuration options list box row:

Field           =>          object_name

Operator    =>          =

Value          =>          UPDATE_RECIPE

Ignore the And/Or field. This screenshot shows the Events page Configuration section:

The Events page Configuration section.

Click OK at the lower right as the last step. This screenshot shows the new session in the Object Explorer:

The Object Explorer, showing the available sessions.

To launch UPDATE_RECIPE_session, right-click it in Object Explorer, and click Start Session, as shown in this screenshot:

Start the new session.

Now, enable the Watch Live Data option. Click it as shown in this screenshot:

Watch the new session live data.

The Watch Live Data option opens a Management Studio tab, as shown in this screenshot:

A live session data tab.

Rollback the recipe again, with this SQL Server statement:

Now that we set up everything, we’ll edit the recipe as we did earlier, and watch the data flow. The following screenshot shows the session tab:

The UPDATE_RECIPE_session live data session tab, with captured data.

In the lower pane, the statement row has this value:

Something changed the @recipe_text argument value to all upper case. We know from earlier steps in the investigation that the @recipe_text argument should look like this:

Based on the investigation, the bug happened before the call to the UPDATE_RECIPE stored procedure. The front-end software probably has a bug. As a first guess, we should look in the code around the call to UPDATE_RECIPE, as shown in this screenshot:

This VB.net method calls the UPDATE_RECIPE stored procedure.

We know the bug involves the @RECIPE_TEXT value, and we can see a potential problem with it at line 599, as shown in the screenshot below:

The VB.net function that causes the reported bug.

The VB.net UCase function converts text values to upper case. If we remove it, roll back the data, and try again, we’ll see that we fixed the bug, as shown in this screenshot:

Test the Recipe Edit module to verify that we fixed the bug.

As configured, the SQL Server Extended Events UPDATE_RECIPE_session only “sees” UPDATE_RECIPE calls that come from outside the server. As we saw earlier, this statement calls UPDATE_RECIPE:

If we run it in Query Analyzer, the UPDATE_RECIPE_session tab won’t see that UPDATE_RECIPE stored procedure call.

Conclusion

As we saw, the SQL Server Extended Events tool offers SQL Server professionals a flexible, powerful way to understand the product and system engineering of the software they build.

Frank Solomon
Development, Testing

About Frank Solomon

Frank Solomon started out building Microsoft stack products, and he gradually focused on SQL Server. Some years ago, he began a parallel shift to writing and technical writing. He wrote published articles, he blogs at Bit Vectors, and he co-wrote The SQL Workshop for Packt Publishing, with SQL Shack writer Prashanth Jayaram. Frank is looking for his next writing / technical writing role. He levers his sharp software development skills, and sharp writing skills, to add great value and solve big problems. He has plenty of remoting experience, and he uniquely relies on the active voice to build high-quality writing products. See more about Frank at LinkedIn, and reach him at fbs.author@gmail.com

247 Views