Что нам скажет SQL Server ERRORLOG?!

Что такое ERRORLOG?! Некоторые специалисты, которые сопровождают MS SQL Server первый раз слышат о нем или не подозревают, что он есть.

ERRORLOG – это журнал MS SQL Server, физически это текстовый файл. По умолчанию он находится в каталоге установке SQL Server в папке Log, к примеру, в «C:\Program Files\Microsoft SQL Server\ MSSQL13.SQL2016\ MSSQL\Log». В нем регистрируются как информационные сообщения, ошибки различной серьезности, пользовательские ошибки информация по dump-ам sql server и другая полезная инфомарция, хотя бывает и не очень полезная.

Журнал создается каждый раз при запуске службы SQL Server, количество их регулируется настройками в SQL Server, желательно указывать 10 или более на важных системах, т.к при установке обновлений, проблемах при нескольких попытках старта SQL Server, они перезаписываются и в итоге вы можете потерять важную информацию при диагностике сервера.

Даже при установке обновлений SQL Server, происходит несколько рестартов служб, что так же создает новый журнал.

В данный журнал записывается информация как об ошибках работы сервера, информация о sql дампах, безопасности, так и информация информационного характера.

Журналы можно просмотреть несколькими способами:

1.    

   Через SQL Server Management Studio, вкладка Management -> SQL Server Logs, дважды щелкнув на нужный файл.

2.       Открыть текстовым любым текстовым редактором из каталог Log.

Текущий всегда будет без расширения и с именем ERRORLOG, далее по возрастанию от 1 и выше, 1 это предпоследний.

3.       Использовать хранимую процедуру.

exec master..xp_ReadErrorLog

Когда журнал большой, лучше его отфильтровать, к примеру таким способом, меню Filter в Log File Viewer:

Или через T-SQL:

create table #t

( logdate datetime,

 processinfo char(15),

 text nvarchar(max)

)

insert into #t

exec xp_ReadErrorLog

select * from #t where text like'%Error%'

drop table #t

.

Если сервер давно не перезагружали или сервер имел много событий, файл журнала событий может вырасти в размере и открытие его будет проблематичным. В данном случае, активный журнал можно пересоздать командой:

EXEC sp_cycle_errorlog

После этого создастся новый текущий журнал, а в файле отразится информация вида:

Message

Attempting to cycle error log. This is an informational message only; no user action is required.

Message

The error log has been reinitialized. See the previous log for older entries.

Чтобы держать файлы в порядке и читабельными, желательно указанную команду прописать в sql задание на раз в месяц.

Итак, что говорит нам SQL Server Log?

Возьмем, для примера, файл с одного с рабочих серверов:

2017-06-18 12:26:50.31 Server      Microsoft SQL Server 2016 (SP1-CU3) (KB4019916) - 13.0.4435.0 (X64)

                Apr 27 2017 17:36:12

                Copyright (c) Microsoft Corporation

                Enterprise Edition: Core-based Licensing (64-bit) on Windows Server 2016 Datacenter 6.3 <X64> (Build 14393: )

Сразу можно определить версию SQL Server, установленные обновления и ОС, время старта SQL Server. Довольно часто, обновления не ставят на сервер, но имеют проблемы. Как-то обратился клиент, у него имелось куча проблем, попросил данный журнал SQL server, а у них версия SQL server 2008R2 RTM, при том что за окном уже SQL версии 2017 на подходе. Первое рекомендация и необходимость дальнейшей работы – установить обновления последния.

Идем далее по файлу:

2017-06-18 12:26:50.32 Server      UTC adjustment: 3:00

Локальное время на сервере.

2017-06-18 12:26:50.32 Server      (c) Microsoft Corporation.

2017-06-18 12:26:50.32 Server      All rights reserved.

2017-06-18 12:26:50.32 Server      Server process ID is 8112.

2017-06-18 12:26:50.32 Server      System Manufacturer: 'FUJITSU', System Model: 'PRIMERGY RX4770 M3'.

Вендор и модель сервера, тоже важно. При виртуализации это здесь так же видно.

2017-06-18 12:26:50.32 Server      Authentication mode is MIXED.

Вид аутефикации на сервере - здесь смешанная.

2017-06-18 12:26:50.32 Server      Logging SQL Server messages in file 'C:\SQL\MSSQL13.MSSQLSERVER\MSSQL\Log\ERRORLOG'.

Каталог расположения этого самого журнала.

2017-06-18 12:26:50.32 Server      The service account is 'AD\SQL_USER'. This is an informational message; no user action is required.

Учетная запись, под которой работает служба SQL Server. Сразу и легко определяес под кем работает служба, далее можно у админов ОС запросить проверку прав в ОС или что-то подобное.

2017-06-18 12:26:50.32 Server      Registry startup parameters:

                 -d C:\SQL\MSSQL13.MSSQLSERVER\MSSQL\DATA\master.mdf

                 -e C:\SQL\MSSQL13.MSSQLSERVER\MSSQL\Log\ERRORLOG

                 -l C:\SQL\MSSQL13.MSSQLSERVER\MSSQL\DATA\mastlog.ldf

                 -T 2371

                 -T 4135

                 -T 2546

Параметры старта SQL server, здесь видим флаги запуска службы SQL server, располжения системных баз данных.

2017-06-18 12:26:50.32 Server      Command Line Startup Parameters:

                 -s "MSSQLSERVER"

2017-06-18 12:26:52.86 Server      SQL Server detected 4 sockets with 24 cores per socket and 48 logical processors per socket, 192 total logical processors; using 192 logical processors based on SQL Server licensing. This is an informational message; no user action is required.

2017-06-18 12:26:52.86 Server      SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.

Видим, сколько процессоров на сервере и включен ли HT.

2017-06-18 12:26:52.86 Server      Detected 3193980 MB of RAM. This is an informational message; no user action is required.

Память на сервере, здесь 3 Тб.

2017-06-18 12:26:52.86 Server      Using locked pages in the memory manager.

2017-06-18 12:26:52.86 Server      Large Page Allocated: 32MB

2017-06-18 12:26:52.87 Server      Large Page Allocated: 32MB

2017-06-18 12:26:52.87 Server      Large Page Allocated: 32MB

2017-06-18 12:26:52.87 Server      Large Page Allocated: 32MB

Видим, что учетной записи SQL server предоставлены права блокировать память на сервере, а также выделение больших страниц в памяти.

2017-06-18 12:26:57.71 Server      Machine supports memory error recovery. SQL memory protection is enabled to recover from memory corruption.

2017-06-18 12:27:00.82 Server      Default collation: Cyrillic_General_CI_AS (us_english 1033)

Collation на сервере,

2017-06-18 12:27:00.82 Server      Automatic soft-NUMA was enabled because SQL Server has detected hardware NUMA nodes with greater than 8 physical cores.

Включается soft-Numa в SQL 2016.

2017-06-18 12:27:00.90 Server      Buffer pool extension is already disabled. No action is necessary.

Buffer pool extension- выключен. Далее идет определения DAC, soft-numa, параметры блокировок:

2017-06-18 12:27:01.04 Server      InitializeExternalUserGroupSid failed. Implied authentication will be disabled.

2017-06-18 12:27:01.04 Server      Implied authentication manager initialization failed. Implied authentication will be disabled.

2017-06-18 12:27:01.13 Server      The maximum number of dedicated administrator connections for this instance is '1'

2017-06-18 12:27:01.13 Server      This instance of SQL Server last reported using a process ID of 8116 at 6/18/2017 1:06:37 PM (local) 6/18/2017 10:06:37 AM (UTC). This is an informational message only; no user action is required.

2017-06-18 12:27:01.13 Server      Node configuration: node 0: CPU mask: 0x0000000000555555:0 Active CPU mask: 0x0000000000555555:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.

…..

   2017-06-18 12:27:01.14 Server      Node configuration: node 15: CPU mask: 0x0000aaaaaa000000:3 Active CPU mask: 0x0000aaaaaa000000:3. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.

2017-06-18 12:27:01.31 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.

2017-06-18 12:27:01.31 Server      Lock partitioning is enabled.  This is an informational message only. No user action is required.

2017-06-18 12:27:01.34 Server      Database Instant File Initialization: enabled. 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.

2017-06-18 12:27:01.41 Server      CLR version v4.0.30319 loaded.

2017-06-18 12:27:01.51 Server      Query Store settings initialized with enabled = 1,

Включается компонент Query Store

Начинается старт системных бд:

2017-06-18 12:27:01.53 spid10s     Starting up database 'master'.

2017-06-18 12:27:01.53 Server      In-Memory OLTP initialized on highend machine.

2017-06-18 12:27:01.59 Server      Common language runtime (CLR) functionality initialized using CLR version v4.0.30319 from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\.

2017-06-18 12:27:01.72 spid10s     CHECKDB for database 'master' finished without errors on 2017-06-21 03:35:10.293 (local time). This is an informational message only; no user action is required.

2017-06-18 12:27:01.72 spid10s     Resource governor reconfiguration succeeded.

2017-06-18 12:27:01.72 spid10s     SQL Server Audit is starting the audits. This is an informational message. No user action is required.

2017-06-18 12:27:01.73 spid10s     Audit: Server Audit: 65537, Initialized and Assigned State: START_FAILED

2017-06-18 12:27:01.73 spid10s     Audit: Server Audit: 65537, Initialized and Assigned State: STARTED

На сервере есть аудиты.

2017-06-18 12:27:01.74 spid10s     SQL Server Audit has started the audits. This is an informational message. No user action is required.

2017-06-18 12:27:01.78 spid10s     Server name is 'server1'. This is an informational message only. No user action is required.

Имя сервера, как не странно)

2017-06-18 12:27:01.80 spid10s     Database mirroring has been enabled on this instance of SQL Server.

2017-06-18 12:27:01.80 spid20s     Always On: The availability replica manager is starting. This is an informational message only. No user action is required.

2017-06-18 12:27:01.81 spid20s     Always On Availability Groups: Waiting for local Windows Server Failover Clustering service to start. This is an informational message only. No user action is required.

2017-06-18 12:27:01.81 spid20s     Always On Availability Groups: Local Windows Server Failover Clustering service started. This is an informational message only. No user action is required.

Сервер является частью кластера, включен компонент AlwaysOn.

2017-06-18 12:27:01.81 spid12s     Starting up database 'mssqlsystemresource'.

2017-06-18 12:27:01.81 spid20s     Always On Availability Groups: Waiting for local Windows Server Failover Clustering node to start. This is an informational message only. No user action is required.

2017-06-18 12:27:01.81 spid20s     Always On Availability Groups: Local Windows Server Failover Clustering node started. This is an informational message only. No user action is required.

2017-06-18 12:27:01.81 spid20s     Always On Availability Groups: Waiting for local Windows Server Failover Clustering node to come online. This is an informational message only. No user action is required.

2017-06-18 12:27:01.81 spid31s     Starting up database 'DB'.

2017-06-18 12:27:01.81 spid22s     Starting up database 'DB2'.

2017-06-18 12:27:01.81 spid25s     Starting up database 'DB3'.

2017-06-18 12:27:01.81 spid26s     Starting up database 'DB4'.

2017-06-18 12:27:01.82 spid24s     Starting up database 'msdb'.

Получаем список баз данных на сервере и далее можно отследить как они инициализируются, без проблем или нет.

2017-06-18 12:27:01.82 spid16s     Server is listening on [ 'any' <ipv6> 1433].

2017-06-18 12:27:01.82 spid16s     Server is listening on [ 'any' <ipv4> 1433].

Получили TCP порты на которые настроен SQL Server

2017-06-18 12:27:01.82 spid16s     Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\MSSQLSERVER ].

2017-06-18 12:27:01.82 spid16s     Server local connection provider is ready to accept connection on [ \\.\pipe\sql\query ].

2017-06-18 12:27:01.82 Server      Server is listening on [ 'any' <ipv6> 1434].

2017-06-18 12:27:01.82 Server      Server is listening on [ 'any' <ipv4> 1434].

2017-06-18 12:27:01.82 Server      Dedicated admin connection support was established for listening remotely on port 1434.

Порт DAC

2017-06-18 12:27:01.83 spid31s     [INFO] HkHostDbCtxt::Initialize(): Database ID: [13] 'DB'. XTP Engine version is 2.9

В базе данных используются компоненты InMemory

2017-06-18 12:27:01.83 spid12s     The resource database build version is 13.00.4435. This is an informational message only. No user action is required.

2017-06-18 12:27:01.83 spid16s     SQL Server is now ready for client connections. This is an informational message; no user action is required.

2017-06-18 12:27:01.83 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.

Проблемы с SPN, возможные, возможно SPN уже есть, просто нет прав на просмотр SPN.

2017-06-18 12:27:01.84 spid26s     [INFO] HkHostDbCtxt::Initialize(): Database ID: [8] 'DB3'. XTP Engine version is 2.9.

2017-06-18 12:27:01.87 spid12s     Starting up database 'model'.

2017-06-18 12:27:01.89 Server      The SQL Server Network Interface library could not register the Service Principal Name (SPN) [ MSSQLSvc/server1.ad.ru ] for the SQL Server service. Windows return code: 0x2098, state: 15. 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.

2017-06-18 12:27:01.89 Server      The SQL Server Network Interface library could not register the Service Principal Name (SPN) [ MSSQLSvc/server1.ad.ru:1433 ] for the SQL Server service. Windows return code: 0x2098, state: 15. 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.

2017-06-18 12:27:01.94 spid12s     CHECKDB for database 'model' finished without errors on 2017-06-21 03:38:53.560 (local time). This is an informational message only; no user action is required.

2017-06-18 12:27:01.94 spid12s     Polybase feature disabled.

2017-06-18 12:27:01.94 spid12s     Clearing tempdb database.

2017-06-18 12:27:02.06 spid12s     Starting up database 'tempdb'.

- стартовали системные бд, дальше идут уже сообщения относящиеся к базам данных, работе сервера или ошибки.

Итак, мы прошлись по журналу ERRORLOG SQL Server, как видим, он содержит много полезной информации и может служит начальной точкой при начале диагностике проблем в MS SQL Server.

Если вас просят провести диагностику сервера или решить проблемы, а с другой стороны специалист мало знаком с SQL Server, просто попросите его найти на сервере файл ERRORLOG, заархивировать его и прислать вам, в итоге вы без лишних разговоров получите много информации об сервере.

Удачи!.