SQL Serverの起動ログ「ERRORLOG」には、何が記録されているのか？：SQL Serverトラブルシューティング（5）（2/2 ページ）

本連載は、「Microsoft SQL Server」で発生するトラブルを「どんな方法で」「どのように」解決していくか、正しい対処のためのノウハウを紹介します。今回は、「起動ログ“ERRORLOG”の見方」を解説します。

[内ヶ島暢之，ユニアデックス株式会社]

起動してから停止するまでの動作を記録している「ERRORLOG」

2016-06-22 17:11:08.77 Server      Microsoft SQL Server 2016 (RTM) - 13.0.1601.5 (X64) 
	Apr 29 2016 23:23:58 
	Copyright (c) Microsoft Corporation
	Enterprise Edition (64-bit) on Windows Server 2012 R2 Datacenter 6.3 <X64> (Build 9600: ) (Hypervisor)
2016-06-22 17:11:08.77 Server      UTC adjustment: 9:00
2016-06-22 17:11:08.77 Server      (c) Microsoft Corporation.
2016-06-22 17:11:08.77 Server      All rights reserved.
2016-06-22 17:11:08.77 Server      Server process ID is 5564.
2016-06-22 17:11:08.77 Server      System Manufacturer: 'XXX.', System Model: 'XXX'.
2016-06-22 17:11:08.77 Server      Authentication mode is MIXED.
2016-06-22 17:11:08.77 Server      Logging SQL Server messages in file 'C:\Program Files\Microsoft SQL Server\MSSQL13.MSSQLSERVER\MSSQL\Log\ERRORLOG'.
2016-06-22 17:11:08.77 Server      The service account is 'DOMAIN\SQLUser'. This is an informational message; no user action is required.
2016-06-22 17:11:08.77 Server      Registry startup parameters: 
	 -d C:\Program Files\Microsoft SQL Server\MSSQL13.MSSQLSERVER\MSSQL\DATA\master.mdf
	 -e C:\Program Files\Microsoft SQL Server\MSSQL13.MSSQLSERVER\MSSQL\Log\ERRORLOG
	 -l C:\Program Files\Microsoft SQL Server\MSSQL13.MSSQLSERVER\MSSQL\DATA\mastlog.ldf
2016-06-22 17:11:08.77 Server      Command Line Startup Parameters:
	 -s "MSSQLSERVER"
2016-06-22 17:11:08.77 Server      SQL Server detected 2 sockets with 1 cores per socket and 1 logical processors per socket, 2 total logical processors; using 2 logical processors based on SQL Server licensing. This is an informational message; no user action is required.
2016-06-22 17:11:08.77 Server      SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2016-06-22 17:11:08.77 Server      Detected 4095 MB of RAM. This is an informational message; no user action is required.
2016-06-22 17:11:08.77 Server      Using conventional memory in the memory manager.
2016-06-22 17:11:08.84 Server      Default collation: Japanese_CI_AS (日本語 1041)
2016-06-22 17:11:08.86 Server      Buffer pool extension is already disabled. No action is necessary. 
2016-06-22 17:11:08.88 Server      InitializeExternalUserGroupSid failed. Implied authentication will be disabled.
2016-06-22 17:11:08.88 Server      Implied authentication manager initialization failed. Implied authentication will be disabled.
2016-06-22 17:11:08.89 Server      The maximum number of dedicated administrator connections for this instance is '1'
2016-06-22 17:11:08.89 Server      This instance of SQL Server last reported using a process ID of 8524 at 2016/06/22 17:11:03 (local) 2016/06/22 8:11:03 (UTC). This is an informational message only; no user action is required.
2016-06-22 17:11:08.89 Server      Node configuration: node 0: CPU mask: 0x0000000000000003:0 Active CPU mask: 0x0000000000000003:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.
2016-06-22 17:11:08.90 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.
2016-06-22 17:11:08.90 Server      Database Instant File Initialization: 有効. 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.
2016-06-22 17:11:08.93 Server      Query Store settings initialized with enabled = 1, 
2016-06-22 17:11:08.93 spid5s      [INFO] HkHostDbCtxt::Initialize(): Database ID: [1] 'master'. XTP Engine version is 0.0.
2016-06-22 17:11:08.93 spid5s      Starting up database 'master'.
2016-06-22 17:11:10.05 spid5s      Server name is 'WIN2012R2'. This is an informational message only. No user action is required.
2016-06-22 17:11:10.07 spid10s     A self-generated certificate was successfully loaded for encryption.
2016-06-22 17:11:10.08 spid10s     Server is listening on [ 'any' <ipv6> 1433].
2016-06-22 17:11:10.08 spid10s     Server is listening on [ 'any' <ipv4> 1433].
2016-06-22 17:11:10.08 spid10s     Server local connection provider is ready to accept connection on [ \\.\pipe\SQLLocal\MSSQLSERVER ].
2016-06-22 17:11:10.08 spid10s     Server local connection provider is ready to accept connection on [ \\.\pipe\sql\query ].
2016-06-22 17:11:10.08 Server      Server is listening on [ ::1 <ipv6> 1434].
2016-06-22 17:11:10.08 Server      Server is listening on [ 127.0.0.1 <ipv4> 1434].
2016-06-22 17:11:10.08 Server      Dedicated admin connection support was established for listening locally on port 1434.
2016-06-22 17:11:10.08 spid10s     SQL Server is now ready for client connections. This is an informational message; no user action is required.
2016-06-22 17:11:10.08 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.
2016-06-22 17:11:10.10 Server      The SQL Server Network Interface library successfully registered the Service Principal Name (SPN) [ MSSQLSvc/Win2012R2.DOMAIN.local ] for the SQL Server service.
2016-06-22 17:11:10.10 Server      The SQL Server Network Interface library successfully registered the Service Principal Name (SPN) [ MSSQLSvc/Win2012R2.DOMAIN.local:1433 ] for the SQL Server service.
2016-06-22 17:11:11.04 Server      Software Usage Metrics is enabled.
2016-06-22 17:11:11.05 spid13s     A new instance of the full-text filter daemon host process has been successfully started.
2016-06-22 17:11:11.10 spid17s     Starting up database 'msdb'.
2016-06-22 17:11:11.10 spid18s     Starting up database 'ReportServer'.
2016-06-22 17:11:11.10 spid19s     Starting up database 'ReportServerTempDB'.
2016-06-22 17:11:11.10 spid20s     Starting up database 'DWDiagnostics'.
2016-06-22 17:11:11.10 spid6s      Starting up database 'mssqlsystemresource'.
2016-06-22 17:11:11.11 spid22s     Starting up database 'DWConfiguration'.
2016-06-22 17:11:11.11 spid24s     Starting up database 'UserDB'.
2016-06-22 17:11:11.11 spid23s     Starting up database 'DWQueue'.
2016-06-22 17:11:11.32 spid6s      The resource database build version is 13.00.1601. This is an informational message only. No user action is required.
2016-06-22 17:11:13.23 spid6s      Recovery completed for database mssqlsystemresource (database ID 32767) in 2 second(s) (analysis 785 ms, redo 0 ms, undo 172 ms.) This is an informational message only. No user action is required.
2016-06-22 17:11:13.61 spid5s      Recovery completed for database DWConfiguration (database ID 8) in 2 second(s) (analysis 773 ms, redo 0 ms, undo 210 ms.) This is an informational message only. No user action is required.
2016-06-22 17:11:13.72 spid5s      Recovery completed for database UserDB (database ID 10) in 2 second(s) (analysis 800 ms, redo 0 ms, undo 237 ms.) This is an informational message only. No user action is required.
2016-06-22 17:11:13.83 spid5s      Recovery completed for database ReportServerTempDB (database ID 6) in 2 second(s) (analysis 664 ms, redo 0 ms, undo 327 ms.) This is an informational message only. No user action is required.
2016-06-22 17:11:13.94 spid5s      Recovery completed for database DWQueue (database ID 9) in 2 second(s) (analysis 847 ms, redo 0 ms, undo 359 ms.) This is an informational message only. No user action is required.
2016-06-22 17:11:14.05 spid5s      Recovery completed for database ReportServer (database ID 5) in 2 second(s) (analysis 653 ms, redo 347 ms, undo 254 ms.) This is an informational message only. No user action is required.
2016-06-22 17:11:14.15 spid5s      Recovery completed for database DWDiagnostics (database ID 7) in 2 second(s) (analysis 412 ms, redo 0 ms, undo 240 ms.) This is an informational message only. No user action is required.
2016-06-22 17:11:15.06 spid6s      Starting up database 'model'.
2016-06-22 17:11:16.57 spid6s      Polybase feature disabled.
2016-06-22 17:11:16.57 spid6s      Clearing tempdb database.
2016-06-22 17:11:17.34 spid6s      Starting up database 'tempdb'.
2016-06-22 17:11:17.51 spid6s      The tempdb database has 2 data file(s).
2016-06-22 17:11:17.51 spid27s     The Service Broker endpoint is in disabled or stopped state.
2016-06-22 17:11:17.51 spid27s     The Database Mirroring endpoint is in disabled or stopped state.
2016-06-22 17:11:17.94 spid27s     Service Broker manager has started.
2016-06-22 17:11:18.00 spid5s      Recovery is complete. This is an informational message only. No user action is required.
2016-06-22 17:11:19.46 spid51      Configuration option 'show advanced options' changed from 0 to 1. Run the RECONFIGURE statement to install.
2016-06-22 17:11:19.51 spid51      Configuration option 'Agent XPs' changed from 0 to 1. Run the RECONFIGURE statement to install.
2016-06-22 17:11:19.55 spid51      Configuration option 'show advanced options' changed from 1 to 0. Run the RECONFIGURE statement to install.
2016-06-22 17:11:20.26 spid51      Attempting to load library 'xpsqlbot.dll' into memory. This is an informational message only. No user action is required.
2016-06-22 17:11:20.26 spid51      Using 'xpsqlbot.dll' version '2015.130.1601' to execute extended stored procedure 'xp_qv'. This is an informational message only; no user action is required.
2016-06-22 17:11:20.35 spid51      Attempting to load library 'xpstar.dll' into memory. This is an informational message only. No user action is required.
2016-06-22 17:11:20.35 spid51      Using 'xpstar.dll' version '2015.130.1601' to execute extended stored procedure 'xp_sqlagent_notify'. This is an informational message only; no user action is required.

「ERRORLOG」の一部を抜粋

　1〜8行目が、「（1）Windowsからサービスが起動される」の動作を示しています。ここから、OSのバージョンやSQL Serverのバージョンが何かを確認できます。

　13〜18行目が、「（2）レジストリから必要な情報を取得してプロセスを起動する」の動作を示しています。プロセスの起動に必要な情報はレジストリに格納されています。

　34〜35行目が、「（3）masterデータベースを起動し、必要な情報を読み取る」の動作を示しています。「master」とは最初に起動されるデータベースのことで、“他のデータベースを起動するための情報”が記録されています。

　37〜44行目が、「（4）クライアント接続できるようにTCP/IPや名前付きパイプの待ち受けを開始する」の動作を示しています。ここで、SQL Serverがクライアントの接続に必要な処理が開始されたことが分かります。

　50〜57行目が、「（5）一部のシステムデータベースとユーザーデータベースを並列に起動する」の動作を示しています。（4）までの処理で起動に必要な情報がそろったので、master以外のデータベースをここで並列して起動します。

　59〜65行目が、「（6）データ整合性を保つためにデータベースのリカバリーを行う」の動作を示しています。データベースの起動直後に、前回停止時の残存情報をリカバリーする処理となります。

　66〜69行目が、「（7）TEMPDBデータベースの再作成とMODELデータベースの起動を行う」の動作を示しています。システムデータベースの一部である「tempdb」と「model」を利用可能にした処理です。

---

　次回は、SQL Server動きが変わる「サービス起動アカウントに実行権限を付与する方法」を解説する予定です。

本トラブルシューティングの対応バージョン：SQL Server 全バージョン

筆者紹介

内ヶ島 暢之（うちがしま のぶゆき）

ユニアデックス株式会社所属。Microsoft MVP Data Platform（2011〜 ）。OracleやSQL Serverなど商用データベースの重大障害や大型案件の設計構築、プリセールス、社内外の教育、新技術評価を行っていた。2016年4月よりIoTビジネス開発の担当となり、新しい仕事に奮闘中。ストレッチをして柔らかい身体を手に入れるのが当面の目標。

椎名 武史（しいな たけし）

ユニアデックス株式会社所属。入社以来 SQL Serverの評価／設計／構築／教育などに携わりながらも、主にサポート業務に従事。SQL Serverのトラブル対応で社長賞の表彰を受けた経験も持つ。休日は学生時代の仲間と市民駅伝に参加し、銭湯で汗を流してから飲み会へと流れる。