Category: "SQL Trace & Profiler"

Dieser Blog ist umgezogen // This Blog has moved: http://andreas-wolter.com/blog/

Sep 20th

Posted by Andreas Wolter in Miscellaneous

No comments

http://andreas-wolter.com/blog/

Liebe Leser
dieser Blog ist hiermit nur noch „Archiv“ und wird nicht mehr weiter gepflegt.
Seit August 2017 finden sich neue Artikel ausschließlich unter der neuen URL:
http://andreas-wolter.com/blog/

Dear Readers
this blog is now merely an „archive“ and no longer being updated.
Since August 2017 new articles are exclusively available under the new URL:
http://andreas-wolter.com/en/blog/

Die aufwändige Mehrsprachigkeit (Deutsch und Englisch professionell manuell übersetzt) wird beibehalten – aber Layout-technisch anders gelöst. Damit dürfte ich immer noch den einzigen mehrsprachigen IT-Blog weltweit betreiben.
Ich hoffe, das neue Design gefällt Ihnen.

The complex multilingualism (German and English professionally manually translated) is being continued – but solved differently in terms of layout. With that I most likely still operate the only multilingual IT-Blog worldwide.
I hope you like the new design.

 

 

Mein aktueller Artikel, der erstmalig ausschließlich auf der neuen Website zu finden ist, lautet: Optimieren von Workflows mit In-Memory und nativ kompilierten Objekten - oder wie es nicht funktioniert

My currently last article, which is exclusively available at the new website for the first time, is Optimizing workflows with In-Memory and Natively Compiled Objects - or how it does not work

 

Cu at my new Blog

Andreas

New Extended Events for Tracing in SQL Server 2014

Apr 5th

Posted by Andreas Wolter in Extended Events

2 comments

Neue “Erweiterte Ereignisse” (XEvents) für Tracing in SQL Server 2014

(de)
Dieser Artikel enthält eine Liste der neuen Erweiterte Ereignisse (“Extended Events”), dem Tracing Framework in SQL Server in dem neuen 2014 Release.

Zunächst gibt es 3 neue Pakete („Packages“), die alle zu der neuen Arbeitsspeicher(„In-Memory“) -OLTP Engine: XTP, aufgeteilt auf 3 DLLs:

(en)
This article contains a list of new Extended Events, the tracing framework in SQL Server in the new 2014 release.

To begin with there are 3 new packages, all belonging to the new In-Memory OLTP Engine: XTP, split up into 3 dlls:

 

Package

description

Module name

XtpRuntime

Extended events for the XTP Runtime

{InstanceDir}\MSSQL\Binn\
hkruntime.dll

XtpEngine

Extended events for the XTP Engine

{InstanceDir}\MSSQL\Binn\
hkengine.dll

XtpCompile

Extended events for the XTP Compile

{InstanceDir}\MSSQL\Binn\
hkcompile.dll

 

Die Anzahl der Extended Events ist von 625 in SQL Server 2012 (SP1) auf 870 in SQL Server 2014 (RTM) angestiegen. Das sind 245 neue Events! – Reichlich Möglichkeiten, in Internas einzutauchen :-)
2 Events sind umbenannt worden:

recovery_incremental_checkpoint in

recovery_indirect_checkpoint

und hekaton_slow_param_passing in

natively_compiled_proc_slow_parameter_passing

Ja, richtig gelesen. Es gab bereits im SQL Server 2012 eine Anzahl an Events für die XTP Engine. Es kommt recht häufig vor, dass man Bits von zukünftigen Entwicklungen in der aktuellen Release findet.

Nebenbei: SQL Trace wurde nicht im geringsten angefasst. Die Anzahl von SQL Trace Events bleibt mit 180 seit SQL Server 2008 stabil. – Here ist ein Überblick von Extended Events gegen SQL Trace Events in den verschiedenen SQL Server Versionen: Extended Events vs SQL Trace im Vergleich – oder warum SQL Trace & Profiler einfach von gestern sind :-)

Weiter zu XEvents: es gibt keine neuen Prädikate, aber eine Anzahl neuer Maps, was natürlich nicht überrascht bei der Menge neuer Events.
Targets, Actions, Typen und Session Optionen  sind unverändert.

Und hier ist die Liste der neuen Extended Events:

The number of Extended Events increased from 625 in SQL Server 2012 (SP1) to 870 in SQL Server 2014 (RTM). That makes 245 new events! – Plenty of opportunities to look into internals :-)
2 events have been renamed:

recovery_incremental_checkpoint into

recovery_indirect_checkpoint

and hekaton_slow_param_passing into

natively_compiled_proc_slow_parameter_passing

Yes, you read correctly. There have already been a couple of events for the new XTP engine within SQL Server 2012. It’s quite common that you can find bits of future developments within the current release.

By the way: SQL Trace has not been touched by the slightest bit. The number of SQL Trace events stays at 180 since SQL Server 2008. – here you find an overview of the number of Extended Events vs SQL Trace events in the various SQL Server versions: Comparing Extended Events vs SQL Trace – or why SQL Trace & Profiler are just a thing of the past :-)

Continuing with XEvents: There are no new predicates, but a couple more maps, which is of course not surprisingly considering the amount of new events.
Targets, actions, types and session options are unchanged.

And here is the list of all new extended events:

 

Package
name		 Event name Description
qds query_store_async_shutdown_failed Fired when query store encounters an error during async query store shutdown
qds query_store_background_cleanup_task_failed Fired if the background task for cleanup of QDS stale data is not completed successfully
qds query_store_background_task_creation_failed Fired if the background task for QDS data persistence could not be created
qds query_store_background_task_initialization_failed Fired if the background task for QDS data persistence could not be initialized
qds query_store_background_task_persist_failed Fired if the background task for QDS data persistence is not completed successfully
qds query_store_begin_persist_runtime_stat Fired immediately before current runtime statistics for a query plan is persisted to the database.
qds query_store_bloom_filter_false_positive Fired if the Bloom filter for QDS statement texts gives a false positive result
qds query_store_check_consistency_init_failed Fired when check consistency task fails during initialization
qds query_store_database_initialization_failed Fired if initialization of the Query Store for database has failed. The Query Store will be disabled for this database
qds query_store_db_cleanup__finished Fired if cleanup of QDS stale data finished for particular database.
qds query_store_db_cleanup__started Fired if cleanup of QDS stale data started for particular database.
qds query_store_disk_size_check_failed Fired when a check against Query Store on-disk size limit fails
qds query_store_disk_size_info Fired when a check against QDS on-disk size is performed
qds query_store_execution_runtime_info Fired when runtime information is sent to the query store.
qds query_store_execution_runtime_info_discarded Fired when runtime information sent to the query store is discarded.
qds query_store_execution_runtime_info_evicted Fired when runtime information sent to the query store is evicted.
qds query_store_flush_failed Fired when query store failed to flush dirty data
qds query_store_loaded Fired when query store is loaded
qds query_store_notify_dirty_shutdown_on_partition_startup Fired when previous instance of query store for the partition is shutdown by force in order to allow creation of a new instance
qds query_store_notify_force_failure_failed Fired when query store failed to notify force failure
qds query_store_persist_task_init_failed Fired when persist task fails during initialization
qds query_store_plan_forcing_failed Occurs when forcing of plan from qds fail
qds query_store_plan_persistence_failure Fired if there's a failure to persist plan
qds query_store_plan_removal Fired when plan is removed
qds query_store_query_persistence_failure Fired if there's a failure to persist query
qds query_store_read_write_failed Fired if the read/write to Query Store internal tables failed
qds query_store_statement_not_found Fired in case when statement couldn't be found due to race condition or ambiguous user request.
qds query_store_unloaded Fired when query store is unloaded from memory
sqlos nonpreemptive_long_syncio record long sync io operation in nonpreemptive worker
sqlos stuck_dispatcher_callback_executed Stuck dispatcher callback executed
sqlos wait_completed Occurs when there is a wait completed on a SQLOS controlled resource.  Use this event to track wait completion.
sqlserver after_natively_compiled_proc_entry_removal_on_drop Fired after the procedure cache entry is flushed when dropping a natively compiled procedure.
sqlserver availability_replica_state Occurs when the Availability Replica is starting or shutting down.
sqlserver before_natively_compiled_proc_entry_removal_on_drop Fired before the procedure cache entry is flushed when dropping a natively compiled procedure.
sqlserver before_redo_lsn_update Occurs just prior to the update of the EOL LSN
sqlserver buffer_pool_eviction_thresholds_recalculated Lazywriter and/or worker clock has wrapped the BUF array and thresholds are re-calculated.
sqlserver buffer_pool_extension_pages_evicted Page is evicted from the buffer pool extension cache.
sqlserver buffer_pool_extension_pages_read Page is read from the buffer pool extension cache.
sqlserver buffer_pool_extension_pages_written Page or contiguous set of pages evicted into the buffer pool extension cache.
sqlserver check_phase_tracing Occurs when DBCC CHECK enters a new phase of the checking. Use this event to trace the phases of DBCC CHECK process.
sqlserver check_thread_message_statistics Occurs when a phase of DBCC CHECK is finished. Use this event to collect the number of messages a DBCC CHECK thread has sent or received.
sqlserver check_thread_page_io_statistics Occurs when a phase of DBCC CHECK is finished. Use this event to collect the number of logical, physical, and read-ahead IOs a DBCC CHECK thread has performed.
sqlserver check_thread_page_latch_statistics Occurs when a phase of DBCC CHECK is finished. Use This event to collect the number and time of page latch and IO latch waits.
sqlserver clustered_columnstore_index_rebuild Occurs when clustered index on the table was rebuilt. This event is raised three times for ALTER index rebuild operation on CCSI. The event is raised when the operation takes lock on index rebuild resource, when lock is taken on the table and when S lock on the table is upgraded to SCH_M lock to switch indexes in metadata.
sqlserver column_store_code_coverage Code coverage Xevent for columnstore code.
sqlserver column_store_index_build_low_memory Occurs when Storage Engine detects low memory condition and the rowgroup size is reduced.
sqlserver column_store_index_build_process_segment Occurs when a segment is processed
sqlserver column_store_index_build_throttle Shows the statistics of columnstore index build parallelism throttling
sqlserver columnstore_tuple_mover_begin_compress Occurs when column store tuple mover starts compressing a deltastore.
sqlserver columnstore_tuple_mover_end_compress Occurs when column store tuple mover is done compressing a deltastore.
sqlserver database_xml_deadlock_report Produces a deadlock report for a victim, with information scoped to the victim's database.
sqlserver db_lock_acquired_from_cache Occurs when a DB lock is acquired from the XactWorkspace DB lock cache.
sqlserver db_lock_released_from_cache Occurs when a DB lock is released from the XactWorkspace DB lock cache.
sqlserver ddl_with_wait_at_low_priority A DDL statement was executed using the WAIT_AT_LOW_PRIORITY options
sqlserver diag_quantum_end Occurs when the diag is notified of quantum end.
sqlserver dyn_throttle_checkpoint Occurs when checkpointing has been dynamically throttled with a new Checkpoint rate.
sqlserver feature_extension Occurs when received and parses data for a feature in feature extension.
sqlserver file_handle_in_use Fired when a file handle we're trying to delete is in use and we don't expect it to be. The typical response is dumping all the handles in the system via SysInternals HANDLE.EXE
sqlserver file_read_enqueued File read enqueued
sqlserver file_read_throttled File read throttled
sqlserver file_write_enqueued File write enqueued
sqlserver file_write_throttled File write throttled
sqlserver ghost_cleanup_task_packet_enqueue A task packet is enqueued
sqlserver ghost_cleanup_task_process_packet A task packet is dequeued and processed
sqlserver ghost_cleanup_task_process_pages_for_db_packet Purge the pages that contain ghost records found in a database
sqlserver ghost_cleanup_task_start Ghost cleanup task start
sqlserver ghost_cleanup_task_suspend Ghost cleanup task suspend
sqlserver hadr_tds_synchronizer_payload_skip Hadron Tds Listener Synchronizer skipped a listener payload because there were no changes since the previous payload.
sqlserver lock_request_priority_state The priority state of a lock request
sqlserver log_cache_write_block Writing a log block to the log cache
sqlserver metadata_ddl_add_column Occurs when an ALTER TABLE ADD column operation is updating base index.
sqlserver metadata_ddl_alter_column Occurs when an ALTER TABLE ALTER column operation is updating base index.
sqlserver metadata_ddl_drop_column Occurs when an ALTER TABLE DROP column operation is updating base index.
sqlserver mixed_extent_activation Track mixed extent activation and deactivation operations.
sqlserver mixed_extent_allocation Track mixed extent allocation operations
sqlserver mixed_extent_deallocation Track mixed extent deallocation operations.
sqlserver mixed_page_allocation Track mixed page allocation operations
sqlserver mixed_page_deallocation Track mixed page allocation operations
sqlserver mixed_page_scan_file Track the activity of SGAM scans for mixed page allocation
sqlserver mixed_page_scan_page Track the activity of SGAM scans for mixed page allocation
sqlserver mixed_page_skipextent Track the activity of SGAM scans for mixed page allocation
sqlserver natively_compiled_proc_execution_started Fired before a natively compiled procedure is executed.
sqlserver natively_compiled_proc_slow_parameter_passing Occurs when a Hekaton procedure call dispatch goes to slow parameter passing code path
sqlserver process_killed_by_abort_blockers A process is killed by an ABORT = BLOCKERS DDL statement
sqlserver query_execution_batch_hash_aggregation_finished Occurs at the end of batch hash aggregation.
sqlserver query_execution_batch_hash_children_reversed Occurs each time when hash join reverses build and probe side while processing data spilled to disk.
sqlserver query_execution_batch_hash_join_spilled Occurs each time when hash join spills some data to disk in batch processing.
sqlserver query_optimizer_estimate_cardinality Occurs when the query optimizer estimates cardinality on a relational expression.
sqlserver query_optimizer_force_both_cardinality_estimation_behaviors Both traceflags 2312 and 9481 were enabled, attempting to force both old and new cardinality estimation behaviors at the same time. The traceflags were ignored. Disable one or both of the traceflags.
sqlserver query_store_failed_to_capture_query Fired if the Query Store failed to capture query. The Query Store will not track statistics for this query
sqlserver query_store_failed_to_load_forced_plan Fired if the query failed to load forced plan from QDS. Forcing policy will not be applied
sqlserver query_store_persist_on_shutdown_failed Occurs when SQL Server fails to store dirty entries in Query Store on database shutdown.
sqlserver recovery_indirect_checkpoint Chose to enqueue an indirect checkpoint as we are near our recovery target
sqlserver remove_database_cache Remove database cache
sqlserver server_max_workers Occurs when a request enqueue fails because a worker was not guaranteed.
sqlserver session_recoverable_state_change Occurs when the server determines a state change in term of session recovery on a connectionresilency-enabled connection.
sqlserver sql_transaction_commit_single_phase Occurs when a sql transaction is committed with single phase commit.
sqlserver xfcb_blob_properties_obtained Windows Azure Storage blob property is obtained from response header.
sqlserver xfcb_failed_request Failed to complete a request to Windows Azure Storage.
sqlserver xfcb_header_obtained Response header is obtained from request to Windows Azure Storage.
sqlserver xfcb_read_complete Read complete from Windows Azure Storage response.
sqlserver xfcb_request_opened A request is opened to Windows Azure Storage.
sqlserver xfcb_send_complete Request send to Windows Azure Storage is complete.
sqlserver xfcb_write_complete Request send to Windows Azure Storage is complete.
sqlserver xtp_create_procedure Occurs at start of XTP procedure creation.
sqlserver xtp_create_table Occurs at start of XTP table creation.
sqlserver xtp_db_page_allocation_allowed Indicates that page allocations for the database are allowed.
sqlserver xtp_db_page_allocation_disallowed Indicates that page allocations for the database are disallowed due to memory pressure.
sqlserver xtp_deploy_done Occurs at completion of XTP object deployment.
sqlserver xtp_matgen Occurs at start of MAT generation.
sqlserver xtp_offline_checkpoint_scan_start Fired by XTP offline checkpoint when the checkpoint thread begins.
sqlserver xtp_offline_checkpoint_scan_stop Fired by XTP offline checkpoint when the checkpoint thread stops.
sqlserver xtp_recover_done Occurs at completion of log recovery of XTP table.
sqlserver xtp_recover_table Occurs at start of log recovery of XTP table.
sqlserver xtp_storage_table_create Occurs at just before the XTP storage table is created.
ucs ucs_connection_rejected_by_proxy_whitelist After a connection attempt to the UCS proxy endpoint is rejected by whitelist check
ucs ucs_proxy_connect_next_hop UCS proxy next hop connection
ucs ucs_proxy_receive_proxy_connect_message UCS proxy receive proxy connect message
ucs ucs_proxy_route_add UCS proxy route added
ucs ucs_proxy_route_disable UCS proxy route disabled
ucs ucs_proxy_route_refresh UCS proxy route refreshed
ucs ucs_proxy_send_proxy_connect_message UCS proxy send proxy connect message
XtpCompile cgen Occurs at start of C code generation.
XtpCompile invoke_cl Occurs prior to the invocation of the C compiler.
XtpCompile mat_export Occurs at start of MAT export.
XtpCompile pitgen_procs Occurs at start of PIT generation for procedures.
XtpCompile pitgen_tables Occurs at start of PIT generation for tables.
XtpEngine after_changestatetx_event Fires after transaction changes state.
XtpEngine alloctx_event  
XtpEngine attempt_committx_event Is raised when a transaction is asked to commit.
XtpEngine before_changestatetx_event Fires before transaction changes state.
XtpEngine dependency_acquiredtx_event Raised after transaction takes a dependency on another transaction.
XtpEngine endts_acquiredtx_event Fires after transaction acquires an end timestamp.
XtpEngine gc_base_generation_evaluation Indicates that an evaluation of updating the GC base generation has been made.
XtpEngine gc_base_generation_updated Indicates that the oldest active transaction hint used for calculating the GC base generation has been updated.
XtpEngine gc_cycle_completed Indicates that a GC notification has been enqueued.
XtpEngine gc_notification Indicates that GC is processing a notification.
XtpEngine redo_single_hk_record Redo on a HK log record
XtpEngine trace_add_delta_filter_begin Adding delta filter.
XtpEngine trace_add_duplicate_delta_filter Adding duplicate delta filte.
XtpEngine trace_adding_tx_filter Adding tx filter.
XtpEngine trace_begin_close_ckpt_processing Beginning close checkpoint processing: checkpoint flush fence = $2 ($3 state).
XtpEngine trace_cfd_entry_deleted Cleaned up data CFD entry for file $2 $3.
XtpEngine trace_cfd_rows_created Successfully created CFD rows.
XtpEngine trace_cfdtable_dump CfdTable dump
XtpEngine trace_cfp_handles_opened Opened CFP handles for {data: $2 delta: $3} in section $4.
XtpEngine trace_cfp_removed_from_freelist Removed CFP from freelist for destination file.
XtpEngine trace_checkpoint_file_flush Indicating that a file has started a flush operation.
XtpEngine trace_checkpoint_load_begin Starting Checkpoint load with checkpoint timestamp=$2.
XtpEngine trace_checkpoint_write_io Logs an event indicating that an IO has started (when event_type == IoStarted) or that an IO has completed (when event_type == IoComplete).
XtpEngine trace_checksum_validation_succeeded Checksum validation for Hekaton checkpoint file during backup succeeded.
XtpEngine trace_ckpt_close_begin Closing checkpoint in active/passive state.
XtpEngine trace_ckpt_close_signaled Signaling checkpoint close. The checkpoint policy object is flagged to close the current checkpoint
XtpEngine trace_ckpt_closed Checkpoint closed
XtpEngine trace_ckpt_load_thread_stats Statistics of the checkpoint load thread.
XtpEngine trace_ckpt_mrt_dump Mrt dump
XtpEngine trace_ckpt_serialization_state_dump Checkpoint serialization state dump.
XtpEngine trace_ckpt_stream_io_stats Io statistics for this particular stream.
XtpEngine trace_close_file_log_rec_created Successfully created close file log record.
XtpEngine trace_data_file_pages_txs This event gives the number of pages and the transaction range for a data file.
XtpEngine trace_data_from_page_deserialized Deserialized data from page $2 in file $4.
XtpEngine trace_data_row_modified Data row modified/deleted.
XtpEngine trace_delete_cfd_rows_begin Matching MRT not found for the Data CFD. Deleting corresponding CFD Rows.
XtpEngine trace_delete_DeletedObjectTable_row_begin Deleting row from DeletedObjectTable in the context of transaction: $5.
XtpEngine trace_delete_merged_source_file Deleting merged source $7 file $5:$6. DeleteLSN = $2:$3:$4.
XtpEngine trace_delete_mrtrow_for_target_begin Deleting mrt row for target.
XtpEngine trace_delta_entry_skipped Skipping delta {$3, $4, $5} because it is beyond the snapshot checkpoint: $6.
XtpEngine trace_delta_file_future_count_rows_pages_update Updating future count pages and count rows for delta file.
XtpEngine trace_delta_file_lastgood_count_rows_pages_update Updating lastgood count pages and count rows for delta file.
XtpEngine trace_delta_file_pages_txs This event gives the number of pages and the transaction range while reading a delta file for a particular operations.
XtpEngine trace_delta_file_processed Completed processing of Delta file.
XtpEngine trace_delta_file_set_clean_or_dirty Delta file set clean or dirty.
XtpEngine trace_delta_filter_removed Removing delta filter from DeltaFilterMap due to transaction filter.
XtpEngine trace_delta_watermark_removed Removed delta watermark.
XtpEngine trace_delta_watermark_updated Updated delta watermark row for FileId: $4.
XtpEngine trace_deserialize_chained_records Info pertaining to the deserialized content of the mrtRecords chain.
XtpEngine trace_deserialize_data_from_page_begin Deserializing data from page $2 in file $4.
XtpEngine trace_deserialize_source_delta_file_begin Deserializing source delta file $4: page range [$2, $3).
XtpEngine trace_dump_cfd_row Dump cfd row
XtpEngine trace_dump_mrt_row Merge Request
XtpEngine trace_file_close_skipped Skipping file close for $2 as the cfp had been merged, It could not be found in the Storage array.
XtpEngine trace_file_skipped Skipping file $4 due to reason $5.
XtpEngine trace_file_skipped_with_tx_range Skipping file $5 with TX range { $3 -> $4 } due to MaxTxId == InvalidTxId.
XtpEngine trace_first_page_header_flushed Flushed first page header for file.
XtpEngine trace_flush_io_operation_for_delta_file This trace is trying to catch pages issued for flush that didn't make it to the file, or were lacking the correct DeltaWatermark Timestamp.
XtpEngine trace_flush_skipped_for_closed_data_file Skipping flush for data file ('$2') as it is closed.
XtpEngine trace_future_count_pages_update Updating future count pages.
XtpEngine trace_initial_merge Doing initial merge for destination $3 at CheckpointTs: $2.
XtpEngine trace_insert_DeletedObjectTable_row_begin Inserting row to DeletedObjectTable in the context of transaction: $5.
XtpEngine trace_intialize_worker_file_begin Processing file close.
XtpEngine trace_mark_data_file_closed Marking the active data file as closed to prevent the offline worker fom flushing them.
XtpEngine trace_merge_cancelled Merge was cancelled for destination $2.
XtpEngine trace_merge_complete_log_rec_ignored MergeCompleteLogRecord ignored for destination file $3.
XtpEngine trace_merge_complete_log_rec_processed Successfully processed MergeCompleteLogRecord.
XtpEngine trace_mrt_dump Mrt dump.
XtpEngine trace_mrt_row_inplace_update Mrt row updated in place.
XtpEngine trace_mrtrow_not_found Could not find row with Destination ID: $2 in MRT table.
XtpEngine trace_new_delta_watermark_inserted Inserted new delta watermark row for FileId $3.
XtpEngine trace_offline_process_stale_merge_item Offline processing of stale merge item {$2, $3} Destination $4.
XtpEngine trace_pending_tx Pending Transaction
XtpEngine trace_populate_storage_array Populating the storage array.
XtpEngine trace_post_writefile This event is fired after issuing IO on the proxy.
XtpEngine trace_process_file_close_begin Processing file close.
XtpEngine trace_process_merge_complete_log_record Process merge complete log record.
XtpEngine trace_process_merge_request Process Merge Request
XtpEngine trace_process_source_file Processing source $4 file $2.
XtpEngine trace_process_target_file Processing target $4 file $2.
XtpEngine trace_queue_merge_work_item Queue work item: {$2, $3} $5 - $6 with CheckpointTs as $4.
XtpEngine trace_recovered_existing_file Recovered exising files files allocated during forward processing that are not already part of the CCB.
XtpEngine trace_resyncing_state_of_file Resyncing state of file $4 ('$5') post recovery:  $2 pages, $3 rows.
XtpEngine trace_serialization_object_cleaned Cleaned serialization object.
XtpEngine trace_serialize_abort_transaction_begin Serializing the abort transaction filter to the delta cache corresponding to its own transaction range.
XtpEngine trace_serialize_tx_begin Serialize TS begin for completing the checkpoint in active state.
XtpEngine trace_serialize_tx_end Serialize TS end for completing the checkpoint.
XtpEngine trace_serialized_delta_rows_to_file Serialized delta rows to file.
XtpEngine trace_source_file_load_stats Load stats for source files in merge.
XtpEngine trace_storage_refreshed_for_file Storage refreshed for file.
XtpEngine trace_uninitialize_file uninitializing_file
XtpEngine trace_wrote_delta_watermark Wrote delta watermark for file: $3, checkpointTs: $2.
XtpEngine waiting_for_dependenciestx_event Raised when we have explicitly waited for dependencies to clear.
XtpEngine xtp_before_create_log_record Fired before submitting a request to the host to serialize a non-transactional log record.
XtpEngine xtp_checkpoint_file_flush Indicates the point at which a given file has been flushed to disk.
XtpEngine xtp_checkpoint_file_flush_complete Indicates the point at which all in-flight buffers have been flushed to disk.
XtpEngine xtp_checkpoint_file_read Indicates reading of a file in XTP checkpoint recovery.
XtpEngine xtp_checkpoint_worker_active_log Indicates that the checkpoint worker has started processing the log records in the active portion of the log.
XtpEngine xtp_checkpoint_worker_started Indicates that the checkpoint worker has started processing the log records.
XtpEngine xtp_checkpoint_worker_stopped Indicates that the checkpoint worker has started processing the log records.
XtpEngine xtp_checkpoint_write_io Indicates that the checkpointing subsystem has issued or completed a write IO.
XtpEngine xtp_complete_checkpoint Indicates the begin and end of complete checkpoint processing.
XtpEngine xtp_create_log_record Fires when the XTP engine creates a log record.
XtpEngine xtp_delta_marked_dirty Indicates that a delete/update was serialized and marked a delta file dirty
XtpEngine xtp_merge_complete_log_record Indicates merge complete log record is posted to the log.
XtpEngine xtp_merge_log_complete_log_record Indicates merge log record was interpreted by the offline worker.
XtpEngine xtp_merge_process_log_record Indicates merge log record was interpreted by the offline worker.
XtpEngine xtp_merge_request_log_record Indicates merge request log record is posted to the log.
XtpEngine xtp_merge_request_started Indicates merge request has been picked up by the merge worker thread.
XtpEngine xtp_root_deserialized Indicates that the load of a checkpoint root is complete.
XtpEngine xtp_root_serialized Indicates that the write of the checkpoint root is complete.
XtpRuntime bind_md Occurs prior to binding metadata for a memory optimized table.
XtpRuntime bind_tables Occurs prior to binding tables for a natively compiled procedure.
XtpRuntime create_table Occurs prior to creating memory optimized table.
XtpRuntime deserialize_md Occurs prior to deserializing metadata.
XtpRuntime load_dll Occurs prior to loading the generated DLL.
XtpRuntime recover_done Occurs at completion of checkpoint recovery of a memory optimized table.
XtpRuntime recover_table Occurs at start of checkpoint recovery of a memory optimized table.
XtpRuntime serialize_md Occurs prior to serializing metadata.
XtpRuntime unload_dll Occurs prior to unloading the generated DLL.

Happy tracing,

 

Andreas

, ,

Comparing Extended Events vs SQL Trace – or why SQL Trace & Profiler are just a thing of the past :-)

Nov 21st

Posted by Andreas Wolter in Extended Events

No comments

Extended Events vs SQL Trace im Vergleich – oder warum SQL Trace & Profiler einfach von gestern sind :-)

(de)
Zur Erinnerung: Extended Events sind seit SQL Server 2008 in SQL Server integriert. Und seit SQL Server 2012 SP1 sind alle Events verfügbar, die es in SQL Trace gibt. Zudem sind Extended Events seit SQL Server 2012 auch für Analysis Services verfügbar (Tracing Analysis Services (SSAS) with Extended Events – Yes it works and this is how).

Für alle, die noch mit dem alten Werkzeug SQL Server Profiler (Profiler ist das Frontend für SQL Trace, gestartet mit sp_trace_create) arbeiten, und sich noch nicht für die neue Technologie entscheiden konnten, hier eine kleine Entscheidungshilfe.

Was Extended Events (XEvents) besser als SQLTrace machen:

(en)
As a reminder: Extended Events have been integrated in SQL Server since SQL Server 2008. And since SQL Server 2012 SP1, all events existing in SQL Trace have been available. In addition, Extended Events have also been available for Analysis Services since SQL Server 2012 Tracing Analysis Services (SSAS) with Extended Events – Yes it works and this is how).

For those of you who are still working with the old tool SQL Server Profiler (Profiler is the frontend for SQL Trace, started with sp_trace_create) and have not quite been able to decide for the new technology, here is some decision guidance.

What Extended Events (XEvents) do better than SQL Trace:
  1. Einzige Möglichkeit neue Features wie FileStream, FileTable, AlwaysOn, ColumnStore, Hekaton/XTP etc. zu Tracen
  2. Viel mehr Events tracebar, auch bereits für ältere Releases (siehe *1, *2 unten)
  3. Deutlich geringerer Beobachter-Overhead
    siehe auch: Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load
  4. Performance/Last lässt sich konfigurieren & tunen
  5. Events und Filter lassen sich live anpassen – während aktiver Session also
  6. Ofiziell 2 µs/Event gg. 4ms/Event in SQLTrace
  7. Event-Verlust konfigurierbar
  8. Effiziente Filterung durch Architektur
  9. Komplexe Prädikate wie z.B. Zähler oder last_error, less_than_min_datatype oder greater_than_max_datatype
  10. Korrelation von Events möglich
  11. Möglichkeit Events vom Client bis in die Datenbank zu verfolgen
  12. Einfache Automatisierung
  13. Direkt in Management Studio integriert
  14. Viele Analysen direkt in der GUI möglich (Um diese noch zu verbessern, bitte hier bei Microsoft Connect voten: Extended Events UI Export Display Settings: include grouping)
  15. Query_hash zum Identifizieren von identischen Abfragen verfügbar
  16. Keine 10 Klicks zum Aufsetzen einer simplen Session inkl. Filter
  17. Unterschiedliche Speicher-Ziele für EventDaten zur Auswahl (6)
  18. „Ergebnisorientierte“ Ziele wie Counter und Histogramm
  19. Multiple Ziele lassen sich für “On the fly - Top-Down Analysen” kombinieren
  20. Möglichkeiten für ganz neue Einblicke in Interna der Datenbank-Engine (Latching, Spinlocks, Multi-victim-Deadlock, Wait_Infos per session/query, Caching-Vorgänge, Ghost-cleanup, Analyse von Page Splits, Page-Compression Vorgänge, um nur einige zu nennen)
  21. Stack Tracen eines einzelnen Prozesses möglich – anstelle eines vollständigen Server Dumps
  22. Definition mit Standard DDL-Statements
  23. API zur Integration in eigene Tools verfügbar
  24. PowerShell-Unterstützung
  25. Last but not least: Endlich ein Grund, XML & XQuery zu lernen? ;-)
  1. The only possibility of Tracing new features like FileStream, FileTable, AlwaysOn, ColumnStore, Hekaton/XTP etc.
  2. Many more Events traceable, even for older releases (see *1, *2 below)
  3. Significantly less Observer-Overhead, also see: Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load
  4. Performance/Overhead can be configured and tuned
  5. Events and Filters can be adapted live – meaning during active session
  6. Official 2 µs/Event vs. 4ms/Event in SQLTrace
  7. Event-loss is configurable
  8. Efficient filtering through architecture
  9. Complex predicates such as Counter or last_error, less_than_min_datatype oder greater_than_max_datatype
  10. Correlation of Events possible
  11. Possibility of following Events from Client into the Database
  12. Easy Automation
  13. Directly integrated in Management Studio
  14. Many analysis directly inside the GUI possible (in order to improve them, please vote at Microsoft Connect: Extended Events UI Export Display Settings: include grouping)
  15. Query_hash for identification of identical queries available
  16. No 10 clicks to set up a simple session including filter
  17. Choice of different destinations for storing EventData (6)
  18. “Goal-oriented” destinations such as Counter and Histogram
  19. Multiple destinations can be combined for “On the fly – top-down analyses”
  20. Possibilities for entirely new insights into internal matters of database engine (Latching, Spinlocks, Multi-victim-Deadlock, Wait_Infos per session/query, Caching-processes, Ghost-cleanup, analysis of Page Splits, Page-Compression processes, to name just a few)
  21. Stack Tracing of a single process possible – instead of a complete Server Dump
  22. Definition with standard DDL-Statements
  23. API for integration into one’s own tools available
  24. PowerShell support
  25. Last but not least: Finally a good reason to learn XML & XQuery? ;-)

 

 *1
Extended Events vs. SQL trace Events per Version

Extended_Events_per_SQL_Server_Version

 

*2
As an example: For Service Broker there are:
15 Events in SQLTrace vs. 44 Events in XEvents (SQL Server 2012 SP1)

 

Ich hoffe, das hilft dem einen oder anderen, die alte Gewohnheit abzulegen, und die kleine Lernphase in Kauf zu nehmen.

Eine Liste aller Extended Events in SQL Server 2012 SP1 samt Ihrem Gegenstück in SQL Trace, welche man für Migrationszwecke (SQLTrace -> XEvent Trace) verwenden kann findet sich in dieser Seite. (Aufgrund einer Größenbeschränkung passte sie nicht mehr hier hinein.)

I hope this helps some of you to unlearn the old habit and accept the little learning phase. 

 

A list of all Extended Events in SQL Server 2012 SP1 including its counter piece in SQL Trace that can be used for migration purposes (SQLTrace-> XEvent Trace) is available on this page. (Due to size restriction, it didn’t fit in here anymore.)

> Mapping Extended Events with sys.trace_xe_event_map to SQL Trace <

 

Happy better Tracing

 

Andreas

 

PS: Für 2014 befindet sich mit den SQL Server Master-Classes zum Thema „Tracing mit Extended Events“ auch die nächste Runde der Trainings zu diesem Thema in der Planung :-)

P.S. For 2014, the next round of training in this topic is being developed in conjunction with SQL Server Master-Classes on the topic “Tracing with Extended Events” :-)

 

,

Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load

Aug 14th

Posted by Andreas Wolter in Tracing & Monitoring

No comments

Leistungseinbußen beim Tracing, Extended Event Ziele gegen SQL Trace unter CPU Last

(DE)

Inspiriert durch den Blog Post Post “Measuring Observer Overhead of SQL Trace vs. Extended Events” von Jonathan Kehayias, war ich neugierig, ein paar weitere Benchmarks durchzuführen. Die Resultate habe ich bereits in meinen SQL Server Master-Class Workshops zu XEvents und auf der PreCon des SQLSaturday #230 präsentiert. Nun teile ich sie endlich hier.

Vor allem folgende Aspekte interessierten mich:

  • Was ist der Performance-overhead einer Extended Event Session selber – ohne die Verarbeitung und des Dispatchens zu den Targets
  • Wie verhält sich das im Vergleich zu SQL Trace – auch das ohne Overhead für ein Ziel (Keine Datei, kein Profiler: gar kein Konsument)

Da ich einmal das Setup bereit hatte, habe ich mich entschieden, alle anderen Ziele ebenfalls aufzunehmen, sowie einige grundlegende Options-Variationen, um einen kompletten Überblick zu erhalten, der in sich vergleichbar ist.

(EN)

Inspired by the Blog Post “Measuring Observer Overhead of SQL Trace vs. Extended Events” by Jonathan Kehayias, I was curious to do some more benchmarking.
I have already presented the results in my SQL Server Master-Class workshops on XEvents as well as at the PreCon of the SQLSaturday #230. Now I am finally sharing them with you here.

I was interested in the following aspects, in particular:

  • What is the Performance-overhead of an Extended Event Session itself – not including the processing/dispatching for the target
  • How does this compare to the old-school SQL Trace – again with no Target overhead (No File, no Profiler: no consumer at all)

Besides that, once I had the setup ready, I decided to include all the other targets and some basic option-variations, to have a complete overview that is comparable in itself.

Ich entschied mich für ein System, das bereits unter CPU Druck steht – die CPU Verwendung liegt fast vollständig bei 100%.
Unter diesen Umständen hoffte ich die maximalen Auswirkungen von Extended Events („Erweiterte Ereignisse“) als auch SQL Trace (Zur Erinnerung: SQL Profiler basiert auf SQL Trace) zu erhalten. Man könnte meinen, dass eine E/A(I/O)-lastige Arbeitslast noch mehr beeinflusst werden würde, aber das hängt an den Targets für Extended Events. – 4 davon gehen lediglich in den Arbeitsspeicher, gegenüber einem File-Target (welches man ohnehin auf ein Nicht-Daten-Volume legen sollte). Und da ich auch den reinen Overhead der Trace-Technologien (ohne Ziel) messen möchte, macht das noch mehr Sinn. Abgesehen davon kann I/O in der Regel meist recht einfach getuned werden, indem man auf ein ansonsten unverwendetes und schnelles Device schreibt, wohingegen es für CPU nicht so einfach ist, die Kosten unsichtbar zu halten. Das im Hinterkopf zu behalten hilft, die Resultate, die hier präsentiert werden zu evaluieren und sie in den rechten Kontext zu rücken.

I also decided for a test of a system that’s already under CPU pressure - so the Processor Usage is almost constantly hitting 100%.
Under these circumstances I was hoping to get the maximum impact of Extended Events as well as SQL Trace. (Remember: SQL Profiler is based on SQL Trace) One could think that an I/O driven workload would be even more influenced, but that depends on the targets of Extended Events. - 4 of which only go to memory, vs. one file target (which one should put onto a non-data volume anyways). And since I also want to measure the pure overhead of the tracing technologies (without any target), this makes even more sense.
Besides that, I/O usually can be tuned quite easily by writing to an otherwise idle and fast device, whereas for CPU it is not as simple to keep the costs invisible. Keeping this in mind helps to evaluate the results presented here and bringing them into the right context.

 

Test Umgebung

“Einfach aber physikalisch”

1 Windows 2008 R2 Server mit SQL Server 2012 SP1. Keine laufenden Dienste abseits des minimal Notwendigem, um Seiten-Effekte zu verhindern.
Ich habe auch die Default-Trace sowie die system_health_session gestoppt.
Der Distributed Replay-Client wurde für alle Test local ausgeführt, und Ja, das hat Effekt auf den Server, aber das war gleich für alle Tests. Alle Tests wurden 3 Mal wiederholt (einige sogar öfter), um sicherzustellen, dass der Durchschnitt/Median valide ist.
Der Server, wie gesagt, war physikalisch (das kommt praktisch, wenn man Benchmarks mit einer Gesamtzeit von ~50 Stunden durchführt.): 1 Dual Core Intel Xeon mit 8 GB RAM (was bei Weitem genug war), Daten Volumen und Volumen für Trace-Targets auf separate Controllers.

Die Arbeitslast war ein Mix von meist kurzen (Sub-Sekunden) aber auch einigen Abfragen mit mehreren Sekunden Laufzeit, (Ad Hoc und gespeicherte Prozeduren), um eine einigermaßen realistische Decision-Support-System Last zu simulieren – jedoch ohne Datenänderungen.
Die Baseline Workload dauerte 00:24:24 Minuten. Die Statistiken blieben für alle Workload-Zyklen identisch. Die verwendete Datenbank war AdventureWorks2012.

Test Environment

“Simple but physical”

1 Windows 2008 R2 Server with SQL Server 2012 SP1. No running services above the minimum required, to avoid side-effects.
I also shut down the default trace as well as the system_health_session.
The Distributed Replay-client was run locally for all tests, so yes, this has effect on the server, but it was equally for all tests. All tests have been repeated 3 times (some even more) to make sure the average/median is valid.
The server, as I already said, was physical (which comes in handy when you are running benchmarks for a total of ~50 hours): 1 Dual Core Intel Xeon with 8 GB of RAM (which was by far enough), Data Volumes and Volumes for Trace-Targets on separate Controllers.

The workload was a mixture of mostly short (sub-second) but also several queries of several second runtime, (Ad Hoc and stored procedures) to simulate a somehow realistic decision-support-systems’ load – no data changes though.
The baseline workload took 00:24:24 minutes. The statistics stayed the same for all workloads cycles. The database used was AdventureWorks2012.

 

Trace-Konfigurationen

Ich habe mich für eine einfache, aber nicht unübliche Trace entschieden, die typischerweise viele Daten sammelt.
Die Trace sammelt nur 2 Ereignisse:

Trace-Configurations

I decided for a simple but not uncommon trace that typically collects a lot of data. The trace collects only 2 events:
  • Lock acquired
  • Lock released

 

Ausgefiltert: System-Sitzungen und andere Datenbanken als die, die hier unter Last steht.

Gesammelte Daten:

Filtered out: System-sessions and other databases than the one under load here.

CollectedData:

 

  • Lock:Released   BinaryData
  • Lock:Released   DatabaseID
  • Lock:Released   TransactionID
  • Lock:Released   SPID
  • Lock:Released   ObjectID
  • Lock:Released   Mode
  • Lock:Released   BigintData1
  • Lock:Released   IntegerData2
  • Lock:Released   ObjectID2
  • Lock:Released   Type
  • Lock:Released   OwnerID
  • Lock:Released   IsSystem
  • Lock:Acquired   BinaryData
  • Lock:Acquired   DatabaseID
  • Lock:Acquired   TransactionID
  • Lock:Acquired   SPID
  • Lock:Acquired   Duration
  • Lock:Acquired   ObjectID
  • Lock:Acquired   IsSystem
  • Lock:Acquired   Mode
  • Lock:Acquired   BigintData1
  • Lock:Acquired   IntegerData2
  • Lock:Acquired   ObjectID2
  • Lock:Acquired   Type
  • Lock:Acquired   OwnerID

Das gab mir den Vorteil, einen validen Test für alle Extended Event Targets, die bereitgestellt werden, zu haben (lediglich ETW-Tracing wurde ausgelassen) - speziell das Histogramm und die „Ereignispaarbildung“ (Pair-Matching)(Die wenigen Ereignisse von Lock-Escalation störten mich bewusst nicht).

Die folgenden Trace Technologien und -Ziele wurden verwendet:

This gave me the advantage to have a valid test for all Extended Event Targets that are provided (only ETW-Tracing was left out) - specifically histogram and Pair Matching (I did not care about the few occasions of lock escalation on purpose).

The following Trace technologies and -Targets were used:

 

  • XEvent Trace, Target: None
  • XEvent Trace, Target: Ring Buffer
  • XEvent Trace, Target: File
  • XEvent Trace, Target: Counter
  • XEvent Trace, Target: Histogram
    • Here I chose to filter on lock acquired and to bucketize on the lock mode
  • XEvent Trace, Target: Pair Matching
    • Guess, what I matched here ;-)
  • SQL Trace, Target: None (I had to trick a little bit to get this to work, but I made sure, the behavior of this unsupported configuration did not distort the results: It’s just a SQL Trace with no Provider processing, so all events are lost by nature.)
  • SQL Trace, Target: File
  • SQL Profiler, remotely

Für jedes Ziel der Extended Events habe ich 4 Varianten getestet, basierend auf den Sitzungsoptionen:

For each Extended Event Target I tested 4 variations, based on the session options:
  • Single event loss
  • No event loss
  • Multiple event loss
  • Single event loss with causality tracking on

Alle anderen Optionen verwendeten die Standardwerte für diese Tests.

All other options were using the defaults for these tests.

 XEvent_PerfComparison_sessions

Picture: the 24 prepared traces

Die Ergebnisse

Ich habe die Gesamtlaufzeit für die Workload sowie Batches pro Sekunde und CPU Zeit % gemessen.

Und hier ist die vollständige Tabelle mit den Ergebnissen:

The Results

I measured the total time for the workload to take as well as batches per second and CPU time %.

And here is the complete Table of Results:

 

 XEvent_PerfComparison_Runtime_Avg_EvSec

EL = Ereignisverlust. S = Verlust einzelner Ereignisse, N = Kein Ereignisverlust, M = Verlust mehrerer Ereignisse

CT = Kausalitätsverfolgung (Causality Tracking) Ein

EL = Event Loss. S = Single event loss, N = No event loss, M = Multiple event loss

CT = Causality Tracking On

 

Um Zeit und Platz zu sparen, konzentriere ich mich auf die Benchmarks mit den Optionen single event loss und no event loss ohne Causality Tracking. Tatsächlich waren die Kosten von Causality Tracking weniger als 1% für alle Ziele.

Hier ist daher das komprimierte Ergebnis:

For the sake of saving space and time, I will focus on the benchmarks with the options single event loss and no event loss without causality tracking. In fact, the cost of causality tracking was less than 1% for all targets.

So this is the more condensed result:

 

 XEvent_PerfComparison_Runtime_S_N_Avg_EvSec

Was wir demnach sagen können, ist:
(Erinnern wir uns daran: alles läuft unter Hoher CPU Last. Das ist die Grundlage aller Ergebnisse.)

What we can tell from that, is:
(Remember: Everything is running under High CPU Load, so that’s the base of all results.)
  • Eine blanke XEvent Session alleine, ohne Targets, hat bereits einen spürbaren Einfluss von ~15 % Leistungsverlust.
  • Der Aufschlag („Overhead“) der künstlich erzeugten (nicht unterstützten) Version einer blanken SQL Trace, ohne den Aufschlag eines Rowset oder File Providers („Target“), ist nicht allzu weit von dem einer Extended Events Session ohne dem Dispatchen zu einem Target entfernt (~19% gegen ~15%).
  • Der Ringpuffer (Ring Buffer) ist das XE-Target mit dem größten Overhead (~40%). (!)
  • Das Ereignisdateiziel (“File-Target”) hat, wie erwartet, wirklich den geringsten Overhead, aber dieser beläuft sich immer noch auf 25%.
  • Die Unterschiede zwischen den Targets Ereigniszähler („Counter“), Histogramm und Ereignispaarbildung („Pair Matching“) sind irrelevant.
    • Ja, sogar der simple Counter hat einen höheren Overhead als das File Target.
    • Das File Target mit No Event Loss zu konfigurieren, fügt fast den vierfachen Overhead hinzu.
    • Die Unterschiede für die anderen Targets zwischen single, multiple und sogar no event loss ist in diesem Szenario fast negierbar.
    • Verglichen mit Extended Events ist der Overhead durch eine SQL Trace fast schon “brutal”: Er vervierfacht die Gesamtlaufzeit.
    • Und noch mehr: Tracing mit dem SQL Profiler ist in solch einem Szenario schlicht ein Ding der Unmöglichkeit: Ich habe 21 Stunden eingetragen, aber das ist tatsächlich eine Schätzung: Ich beendete diese Test-Zyklen nach rund 3 Stunden (man möge mir verzeihen, aber es ist schlicht Zeitverschwendung...), zählte die beendeten Events und rechnete aus, wie lange es noch gedauert hätte, grob – aber tatsächlich eher optimistisch. Profiler ist, wie ich es immer sage, ein “No-Go” um für längere Zeiträume zu tracen, vor allem, wenn die Performance ohnehin bereits leidet.
  
  • A plain XEvent Session itself, with no Targets, already does have a noticeable impact of ~15 % performance decrease.
  • The overhead of the artificial (not supported) version plain SQL Trace, without the overhead of a rowset or file provider (aka target), is not too far off the Extended Events Session without the dispatching to any target (~19% versus ~15%).
  • The Ring Buffer is the XE-Target with the greatest overhead (~40%). (!)
  • The File-Target really does have the lowest overhead as expected, but it’s still 25%.
  • The differences between the Targets Counter, Histogram and Pair Matching are irrelevant.
    • Yes, even the simple Counter has a higher overhead than the File Target.
    • Configuring the file target with no event loss adds approximately 4 times as much performance overhead.
    • The difference for the other targets between single, multiple and even no event loss is mostly negligible in this scenario.
    • Compared to Extended Events, the overhead through SQL Trace is almost “brutal”: It quadruplicated the total runtime.
    • And there's even more: Tracing with SQL Profiler is absolutely impossible for such a scenario: I filled in 21 hours, but that’s actually an estimate: I stopped those test cycles after around 3 hours (forgive me, but it’s just a waste of time...), counted the finished events and calculated how much else it would have taken, roughly – in an actually rather optimistic manner. Profiler, as I always say, is a “no go” for tracing longer periods of time, especially if performance is already at stake.

Ein schönes Bild der SQL Trace Architektur findet sich in den BOL: msdn.microsoft.com/en-us/library/hh245121.aspx
Die Extended Events Architektur wird hier bildlich gezeigt: msdn.microsoft.com/en-us/library/bb630318%28v=sql.105%29.aspx

You have a nice picture of the SQL Trace Architecture in BOL: msdn.microsoft.com/en-us/library/hh245121.aspx
The Extended Events Architecture is depicted here: msdn.microsoft.com/en-us/library/bb630318%28v=sql.105%29.aspx

 

Hinzufügen von Filtern

Wie ändert das Hinzufügen von Filtern den Beobachter-Overhead?

Es ist wichtig, zu wissen, was ich als Filter verwendet habe: Die database_id / source_database_id.
- Tatsächlich habe ich einen Filter verwendet, der niemals “true” zurückgeben würde, indem ich einen Filter auf database_id = 77 angelegt habe – da keine Sitzung/Abfrage/Sperre je auf dieser nicht-existenten Datenbank lag.
Warum habe ich das gemacht? – Das ist ein rein künstlicher Test/Benchmark. Was mich interessiert, ist der reine Overhead des Tracen, und nicht, was passiert, wenn ein bestimmter Prozentsatz der Aktivität nicht protokolliert wird. (Das könnte vielleicht etwas für einen anderen Benchmark sein. :-))

Adding Filters

How does adding filters change the observer overhead?

Now it is important to note what I actually used as a filter: The database_id / source_database_id.
- I essentially added a filter that would never return “true” by adding a filter on database_id = 77 – since no session/query/lock was on this non-existing database.
Why did I do that? – This is a totally artificial test/benchmark. I am interested what the pure overhead of tracing is, and not what happens if a certain percentage of activity is not logged. (That might be something for a different benchmark. :-))

Dieses Mal konzentriere ich mich nur auf „single“ und „no event loss“.

Die Resultate des gefilterten Tracing, ohne tatsächlich irgendwelche Events zu speichern/protokollieren, ist wie folgt:

This time I only focused on “single” and “no event loss”.

The results of Filtered Tracing, without actually storing/logging any events is as follows:

 

 XEvent_PerfComparison_Runtime_Filtered_Avg

  • Wie man sehen kann, fällt der Overhead der reinen XEvent Session ohne Target von ~ 15% auf 9% bzw. ~ 16,5% gg. 12,5 % (No Event loss)
  • Die anderen Targets zeigen in diesem Setup tatsächlich die größten Unterschiede:
    • Das Counter Target mit single event loss profitiert am Meisten von dem Filter und fällt von ~33,5 auf 8,4 % Overhead.
    • Nur Ring Buffer und Pair Matching zeigen keinen Unterschied zwischen single und no event loss.
    • SQL Trace mit und ohne rowset Provider (Datei) als Target haben fast den gleichen Overhead – keine Überraschung, wenn man die Architektur kennt. Das ist tatsächlich ein weiterer risen Unterschied, der für Extended Events spricht, wo Filters viel früher in der Trace berücksichtigt werden.
    • Das der Overhead von SQL Trace ohne Target und zugleich aller Events herausgefiltert sogar höher ist, als der Overhead ohne Target aber auch ohne Filter (von dem vorhergehenden Test-Zyklus), muss an dem Verarbeiten des Ausfilterns selber liegen. Ich werde mich damit aber nicht weiter befassen, da das Setup weder dokumentiert noch unterstützt ist.
      Und in meinen Augen ist “SQL Trace“ sowieso „tot“ ;-) – Okay, ich übertreibe hier ein wenig, aber ich bin auch ganz offen: Für SQL Server 2012 gibt es fast keinen Grund mehr zu dessen Verwendung. – Benchmarks mithilfe von Distributed Replay durchzuführen, ist so ein Grund – ist das nicht ironisch?

Für diesen Test habe ich SQL Profiler nicht ausgeführt, Pardon. Sie wissen bis hierhin wahrscheinlich schon, warum. ;-)
  • As one can see, the overhead of the pure XEvent session without target drops from ~ 15% to 9% respectively ~ 16.5% vs. 12.5 % (no Event loss)
  • The other targets do in fact show more differences in this setup:
    • The Counter Target with single event loss benefits most of the filter and drops from ~33.5 to 8.4 % overhead.
    • Only Ring Buffer and Pair Matching show no difference between single and no event loss.
    • SQL Trace with and without rowset provider (file) as target have almost the same overhead – no surprise if you know the architecture. This is in fact another huge difference which counts for Extended Events, where filters get honored much sooner within the Trace.
    • That the overhead of SQL Trace without target and at the same time all events being filtered out is actually higher than the overhead without target but no filtering (from the former test cycle) must be caused by the processing of for filtering out. I will not dive more into this though, since this setup is not documented and or supported.
      And in my eyes, “SQL trace is dead” anyways ;-) – okay, I am exaggerating a bit here, but I am also just being frank: For SQL Server 2012 there is almost no need to use it any more. – Running benchmarks using Distributed Replay is such a reason – isn’t that ironic?

I did not run SQL Profiler for this Test, forgive me. You probably know why by now. ;-)

 

Wait-Types für Extended Events

Ein weiterer Aspekt, der mich interessierte, waren die XEvent Wait-Typen, die auftreten würden, wenn man Extended Event Sessions ausführt. (Die Warte-Statistiken sind oft die Basis für Performance-Analysen)

Allgemein sieht man folgende:

Wait-Types for Extended Events

Another aspect I was interested in were the specific XEvent wait-types which would occur when running Extended Event sessions.
(Wait-Statistics are often the base for performance analysis)

In general, you will see the following:

 

Beim Starten einer Sitzung:

When starting a session:

PREEMPTIVE_XE_TARGETINIT
PREEMPTIVE_XE_CALLBACKEXECUTE
PREEMPTIVE_XE_SESSIONCOMMIT

Beim Beenden einer Sitzung:

When stopping a session:

PREEMPTIVE_XE_SESSIONCOMMIT
XE_BUFFERMGR_ALLPROCESSED_EVENT
PREEMPTIVE_XE_CALLBACKEXECUTE

 Während Sessions aktiv sind, sieht man:

While running sessions you will see:

XE_DISPATCHER_WAIT  - From BOL: Occurs when a background thread that is used for Extended Events sessions is waiting for event buffers to process. - You should be able to safely ignore this unless you believe a problem is occurring with processing of events for async targets. Since this works on a queue you can have bursts of high wait times especially when no XEvent sessions are active.

XE_TIMER_EVENT – From BOL: Used to indicate a background task is waiting for "expired" timers for internal Xevent engine work. - You should be able to safely ignore this one. Just used by the Xevent engine for internal processing of its work. If something was possibly wrong with Xevent processing you might see if this thread ever "wakes up"

Beim Starten eines File-Targets sieht man außerdem:

When starting the File target you will also see:

PREEMPTIVE_XE_TARGETINIT

Wenn man eine Sitzung mit der No Event Loss Option ausführt, sieht man gegebenenfalls:

If you run a session with the no event loss option you might see

XE_BUFFERMGR_FREEBUF_EVENT - which by BOL means: An Extended Events session is configured for no event loss, and all buffers in the session are currently full. This can indicate that the buffers for an Extended Events session are too small, or should be partitioned.

 

So. Ich hoffe das war interessant. Man kann noch weitere und andere Schlüsse aus den Ergebnissen ziehen. Immer im Hinterkopf zu behalten, ist, dass das ein sehr spezielles Szenario ist, wo keine CPU Reserven zur Verfügung stehen, so das der Trace/Beobachter-Overhead sich manifestieren muss – keine Chance, als eben (CPU) Ressourcen wegzunehmen.

So, I hope this was interesting for you. You may draw more and other conclusions out of these results. Remember though: this is a very specific scenario with no CPU reserves, so the Tracing/observer overhead has to show up – no choice but to take away (CPU) resources.

 

Happy Tracing

 

Andreas

PS: I just discovered that my MCM and SQLSkills-class buddy Steven Ormrod also has recently blogged about the performance overhead from a SQL Trace to remote file share on production here: stevenormrod.com/2013/06/remote-trace-slowing-down-server/

, , , ,

Survey: Which Tracing and Analysis-Tools do you use for SQL Server?

Jun 21st

Posted by Andreas Wolter in Tracing & Monitoring

14 comments

 Umfrage: Welche Tracing und Analyse-Tools verwendet ihr für SQL Server?

(DE)
In meiner Session „Hasta la vista Profiler – Tracing with Extended Events“, die ich nun seit über einem Jahr bei diversen Gelegenheiten gehalten habe, habe ich die Zuhörer meist gefragt, welche Monitoring-Tools sie bisher verwendeten.

Ich möchte diese Stelle einmal nutzen, um einmal breit zu erheben, welche Werkzeuge von SQL Server Professionals zur Protokollierung und Analyse von Performance-Problemen verwendet werden. Um ein differenzierteres Bild zu erhalten, ist auch eine Einordnung in „Administrator“, und „Entwickler“ sicherlich interessant.

Die Ergebnisse werde ich auf dem kommenden SQLSaturday #230 am 12. Juli in St. Augustin auf der PreCon, „From SQL Traces to Extended Events. The next big switch.“, die ich zusammen mit Mladen Prajdic gebe, präsentieren, und später mit Sicherheit noch auf dem PASS Camp sowie bei weiteren Gelegenheiten der deutschen und auch internationalen PASS - und natürlich hier in meinem Blog selber. Die Antworten können natürlich auch anonym abgegeben werden.

Im Folgenden liste ich eine Reihe von geläufigen Tools auf.

Bitte gebt Eure Stimme einfach als Kommentar wie im folgenden Beispiel ab - ich gebe ALLE Antworten (außer reinem Spam und Werbung) frei, auch Oracle-Tools ;-)

(EN-US)
In my session Session „Hasta la vista Profiler – Tracing with Extended Events“, that I have been presenting at several occasions, I used to ask the audience, which tools they used for monitoring so far.

I would like to use this platform to survey on a broader range, which tools are being used by SQL Server professionals for logging and analyzing performance-problems. In order to get a differentiated result, a classification in “Administrator” and “Developer” is certainly also interesting.

The results will be presented first at the upcoming SQLSaturday #230 on the 12th of Juli in St. Augustin/Germany at the PreCon, From SQL Traces to Extended Events. The next big switch.“, which I will be giving together with Mladen Prajdic gebe, and later on certainly also at the PASS Camp and other occasions of the German and international PASS - and of course also here in my blog itself. You can of course also keep your comments anonymously.

In the following I am listing a series of common tools.

Please simply provide your vote as a comment like in the following example – I will publish ALL answers (except plain spam/ads), even Oracle-Tools ;-)

„Administrator and/or Developer“
A 3
B 1
D 2
L 0

Dabei stehen die Zahlen für // The numbers stand for:

3: fast immer // almost all the time
2: manchmal // sometimes
1: selten // rarely
-1: das Tool ist mir unbekannt // I haven't hear of this tool

- Die Auswahl “unbekannt” auf Anregung eines Lesers (Danke!).

Werkzeuge, die nie verwendet werden gerne einfach weglassen.

Und das ist die Auswahl an Tools:

The choice “unknown” at a reader’s suggestion (Thank you!).

Tools that are not used can be simply left out.

And these are the choices of tools:

A) ClearTrace
B) Datenbankoptimierungsratgeber // Database Engine Tuning Advisor
C) Dynamic Management Views (DMV's)
D) Event Notifications
E) Extended Events unter 2008/R2
F) Extended Events unter 2012
G) Management Datawarehouse (MDW) / Data Collection Reports
H) PAL
I) PerfMon
J) RML Utilities / ReadTrace
K) SQL Diag
L) SQL Profiler
M) SQL Trace
N) Software von Drittherstellern – siehe auch O) // Third-Party Tools - also see O)
O) Andere // Other: …

- Die Reihenfolge ist alphabetisch und soll nichts implizieren :-)

Meine Liste enthält ausschließlich mit SQL Server gelieferte, sowie codeplex-Tools, es können aber auch andere angegeben werden. (Punkt „O“)

Mir ist natürlich völlig bewusst, das auch die SQL Server Version und ggf. Edition Einfluss auf die zur Verfügung stehende Auswahl hat, aber ich möchte die Umfrage auch nicht zu komplex gestalten. Das Ziel, einen Eindruck über die Verbreitung der Tracing-Gewohnheiten zu erreichen, wird so sicherlich erreicht werden können :-)

Vielen Dank an dieser Stelle schon einmal für die Beteiligung - ich bin sicher, dass es auch viele andere Community-Mitglieder gern sehen, was andere so für ihre Arbeit einsetzen.

- The order is alphabetical and not supposed to imply anything :-)

My list contains solely tools shipped with SQL Server and from codeplex, but feel free to add others (point “O”)

I am totally aware that also the SQL Server version and possibly edition have an influence on the choices available, but I also do not want to make the survey all too complex. The aim, to gain an impression on the prevalence and practices of tracing-habits will certainly be reached like that, too :-)

Thank you very much for participating – I am sure that many members of the SQL Server Community are also interested to see, what others use for their work.

Andreas

, , , , ,
1 2