Help: SQL Server

Sharing my knowlege about SQL Server Troubleshooting Skills

Archive for February, 2014

A-Z of In-Memory OLTP : Extended Events (XEvents)

Posted by blakhani on February 18, 2014


All of us want to know “internals” of many things. Doctors want to know internals of body; Engineer wants to know internals of machines. On the same line SQL DBA always wants to know internals of SQL Server. Sometimes there are easier ways to look at internals of SQL Server via extended events as compare to any other tool available. In this blog, we would have a look at the XEvents (eXtended Events) which are available to provide information about In-Memory OLTP. If you want to learn about XEvents, then start from Jonathan’s blog series (An XEvent a Day)

To get the list of XEvents which are related to In-Memory OLTP, we can either use query or Interface. There are three packages available for XTP (Hope you have read my initial blog of series which explains XTP, if not, read here)

Name Description
XtpRuntime Extended events for the XTP Runtime
XtpCompile Extended events for the XTP Compile
XtpEngine Extended events for the XTP Engine

 

We can view events for Registered Packages using below queries. I have modified the one available on books online. Here is the query and the output

USE msdb 

SELECT p.name, 
       c.event, 
       k.keyword, 
       c.channel, 
       c.description 
FROM   (SELECT event_package=o.package_guid, 
               o.description, 
               event=c.object_name, 
               channel=v.map_value 
        FROM   sys.dm_xe_objects o 
               LEFT JOIN sys.dm_xe_object_columns c 
                      ON o.name = c.object_name 
               INNER JOIN sys.dm_xe_map_values v 
                       ON c.type_name = v.name 
                          AND c.column_value = Cast(v.map_key AS NVARCHAR) 
        WHERE  object_type = 'event' 
               AND ( c.name = 'CHANNEL' 
                      OR c.name IS NULL )) c 
       LEFT JOIN (SELECT event_package=c.object_package_guid, 
                         event=c.object_name, 
                         keyword=v.map_value 
                  FROM   sys.dm_xe_object_columns c 
                         INNER JOIN sys.dm_xe_map_values v 
                                 ON c.type_name = v.name 
                                    AND c.column_value = v.map_key 
                                    AND 
                         c.type_package_guid = v.object_package_guid 
                         INNER JOIN sys.dm_xe_objects o 
                                 ON o.name = c.object_name 
                                    AND o.package_guid = c.object_package_guid 
                  WHERE  object_type = 'event' 
                         AND c.name = 'KEYWORD') k 
              ON k.event_package = c.event_package 
                 AND ( k.event = c.event 
                        OR k.event IS NULL ) 
       INNER JOIN sys.dm_xe_packages p 
               ON p.guid = c.event_package 
WHERE  name LIKE '%xtp%' 
        OR c.event LIKE '%xtp%' 
        OR c.description LIKE '%xtp%' 
        OR k.event LIKE '%xtp%' 
        OR k.keyword LIKE '%xtp%' 
ORDER  BY 1, 
          keyword DESC, 
          channel, 
          event  

Here is the output

Name Event keyword channel description
sqlserver natively_compiled_proc_slow_parameter_passing xtp Analytic Occurs when a Hekaton procedure call dispatch goes to slow parameter passing code path
sqlserver after_natively_compiled_proc_entry_removal_on_drop xtp Debug Fired after the procedure cache entry is flushed when dropping a natively compiled procedure.
sqlserver before_natively_compiled_proc_entry_removal_on_drop xtp Debug Fired before the procedure cache entry is flushed when dropping a natively compiled procedure.
sqlserver natively_compiled_proc_execution_started xtp Debug Fired before a natively compiled procedure is executed.
sqlserver xtp_create_procedure xtp Debug Occurs at start of XTP procedure creation.
sqlserver xtp_create_table xtp Debug Occurs at start of XTP table creation.
sqlserver xtp_deploy_done xtp Debug Occurs at completion of XTP object deployment.
sqlserver xtp_matgen xtp Debug Occurs at start of MAT generation.
sqlserver xtp_offline_checkpoint_scan_start xtp Debug Fired by XTP offline checkpoint when the checkpoint thread begins.
sqlserver xtp_offline_checkpoint_scan_stop xtp Debug Fired by XTP offline checkpoint when the checkpoint thread stops.
sqlserver xtp_recover_done xtp Debug Occurs at completion of log recovery of XTP table.
sqlserver xtp_recover_table xtp Debug Occurs at start of log recovery of XTP table.
sqlserver xtp_storage_table_create xtp Debug Occurs at just before the XTP storage table is created.
XtpCompile cgen deploy Debug Occurs at start of C code generation.
XtpCompile invoke_cl deploy Debug Occurs prior to the invocation of the C compiler.
XtpCompile mat_export deploy Debug Occurs at start of MAT export.
XtpCompile pit_export deploy Debug Occurs at start of PIT export.
XtpCompile pitgen_procs deploy Debug Occurs at start of PIT generation for procedures.
XtpCompile pitgen_tables deploy Debug Occurs at start of PIT generation for tables.
XtpEngine after_changestatetx_event transaction Debug Fires after transaction changes state
XtpEngine alloctx_event transaction Debug  
XtpEngine attempt_committx_event transaction Debug Is raised when a transaction is asked to commit
XtpEngine before_changestatetx_event transaction Debug Fires before transaction changes state
XtpEngine dependency_acquiredtx_event transaction Debug Raised after transaction takes a dependency on another transaction
XtpEngine endts_acquiredtx_event transaction Debug Fires after transaction acquires an end timestamp
XtpEngine redo_single_hk_record transaction Debug Redo on a HK log record
XtpEngine waiting_for_dependenciestx_event transaction Debug Raised when we have explicitly waited for dependencies to clear
XtpEngine xtp_create_log_record transaction Debug Fires when the XTP engine creates a log record.
XtpEngine gc_base_generation_evaluation gc Debug Indicates that an evaluation of updating the GC base generation has been made.
XtpEngine gc_base_generation_updated gc Debug Indicates that the oldest active transaction hint used for calculating the GC base generation has been updated.
XtpEngine gc_cycle_completed gc Debug Indicates that a GC notification has been enqueued.
XtpEngine gc_notification gc Debug Indicates that a GC notification has not being able to process a notification.
XtpEngine xtp_checkpoint_file_flush checkpoint Debug Indicates the point at which a given file has been flushed to disk.
XtpEngine xtp_checkpoint_file_flush_complete checkpoint Debug Indicates the point at which all in-flight buffers have been flushed to disk.
XtpEngine xtp_checkpoint_file_read checkpoint Debug Indicates reading of a file in XTP checkpoint recovery.
XtpEngine xtp_checkpoint_write_io checkpoint Debug Indicates that the checkpointing subsystem has issued or completed a write IO.
XtpEngine xtp_root_deserialized checkpoint Debug Indicates that the load of a checkpoint root is complete.
XtpEngine xtp_root_serialized checkpoint Debug Indicates that the write of the checkpoint root is complete.
XtpRuntime bind_md deploy Debug Occurs prior to binding metadata for a memory optimized table.
XtpRuntime bind_tables deploy Debug Occurs prior to binding tables for a natively compiled procedure.
XtpRuntime create_table deploy Debug Occurs prior to creating memory optimized table.
XtpRuntime deserialize_md deploy Debug Occurs prior to deserializing metadata.
XtpRuntime load_dll deploy Debug Occurs prior to loading the generated DLL.
XtpRuntime recover_done deploy Debug Occurs at completion of checkpoint recovery of a memory optimized table.
XtpRuntime recover_table deploy Debug Occurs at start of checkpoint recovery of a memory optimized table.
XtpRuntime serialize_md deploy Debug Occurs prior to serializing metadata.

 

This output shows something interesting. Notice that most of the events are under “Debug” Channel. This means, if we would go to wizard of creation of XEvent session in SSMS, we would not see them because Debug channel is not checked by default.

image

After checking Debug, we should be able to see the events. In below, I have put filter of work XTP.

image

Let’s use XEvent to understand a concept. We have learned that DLLs of table is loaded as soon as database is started whereas the stored procedure DLL is loaded when its first executed. We have already discussed this concepts in Behind the Scenes

To demonstrate, I have created below XEvent Session. My database already has table and natively compiled stored procedure.

 CREATE EVENT SESSION [SQLServerHelp] ON SERVER 

     ADD EVENT sqlserver.database_started 
        (ACTION(sqlos.cpu_id, sqlserver.database_id) 
            WHERE ([database_id] = (5)))
    ,ADD EVENT XtpRuntime.load_dll 
        (ACTION(sqlos.cpu_id, sqlserver.client_hostname)) 
        
    ADD TARGET package0.event_file (SET filename = N'SQLServerHelp')
    
    WITH (
            MAX_MEMORY = 4096 KB
            ,EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS
            ,MAX_DISPATCH_LATENCY = 30 SECONDS
            ,MAX_EVENT_SIZE = 0 KB
            ,MEMORY_PARTITION_MODE = NONE
            ,TRACK_CAUSALITY = OFF
            ,STARTUP_STATE = ON
            )
GO

 

I have put filter on database_id = 5 which you may want to change based on your system. After creating the session, I restarted SQL Server and after some time I executed stored procedure as well. As we can see in below that table DLL is loaded before database startup was complete.

image

Also notice that stored procedure DLL was loaded when I have manually executed stored procedure. Wow! extended events have confirmed our learning about DLLs generation and loading.

Conclusion

There are various extended events which can help us understand internals of hekaton / In-Memory OLTP. We will try to use more and see practical of theory which we have learned so far in this A-Z Series.

Hope you have learned something new today!

  • Cheers,
  • Balmukund Lakhani
  • Twitter @blakhani
  • Author: SQL Server 2012 AlwaysOnPaperback, Kindle
  • Advertisements

    Posted in A - Z Series, In Memory OLTP, In-Memory OLTP, SQL Server 2014 | Tagged: , , , , , , , , , , , , , , , | Leave a Comment »

    A-Z of In-Memory OLTP : Performance Monitor Counters

    Posted by blakhani on February 13, 2014


    Have you ever had a chance to see how athletes train? The coach is constantly watching the stopwatch while the athletes make multiple runs. The stopwatch is used to check the performance of students as they perform the run. In a similar way, SQL Server In-Memory OLTP performance can be monitored using Performance Monitor (PerfMon). In this blog we will discuss about some of the performance counters we can use to monitor various parameters of In-Memory OLTP.

    We must call out a difference between the way In-Memory OLTP counters (also known as XTP) vs. traditional counters are laid out in perfmon. If we look at earlier performance counters, the object is Instance specific and under that we have counter (Refer Image#1)

    image
    Image#1 Layout of Traditional SQL Counters

    On the other hand, for XTP the counter objects are listed first and under that we have instance names listed. (Refer Image#2)

    image
    Image#2 Layout of XTP related SQL Counters

    On my machine I only have one default instance and that’s why we see only MSSQLSERVER under “Instance of selected object”. In CTP2, we can see below performance monitor objects.

    XTP Cursors
    XTP Garbage Collection
    XTP Phantom Processor
    XTP Transaction Log
    XTP Transactions

    The list of various counters can be achieved using below SQL Server query.

    SELECT * 
    FROM sys.dm_os_performance_counters 
    WHERE object_name LIKE '%xtp%'
    

    image
    Image#3 SQL query to get list of XTP related SQL Counters

    The meaning of various counters is available on books online.

    To demonstrate one of the theory which we learned earlier, we would use “XTP Transaction Log” counter for demo. In this blog about transaction logging concepts, we read “Transaction log records are written only if the transaction on in-memory table is committed. This would mean that no UNDO information would be logged“.

    Here is the information about counters under “XTP Transaction Log” taken from book online

    Counter

    Description

    Log bytes written/sec

    The number of bytes written to the SQL Server transaction log by the XTP engine (on average), per second.

    Log records written/sec

    The number of records written to the SQL Server transaction log by the XTP engine (on average), per second.

     

    Here is the script which we can run and capture perform at the same time.

    Select Getdate() AS 'begin of Transaction 1'
    INSERT INTO [dbo].[MyFirstMemporyOptimizedTable]
        ([iID],[vFName],[vSite])
         VALUES
        (1,'Balmukund','SQLServer-Help.com')
    Select Getdate() AS 'End of Transaction 1'
    
    BEGIN TRAN
    Select Getdate()  AS 'begin of Transaction 2'
    INSERT INTO [dbo].[MyFirstMemporyOptimizedTable]
        ([iID],[vFName],[vSite])
         VALUES
        (2,'Balmukund','SQLServer-Help.com')
    -- Wait for 10 second
    waitfor delay '00:00:10'
    COMMIT TRAN
    Select Getdate()  AS 'commit of Transaction 2'
    
    BEGIN TRAN
    Select Getdate() AS 'begin of Transaction 3'
    INSERT INTO [dbo].[MyFirstMemporyOptimizedTable]
        ([iID],[vFName],[vSite])
         VALUES
        (3,'Balmukund','SQLServer-Help.com')
    -- Wait for 10 second
    waitfor delay '00:00:10'
    ROLLBACK TRAN
    Select Getdate() AS 'rollback of Transaction 3'
    
    

    Here is the output and perfmon data.

    image

    Image#4 perfmon counter and transaction

    Here are the conclusion we can make from the graph.

    • Logging is done at commit time of transaction. We introduced 10 second delay in our script and due to that second spike appears.
    • For uncommitted/rollback of transaction nothing is logged in transaction log.  

    Stay tune for learning more on Hekaton / In-Memory OLTP.

  • Cheers,
  • Balmukund Lakhani
  • Twitter @blakhani
  • Author: SQL Server 2012 AlwaysOnPaperback, Kindle
  • Posted in A - Z Series, In Memory OLTP, In-Memory OLTP, SQL Server 2014 | Tagged: , , , , , , , , , , , , , , , | Leave a Comment »

    A-Z of In-Memory OLTP : Garbage Collection (Part 2)

    Posted by blakhani on February 11, 2014


    In the previous blog of A-Z Series, we started learning about garbage collection; we have learned theory about garbage collection of stale rows in SQL Server In-Memory OLTP tables. If you have not read that, I would like you to start from part 1. There are below DMVs available to check the work done by garbage collection system.

    • sys.dm_xtp_gc_stats
    • sys.dm_xtp_gc_queue_stats
    • sys.dm_db_xtp_gc_cycle_stats – Database Level

    Before we move any forward, there is another important concept which would help in reading DMV data which is called as “generation”. We can think of generation as queue. There are 16 queues (generations) available in SQL Server 2014 CTP2. Generation queue holds the transaction which have generated versions. As per Kalen’s whitepaper, this number (16) can be changed later. The details of generation queue can be seen by DMV sys.dm_db_xtp_gc_cycle_stats. We would also see another queue which is equal to number of schedulers/cores on the machine. This GC worker queue contains the actual work which is queued by garbage collection process and statistics can be seen by DMV sys.dm_xtp_gc_queue_stats.

    On periodic basis, the transactions which have generated version is moved to the generation queue. GC threads picks up transaction from generation queues and keep them in GC worker queue. The frequency of checking completed transaction is 1 minute, which can be more aggressive if more transactions are waiting to be processed. Once the work is queued, the user threads can co-operate with main GC thread and clean the garbage which is kept in worker queue.

    Let’s see this in action. For demo purpose, I have created a wide-column table with around 30K rows. Here is the script which can be used.

    -- Create database with IMO Filegroup, If exists drop it.
    Use Master
    go
    If db_id('SQLSeverHelp_IMO') is NOT NULL
    drop database SQLSeverHelp_IMO
    GO
    CREATE DATABASE SQLSeverHelp_IMO 
        ON PRIMARY (
        NAME = [SQLSeverHelp_IMO_data]
        ,FILENAME = 'C:\IMO_Database\SQLSeverHelp_IMO.mdf'
        )
        
        ,FILEGROUP [SQLSeverHelp_IMO_FG] CONTAINS MEMORY_OPTIMIZED_DATA ( 
        NAME = [SQLSeverHelp_IMO_dir]
        ,FILENAME = 'C:\IMO_Database\SQLSeverHelp_IMO_dir'
        ) 
        
        LOG ON (
        NAME = [SQLSeverHelp_IMO_log]
        ,Filename = 'C:\IMO_Database\SQLSeverHelp_IMO_log.ldf'
        ) 
        COLLATE Latin1_General_100_BIN2 
    GO
    
    
    -- Create table in database
    -- use the database which is already created
    Use SQLSeverHelp_IMO
    GO
    CREATE TABLE MyFirstMemporyOptimizedTable
    (
    iID INT NOT NULL,
    vFName CHAR(900) NOT NULL,
    vSite CHAR(7000) NOT NULL,
    CONSTRAINT imo_pk_iID primary key NONCLUSTERED HASH (iID) WITH (BUCKET_COUNT = 1048576),
    index imo_idx_vFname  NONCLUSTERED HASH (vFName) WITH (BUCKET_COUNT = 8)
    ) WITH (MEMORY_OPTIMIZED = ON, DURABILITY = SCHEMA_AND_DATA)
    GO
    
    
    Use SQLSeverHelp_IMO 
    GO
    CREATE PROCEDURE [dbo].[InsertName] 
      WITH 
        NATIVE_COMPILATION, 
        SCHEMABINDING, 
        EXECUTE AS OWNER
    AS 
    BEGIN ATOMIC 
      WITH 
    (TRANSACTION ISOLATION LEVEL = SNAPSHOT,
     LANGUAGE = 'us_english')
     
    DECLARE @counter INT 
    SET @counter = 1
    
    WHILE @counter <= 30000
      BEGIN 
          INSERT INTO dbo.MyFirstMemporyOptimizedTable 
          VALUES      (@counter, 
                       'SQLServer-Help.com', 
                       'Balmukund Lakhani');
          INSERT INTO dbo.MyFirstMemporyOptimizedTable 
          VALUES      (@counter + 1, 
                       'ExtremeExperts.com', 
                       'Vinod Kumar M');
          INSERT INTO dbo.MyFirstMemporyOptimizedTable 
          VALUES      (@counter + 2, 
                       'SQLAuthority.Com', 
                       'Pinal Dave') 
    
          SET @counter = @counter + 3 
      END
    END
    GO
    
    exec InsertName
    go
    
    

     

    After creating the objects and pumping the data, I have recycled SQL Services to clear the data in DMVs. It’s worth mentioning that this should not be done with production server. Post restart, I waited for some time so that sys.dm_db_xtp_gc_cycle_stats has some rows. Recall that GC thread starts at approximately 1 min. I have not done any transaction and that’s why “base_generation” stays as 1. We can also see 16 generations as column in each row.

    USE    SQLSeverHelp_IMO
    go
    select    * 
    from    sys.dm_db_xtp_gc_cycle_stats

    image

    Each row corresponds to one cycle when GC has scanned committed transactions. If we try to see the difference between start of two rows, its 60000 ticks which is 60 seconds. I have used CTE in below query to find the same.
    WITH tbldifference 
         AS (SELECT Row_number() 
                      OVER ( 
                        ORDER BY ticks_at_cycle_start) AS RowNumber, 
                    cycle_id, 
                    ticks_at_cycle_start, 
                    base_generation 
             FROM   sys.dm_db_xtp_gc_cycle_stats)
    -- CTE 
    SELECT Cur.cycle_id, 
           Cur.ticks_at_cycle_start                            AS CurrentTickstValue , 
           Prv.ticks_at_cycle_start                            AS PreviousTicksValue, 
           Cur.ticks_at_cycle_start - Prv.ticks_at_cycle_start AS Difference, 
           Cur.base_generation 
    FROM   tbldifference Cur 
           LEFT OUTER JOIN tbldifference Prv 
                        ON Cur.RowNumber = Prv.RowNumber + 1 
    ORDER  BY Cur.ticks_at_cycle_start  
     
    image
     
    If we check server startup time in minutes and number of cycles, they would be same.
    USE SQLSeverHelp_IMO
    go
    select count(*) from sys.dm_db_xtp_gc_cycle_stats
    go
    
    SELECT Datediff(mi, last_startup_time, Getutcdate()) 
           'Minutes Since Last restart' 
    FROM   sys.dm_server_services 
    WHERE  servicename = 'SQL Server (MSSQLSERVER)' 
    
     
    image
     
    Based on above, its clear that cycle is running every minute. We have not performed any update or delete to generate stale rows so far. Here is the memory used by table. Query available here.
    image
     
    Now, let’s generate garbage rows and check the DMVs again. We are going to delete 1000 rows.
     
    DECLARE @i INT 
    SET @i = 1 
    WHILE ( @i <= 1000 ) 
      BEGIN 
          DELETE FROM MyFirstMemporyOptimizedTable 
          WHERE  vFName = 'SQLServer-Help.com' 
                 AND iID <= @i * 3 
          SET @i = @i + 1 
      END   
    
    
     
    As soon as rows are deleted, we would start seeing activity on garbage collection. If we can same query to find cycles again, here is the output
     

    cycle_id             CurrentTickstValue   PreviousTicksValue   Difference           base_generation

    ——————– ——————– ——————– ——————– ——————–

    …. Truncated for clarity….

    41                   92361828             92301828             60000                1

    42                   92421828             92361828             60000                1

    43                   92481828             92421828             60000                1

    44                   92504781             92481828             22953                1

    45                   92564781             92504781             60000                993

    46                   92565281             92564781             500                  993

    47                   92625281             92565281             60000                993

    48                   92685281             92625281             60000                993

    49                   92745281             92685281             60000                993

    50                   92805281             92745281             60000                993

    (50 row(s) affected)

     
    As we can see above that cycle have become more aggressive (less than 60 seconds) as we did a lot of transaction. Also notice that base generation moves in multiple of 16 (explained earlier) 993-1 = 992 = 62*16. I have to do minimum 16 transactions to increase the base generation.
     
    Now, let’s look at output of DMV sys.dm_xtp_gc_queue_stats
     
    image
    We can see that work was enqueued, got dequeued and current_queue_length is zero. This means there is no garbage data in the queue. Let’s check memory usage of table.
    image
    This means garbage collection has done it’s work and free’ed up memory used by table as unused memory has increased.
     
    We would continue to explore more on garbage collection in next blog as well.
     
     
  • Cheers,
  • Balmukund Lakhani
  • Twitter @blakhani
  • Author: SQL Server 2012 AlwaysOnPaperback, Kindle
  • Posted in A - Z Series, In Memory OLTP, In-Memory OLTP, SQL Server 2014 | Tagged: , , , , , , , , , , , | Leave a Comment »