SQL Server 的 Log 文件夾中的 HKEngineEventFile
如本問題所述,我們的數據庫中存在不一致問題。現在已修復相同的問題,並且數據庫正在執行,沒有任何問題。
我注意到 SQL 服務在過去 3 天內多次重啟(根據錯誤日誌),這次重啟只用了 1 到 2 秒,令我驚訝的是,沒有人注意到這一點,而這發生在工作時間。這是一個生產數據庫並且被大量使用,這意味著每秒有 1-3 個事務命中數據庫。
我記錄了重新啟動服務的時間或最近幾天,並註意到同時(每次)都會創建一個名為“ HkEngineEventFile_0_XXXX ”的文件,大小為 68KB。試圖用不同的工具打開它,但沒有得到任何資訊。
有人可以幫助我理解這一點,而且我還需要了解這是否是服務的真正重啟或其他原因。
以下是 SQL 錯誤日誌中的條目:
2019-07-07 16:51:22.32 Server Microsoft SQL Server 2014 (SP3) (KB4022619) - 12.0.6024.0 (X64) Sep 7 2018 01:37:51 Copyright (c) Microsoft Corporation Enterprise Edition: Core-based Licensing (64-bit) on Windows NT 6.3 <X64> (Build 9600: ) (Hypervisor) 2019-07-07 16:51:22.32 Server UTC adjustment: 3:00 2019-07-07 16:51:22.32 Server (c) Microsoft Corporation. 2019-07-07 16:51:22.32 Server All rights reserved. 2019-07-07 16:51:22.32 Server Server process ID is 7916. 2019-07-07 16:51:22.32 Server System Manufacturer: 'VMware, Inc.', System Model: 'VMware Virtual Platform'. 2019-07-07 16:51:22.32 Server Authentication mode is MIXED. 2019-07-07 16:51:22.32 Server Logging SQL Server messages in file 'E:\DB_SQL12.ABC\DB_SQL\Log\ERRORLOG'. 2019-07-07 16:51:22.32 Server The service account is 'Organization_Name\Service_Account'. This is an informational message; no user action is required. 2019-07-07 16:51:22.32 Server Registry startup parameters: -d E:\DB_SQL12.ABC\DB_SQL\DATA\master.mdf -e E:\DB_SQL12.ABC\DB_SQL\Log\ERRORLOG -l E:\DB_SQL12.ABC\DB_SQL\DATA\mastlog.ldf 2019-07-07 16:51:22.32 Server Command Line Startup Parameters: -s "ABC" 2019-07-07 16:51:22.55 Server SQL Server detected 2 sockets with 4 cores per socket and 4 logical processors per socket, 8 total logical processors; using 8 logical processors based on SQL Server licensing. This is an informational message; no user action is required. 2019-07-07 16:51:22.55 Server SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required. 2019-07-07 16:51:22.55 Server Detected 24575 MB of RAM. This is an informational message; no user action is required. 2019-07-07 16:51:22.55 Server Using conventional memory in the memory manager. 2019-07-07 16:51:22.72 Server Default collation: SQL_Latin1_General_CP1_CI_AS (us_english 1033) 2019-07-07 16:51:22.77 Server The maximum number of dedicated administrator connections for this instance is '1' 2019-07-07 16:51:22.78 Server This instance of SQL Server last reported using a process ID of 6672 at 7/7/2019 4:50:49 PM (local) 7/7/2019 1:50:49 PM (UTC). This is an informational message only; no user action is required. 2019-07-07 16:51:22.78 Server Node configuration: node 0: CPU mask: 0x00000000000000ff:0 Active CPU mask: 0x00000000000000ff:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required. 2019-07-07 16:51:22.80 Server Using dynamic lock allocation. Initial allocation of 2500 Lock blocks and 5000 Lock Owner blocks per node. This is an informational message only. No user action is required. 2019-07-07 16:51:22.80 Server Database Instant File Initialization: disabled. For security and performance considerations see the topic 'Database Instant File Initialization' in SQL Server Books Online. This is an informational message only. No user action is required. 2019-07-07 16:51:22.83 spid7s Starting up database 'master'. 2019-07-07 16:51:22.88 Server CLR version v4.0.30319 loaded. 2019-07-07 16:51:22.89 spid7s 14 transactions rolled forward in database 'master' (1:0). This is an informational message only. No user action is required. 2019-07-07 16:51:22.90 spid7s 0 transactions rolled back in database 'master' (1:0). This is an informational message only. No user action is required. 2019-07-07 16:51:22.90 spid7s Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required. 2019-07-07 16:51:22.96 Server Common language runtime (CLR) functionality initialized using CLR version v4.0.30319 from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\. 2019-07-07 16:51:23.01 spid7s CHECKDB for database 'master' finished without errors on 2019-07-05 21:45:01.463 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:23.01 spid7s Resource governor reconfiguration succeeded. 2019-07-07 16:51:23.01 spid7s SQL Server Audit is starting the audits. This is an informational message. No user action is required. 2019-07-07 16:51:23.01 spid7s Audit: Server Audit: 65536, Initialized and Assigned State: START_FAILED 2019-07-07 16:51:23.01 spid7s Audit: Server Audit: 65536, Initialized and Assigned State: STARTED 2019-07-07 16:51:23.01 spid7s SQL Server Audit has started the audits. This is an informational message. No user action is required. 2019-07-07 16:51:23.03 spid7s SQL Trace ID 1 was started by login "sa". 2019-07-07 16:51:23.03 spid7s Server name is 'Organization_Name-Service_Account\ABC'. This is an informational message only. No user action is required. 2019-07-07 16:51:23.03 spid7s The NETBIOS name of the local node that is running the server is 'Organization_Name-MWDB01'. This is an informational message only. No user action is required. 2019-07-07 16:51:23.06 spid15s A self-generated certificate was successfully loaded for encryption. 2019-07-07 16:51:23.09 spid15s Server is listening on [ 192.168.100.170 <ipv4> 1433]. 2019-07-07 16:51:23.09 spid15s Started listening on virtual network name 'Organization_Name-Service_Account'. No user action is required. 2019-07-07 16:51:23.09 spid15s Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\ABC ]. 2019-07-07 16:51:23.09 spid15s Server named pipe provider is ready to accept connection on [ \\.\pipe\$$\Organization_Name-Service_Account\DB_SQL$ABC\sql\query ]. 2019-07-07 16:51:23.10 spid15s SQL Server is now ready for client connections. This is an informational message; no user action is required. 2019-07-07 16:51:23.10 Server SQL Server is attempting to register a Service Principal Name (SPN) for the SQL Server service. Kerberos authentication will not be possible until a SPN is registered for the SQL Server service. This is an informational message. No user action is required. 2019-07-07 16:51:23.18 Logon Error: 18456, Severity: 14, State: 38. 2019-07-07 16:51:23.18 Logon Login failed for user 'ABCuser'. Reason: Failed to open the explicitly specified database 'Organization_Name_DB2'. [CLIENT: 192.168.100.151] 2019-07-07 16:51:23.23 Server The SQL Server Network Interface library could not register the Service Principal Name (SPN) [ DB_SQLSvc/Organization_Name-Service_Account.Organization_Name.COM:ABC ] for the SQL Server service. Windows return code: 0x2098, state: 20. Failure to register a SPN might cause integrated authentication to use NTLM instead of Kerberos. This is an informational message. Further action is only required if Kerberos authentication is required by authentication policies and if the SPN has not been manually registered. 2019-07-07 16:51:23.23 Server The SQL Server Network Interface library could not register the Service Principal Name (SPN) [ DB_SQLSvc/Organization_Name-Service_Account.Organization_Name.COM:1433 ] for the SQL Server service. Windows return code: 0x2098, state: 20. Failure to register a SPN might cause integrated authentication to use NTLM instead of Kerberos. This is an informational message. Further action is only required if Kerberos authentication is required by authentication policies and if the SPN has not been manually registered. 2019-07-07 16:51:23.40 Logon Error: 18456, Severity: 14, State: 38. 2019-07-07 16:51:23.40 Logon Login failed for user 'DB2user'. Reason: Failed to open the explicitly specified database 'Organization_Name_DB2'. [CLIENT: 192.168.100.151] 2019-07-07 16:51:23.45 spid16s A new instance of the full-text filter daemon host process has been successfully started. 2019-07-07 16:51:23.49 spid19s Starting up database 'msdb'. 2019-07-07 16:51:23.49 spid20s Starting up database 'Organization_Name_DB1'. 2019-07-07 16:51:23.49 spid22s Starting up database 'Organization_Name_DB2'. 2019-07-07 16:51:23.50 spid21s Starting up database 'Organization_Name_ABC'. 2019-07-07 16:51:23.50 spid23s Starting up database 'DB3'. 2019-07-07 16:51:23.50 spid24s Starting up database 'DBA_Maintenance'. 2019-07-07 16:51:23.50 spid10s Starting up database 'DB_SQLsystemresource'. 2019-07-07 16:51:23.50 spid25s Starting up database 'DB4'. 2019-07-07 16:51:23.53 spid10s The resource database build version is 12.00.6024. This is an informational message only. No user action is required. 2019-07-07 16:51:23.60 spid25s 2 transactions rolled forward in database 'DB4' (10:0). This is an informational message only. No user action is required. 2019-07-07 16:51:23.72 spid7s 0 transactions rolled back in database 'DB4' (10:0). This is an informational message only. No user action is required. 2019-07-07 16:51:23.72 spid10s Starting up database 'model'. 2019-07-07 16:51:23.75 spid24s 47 transactions rolled forward in database 'DBA_Maintenance' (9:0). This is an informational message only. No user action is required. 2019-07-07 16:51:23.81 spid20s 1001 transactions rolled forward in database 'Organization_Name_DB1' (5:0). This is an informational message only. No user action is required. 2019-07-07 16:51:23.93 spid7s 0 transactions rolled back in database 'DBA_Maintenance' (9:0). This is an informational message only. No user action is required. 2019-07-07 16:51:23.93 spid7s Recovery is writing a checkpoint in database 'DBA_Maintenance' (9). This is an informational message only. No user action is required. 2019-07-07 16:51:23.97 spid19s 1934 transactions rolled forward in database 'msdb' (4:0). This is an informational message only. No user action is required. 2019-07-07 16:51:24.06 Server Software Usage Metrics is disabled. 2019-07-07 16:51:24.08 spid10s CHECKDB for database 'model' finished without errors on 2019-07-05 21:45:02.243 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:24.08 spid10s Clearing tempdb database. 2019-07-07 16:51:24.14 spid7s 0 transactions rolled back in database 'Organization_Name_DB1' (5:0). This is an informational message only. No user action is required. 2019-07-07 16:51:24.14 spid7s Recovery is writing a checkpoint in database 'Organization_Name_DB1' (5). This is an informational message only. No user action is required. 2019-07-07 16:51:24.24 spid10s Starting up database 'tempdb'. 2019-07-07 16:51:24.25 spid7s 0 transactions rolled back in database 'msdb' (4:0). This is an informational message only. No user action is required. 2019-07-07 16:51:24.25 spid7s Recovery is writing a checkpoint in database 'msdb' (4). This is an informational message only. No user action is required. 2019-07-07 16:51:24.36 spid10s The tempdb database has 1 data file(s). 2019-07-07 16:51:24.36 spid30s The Service Broker endpoint is in disabled or stopped state. 2019-07-07 16:51:24.36 spid30s The Database Mirroring endpoint is in disabled or stopped state. 2019-07-07 16:51:24.36 spid19s CHECKDB for database 'msdb' finished without errors on 2019-07-05 21:45:02.820 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:24.37 spid30s Service Broker manager has started. 2019-07-07 16:51:24.40 spid25s CHECKDB for database 'DB4' finished without errors on 2019-07-03 23:30:07.940 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:24.40 spid24s CHECKDB for database 'DBA_Maintenance' finished without errors on 2019-07-04 07:58:21.313 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:24.43 spid20s CHECKDB for database 'Organization_Name_DB1' finished without errors on 2019-07-03 23:30:44.193 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:24.55 spid52 Configuration option 'show advanced options' changed from 0 to 1. Run the RECONFIGURE statement to install. 2019-07-07 16:51:24.55 spid52 Configuration option 'Agent XPs' changed from 0 to 1. Run the RECONFIGURE statement to install. 2019-07-07 16:51:24.56 spid52 Configuration option 'show advanced options' changed from 1 to 0. Run the RECONFIGURE statement to install. 2019-07-07 16:51:24.81 spid23s 1391 transactions rolled forward in database 'DB3' (8:0). This is an informational message only. No user action is required. 2019-07-07 16:51:24.82 spid52 Attempting to load library 'xpsqlbot.dll' into memory. This is an informational message only. No user action is required. 2019-07-07 16:51:24.82 spid52 Using 'xpsqlbot.dll' version '2014.120.6024' to execute extended stored procedure 'xp_qv'. This is an informational message only; no user action is required. 2019-07-07 16:51:24.90 spid52 Attempting to load library 'xpstar.dll' into memory. This is an informational message only. No user action is required. 2019-07-07 16:51:24.91 spid52 Using 'xpstar.dll' version '2014.120.6024' to execute extended stored procedure 'xp_sqlagent_notify'. This is an informational message only; no user action is required. 2019-07-07 16:51:24.92 spid7s 0 transactions rolled back in database 'DB3' (8:0). This is an informational message only. No user action is required. 2019-07-07 16:51:24.92 spid7s Recovery is writing a checkpoint in database 'DB3' (8). This is an informational message only. No user action is required. 2019-07-07 16:51:24.94 spid23s CHECKDB for database 'DB3' finished without errors on 2019-07-03 23:41:10.877 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:25.04 spid22s Recovery of database 'Organization_Name_DB2' (6) is 0% complete (approximately 313 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required. 2019-07-07 16:51:25.05 spid22s Recovery of database 'Organization_Name_DB2' (6) is 0% complete (approximately 310 seconds remain). Phase 1 of 3. This is an informational message only. No user action is required. 2019-07-07 16:51:25.29 spid22s 5868 transactions rolled forward in database 'Organization_Name_DB2' (6:0). This is an informational message only. No user action is required. 2019-07-07 16:51:25.42 spid21s 82 transactions rolled forward in database 'Organization_Name_ABC' (7:0). This is an informational message only. No user action is required. 2019-07-07 16:51:25.49 spid7s 0 transactions rolled back in database 'Organization_Name_DB2' (6:0). This is an informational message only. No user action is required. 2019-07-07 16:51:25.49 spid7s Recovery is writing a checkpoint in database 'Organization_Name_DB2' (6). This is an informational message only. No user action is required. 2019-07-07 16:51:25.51 spid22s CHECKDB for database 'Organization_Name_DB2' finished without errors on 2019-07-03 23:30:45.717 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:25.62 spid7s 0 transactions rolled back in database 'Organization_Name_ABC' (7:0). This is an informational message only. No user action is required. 2019-07-07 16:51:25.62 spid7s Recovery is writing a checkpoint in database 'Organization_Name_ABC' (7). This is an informational message only. No user action is required. 2019-07-07 16:51:25.64 spid21s CHECKDB for database 'Organization_Name_ABC' finished without errors on 2019-07-03 03:31:59.657 (local time). This is an informational message only; no user action is required. 2019-07-07 16:51:25.64 spid7s Error: 8355, Severity: 16, State: 1. 2019-07-07 16:51:25.64 spid7s Server-level event notifications can not be delivered. Either Service Broker is disabled in msdb, or msdb failed to start. Event notifications in other databases could be affected as well. Bring msdb online, or enable Service Broker. 2019-07-07 16:51:25.64 spid7s Recovery is complete. This is an informational message only. No user action is required. 2019-07-07 16:54:38.88 spid57 ex_dump_if_requested: Exception raised, major=52, minor=42, state=9, severity=22, attempting to create symptom dump 2019-07-07 16:54:38.88 spid57 Using 'dbghelp.dll' version '4.0.5' 2019-07-07 16:54:38.89 spid57 **Dump thread - spid = 0, EC = 0x00000004D7695F10
版本:Microsoft SQL Server 2014 (SP3) (KB4022619) - 12.0.6024.0 (X64) Sep 7 2018 01:37:51 版權所有 (c) Microsoft Corporation Enterprise Edition:Windows NT 6.3 上基於核心的許可(64 位)(內部版本 9600:)(管理程序)
這是“內部”擴展事件 (XE) 會話的輸出,它提供記憶體中 OLTP (Hekaton) 表的故障排除資訊。雖然它沒有顯示在 SSMS GUI 中,但您可以看到它在 DMV 中的定義位置:
SELECT s.[name], s.session_source, st.target_name, soc.column_name, soc.column_value FROM sys.dm_xe_sessions s INNER JOIN sys.dm_xe_session_targets st ON st.event_session_address = s.[address] INNER JOIN sys.dm_xe_session_object_columns soc ON soc.event_session_address = s.[address] WHERE s.[name] = 'hkenginexesession' AND st.target_name = 'event_file' AND soc.object_type = 'target' ORDER BY s.[name], soc.column_name;
顯示這些結果:
name session_source target_name column_name column_value hkenginexesession internal event_file filename HkEngineEventFile.xel hkenginexesession internal event_file increment 0 hkenginexesession internal event_file lazy_create_blob true hkenginexesession internal event_file max_file_size 5 hkenginexesession internal event_file max_rollover_files 20 hkenginexesession internal event_file metadatafile NULL
如您所見,在它們開始被覆蓋之前,它一次最多可以有 20 個文件。
68 KB 只是寫入該文件(基本外部 XML 結構)的最小數據量,因此您不能使用 Hekaton。
由於正常原因(服務重新啟動、伺服器重新啟動、事件會話停止/啟動等),將創建新文件。內部會話翻轉可能還有其他原因,但我不知道有任何原因。
請注意,您顯示的 SQL Server 日誌輸出確實表明 SQL Server 已重新啟動,並且正在啟動 - 並且時間與螢幕截圖中的 .xel 文件之一一致(7 月 7 日下午 4:51)。
最後,您可能想查看日誌的最後幾行,並可能向 Microsoft 開一個案例,因為看起來 SQL Server 可能正在生成故障轉儲文件:
ex_dump_if_requested:引發異常,major=52,minor=42,state=9,severity=22,嘗試
使用“dbghelp.dll”版本“4.0.5”創建症狀轉儲
**轉儲執行緒 - spid = 0,EC = 0x00000004D7695F10