none
Confusing output of SQL Server Profiler

    Question

  • Try to be brief. Here is my table and SP in SQL Server 2008 R2 database:

    CREATE TABLE dbo.TEST_TABLE
    (
        ID INT NOT NULL IDENTITY (1,1) PRIMARY KEY, 
        VALUE varchar(23)
    )
    GO
    
    CREATE PROCEDURE USP_TEST_PROCEDURE
    ( 
        @Param1 varchar(23)
    )
    AS
    BEGIN
        INSERT INTO TEST_TABLE (VALUE) VALUES (@Param1)
    END
    GO

    Here is the C# code:

    using (SqlConnection con = GetConection())
    {
        using (var cmd = new SqlCommand("USP_TEST_PROCEDURE", con))
        {
            cmd.CommandType = CommandType.StoredProcedure;
            cmd.Parameters.Add("@Param1", SqlDbType.DateTime, 23).Value = "2013-12-10 12:34:56.789";
            cmd.Connection.Open();
            cmd.ExecuteNonQuery();
        }
    }

    Pay attention that I intentionally specified the type of @Param1 as DateTime. Now launch SQL Server Profiler and run the .NET code. When done, don’t stop the profiler, just look at the output. I see the following text for the RPC:Completed EventClass:

    exec USP_TEST_PROCEDURE @Param1='2013-12-10 12:34:56.790'

    Now copy this text, open SSMS, paste to the new query window and run it without any changes. Now stop the profiler and make sure that the SSMS produced the same text in the profiler as ADO.NET app:

    exec USP_TEST_PROCEDURE @Param1='2013-12-10 12:34:56.790'

    Now select from the TEST_TABLE table. I see the following result:

    ID VALUE
    1  Dec 10 2013 12:34PM
    2  2013-12-10 12:34:56.790

    The question is why the two identical commands (from SQL Server Profiler’s point of view) produce different results?

    It seems like profiler does not show correctly what is going on behind the scene. After I had ran the .NET app I expected to see the following:

    DECLARE @Param1 Datetime = '2013-12-10 12:34:56.789';
    exec USP_TEST_PROCEDURE @Param1

    If my understanding is correct, then I would like to rephrase the question: Why SQL Server Profiler shows something strange and confusing? Are there any options to correct this?


    Alexey

    Wednesday, December 11, 2013 7:22 PM

Answers

  • It is correct that profiler doesn't show use the "truth" when you execute a stored procedure propely. The reason (methinks) is that when you execute a procedure propely you do a *binary* call to SQL Server. Showing a lots of zeroes and ones or some hex representation of that binary call isn't very helpful to a human. So it has to do something to make that call readable to us humans. Basically, what we have cooked down this to is that you don't agree with the textual representation that Profiler uses and you want a more ... precise (?) textual representation from Profiler. That I can agree with. I am a little bit surprised by what you are seeing, though. I'm not a .NET programmer, but when I execute below code:

            'Parameterize as stored procedure, RPC:Completed
            Dim cmdRpc As New SqlCommand("dbo.GetOrderStatusOut", cn)
            cmdRpc.CommandType = CommandType.StoredProcedure
            Dim prmSalesOrderID As SqlParameter = New SqlParameter("@SalesOrderID", SqlDbType.Int)
            prmSalesOrderID.Value = ProductID
            cmdRpc.Parameters.Add(prmSalesOrderID)
            Dim prmStatus As SqlParameter = New SqlParameter("@Status", SqlDbType.TinyInt)
            prmStatus.Direction = ParameterDirection.Output
            cmdRpc.Parameters.Add(prmStatus)

    I see below in Profiler:

    declare @p2 tinyint
    set @p2=5
    exec dbo.GetOrderStatusOut @SalesOrderID=43664,@Status=@p2 output
    select @p2


    Tibor Karaszi, SQL Server MVP | web | blog

    • Marked as answer by AlexeyGa Wednesday, December 18, 2013 10:11 AM
    Wednesday, December 11, 2013 10:00 PM
    Moderator
  • It could be an option. (I have just voted for the feature suggested by Steve Kass). However, the main point is that currently, profiler gives us an information which is not 100% accurate. And it should be fixed.

    Profiler and SQL Trace are deprecated, and they will not change.

    You may have better luck with extended events. But I doubt they will ever bother of that either. The problem is that the client sends TDS packages and no T-SQL statement, and any text representation will just be a model of those packages and they will never reproduced the TDS packages with 100% accuracy. A good example is when you have a stored procedure that accepts a TVP. SQL Trace will show you a declaration of a table variable, INSERT statements into that table variable of the data, and then the call. If there may rows in the TVP, the INSERT statement is unwieldy, and if there are more than 1000 rows, it may not even compile. (How it looks like with extended events, I don't know.) Whatever, at the actual execution there is no extra table variable, but the data is streamed directly to the TVP, and this can be very efficient. Which you can't say about the INSERT statement, which has a large compilation overhead.


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    • Marked as answer by AlexeyGa Wednesday, December 18, 2013 10:13 AM
    Friday, December 13, 2013 11:48 AM

All replies

  • You should make the parameter datetime.

    String datetime values are subject to any number of "trick" conversions. You can invent your own string date format.


    Kalman Toth Database & OLAP Architect IPAD SELECT Query Video Tutorial 3.5 Hours
    New Book / Kindle: Exam 70-461 Bootcamp: Querying Microsoft SQL Server 2012




    Wednesday, December 11, 2013 7:32 PM
    Moderator
  • You should make the parameter datetime.

    String datetime values are subject to any number of "trick" conversions. You can invent your own string date format.


    Kalman Toth Database & OLAP Architect IPAD SELECT Query Video Tutorial 3.5 Hours
    New Book / Kindle: Exam 70-461 Bootcamp: Querying Microsoft SQL Server 2012




    Thank you for the response. The question is not about how to fix my code. The question is about the confusing behavior of SQL Server Profiler.

    Let’s imagine I have a 3rd party application and don’t have access to the source code. So I don’t know what SqlDbType is assigned to SqlParameter. Maybe it has SqlDbType.DateTime or maybe SqlDbType.VarChar. In this case the only way to see what is going on is to use profiler. So I launch it and see the following:

    exec USP_TEST_PROCEDURE @Param1='2013-12-10 12:34:56.790'

    How do I know that the application is sending a datetime, not a string? It is not obvious. Is there any parameter in the profiler that can force the profiler to show this information?


    Alexey

    Wednesday, December 11, 2013 8:18 PM
  • It is correct that profiler doesn't show use the "truth" when you execute a stored procedure propely. The reason (methinks) is that when you execute a procedure propely you do a *binary* call to SQL Server. Showing a lots of zeroes and ones or some hex representation of that binary call isn't very helpful to a human. So it has to do something to make that call readable to us humans. Basically, what we have cooked down this to is that you don't agree with the textual representation that Profiler uses and you want a more ... precise (?) textual representation from Profiler. That I can agree with. I am a little bit surprised by what you are seeing, though. I'm not a .NET programmer, but when I execute below code:

            'Parameterize as stored procedure, RPC:Completed
            Dim cmdRpc As New SqlCommand("dbo.GetOrderStatusOut", cn)
            cmdRpc.CommandType = CommandType.StoredProcedure
            Dim prmSalesOrderID As SqlParameter = New SqlParameter("@SalesOrderID", SqlDbType.Int)
            prmSalesOrderID.Value = ProductID
            cmdRpc.Parameters.Add(prmSalesOrderID)
            Dim prmStatus As SqlParameter = New SqlParameter("@Status", SqlDbType.TinyInt)
            prmStatus.Direction = ParameterDirection.Output
            cmdRpc.Parameters.Add(prmStatus)

    I see below in Profiler:

    declare @p2 tinyint
    set @p2=5
    exec dbo.GetOrderStatusOut @SalesOrderID=43664,@Status=@p2 output
    select @p2


    Tibor Karaszi, SQL Server MVP | web | blog

    • Marked as answer by AlexeyGa Wednesday, December 18, 2013 10:11 AM
    Wednesday, December 11, 2013 10:00 PM
    Moderator
  • In addition to Tibor's post:

    When you say

    exec USP_TEST_PROCEDURE @Param1='2013-12-10 12:34:56.790'

    In SSMS, the actual parameter is a literal, more precisely a string literal.

    Profiler on the other represents something which is more like:

    Op = RPC CALL
    Name = USP_TESTPROCEDURE
    Param = {Value=0x0000A29000CF5A2D, Type=datetime, Name=@param1}

    To make it more useful to you, it represents this as an EXEC command. Since there is no datetime literal in SQL Server, it needs to find a text represenation of the datetime value, and it converts the value to string using the format YYYY-MM-DD. Note that at this point, Profiler has no information that the formal parameter is varchar(23).

    When procedure is invoked the datetime value is converted to varchar(23), but this time in SQL Server, and the default format for datetime-to-string conversion in SQL Server is 'Mon Day Year hh:mm' (because of legacy).


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    Wednesday, December 11, 2013 10:52 PM
  • To add to Erland's post, I filed a suggestion on connect to use neutral date formats when rendering RPC call parameters for this very reason.  The response was "we won't be able to address this request anytime soon."  They weren't kidding since that was 6 years ago.  Feel free to vote:

    https://connect.microsoft.com/SQLServer/feedback/details/302236/use-neutral-date-format-for-datetime-parameter-values


    Dan Guzman, SQL Server MVP, http://www.dbdelta.com

    Thursday, December 12, 2013 3:39 AM
  • It is correct that profiler doesn't show user the "truth" when you execute a stored procedure properly. The reason (methinks) is that when you execute a procedure properly you do a *binary* call to SQL Server. Showing a lots of zeroes and ones or some hex representation of that binary call isn't very helpful to a human. So it has to do something to make that call readable to us humans. Basically, what we have cooked down this to is that you don't agree with the textual representation that Profiler uses and you want a more ... precise (?) textual representation from Profiler. That I can agree with.

    Yes, you are right. I am not satisfied with the textual representation that SQL Server Profiler uses to show us stored procedures calls. I repeated my test using SQL Server 2012 and SQL Server 2012 Profiler. Unfortunately, I saw the same statement in the TestData column. Then I decided to use Extended Events graphical user interface in SQL Server Management Studio 2012, because Microsoft is announcing the deprecation of SQL Server Profiler for Database Engine Trace Capture. I created a new session, started it and launched my .net app. Eventually, I saw the same statement for rpc_completed event:

    exec USP_TEST_PROCEDURE @Param1='2013-12-10 12:34:56.790'
    I don't understand why it is not shown like that:
    declare @p1 datetime
    set @p1='2013-12-10 12:34:56.789'
    exec USP_TEST_PROCEDURE @Param1=@p1


    Alexey


    • Edited by AlexeyGa Thursday, December 12, 2013 3:32 PM
    Thursday, December 12, 2013 3:14 PM
  • What type of event are you seeing? SQLBatch or RPC?

    Tibor Karaszi, SQL Server MVP | web | blog

    Thursday, December 12, 2013 3:27 PM
    Moderator
  • What type of event are you seeing? SQLBatch or RPC?

    Tibor Karaszi, SQL Server MVP | web | blog

    It is rpc_completed event.

    Alexey

    Thursday, December 12, 2013 3:33 PM
  • I don't understand why it is not shown like that:

    declare @p1 datetime
    set @p1='2013-12-10 12:34:56.789'
    exec USP_TEST_PROCEDURE @Param1=@p1

    Because this would be very tedious to read when there are 50 parameters. Please keep in mind that the case you encountered is a very unusual situation. (And, no, it is not possible to get the display above only when there is a type mismatch, because the trace/x-event does not have the information about the parameter profile.)


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    Thursday, December 12, 2013 3:34 PM
  • I am a little bit surprised by what you are seeing, though. I'm not a .NET programmer, but when I execute below code:

            'Parameterize as stored procedure, RPC:Completed
            Dim cmdRpc As New SqlCommand("dbo.GetOrderStatusOut", cn)
            cmdRpc.CommandType = CommandType.StoredProcedure
            Dim prmSalesOrderID As SqlParameter = New SqlParameter("@SalesOrderID", SqlDbType.Int)
            prmSalesOrderID.Value = ProductID
            cmdRpc.Parameters.Add(prmSalesOrderID)
            Dim prmStatus As SqlParameter = New SqlParameter("@Status", SqlDbType.TinyInt)
            prmStatus.Direction = ParameterDirection.Output
            cmdRpc.Parameters.Add(prmStatus)

    I see below in Profiler:

    declare @p2 tinyint
    set @p2=5
    exec dbo.GetOrderStatusOut @SalesOrderID=43664,@Status=@p2 output
    select @p2


    Tibor Karaszi, SQL Server MVP | web | blog

    Your reply inspired me to make another test.

    I changed the input parameter of my SP to output. So the procedure now looks like that:

    CREATE PROCEDURE USP_TEST_PROCEDURE
    ( 
        @Param1 varchar(23) output
    )
    AS
    BEGIN
        INSERT INTO TEST_TABLE (VALUE) VALUES (@Param1)
    END

    And I adopted my .net app by adding one more line of code:

    cmd.Parameters[0].Direction = ParameterDirection.InputOutput;
    After I launched SQL Server Profiler and run the .NET code, I saw the following for the rpc_completed event:
    declare @p1 datetime
    set @p1='2013-12-10 12:34:00'
    exec USP_TEST_PROCEDURE @Param1=@p1 output
    select @p1
    In essence, my SP has not changed. It still inserts the data to TEST_TABLE and it has the same type of the only parameter (varchar(23)). However, as you can see, the first line in the profiler output is the declaration of the variable and we can clearly see the type of that variable. It is datetime. So this test confirms that behind the scene a variable of datetime type is used in both scenarios. What is not clear is why profiler in the first case does not show the type of the variable, but in the second case it shows that.


    Alexey

    Thursday, December 12, 2013 3:59 PM
  • Profiler on the other represents something which is more like:

    Op = RPC CALL
    Name = USP_TEST_PROCEDURE
    Param = {Value=0x0000A29000CF5A2D, Type=datetime, Name=@param1}

    Is there a possibility to see this in profiler? I'd really like to see it, especially Type=datetime.

    Alexey

    Thursday, December 12, 2013 4:11 PM
  • I don't understand why it is not shown like that:

    declare @p1 datetime
    set @p1='2013-12-10 12:34:56.789'
    exec USP_TEST_PROCEDURE @Param1=@p1

    Because this would be very tedious to read when there are 50 parameters.

    I don't think it is a good reason. In my point of view, it is better to get bored by 50 parameters than be confused by lack of information. 

    Alexey

    Thursday, December 12, 2013 4:30 PM
  • I've made another test, which is more interesting. I used the same table and SP as initially:

    CREATE TABLE dbo.TEST_TABLE
    (
        ID INT NOT NULL IDENTITY (1,1) PRIMARY KEY, 
        VALUE varchar(23)
    )
    GO
    
    CREATE PROCEDURE USP_TEST_PROCEDURE
    ( 
        @Param1 varchar(23)
    )
    AS
    BEGIN
        INSERT INTO TEST_TABLE (VALUE) VALUES (@Param1)
    END
    GO

    and I used the same code as before:

    using (SqlConnection con = GetConection())
    {
        using (var cmd = new SqlCommand("USP_TEST_PROCEDURE", con))
        {
            cmd.CommandType = CommandType.StoredProcedure;
            cmd.Parameters.Add("@Param1", SqlDbType.DateTime, 23).Value = "2013-12-10 12:34:56.789";
            cmd.Connection.Open();
            cmd.ExecuteNonQuery();
        }
    }

    I launched SQL Server Profiler. This time I used TSQL_Replay trace template. Then I ran the .NET code. Then I stopped the trace and saved it.

    Select * from TEST_TABLE gives me one row:

    ID VALUE
    1  Dec 10 2013 12:34PM

    Then I replayed the trace and selected rows from the TEST_TABLE again:

    ID VALUE
    1  Dec 10 2013 12:34PM
    2  2013-12-10 12:34:56.790

    So even SQL Server Profiler can't reproduce the same result. Funny, isn't it? I would say that this is a bug in the profiler.

    By the way, if the trace was like that:

    declare @p1 datetime
    set @p1='2013-12-10 12:34:56.789'
    exec USP_TEST_PROCEDURE @Param1=@p1
    the result would be correct (would be identical to the first row).

    Alexey



    • Edited by AlexeyGa Thursday, December 12, 2013 5:15 PM
    Thursday, December 12, 2013 5:12 PM
  • I don't think it is a good reason. In my point of view, it is better to get bored by 50 parameters than be confused by lack of information. 

    And if there is a parameter error in the client code among those 50 parameters, would you even notice? You would still be equally confused.

    Here is a Connect item from Steve Kass,
    http://connect.microsoft.com/SQLServer/feedback/details/356470/support-syntax-for-typed-literal-values
    which suggest a syntax for typed literals. If this was implemented, it would be possible to show RPC calls more faithfully without littering the text with parameter declarations.


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    Thursday, December 12, 2013 10:41 PM
  • Here is a Connect item from Steve Kass,

    http://connect.microsoft.com/SQLServer/feedback/details/356470/support-syntax-for-typed-literal-values
    which suggest a syntax for typed literals. If this was implemented, it would be possible to show RPC calls more faithfully without littering the text with parameter declarations.

    It could be an option. (I have just voted for the feature suggested by Steve Kass). However, the main point is that currently, profiler gives us an information which is not 100% accurate. And it should be fixed.

    It might be done by introducing a new syntax for typed literals or by using parameter declarations, IMHO.


    Alexey

    Friday, December 13, 2013 10:14 AM
  • It could be an option. (I have just voted for the feature suggested by Steve Kass). However, the main point is that currently, profiler gives us an information which is not 100% accurate. And it should be fixed.

    Profiler and SQL Trace are deprecated, and they will not change.

    You may have better luck with extended events. But I doubt they will ever bother of that either. The problem is that the client sends TDS packages and no T-SQL statement, and any text representation will just be a model of those packages and they will never reproduced the TDS packages with 100% accuracy. A good example is when you have a stored procedure that accepts a TVP. SQL Trace will show you a declaration of a table variable, INSERT statements into that table variable of the data, and then the call. If there may rows in the TVP, the INSERT statement is unwieldy, and if there are more than 1000 rows, it may not even compile. (How it looks like with extended events, I don't know.) Whatever, at the actual execution there is no extra table variable, but the data is streamed directly to the TVP, and this can be very efficient. Which you can't say about the INSERT statement, which has a large compilation overhead.


    Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
    • Marked as answer by AlexeyGa Wednesday, December 18, 2013 10:13 AM
    Friday, December 13, 2013 11:48 AM
  • If there may rows in the TVP, the INSERT statement is unwieldy, and if there are more than 1000 rows, it may not even compile. (How it looks like with extended events, I don't know.)

    The captured RPC in Extended Events looks similar to SQL Trace:

    declare @p3 dbo.TvpType  
    insert into @p3 values(0)  
    insert into @p3 values(1)  
    insert into @p3 values(2)  
    insert into @p3 values(3)  
    insert into @p3 values(4)  
    insert into @p3 values(5)  
    insert into @p3 values(6)  
    insert into @p3 values(7)  
    insert into @p3 values(8)  
    insert into @p3 values(9)    
    exec sp_executesql N'SELECT Col1 FROM @Tvp;',N'@Tvp [dbo].[TvpType] READONLY',@Tvp=@p3


    Dan Guzman, SQL Server MVP, http://www.dbdelta.com

    Friday, December 13, 2013 1:22 PM