DBの停止に関しまして

[tomo.k...@apps.vintage.ne.jp]

お世話になります。ヴィンテージ片山です。

以下環境でWebサイトを運営しております。

・apache 2.4.6

・maria-db 5.5.44

本日以下の流れでWebサイトの閲覧障害発生から復旧作業までを実施しました。

①4つの記事を本日10:00に公開設定

②本日10:00にブラウザで確認

③1分以上応答なし

④1分30秒程度で以下メッセージがブラウザに表示

　Service Temporaly Unavailable

   The server could not connect to the database.

⑤DBのログから再起動が正常に行えていないと判断、手動で起動し症状解消

備考

　access_log、ssl_accessを確認しa-blogへの合計アクセス数は10:00:00～10:00:10で6でした。

■ご相談

なぜDBが再起動したのかログからは確認できませんでした。

原因を特定したいのですが現状手詰まりの状態です。

調査手順や改善案等ご指導いただければ幸いです。

以下エラーログとMariaDBログを載せております。

■SSL_ERROR_LOG

[Tue Feb 07 10:01:28.146500 2017] [:error] [pid 29513] [client 10.21.0.232:41728] PHP Warning:  mysql_query(): MySQL server has gone away in /var/www/html/php/DB.php on line 161

■ERROR_LOG

[Tue Feb 07 10:01:28.146491 2017] [:error] [pid 4235] [client 10.21.0.233:48162] PHP Warning:  mysql_query(): MySQL server has gone away in /var/www/html/php/DB.php on line 161, referer: https://search.yahoo.co.jp/

■MariDBログ

Version: '5.5.44-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

170207 10:01:32 mysqld_safe Number of processes running now: 0

170207 10:01:33 mysqld_safe mysqld restarted

170207 10:01:39 [Note] /usr/libexec/mysqld (mysqld 5.5.44-MariaDB) starting as process 4750 ...

/usr/libexec/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later

170207 10:01:39 InnoDB: The InnoDB memory heap is disabled

170207 10:01:39 InnoDB: Mutexes and rw_locks use GCC atomic builtins

170207 10:01:39 InnoDB: Compressed tables use zlib 1.2.7

170207 10:01:39 InnoDB: Using Linux native AIO

170207 10:01:39 InnoDB: Initializing buffer pool, size = 512.0M

InnoDB: mmap(551026688 bytes) failed; errno 12

170207 10:01:39 InnoDB: Completed initialization of buffer pool

170207 10:01:39 InnoDB: Fatal error: cannot allocate memory for the buffer pool

170207 10:01:39 [ERROR] Plugin 'InnoDB' init function returned error.

170207 10:01:39 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

170207 10:01:40 [Note] Plugin 'FEEDBACK' is disabled.

170207 10:01:40 [ERROR] Unknown/unsupported storage engine: InnoDB

170207 10:01:40 [ERROR] Aborting

170207 10:01:40 [Note] /usr/libexec/mysqld: Shutdown complete

170207 10:01:40 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended

170207 10:02:44 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql

170207 10:02:44 [Note] /usr/libexec/mysqld (mysqld 5.5.44-MariaDB) starting as process 5519 ...

/usr/libexec/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later

170207 10:02:44 InnoDB: The InnoDB memory heap is disabled

170207 10:02:44 InnoDB: Mutexes and rw_locks use GCC atomic builtins

170207 10:02:44 InnoDB: Compressed tables use zlib 1.2.7

170207 10:02:44 InnoDB: Using Linux native AIO

170207 10:02:44 InnoDB: Initializing buffer pool, size = 512.0M

170207 10:02:44 InnoDB: Completed initialization of buffer pool

170207 10:02:44 InnoDB: highest supported file format is Barracuda.

InnoDB: Log scan progressed past the checkpoint lsn 532322651858

170207 10:02:44  InnoDB: Database was not shut down normally!

InnoDB: Starting crash recovery.

InnoDB: Reading tablespace information from the .ibd files...

InnoDB: Restoring possible half-written data pages from the doublewrite

InnoDB: buffer...

InnoDB: Doing recovery: scanned up to log sequence number 532327894528

InnoDB: Doing recovery: scanned up to log sequence number 532333137408

InnoDB: Doing recovery: scanned up to log sequence number 532338380288

InnoDB: Doing recovery: scanned up to log sequence number 532343623168

InnoDB: Doing recovery: scanned up to log sequence number 532348866048

InnoDB: Doing recovery: scanned up to log sequence number 532354108928

InnoDB: Doing recovery: scanned up to log sequence number 532359351808

InnoDB: Doing recovery: scanned up to log sequence number 532364594688

InnoDB: Doing recovery: scanned up to log sequence number 532369837568

InnoDB: Doing recovery: scanned up to log sequence number 532375080448

InnoDB: Doing recovery: scanned up to log sequence number 532380323328

InnoDB: Doing recovery: scanned up to log sequence number 532385566208

InnoDB: Doing recovery: scanned up to log sequence number 532390809088

InnoDB: Doing recovery: scanned up to log sequence number 532396051968

InnoDB: Doing recovery: scanned up to log sequence number 532401294848

InnoDB: Doing recovery: scanned up to log sequence number 532404136882

InnoDB: 1 transaction(s) which must be rolled back or cleaned up

InnoDB: in total 1533 row operations to undo

InnoDB: Trx id counter is 1475F200

170207 10:02:44  InnoDB: Starting an apply batch of log records to the database...

InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 

InnoDB: Apply batch completed

InnoDB: Starting in background the rollback of uncommitted transactions

170207 10:02:45  InnoDB: Rolling back trx with id 1475F07B, 1533 rows to undo

InnoDB: Progress in percents: 1170207 10:02:45  InnoDB: Waiting for the background threads to start

 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100

InnoDB: Rolling back of trx id 1475F07B completed

170207 10:02:45  InnoDB: Rollback of non-prepared transactions completed

170207 10:02:46 Percona XtraDB (http://www.percona.com) 5.5.43-MariaDB-37.2 started; log sequence number 532404136882

170207 10:02:46 [Note] Plugin 'FEEDBACK' is disabled.

170207 10:02:46 [Note] Server socket created on IP: '0.0.0.0'.

170207 10:02:46 [Note] Event Scheduler: Loaded 0 events

170207 10:02:46 [Note] /usr/libexec/mysqld: ready for connections.

Version: '5.5.44-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

170207 10:03:15 [ERROR] mysqld: Table './kyutech_cms/acms_fulltext' is marked as crashed and should be repaired

170207 10:03:15 [Warning] Checking table:   './kyutech_cms/acms_fulltext'

[tomo.k...@apps.vintage.ne.jp]

お世話になります。ヴィンテージ片山です。

補足ですがログを確認したところ公開日時のタイミングで

DBのメモリ使用量が増えサーバーの空きメモリが枯渇しておりました。

再現性確認の為同様に4つの記事を同時刻に公開設定するように投稿し

同時刻に4つに記事に対して複数回アクセスしましたが、ＤＢの

メモリ使用量増加は発生しませんでした。

[伊藤淳]

お世話になっております。

サーバー側の設定などが影響してくると思いますので、あまりサポートができないのですが

Unknown/unsupported storage engine: InnoDB というログが気になります。

InnoDBを使わないような設定にしていないでしょうか？

よろしくお願いいたします。

[tomo.k...@apps.vintage.ne.jp]

お世話になります。

ご回答ありがとうございます。

InnoDBは利用してます。

停止した理由はOSがメモリの空き容量が足りずmysqldを停止させてました。

色々と試しておりますが、mysqldのメモリ使用量が増える現象の再現ができない状況です。

全クエリをログに出したりして解析するしかありませんでしょうか？

以上よろしくお願いいたします。

[伊藤淳]

お世話になっております。

申し訳ないのですが、現象が再現できないとなると難しそうです。

今回の現象と関係ないかもしれませんが、キャッシュを削除するタイミングでoptimize tableを行なっているのですが、optimize tableを行わないようにするオプションを次期バージョンで準備中です。（次期バージョンではデフォルトOFFにする予定）

パッチとしてお渡しする事も可能ですのでその際は in...@a-blogcms.jp 宛にご連絡ください。

よろしくお願いいたします。

[tomo.k...@apps.vintage.ne.jp]

お世話になります。

パッチの作成ありがとうございました。

パッチはまだ未適用の段階です。

mysqldの停止原因はOMM Killerが発動し、mysqldをkillされたことによるものでした。

その後、swapを増やして（下記スペック）様子をみておりました。

OS CentOS 7.1

メモリ 4GB(Swap6GB)

本日、設定した予約投稿がありましたので監視を行いました。

mysqldは停止しませんでしたが、下記現象が約10分程度ランダムで続いて自然解消しました。

・ブラウザで更新実行後、1分程度でタイムアウト発生（ブラウザのエラー）

・ブラウザで更新実行後、1分程度でページが正常に表示

以下時系列での説明になります。前回同様、予約投稿時にhttpdプロセスが大量発生し

リクエストへの返信が遅れ/タイムアウトします。

同時アクセスは2程度です。調査方法等ご提案いただければ幸いです。

09:30 サーバでtopおよびpsコマンドで監視を開始

09:45 psコマンドで確認するとhttpdプロセスは6個

10:00 計6件の予約投稿記事が公開、トップページへchromeブラウザでhttp/httpsアクセス開始

10:01 ブラウザアクセス 

        https・・・1分以上経過後、「***.jpからデータが表示されませんでした」とエラー表示（https）

　　　　　　　　⇒更新⇒1分以上経過後、正常に表h字

　　  http・・・1分以上経過後正常に表示⇒更新⇒1分以上経過後正常に表示

　

10:02 topコマンドで確認するとswap領域を使い始めており、psコマンドではhttpdプロセスが約170個起動していた

10:05 swap領域を半分程度利用、httpdプロセス数が減り始める

10:10 httpdプロセス数が6個程度に戻る

[伊藤淳]

お世話になっております。お返事遅くなり申し訳ございません。

httpdプロセスが大量に発生することが気になっております。一点確認したいのですが、キャッシュの自動生成機能を利用していますでしょうか？

よろしくお願いいたします。

[tomo.k...@apps.vintage.ne.jp]

お世話になります。

返信が遅れ申し訳ありません。

キャッシュの自動生成機能は利用しております。

以上よろしくお願いします。

[山本一道@アップルップル]

どれくらの URL を登録されていますか？

[tomo.k...@apps.vintage.ne.jp]

お世話になります。

申し訳ありません。間違った情報をお伝えしておりました。

キャッシュ自動生成は機能設定で有効にしておりますが

キャッシュ生成リストには登録がありませんでした。

[伊藤淳]

お世話になっております。

a-blog cmsである特定の時に大量のhttpプロセスが発生するのは、ここのキャッシュ生成リストに大量の書かれている場合ぐらいだと思います。

もしくはどこかのページでリダイレクトループのような、無限ループに陥ってる可能性もあります。

高負荷時のアクセスログを見ると、どのようなアクセスがありますでしょうか？

よろしくお願いいたします。