none
extended event trace on event rpc_completed not capturing sql_text action (Unable to retrieve SQL text)

    Question

  • I create this session: 
    CREATE EVENT SESSION rpc_completed ON SERVER 
    	ADD EVENT sqlserver.rpc_completed (
    		ACTION (	sqlserver.sql_text								
    				,	sqlserver.database_id				
    				,	sqlserver.client_hostname
    				,	sqlserver.client_app_name
    				) 
    				WHERE sqlserver.database_id = 5
    				AND sqlserver.client_hostname = 'MyHostName'
    		)	
    	ADD TARGET package0.asynchronous_file_target
    	(SET	filename='D:\MyHostName.xel'
    	,		metadatafile='D:\MyHostName.xem'
     )
    
     
    Most statements get captured, but there is a particular application that has extremely long argument values being passed in as XML.  These rpc_completed sql_text values NEVER come back, it is always 'Unable to retrieve SQL text'.  If I use profiler I can see the textdata has a length usually around 12,000 to 14,000 characters, but sometimes it is even down as low as 2-300 characters and it still never shows up.
     
    Is it because the text is XML or because of the length?
     
    The profiler textdata shows something like this: 
    declare @p2 xml
    set @p2=convert(xml,N'<Orders><Order><OrderID>121118</OrderID><CreateDate>....(abbreviated)...</Orders>')
    declare @p3 varchar(max)
    set @p3=''
    declare @p4 varchar(max)
    set @p4=''
    exec [dbo].mySproc @p_SpaceID=703,@p_ObjectXml=@p2 output,@p_SummaryMsg=@p3 output,@p_DetailMsg=@p4 output
    select @p2, @p3, @p4
    
     
    I actually don't need the @p2 variable and its assignment, I only need the exec statement forward.  Is there a way I can limit the sql_text (applying a substring type operator if a certain condition exists)? 
    Also, there is also no plan_handle if I add that action, it is always:

    0x000000000000000000000000000000000000000000000000

     
    <event name="rpc_completed" package="sqlserver" id="64" version="1" timestamp="2011-04-19T22:41:44.307Z">
     <data name="cpu">
     <value>281</value>
     <text />
     </data>
     <data name="duration">
     <value>290</value>
     <text />
     </data>
     <data name="reads">
     <value>50561</value>
     <text />
     </data>
     <data name="writes">
     <value>0</value>
     <text />
     </data>
     <action name="sql_text" package="sqlserver">
     <value>Unable to retrieve SQL text</value>
     <text />
     </action>
     <action name="plan_handle" package="sqlserver">
     <value>&lt;plan handle='0x000000000000000000000000000000000000000000000000'/&gt;</value>
     <text />
     </action>
     <action name="database_id" package="sqlserver">
     <value>5</value>
     <text />
     </action>
     <action name="client_hostname" package="sqlserver">
     <value>hostname</value>
     <text />
     </action>
     <action name="client_app_name" package="sqlserver">
     <value>appname</value>
     <text />
     </action>
    </event>
    
    I have tried ring buffer as a target with the same result, as well as different WITH options but no luck (may be because I haven't found right property to adjust).
    Has anyone else seen this and found a way to overcome it?
    This is SQL 2008 SP2 CU8 EE
    Many thanks,
    Robert Towne
     

    • Edited by sqlserver411 Tuesday, April 19, 2011 11:32 PM clarification
    Tuesday, April 19, 2011 11:30 PM

All replies

  • Add the sqlserver.module_end event to the session which fires when the SP:Completed event in trace used to fire, and then turn CAUSALITY_TRACKING on for the event session so that you can match the events up using their attach_activity_id actions.  If all you need is the proc name, use the object_id returned by the sqlserver.module_end event inside of OBJECT_NAME() to get the procedure being executed.

    Jonathan Kehayias | Senior Consultant, SQLSkills.com
    SQL Server MVP | Microsoft Certified Master: SQL Server 2008
    Feel free to contact me through My Blog or Twitter
    Please click the Mark as Answer button if a post solves your problem!

    • Proposed as answer by mbourgon Friday, June 29, 2012 8:35 PM
    Wednesday, April 20, 2011 2:44 PM
    Moderator
  • Thanks for the answer, Jonathan. The module_end event won't give me the SQL parameters being passed in normally to rpc_completed though, will it?

     

    In other words, I need the exec statement, not all the parameter assignment prior typically seen in in rpc_completed. In particular I need the highlighted bit below.

     

    declare @p2 xml
    set @p2=convert(xml,N'<Orders><Order><OrderID>121118</OrderID><CreateDate>....(abbreviated)...</Orders>')
    declare @p3 varchar(max)
    set @p3=''
    declare @p4 varchar(max)
    set @p4=''
    exec [dbo].mySproc @p_SpaceID=703,@p_ObjectXml=@p2 output,@p_SummaryMsg=@p3 output,@p_DetailMsg=@p4 output
    select @p2, @p3, @p4

     

    The root problem I am still not sure of, is it because of the length of the sql_text or the fact that it contains XML that it isn't showing?

     

    Thanks for the help..

     

    Robert

     

     

     

    Wednesday, April 20, 2011 7:22 PM
  • Hi Guys,

     

    We are experiencing the same issue. Extended events does not show the SQL text while profiler does.

    I am trying to look for solutions and would be happy to hear if you come up with one.

    discovering the parameters to the SP is essential for our investigation of a bottleneck we have.

     

    Thanks

    DB

    Wednesday, August 10, 2011 8:05 AM
  • In either scenario, you need to us causality tracking at the session level by setting TRACK_CAUSALITY = ON for the sessions options and then to really be able to use the information, you have to add additional events into the session, for example sqlserver.rpc_starting, sqlserver.rpc_completed, so that you can match the lead starting event to the final completed event and then track all the inner related events using the activity_xref_id field that is appended to the events by causality tracking.

    Jonathan Kehayias | Senior Consultant, SQLSkills.com
    SQL Server MVP | Microsoft Certified Master: SQL Server 2008
    Feel free to contact me through My Blog or Twitter. Become a SQLskills Insider!
    Please click the Mark as Answer button if a post solves your problem!

    Thursday, August 18, 2011 3:02 PM
    Moderator
  • I have the same problem. In Sql profiler, i can see sql text with the RPC.completed event but it doesnt work in extended events.

    CREATE EVENT SESSION [dml_on_db]
    ON SERVER
    ADD EVENT sqlserver.lock_acquired(
       ACTION (sqlserver.sql_text)
       WHERE (([sqlserver].[database_id]=(120)))),
    ADD EVENT sqlserver.rpc_completed(
       ACTION (sqlserver.sql_text)
       WHERE (([sqlserver].[database_id]=(120))))
    ADD TARGET package0.asynchronous_file_target(
       SET filename='G:\ExtendedEvents\EE.xel', METADATAFILE='G:\ExtendedEvents\EE.xem')
    WITH (MAX_MEMORY = 4096KB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY = 1 SECONDS, MAX_EVENT_SIZE = 0KB, MEMORY_PARTITION_MODE = NONE, TRACK_CAUSALITY = ON, STARTUP_STATE = OFF)



    MCSA, MCDBA
    Tuesday, August 30, 2011 8:06 AM
  • I have the same problem. In Sql profiler, i can see sql text with the RPC.completed event but it doesnt work in extended events.

     

    CREATE EVENT SESSION [dml_on_db]
    
    ON SERVER
    
    ADD EVENT sqlserver.lock_acquired(
    
      ACTION (sqlserver.sql_text)
    
      WHERE (([sqlserver].[database_id]=(120)))),
    
    ADD EVENT sqlserver.rpc_completed(
    
      ACTION (sqlserver.sql_text)
    
      WHERE (([sqlserver].[database_id]=(120))))
    
    ADD TARGET package0.asynchronous_file_target(
    
      SET filename='G:\ExtendedEvents\EE.xel', METADATAFILE='G:\ExtendedEvents\EE.xem')
    
    WITH (MAX_MEMORY = 4096KB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY = 1 SECONDS, MAX_EVENT_SIZE = 0KB, MEMORY_PARTITION_MODE = NONE, TRACK_CAUSALITY = ON, STARTUP_STATE = OFF)


     


    MCSA, MCDBA

    Have you tried following the previous recommendation in this thread of adding the sqlserver.module_end event and using TRACK_CAUSALITY at the session level to correlate the events?  If this doesn't work for you, you will need to revert back to SQL Trace to capture the information you are after in SQL Server 2008.

    Jonathan Kehayias | Principal Consultant, SQLSkills.com
    SQL Server MVP | Microsoft Certified Master: SQL Server 2008
    Feel free to contact me through My Blog or Twitter. Become a SQLskills Insider!
    Please click the Mark as Answer button if a post solves your problem!

    Tuesday, August 30, 2011 8:14 AM
    Moderator
  • I am sorry for giving half cooked info earlier.

    In my case, for ext event capture, lock escalation and rpc completed catch sqltext but it looks like "*Password-------------------------------------------------".Do you think the java sql driver is a reason for this ?

    I tried module_end event but i guess its not getting fired in my case.


    MCSA, MCDBA
    Tuesday, August 30, 2011 9:29 AM
  • I am sorry for giving half cooked info earlier.

    In my case, for ext event capture, lock escalation and rpc completed catch sqltext but it looks like "*Password-------------------------------------------------".Do you think the java sql driver is a reason for this ?

    I tried module_end event but i guess its not getting fired in my case.


    MCSA, MCDBA


    If the sql_text Action returns:

      <action name="sql_text" package="sqlserver">
       <type name="unicode_string" package="package0" />
       <value>*password------------------------------</value>
       <text />
      </action>
    

    the text was stripped by the engine because it contained a password reference in it.  This functionality occurs in SQL Trace as well and is a security measure to prevent passwords from being returned in the trace results. 

    What specifically are you trying to do with your Event Session here?  The lock_acquired event shouldn't be used in an Event Session that specifies a MAX_DISPATCH_LATENCY of 1 second and allowing SINGLE_EVENT_LOSS on a busy production system.  I use configurations like that in my blog posts for examples because I am working on limited activity test systems but I wouldn't set MAX_DISPATCH_LATENCY to 1 SECOND on any production implementation writing to a file target, unless you have a customized polling process that reads the file continuously with offset parsing to harvest the data in near real time.  I covered all the session options in my blog post:

    http://sqlskills.com/blogs/jonathan/post/An-XEvent-a-Day-(26-of-31)-Configuring-Session-Options.aspx 

    I also provide the same disclaimer made above about the options shown in my other blog posts.  They don't apply to actual production work.

    Post further details about what you are trying to figure out and I'd be happy to try and help, but you aren't going to get around the password in text issue.

     

     


    Jonathan Kehayias | Principal Consultant, SQLSkills.com
    SQL Server MVP | Microsoft Certified Master: SQL Server 2008
    Feel free to contact me through My Blog or Twitter. Become a SQLskills Insider!
    Please click the Mark as Answer button if a post solves your problem!

    Tuesday, August 30, 2011 3:49 PM
    Moderator
  • Yes, i talked to our Java developer and they are encrypting password field only when storing user info. But then what is extended events looking out for, keywords like "password" etc and strips them off ?

    Also i can get the whole sql text without any stripping off from Sql trace:-

    this is the output of the trace

    declare @p1 int
    set @p1=170
    exec sp_prepexec @p1 output,N'@P0 bit,@P1 datetime2,@P2 nvarchar(4000),@P3 nvarchar(4000),@P4 nvarchar(4000),@P5 smallint,@P6 nvarchar(4000),@P7 nvarchar(4000),@P8 varchar(8000),@P9 int,@P10 nvarchar(4000),@P11 int',N'insert into mytable (IsActive, Created, Email, FirstName, LastName, NumFailedLogins, Password, PasswordSalt, Phone, StaffRoleId, UserName, Version) values (@P0, @P1, @P2, @P3, @P4, @P5, @P6, @P7, @P8, @P9, @P10, @P11)                                                select SCOPE_IDENTITY() AS GENERATED_KEYS',1,'2011-08-30 17:53:35.4920000',N'none@company.com',N'none',N'none',0,N'1acdcd67b54adf96c3d1e34b03c07022',N'82636e24-3ff2-470b-8f44-e338124415cf',NULL,1,N'none',NULL
    select @p1


    I am using extended events in functional test environments to check if the application is not abusing the database and is taking the right locks.

    Anyways it was good to know about this. Thank you for your help.


    MCSA, MCDBA
    Tuesday, August 30, 2011 3:59 PM
  • Alright extended event doesnt capture any sql text which has keyword "password" in it.

    For eg. if you insert in a table

     

    INSERT INTO badm VALUES(455,'')
    go
    INSERT INTO badm(srno,password) VALUES(158,'')
    GO
    
    

    Extended event will not capture the second statement. This should be fixed.

    Right now we trace newly developed features, as to how they are performing locks and we dont see some sql stmts in the trace. To me it sounds like extended event cannot be trusted.


    MCSA, MCDBA
    Thursday, September 15, 2011 4:18 PM
  • Alright extended event doesnt capture any sql text which has keyword "password" in it.

    For eg. if you insert in a table

     

    INSERT INTO badm VALUES(455,'')
    
    go
    
    INSERT INTO badm(srno,password) VALUES(158,'')
    
    GO
    
    
    
    

    Extended event will not capture the second statement. This should be fixed.

    Right now we trace newly developed features, as to how they are performing locks and we dont see some sql stmts in the trace. To me it sounds like extended event cannot be trusted.


    MCSA, MCDBA

    In this case Extended Events is actually working as designed.  The SQL_Text action uses a different code path in the engine to retrieve the InputBuffer for the event, which performs this stripping when password is included in the statement executing.  SQL Trace did this same thing until a change was made in 2005 to use the post parsed text output by the parser so that only DDL operations would strip the password out as --*CREATE LOGIN ------------------------------------

    In SQL Denali, you get the statement and batch_text customizable columns on the sql_statement_starting/completed and sql_batch_starting/completed events which matches the current profiler functionality of using the post parsed text for the statement.  Your expectation of the sql_text is providing in this case is incorrect.  I had discussions about this with the PM for Extended Events at Microsoft to confirm, but this is functioning as designed.  You need to wait for the statement and batch_text columns in Denali to the functionality you are expecting.


    Jonathan Kehayias | Principal Consultant, SQLSkills.com
    SQL Server MVP | Microsoft Certified Master: SQL Server 2008
    Feel free to contact me through My Blog or Twitter. Become a SQLskills Insider!
    Please click the Mark as Answer button if a post solves your problem!

    Friday, September 16, 2011 2:21 PM
    Moderator
  • To turn CAUSALITY_TRACKING on: put "TRACK_CAUSALITY = ON" in the WITH phrase.

    (this is mentioned lower in the thread by Jonathan; putting it here to make it more obvious)

    Friday, June 29, 2012 8:37 PM