Apache + PHP + MySQL で「Lock wait timeout exceeded; try restarting transaction」がでるときの対策。

Apache + PHP + MySQL で「Lock wait timeout exceeded; try restarting transaction」がでるときは、PDO::ATTR_PERSISTENTやmysql_pconnect等でコネクションプールをしている時のトランザクションに問題がある。

なので、MySQLの接続アカウントを更新用と参照用に分けて、参照用のみコネクションプールし、更新用はプールしないというのが単純で結構効果的な解決方法だと思う。

クエリの最適化で改善できればそれに超したことはないのは確かではあるけれど、影響範囲がでかかったりすると、そうそう手をつけられない場合があるので。


【参考URL】
・Lock wait timeout exceeded; try restarting transaction
http://www.mysqlpracticewiki.com/index.php/Lock_wait_timeout_exceeded;_try_restarting_transaction


・トランザクションを強制的に終了させる
http://d.hatena.ne.jp/hhelibex/20110329/1301421815

Rails 3.1.3 から Rails 3.2.11 にアップグレードのメモ。

脆弱性対応でRailsをアップグレードしたのでメモ。

http://www.atmarkit.co.jp/ait/articles/1301/10/news081.html

これまでメインで使っていたのが Rails 3.1.3 でこれを 3.2.11 にアップグレード。
ざっくりやった内容をメモ。

【アップグレード先サンプル準備】
Rails 3.2.11 のデフォルトプロジェクトの設定ファイルを手に入れて、既存ソースとの差分を確認する手がかりにするのが目的。

１、どこかの環境で gem install rails して Rails 3.2.11 をインストール
２、rails new dummy とかやって、3.2.11 のプロジェクトを作成 → config のサンプルゲット。
３、作成したプロジェクトフォルダに移動して bundle 実行 → Gemfile, Gemfile.lock のサンプルゲット。



【アプリソース修正】
　既存のソースの config および Gemfile、Gemfile.lock を注意深く差分を見つめつつマージ。
　実際のところ、configは3.1.3のままでも動くが、後々の禍根の種を残さないためにも、configもマージする。


■mass assignment対策の対応
　http://d.hatena.ne.jp/rochefort/20120314/p1
　Rails 3.2.11 のデフォルトプロジェクトのconfigではmass assignment対策がONになっているので、既存ソースのモデルクラスが対応していないから修正を加える。
　（該当箇所をgrepして attr_accessible を書きまくった。面倒だった）

■アセットパイプラインの設定
　Rails2からの歴史的経緯と諸事情があって、もともとアセットパイプラインを利用していなかったので、ここでもOFF。
　（なんか設定増えた？のか、ちょっとハマった）
　


【アップグレード実施】
１、強く推奨されていたので、Ruby も更新（Ruby 1.9.3-p374）
２、gem update --system で gem自身もアップデート
３、修正済みのアプリソースで bundle update
　※bundle update は、ひとまず各gemを最新にしてGemfile.lockを更新する目的。
　※production環境で反映するときは更新したGemfile.lockを撒いて bundle 。
４、rspecを実行して確認したり、実際にアプリ起動してテストしたりして、Rails 3.2.11へのアップグレードが正常に完了したことを確認する。
　※ここで日々のテスト実装の努力が報われる、といいね！


【そのほか】
■Railsのアップグレードをした際、キャッシュをクリアしないと、"instance of IO needed" とかいうエラーに怒られる場合がある（というか、怒られた）。
rails runner "Rails.cache.clear" とか実行して一度キャッシュを消してあげたら正常化した。
https://github.com/rails/rails/issues/4042

■Rails 3.2.x は 3.1.3 と比べて ActionController::RoutingError (No route matches ...) のスタックトレースが盛大に吐かれるようになった？
ログが肥大化しまくって困るので、存在しないファイルへのアクセスをまじめに解消するなど対応が必要。ログレベルを上げて済まして良い場合はそれでも可。

■Ruby 1.9.3-p0 で Rails 3.2.11 を使うと、Modelクラスの処理で謎の例外が発生した。
でもRuby 1.9.3-p374にしたら直ったので気にしない。


■検索しまくってなんとか生き延びることができました。
情報をネットに上げてくれている皆様、あとGoogleさん、ありがとうございます。ホントに。

CakePHP2.2のバッチ用ファイルの置き場所とファイル名のルールはCakePHP1.3と違う

CakePHP2.2で試してはまったのでメモ。

諸事情でCakePHPでバッチ処理を書こうと思い立ちまして、2.0のガイドが英語なので、どうせ似たようなもんだろうって思って1.3用の日本語ガイド読みながらコピペしたりして試したんですよ。

そしたら、なんか↓みたいなエラーが出るんです。

Error: Shell class HelloShell could not be found.

いろいろググったり試したりして、結局↓のようにしたら動きました。
（2.0の英語のガイド読んだらそうしろって書いてあるしギャフン）

１、バッチ処理のファイルは APP/Console/Command/ 以下に置く。
２、バッチ処理のファイル名はクラス名をそのまま使う（HelloShellクラスならHelloShell.php）


CakePHP1.3と全然違うんですねぇ。

ActiveRecordでset_table_nameを使わずにテーブル名を変えてクエリを実行する

Rails 3.1.3で試した。

影響の大きいset_table_nameを使わずに、O/RマッパーとかSQL生成とかActiveRecordの便利な機能を使いつつ、別名のテーブルにクエリを実行する。

# "Hoge"というモデルがあって、デフォルトで関連づけられた "hoges" テーブルではなく、
# "hoges_2012" という別テーブルにアクセスする例。
target_table = "hoges_2012"
record = Hoge.where(id:1)
result = record.find_by_sql( record.to_sql.gsub( record.table_name, target_table ) )

できたー＼(^O^)／
テキストを置換して強引にやってるので、その分負荷があるからOLTPなサービスとかでは使いづらいけど、裏側で回す解析処理とかならこれで十分。

HTTPステータスコード499のとき、GETリクエストが即座に再送される？

nginx 0.8.x をリバースプロキシにして、unicorn + rails の構成。

なんか、全く同じパラメータのGETリクエストが2回飛んで来ることがある。
それで、一回しか処理しないつもりのものが二回処理されて地獄発動。

アクセスログをみてみると、同じ時間に全く同じパラメータのGETリクエストが2個ついている。
GETパラメータにはキャッシュ回避のためのランダム値をリクエスト時に必ず更新して入れるようにしてるので、その値が全く同一であることから、クライアント側でわざわざリトライ処理をしていないことは明白。

で、ログをよく見てみると、HTTPのステータスコードが、片方は499、もう片方は200となってることがわかった。

んで、検索したところ、↓のような情報が見つかった。

Why does Nginx return 499 errors?
http://technosophos.com/node/187

どうも、クライアント側がレスポンス受け取り切らない内に接続が切れたらつくらしい。

想像するに、ブラウザ側の都合でリクエストを強制切断して、ブラウザが気を利かせてもう一回リクエストを再送した模様。
今回の事例、ブラウザは Opera だったんだけど、Operaの癖なのか、ブラウザ全般の挙動なのかはよくわかってない。

まあ、重複処理防止策を講じろよ、ということですよね。
なにか、手軽な方法があればいいんですが、セッション的なことやってないっぽいんですよねぇ。。。



■2012/08/10追記
記事をよく読んだら、nginxのHTTPコード499は、クライアントには送信してないですね。
クライアント側はHTTPコード200として受け取っているみたい。
レスポンス中にクライアント側から切断されたときに、あくまでもnginxがログに記録するだけみたい。



■2013/07/01追記
結構HTTPステータスコード499で戸惑ってる人居るみたいですね。
どういう仕様なのか具体的に特定する作業はしてませんが、事実として同じリクエストが重複して行われることは確実なので、結局重複実行防止の対策をするしか解決方法はないと思います。

動作の特徴として、全く同じパラメータが送信されてくることが分かっているので、リクエスト毎に変わる使い捨てのトークンをパラメータに付加して、同じトークンだったら処理しないという実装でしのぎました。



■2013/08/23追記
もともとHTTPのGETメソッドは「データ取得」を目的として定義されてるものなので、GETメソッドをリクエストしたことでサーバー側に何か変化が発生するようなことは、使い方として想定してない模様。

二重に処理して困るような、サーバー側に変化をさせるようなリクエストはPOSTメソッドを使おうぜ、というのがHTTPの作法としては正しいのかもしれません。

POSTメソッドだとHTTPステータス499が出ないのかどうかは、試してないので不明ですが、ステータス499のときはまったく同じパラメータでリクエストが再送されてきていることから、再送側は再送しても副作用がないことを想定しているっぽいですね。

Rails（というかAcriveRecord）で日次テーブルに書き込む（保存時に保存先テーブル名を変更する）

Rails 3.2.2で試した。

ログテーブルのように日次で保存先を切り替える需要があります。
ActiveRecordは通常、クラス名とテーブル名が一対一で関連付いているので、切り替えは切り替えを書いてあげる必要があります。

set_table_nameをクラス定義部分で書く方法がありますが、これだと最初のアクセス時にそのテーブルを使うようになりますが、以降はずっとそのままです。
対策として、毎日再起動すると切り替えが可能です。
可能ですが。
いかに unicorn が　kill -s　USR2 とかで安全に再起動できたとしても、やっぱり気持ち悪いですね。
あと、切り替わりタイミングが再起動時に限定されてしまいます。

もう一つの方法として、before_create コールバックを利用する方法を今回試しました。
↓こんな具合。

class Foo < ActiveRecord::Base
  before_create :change_table
  
  def change_table
    Foo.set_table_name "bars" if Foo.table_name != "bars"
  end
end

これで Foo.create とか、Foo.new.save とかやると、bars テーブルに書き込みます。
あとは、"bars" の部分を、日次で変わる文字列にしてあげれば良い。
※ちなみに、この例だと、barsテーブルのほかに、Fooクラスに対応するfoosテーブルが無いとエラーになります。

あと、set_table_name でセットしたテーブル名は、セッション単位ではなく、 unicorn プロセス単位で有効、つまり、変更したらずっとそのままなので、そのつもりで扱うべし。
まあ、brefore_create で毎回変更していれば気にならないかもしれないけど。

ただし、（ログだし、普通あり得ないけど、）万が一日付をさかのぼってログを追記したい時とかは、before_create コールバックを外してやる必要があります。
Rails.envでbefore_createを呼ばない分岐作っても良いですね。

※2012/5/6、change_tableメソッド内、Foo.set_table_name ってするところを Blog.set_table_name とかやってて、クラス名が違っていたのを訂正。

【訂正】Railsでconnection数を破綻させずにestablish_connectionで別DBを利用する

　前のエントリ（http://d.hatena.ne.jp/raugisu/20120428/1335598633）で、ActiveRecord で別DBに接続するために establish_connection を安易に使うことで発生する地獄について書いた。

　んで、その地獄への対策として挙げたもののなかで、一番良いと思われる、「別DBへのコネクションプールを引き受けるクラスを作って継承する」方法を試してみた。
　ぶっちゃけ、元ネタ（http://d.hatena.ne.jp/rudeboyjet/20101221/p1 ）のほうがキチンとしてるので、そっち見た方が参考になる。

（2012/5/8、コメント欄で「self.abstract_class = true」の設定の指摘をいただいたので訂正しました。ありがとうございました！）
（2012/5/29、訂正部分、打ち消し線で訂正とかしてたんだけど、読みづらいので消しました）


　方法は、Railsでモデルを2個（hoge.rb, fuga.rb）作って、適当なコントローラ(foo_controller.rb)のindexアクションで、render :text => (Hoge.count + Fuga.count).to_s
とかやっておしまい。viewまでする必要もなし。

　最初は別DBにつながず、/foo/index を何度か実行して、mysqlのshow processlist; でコネクション数を確認する。

mysql> show processlist;


    

     Id  
     User 
     Host      
     db                
     Command 
     Time 
     State 
     Info             
    

    

     158 
     root 
     localhost 
     mysql             
     Query   
        0 
     NULL  
     show processlist 
    

    

     195 
     root 
     localhost 
     rider_development 
     Sleep   
        5 
           
     NULL             
    

    

     196 
     root 
     localhost 
     rider_development 
     Sleep   
        5 
           
     NULL             
    


3 rows in set (0.00 sec)

　※DB名はドンマイ。
　unicornのワーカー数を2個にしているので、2個（＋mysqlコンソールの1個）のコネクションがでる。
　まあ、普通。

　ここで、もう一個 create database rider_dummy でmysqlにDBを作り、database.ymlにもrider_dummy用の設定を書く「dummy:」で作るといいんじゃないかな。
　DBの中身は元のrider_developmentをmysqldumpして書き込めばいいと思うよ。

$ vi database.yml
development:                     
  adapter: mysql2                
  encoding: utf8                 
  reconnect: false               
  database: rider_development    
  pool: 5                        
  username: root                 
  password:                    
  host: localhost                
                                 
dummy:                           
  adapter: mysql2                
  encoding: utf8                 
  reconnect: false               
  database: rider_dummy          
  pool: 5                        
  username: root                 
  password:                      
  host: localhost

　そして、HogeとFugaの中に、establish_connection :dummy って書き込んでやり、再び foo/index を実行して、mysqlのコネクション数を見る。

mysql> show processlist;


    

     Id  
     User 
     Host      
     db                
     Command 
     Time 
     State 
     Info             
    

    

     158 
     root 
     localhost 
     mysql             
     Query   
        0 
     NULL  
     show processlist 
    

    

     163 
     root 
     localhost 
     rider_development 
     Sleep   
       22 
           
     NULL             
    

    

     164 
     root 
     localhost 
     rider_dummy       
     Sleep   
       26 
           
     NULL             
    

    

     165 
     root 
     localhost 
     rider_dummy       
     Sleep   
       26 
           
     NULL             
    

    

     166 
     root 
     localhost 
     rider_development 
     Sleep   
       23 
           
     NULL             
    

    

     167 
     root 
     localhost 
     rider_dummy       
     Sleep   
       23 
           
     NULL             
    

    

     168 
     root 
     localhost 
     rider_dummy       
     Sleep   
       23 
           
     NULL             
    


7 rows in set (0.00 sec)

　rider_dummyにつなぎに行くクラスが2個なので、コネクションがunicornワーカーひとつにつき2個できたのがわかる。
　rider_developmentへのコネクションは、使ってなくてもできちゃうんだね（でも、pool分のコネクションは作らない模様）

　で、ここで、もう一個ActiveRecord::Baseを継承したクラス（dummy_access.rb）をつくる。

$ vi app/models/dummy_access.rb
class  DummyAccess < ActiveRecord::Base
  self.abstract_class = true
  establish_connection :dummy
end

　DummyAccess に self.abstract_class = true を書き込んでおくと継承用のモデルクラスになるそうで、対応するテーブルなくても大丈夫。
　で、establish_connection :dummy と書き込んで、これが別DBに接続しにいくようにする。
　さらに、HogeとFugaを DummyAccess を継承するように書き換える。

$ vi hoge.rb
class Hoge < DummyAccess
end

$ vi fuga.rb
class Fuga < DummyAccess
end

　で、ここまでやってから、一度 unicorn を再起動させ、foo/index を何度か実行してから mysql で show processlist; してみる。

mysql> show processlist;


    

     Id  
     User 
     Host      
     db                
     Command 
     Time 
     State 
     Info             
    

    

     158 
     root 
     localhost 
     mysql             
     Query   
        0 
     NULL  
     show processlist 
    

    

     187 
     root 
     localhost 
     rider_development 
     Sleep   
        3 
           
     NULL             
    

    

     188 
     root 
     localhost 
     rider_dummy       
     Sleep   
        3 
           
     NULL             
    

    

     189 
     root 
     localhost 
     rider_development 
     Sleep   
        3 
           
     NULL             
    

    

     190 
     root 
     localhost 
     rider_dummy       
     Sleep   
        5 
           
     NULL             
    


5 rows in set (0.00 sec)

　みごと、別DBであるrider_dummyへの接続が1個になった＼(^O^)／
　これで一安心。


（2012/5/29追記）
　当初、「self.abstract_class = true」の設定を知らなくて、DummyAccessでもダミーのテーブルをset_table_nameでセットしたり、それを継承したHogeクラス、Fugaクラスでもわざわざset_table_nameでセットする必要がある、と書いていました。
　でもさすがはRuby On Rails、人気のフレームワークだけあって、そんなアホなことはなかったですね！
　コメント欄でアドバイスくださった通りすがりの方、マジでありがとう！
　すごい助かりました。
　いくつかある地獄の一つを解決できました。