ここから本文です

SQL Serverの起動ログ「ERRORLOG」には、何が記録されているの?

@IT 7月14日(木)6時10分配信

 本連載では、「Microsoft SQL Server(以下、SQL Server)」で発生するトラブルについて、「なぜ起こったか」の理由を理解し、正しく対処するためのノウハウを紹介していきます。今回より数回にわたって、「SQL Serverは、起動時にどんな動きをしているのか」の理解を深めていきましょう。

【その他の画像】Windowsで確認できるSQL Serverのサービス

 まず、「ログを確認して、正しく対処する」の基礎を踏まえ、SQL Serverの起動ログ「ERRORLOG」の見方を解説します。

●【1】起動から、利用可能になるまでの流れをログから理解する

 SQL Serverは、規定値のままインストールするとOSの起動と共にサービスが起動し、クライアントから利用可能になります。起動時のトラブルは、ユーザーまたはアプリケーションから見て「つながらない」という1つの現象に見えることがほとんどです。

 SQL ServerはWindowsから見ると、「サービスアプリケーション(以下、サービスと呼びます)」として動作します。ここでは「Windowsにおけるサービス」を「Windows上で動作し、ユーザーに対して何らかの機能を長時間提供し続けるプログラム」と定義します。Windowsのサービスの画面からは、以下のようにSQL Serverのサービスが見えています(図1)。

 ずらりと並ぶサービスのうち、「SQL Full-text Filter Daemon Launcher」から「SQL Server エージェント(MSSQLSERVER)」までがSQL Serverに関連しています。ただしこの画面は、Windows上でプログラムが実行されている/登録されていることを示すもので、実際にサービスが正しく動作しているかは別の話です。このことを理解すれば、「なぜつながらないのか」の解決策を導けます。

 SQL Serverは、起動後におおよそ以下の順序でクライアントから接続できるまでの準備をします。厳密には、複数のスレッドが動作し、平行して処理を進めますが、ここでは、実際に何をしているのかを理解すれば大丈夫です。このときに起動したSQL Serverのプロセスとメモリ空間を、「インスタンス」と呼びます。

 (1)Windowsからサービスが起動される
 (2)レジストリ(*1)から必要な情報を取得してプロセスを起動する
 (3)「masterデータベース」(*2)を起動し、必要な情報を読み取る
 (4)クライアント接続できるようにTCP/IPや「名前付きパイプ」(*3)の待ち受けを開始する
 (5)一部のシステムデータベースとユーザーデータベースを並列に起動する
 (6)データ整合性を保つためにデータベースのリカバリーを行う
 (7)TEMPDBデータベースの再作成とMODELデータベースの起動を行う

*1:レジストリは、OSが持つ設定情報を格納する仕組みです。SQL Serverはレジストリから起動に必要なmasterデータベースの場所やインスタンス名などを読み込みます
*2:masterデータベースにはインスタンスに含まれる各データベースの内容や設定値が入っています
*3:TCP/IPや名前付きパイプは、SQL Serverとアプリケーションが通信するためのプロトコルです

 SQL Serverには、起動してから停止するまでの動作を記録している「ERRORLOG」というログがあります。そのログの内容と、上記の起動までの流れを見比べてみましょう。

●起動してから停止するまでの動作を記録している「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」を利用可能にした処理です。

--
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.
--


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

●筆者紹介
内ヶ島 暢之(うちがしま のぶゆき)
ユニアデックス株式会社所属。Microsoft MVP Data Platform(2011~ )。OracleやSQL Serverなど商用データベースの重大障害や大型案件の設計構築、プリセールス、社内外の教育、新技術評価を行っていた。2016年4月よりIoTビジネス開発の担当となり、新しい仕事に奮闘中。ストレッチをして柔らかい身体を手に入れるのが当面の目標。
椎名 武史(しいな たけし)
ユニアデックス株式会社所属。入社以来 SQL Serverの評価/設計/構築/教育などに携わりながらも、主にサポート業務に従事。SQL Serverのトラブル対応で社長賞の表彰を受けた経験も持つ。休日は学生時代の仲間と市民駅伝に参加し、銭湯で汗を流してから飲み会へと流れる。

最終更新:7月14日(木)6時10分

@IT