Bug #1879

デッドロックについて

Added by Kentoku SHIBA over 4 years ago. Updated over 4 years ago.

Status:担当者作業中Start date:07/27/2013
Priority:NormalDue date:
Assignee:Kentoku SHIBA% Done:

10%

Category:-
Target version:-

Description

田辺です。


mroongaテーブルをストレージモードにて、カウンタとして利用していたところ、mysqlへ接続できない状況になることが何度かありました。

バージョンはこれまでと同じく
wingリポジトリのmysql 5.5.32、mroonga 3.04
です。

テーブル構造はおよそ以下の形になっています。

CREATE TABLE `main` (
  `id` int(11) unsigned NOT NULL AUTO_INCREMENT,
  `name` varchar(100) CHARACTER SET utf8 COLLATE utf8_unicode_ci NOT NULL,
  `tag` varchar(500) CHARACTER SET utf8 COLLATE utf8_unicode_ci NOT NULL,
  `date` datetime NOT NULL,
  `access` int(11) unsigned NOT NULL DEFAULT '0',
  PRIMARY KEY (`id`),
  FULLTEXT KEY `tag` (`tag`) COMMENT 'parser "TokenDelimit"',
  FULLTEXT KEY `name` (`name`) COMMENT 'normalizer "NormalizerMySQLUnicodeCIExceptKanaCIKanaWithVoicedSoundMark"',
  FULLTEXT KEY `multi` (`name`,`tag`)
) ENGINE=mroonga DEFAULT CHARSET=utf8;


本番環境で一般ユーザからのアクセスがある状況下で、accessカラムをアクセスカウンタとして利用しており、

UPDATE  `main` SET  `access` =  `access` +1 WHERE `id` =  '1'
UPDATE  `main` SET  `access` =  `access` +1 WHERE `id` =  '500'

のようなSQLがある程度頻繁に発行される状況で運用していました。

この状態で障害発生の際には、mysqlがCPUを使い切っていて、
新規接続ができない状況となっており(接続数上限まで接続プロセスが増えていた)、mysqld stopが効かない状態となっていました。

SHOW PROCESSLIST
にて状況は確認できたのですが、先ほどのカウント処理SQLが
System lock あるいは Waiting for table level lock
となっていて、ロックが取得できない状態になっているようでした。

他のプロセスとしては
SELECT COUNT(  "*" ) AS result FROM  `main`
のようにテーブル全体のカウント数を取得するクエリが
System lock
となっていました。

インクリメント処理が原因のようだったので、実際のインクリメントはNoSQLなどで担当させ、mroongaテーブルへ定期的に反映させる形に変更したところ、再発しなくなりました。

もともとmysqlを直接アクセスカウンタに使うと、負荷の面でよくないという話があるかと思いますが、今回はさほどアクセス数がない状態(デイリーで数千PV程度)だったことと、参照ロックフリーということだったので、大丈夫だろうと考えていました。


おそらく問題の原因としては、インクリメントの際にかかったロックが解除されず、テーブルにデッドロックがかかった状態になっていた点かと考えています。

この点について、
「不具合なのか、仕様上そうなる場合もあるのか?」
「そもそもデッドロックを回避するような仕組みをアプリケーション側で何らか実装する必要があるのか?」
についてご教授頂きたいと思います。

原因がデッドロックでない可能性もあれば、合わせてご教授をお願いします。

myisamでは同じような作りで接続に問題が出たことがなかったため、mroonga側に問題があるのではと考えています。


現状では、障害の再現に使える環境が本番環境しかなく、手元での再現ができないためかなり調査しにくい内容とは思いますが、ご対応お願いできるでしょうか?


以下、障害発生直前のgroonga.logですが、単純なシンタックスエラーしか出ていないように思います。
mysqlの方のログも障害直前にはエラーらしきものは出ていませんでした。
障害発生中は双方のログには何も記載がありませんでした。


2013-07-14 10:54:14.405573|e|526d7700|Syntax error! (*)
2013-07-14 10:54:14.408583|e|526d7700|/usr/lib64/libgroonga.so.0(grn_expr_parser+0x170c) [0x3d47a626dc]
2013-07-14 10:54:14.408624|e|526d7700|/usr/lib64/libgroonga.so.0() [0x3d47a62f0a]
2013-07-14 10:54:14.408650|e|526d7700|/usr/lib64/libgroonga.so.0(grn_expr_parse+0x66d) [0x3d47a6619d]
2013-07-14 10:54:14.408664|e|526d7700|/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga54generic_ft_init_ext_prepare_expression_in_boolean_modeEP14st_mrn_ft_infoP6S
tringP8_grn_objS5_S5_S5_+0xc1) [0x7f0f99de4e31]
2013-07-14 10:54:14.408675|e|526d7700|/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga26generic_ft_init_ext_selectEjjP6String+0x401) [0x7f0f99de5441]
2013-07-14 10:54:14.408686|e|526d7700|/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga19generic_ft_init_extEjjP6String+0x9e) [0x7f0f99de553e]
2013-07-14 10:54:14.408697|e|526d7700|/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga19storage_ft_init_extEjjP6String+0x9) [0x7f0f99de5709]
2013-07-14 10:54:14.408708|e|526d7700|/usr/libexec/mysqld(_ZN15Item_func_match11init_searchEb+0x182) [0x6b1f02]
2013-07-14 10:54:14.408719|e|526d7700|/usr/libexec/mysqld(_Z12init_ftfuncsP3THDP13st_select_lexb+0x57) [0x546507]
2013-07-14 10:54:14.408729|e|526d7700|/usr/libexec/mysqld(_ZN4JOIN8optimizeEv+0x29c8) [0x5b3828]
2013-07-14 10:54:14.408740|e|526d7700|/usr/libexec/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex
_unitP13st_select_lex+0x105) [0x5b9af5]
2013-07-14 10:54:14.408782|e|526d7700|/usr/libexec/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x174) [0x5ba5d4]
2013-07-14 10:54:14.408794|e|526d7700|/usr/libexec/mysqld() [0x57ba9d]
2013-07-14 10:54:14.408805|e|526d7700|/usr/libexec/mysqld(_Z21mysql_execute_commandP3THD+0x10d5) [0x57ff45]
2013-07-14 10:54:14.408815|e|526d7700|/usr/libexec/mysqld(_ZN18Prepared_statement7executeEP6Stringb+0x3f9) [0x591869]
2013-07-14 10:54:14.408825|e|526d7700|/usr/libexec/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0x98) [0x591918]
2013-07-14 10:54:14.408860|e|526d7700|failed to parse fulltext search keyword: <+*>: 


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


田辺公平

History

#1 Updated by Kentoku SHIBA over 4 years ago

斯波です。

不具合のご連絡ありがとうございます。

> この状態で障害発生の際には、mysqlがCPUを使い切っていて、
> 新規接続ができない状況となっており(接続数上限まで接続プロセスが増えていた)、 mysqld stopが効かない状態となっていました。

ということは、DBへのアクセスを止めてもCPU負荷が下がらない状態になったということであっておりますでしょうか?
また、該当のテーブルのレコード数がわかりましたら、ご教示頂けますと助かります。

ちょっと確認が週末あたりになってしまうと思いますが、しばらくお待ちいただけますようお願いいたします。

どうぞ、よろしくお願いします。

#2 Updated by Kentoku SHIBA over 4 years ago

田辺です。

> > この状態で障害発生の際には、mysqlがCPUを使い切っていて、
> > 新規接続ができない状況となっており(接続数上限まで接続プロセスが増えていた)、 mysqld stopが効かない状態となっていました。
>
> ということは、DBへのアクセスを止めてもCPU負荷が下がらない状態になったということであっておりますでしょうか?
> また、該当のテーブルのレコード数がわかりましたら、ご教示頂けますと助かります。

はい、DBへのアクセスを行っていたapacheを停止しても引き続きmysqldプロセスがCPUを使い切ったままとなっていました。

レコード数は1200レコード程度です。

お手数ですが、以上よろしくお願いします。

#3 Updated by Kentoku SHIBA over 4 years ago

  • Status changed from 新規 to 担当者作業中
  • % Done changed from 0 to 10

定期的に更新を並列で実行しておく。

#4 Updated by Kentoku SHIBA over 4 years ago

5日ほど様子を見たが問題の現象の再現はなし。

#5 Updated by Kentoku SHIBA over 4 years ago

田辺です


デッドロックが発生する件、こちらでほぼ本番環境に近い状態を作ってテストを行いましたが、テスト環境では未だ再現ができておらず、お伝えしたインクリメント処理以外に問題点がある可能性が高いように感じました。

> > インクリメント処理が原因のようだったので、実際のインクリメントはNoSQLなどで担当させ、mroongaテーブルへ定期的に反映させる形に変更したところ、再発しなくなりました。

こちら、この対応を行っても不具合が再現してしまうことを確認しました。
ただ、頻度自体はかなり稀になっているため、解決はしないものの、インクリメント処理の頻度に応じて再現率が変わっているようには感じます。



また、原因になりそうな点で認識できていなかった部分が見つかりましたので、お伝えしたいと思います。



まず前回のテーブルに追加して、以下のuserカラムに通常のインデックスが貼られた状態となっています。
  `user` varchar(20) CHARACTER SET utf8 COLLATE utf8_bin NOT NULL,

そこに、以下のようなselect文がまず発行されます。
select name from main where user='username' order by id desc limit 1

その後、最大2分間ほどのバッチ処理が行われ、その応答を待ちます。
(バッチ処理内ではSQL文は発行されていない)

応答が帰って来た段階で、
insert into main(name, tag, date, access) values('name', 'tag1 tag2 tag3', NOW(), 1);

のようにinsertが実施されるようになっています。



この操作は滅多に実行されないため、問題とならないと考えていますが、バッチ処理の間、mysqlへの接続が維持された状態となっており、コネクション数に影響があるかと考えました。

そこで、バッチ処理前後で切断・再接続を行い、長期間接続が維持されないように調整を行ったところ、現時点では不具合は再発しない状態となっております。

ただ、こちらの処置も頻度の軽減にしかなっていない可能性はあるため、今後再現されるか注視していきたいと思います。


テーブルロックが発生する処理としては、先にお伝えしたupdateによるインクリメント処理の他に、現時点では稀に実行される上記のinsertが考えられる状態となっています。

不具合の際にSHOW PROCESSLISTにて確認できる内容には、上記のinsertがブロックされている内容はありませんでした。

ただ、デッドロックの引き金となっている処理自体は、SHOW PROCESSLISTに上がって来ていない可能性があるので、その他ロックされる処理として先ほどのinsertがあるのではないかと考えています。


さらに、以下のシンタックスエラーがある程度頻繁に出てしまう状況となっていたところを、発生しないように今回調整を行いました。
failed to parse fulltext search keyword: <+*>: 


こちらでも再現が難しいため、かなり対処が難しいとは思いますが、可能性として有りそうな点を引き続き調査して頂けますと幸いです。

#6 Updated by Kentoku SHIBA over 4 years ago

select→120秒待つ→insert
syntax errorとなるselect
を、定期的に流すSQLとして追加

#7 Updated by Kentoku SHIBA over 4 years ago

これまで経過観察してみたが、再現は確認できず、 disk fullを迎えてしまった。

Also available in: Atom PDF