Início / dba / Perguntas / 242347
Accepted
Learning_DBAdmin
Asked: 2019-07-09 04:59:28 +0800 CST

HKEngineEventFile na pasta Log do SQL Server

  • 772

Houve um problema de inconsistência em nosso banco de dados, conforme solicitado nesta pergunta . O mesmo está corrigido agora e o banco de dados está sendo executado sem nenhum problema.

Percebi que o serviço SQL foi reiniciado muitas vezes nos últimos 3 dias (conforme o log de erros) e essa reinicialização levou apenas 1 a 2 segundos e, para minha surpresa, ninguém percebeu isso, enquanto isso acontecia no horário comercial. Este é um banco de dados de produção e é muito usado, o que significa que a cada segundo há 1-3 transações que atingem o banco de dados.

Anotei a hora da reinicialização do serviço ou dos últimos dias e notei que ao mesmo tempo (todas as vezes), um arquivo é criado com o nome " HkEngineEventFile_0_XXXX " de tamanho 68KB. tentei abrir isso em uma ferramenta diferente, mas não obtive nenhuma informação.

HKEngineEvent_0_XXX

Alguém pode me ajudar a entender isso e também preciso entender se foi uma reinicialização real do serviço ou outra coisa.

Abaixo estão a entrada do log de erros do 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

Versão: Microsoft SQL Server 2014 (SP3) (KB4022619) - 12.0.6024.0 (X64) 7 de setembro de 2018 01:37:51 Copyright (c) Microsoft Corporation Enterprise Edition: Licenciamento baseado em núcleo (64 bits) no Windows NT 6.3 ( Build 9600: ) (Hipervisor)

sql-server event

1 respostas

  1. Best Answer

    Essa é a saída de uma sessão "interna" de eventos estendidos (XE) que fornece informações de solução de problemas para tabelas OLTP na memória (Hekaton). Embora não apareça na GUI do SSMS, você pode ver onde está definido nos DMVs:

    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;

    Que exibe estes resultados:

    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

    Como você pode ver, ele pode ter até 20 arquivos por vez antes que eles comecem a ser substituídos.

    68 KB é apenas a quantidade mínima de dados gravados nesse arquivo (a estrutura XML externa básica), portanto, você não deve usar o Hekaton.

    Novos arquivos serão criados pelos motivos normais (reinicialização do serviço, reinicialização do servidor, parada/início da sessão do evento, etc). Pode haver outros motivos para o rollover das sessões internas, mas não tenho conhecimento de nenhum.

    Observe que a saída de log do SQL Server que você mostrou indica que o SQL Server foi reiniciado e está inicializando - e o tempo se alinha com um dos arquivos .xel em sua captura de tela (7/7 às 16h51).

    Finalmente, você pode querer examinar essas últimas linhas do log e possivelmente abrir um caso com a Microsoft, pois parece que o SQL Server pode estar produzindo arquivos de despejo de memória:

    ex_dump_if_requested: exceção gerada, major=52, minor=42, state=9, gravity=22, tentando criar despejo de sintomas
    Usando 'dbghelp.dll' versão '4.0.5'
    **Dump thread - spid = 0, EC = 0x00000004D7695F10

    • 2

relate perguntas