MySQL 5.5.19 にて ON DUPLICATE KEY UPDATE 使用時に LAST_INSERT_ID を呼ぶとプライマリキーの値によって不可思議な現象が起こる話

例によって同僚に、ON DUPLICATEを使ってる時の、LAST_INSERT_IDの挙動がなんかおかしいという話を受け調査を開始した。
複数の同僚に手伝ってもらいながら検証した結果次のような現象が起こることが分かったため、メモしておく。

ON DUPLICATE でプライマリキーに「文字」を利用する場合、LAST_INSERT_IDの値が 0 に変化し予期せぬ更新がかかったり、更新が失敗する問題がある。

これは、LAST_INSERT_ID が数値 しか扱えないことが原因と思われる。

次に検証手順を記す。
とりあえず、MySQLのバージョンは 5.5.19

■一つ目のパターン「数値」の場合
このパターンは想定通りに動くので、特に問題は起こらない

1.まずは簡単なテーブルを作成する

mysql> CREATE TABLE IF NOT EXISTS fff (
    ->     id          VARCHAR(64),
    ->     last_update DATETIME,
    ->     PRIMARY KEY (id)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Query OK, 0 rows affected (0.03 sec)

2.プライマリキーに 「数値」をいれて、普通にINSERTする ･･･まあ普通に通る

mysql> INSERT INTO fff (id, last_update) VALUES ('9', NOW());
Query OK, 1 row affected (0.04 sec)

mysql> SELECT * FROM fff\G
*************************** 1. row ***************************
         id: 9
last_update: 2013-01-11 22:11:45
1 row in set (0.00 sec)

3. プライマリキーに 「数値」をいれて、普通にON DUPLICATEする ･･･これも問題なく通る
正しくインサーとされ、LAST_INSERT_IDも正しい値が取れる。

mysql> INSERT INTO fff (id, last_update) VALUES ('9', NOW()) ON DUPLICATE KEY UPDATE id = LAST_INSERT_ID(id), last_update = NOW();
Query OK, 2 rows affected (0.02 sec)

mysql> SELECT * FROM fff\G
*************************** 1. row ***************************
         id: 9
last_update: 2013-01-11 22:11:51
1 row in set (0.00 sec)

mysql> SELECT LAST_INSERT_ID();
+------------------+
| LAST_INSERT_ID() |
+------------------+
|                9 |
+------------------+
1 row in set (0.00 sec)

4. 最後にお掃除する

mysql> DROP TABLES fff;
Query OK, 0 rows affected (0.01 sec)

■二つ目のパターン「文字」の場合
このパターンは想定通りに動かないので、特に注意を要する

1.まずは簡単なテーブルを作成する

mysql> CREATE TABLE IF NOT EXISTS fff (
    ->     id          VARCHAR(64),
    ->     last_update DATETIME,
    ->     PRIMARY KEY (id)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Query OK, 0 rows affected (0.03 sec)

2.プライマリキーに 「文字」をいれて、普通にINSERTする ･･･まあ普通に通る

mysql> INSERT INTO fff (id, last_update) VALUES ('X', NOW());
Query OK, 1 row affected (0.01 sec)

mysql> SELECT * FROM fff\G
*************************** 1. row ***************************
         id: X
last_update: 2013-01-11 22:12:29
1 row in set (0.00 sec)

3. プライマリキーに 「文字」をいれて、普通にON DUPLICATEする ･･･これはWARNINGSは出るものの問題なく通るように見える
･･･が、SELECTの結果をみるとid が X から 0 になぜか変換されている。
LAST_INSERT_IDもX ではなく 0 が取れる。

この時点ですでにおかしいが、さらに続ける。

mysql> INSERT INTO fff (id, last_update) VALUES ('X', NOW()) ON DUPLICATE KEY UPDATE id = LAST_INSERT_ID(id), last_update = NOW();
Query OK, 2 rows affected, 1 warning (0.01 sec)

mysql> SHOW WARNINGS;
+---------+------+----------------------------------------+
| Level   | Code | Message                                |
+---------+------+----------------------------------------+
| Warning | 1292 | Truncated incorrect INTEGER value: 'X' |
+---------+------+----------------------------------------+
1 row in set (0.00 sec)

mysql> SELECT * FROM fff\G
*************************** 1. row ***************************
         id: 0
last_update: 2013-01-11 22:12:38
1 row in set (0.02 sec)

mysql> SELECT LAST_INSERT_ID();
+------------------+
| LAST_INSERT_ID() |
+------------------+
|                0 |
+------------------+
1 row in set (0.00 sec)

4. 再度プライマリキーに 「文字」をいれて、普通にON DUPLICATEする ･･･今度はWARNINGSも出ず問題なく通る
SELECT結果も正しく、Xの行が追加されている
LAST_INSERT_IDはやはり X ではなく 0 が取れる。

mysql> INSERT INTO fff (id, last_update) VALUES ('X', NOW()) ON DUPLICATE KEY UPDATE id = LAST_INSERT_ID(id), last_update = NOW();
Query OK, 1 row affected (0.02 sec)

mysql> SELECT * FROM fff\G
*************************** 1. row ***************************
         id: 0
last_update: 2013-01-11 22:38:33
*************************** 2. row ***************************
         id: X
last_update: 2013-01-11 22:39:18
2 rows in set (0.00 sec)

mysql> SELECT LAST_INSERT_ID();
+------------------+
| LAST_INSERT_ID() |
+------------------+
|                0 |
+------------------+
1 row in set (0.00 sec)

5. さらに再度プライマリキーに 「文字」をいれて、普通にON DUPLICATEする ･･･今度はERRORになてインサートできない
わかる人にはもうわかると思うが、これは id = 'X' ではなく、既に存在する別の id = 0 の行とおなじプライマリキーで id = 'X' の行をUPDATE 仕様とした結果、プライマリキーの競合が起こり更新できい状態が発生している。

mysql> INSERT INTO fff (id, last_update) VALUES ('X', NOW()) ON DUPLICATE KEY UPDATE id = LAST_INSERT_ID(id), last_update = NOW();
ERROR 1062 (23000): Duplicate entry '0' for key 'PRIMARY'

6. 最後にお掃除する

mysql> DROP TABLES fff;
Query OK, 0 rows affected (0.01 sec)

■まとめ
このように、LAST_INSERT_ID が数値 しか扱えないず、LAST_INSERT_ID('文字') とした場合には 0 が返る仕様？によりON DUPLICATEとLAST_INSERT_IDを併用する際にプライマリキーに 「文字」をいれた場合、不可思議な現象が発生することが有るようです。

PHPのAPCの apc.include_once_override 設定時にいくつかの条件を満たした場合に include_once 等が失敗する現象

↓の続き
誤報 APC の apc.include_once_override で動的な include_once 等が失敗する問題
http://d.hatena.ne.jp/narusase/20121030

どうも同僚の調査によると、動的なinclude_onceが原因ではないようだ
･･･というわけで、極限まで単純化したサンプルコードを書いてテストしてみた。

ファイルその1. /home/htdocs/test.php

<?php
function include_test($x = array()) {
    include_once('hogehoge.php');
}
echo '1'."\n";
include_test();
echo '2'."\n";
include_test();
echo 'end-'."\n";

ファイルその2. /home/lib/hogehoge.php

<?php
class hogehoge {

}

or

<?php
const hogehoge = 0;

ざっくりとわかっている条件を列挙する

• 1.二つのファイルにわかれている必要がある(include_onceするので当然だが)
  • さらに読みこまれるファイルがカレントディレクトリにある場合は起こらない(パス周辺の条件がある？)
• 2.include_onceする対象は相対パス指定でないといけない(フルパス指定では起こらない)
  • なお、当然だが、パスは通っている必要がある
• 3.include_onceするされる相対はclass or constを記述する(functionでは起こらない)
  • const のばあい 下記のNoticeになるがFATALではないので動きはする
    • Notice: Constant hogehoge already defined in /home/lib/hogehoge.php on line 2
• 4.関数内でinclude_onceしないと起こらない
• 5.関数内には必ず引数が必要で array() で初期化されている(引数が無い、初期化の値がNULLだとおこらない)
  • また、その引数にはコールする際いかなる値も渡してはならない

つまり、5. の条件は不明だがそもそも関数内でinclude_onceされており、さらにパスがini_setなどによるパスの変化によって別ファイルが指定される可能性がある場合に起こっているようだ。

結論としては、発生条件は良く分からないが、下記の条件のいずれかを守れば「回避できそう」ということが分かりました。
1.関数内でinclude_once or require_once を呼ばない。
2.カレントディレクトリ以外のファイルの include_once or require_once はフルパスで指定する
3.どうしても関数内でinclude_once or require_once を呼ぶ場合、引数の初期化を行わないか、必ずarray()以外(NULL推奨)で初期化する

誤報APC の apc.include_once_override で動的な include_once 等が失敗する問題

とあるよくわからないエラーを調査したときPEARのMail.php の@ 指定を解除したところ下記のようなエラーが発生したのでちょいと調べて見た。
結果としては先に設定したAPCの apc.include_once_override = 1 の設定が悪さをしていた事が分かったので一応メモっておく

PHP Fatal error:  include() [<a href='function.include'>function.include</a>]: 
Cannot redeclare class mail_smtp in /省略/Mail.php on line 52

ネット上をいろいろ探してみるといくつかのサイトで引っかかる既知の問題のようだが、PEARのMail.phpの下記のようなコードが駄目らしい。

static function &factory($driver, $params = array())
{
    $driver = strtolower($driver);
    @include_once 'Mail/' . $driver . '.php';
    ...省略...
}

具体的にはこのfactory関数は include_once で関数の引数として渡される文字列からinclude対象のファイル名を作っているのだが、include_once_override はこのような include_once の書き方に対応できないらしい。
まだきちんと原因を追ったのではないがおそらく、APCのinclude_once_overrideの利用時はinclude_onceはincludeと同じような動きをするようになってしまっており二重定義をして起こられている物と思われる。
また、これは動的なinclude_onceだけで起こっているようなので、静的にinclude_onceに続く文字列をキーにしてincludeするかしないかを決定していると考えると現象に説明がつく。(ほんと推測ではなくはソースを当たるべき)

とりあえずは、include_once_overrideを無効化して対処したが、上記のコードはおそらく、下記のようにすることで回避できると思われる。

static function &factory($driver, $params = array())
{
    $driver = strtolower($driver);

    switch ($driver) {
    case 'mail':
        include_once 'Mail/mail.php';
        break;
    case 'sendmail':
        include_once 'Mail/sendmail.php';
        break;
    case 'smtp':
        include_once 'Mail/smtp.php';
        break;
    default:
        include_once 'Mail/' . $driver . '.php'; // include_once_override 非利用時用の保険
        break;
    }
    ...省略...
}

追記：
いろいろ調べたてサンプルコードを書いたところこちらの原因は誤報でした
動的に変数を使わずinclude_onceしてもこのエラーは起こるようです
もう少し調べたのち、改めてメモ書きます

PHPのAPCの利用によるメモリ使用量の削減について

きたーーーメモリ使用量減った！！

以前から悩んでいたPHPのメモリ使用量が高い問題だがようやく対処方法が分かった

php.iniに下記の設定を追加することで、とあるプログラムでは14MB食ってたのが4MBまで減少した(1プロセス当り)

apc.include_once_override = 1
apc.lazy_classes = 1
apc.lazy_functions = 1

この設定は関数やクラスの遅延読み込み的なことをする設定のようなので、実際には走らないコードを多く含むものについてはそこそこ効くと思われます。

なお、include_once_override の設定はコードの書き方によってはトラブルになることが多いとのことなので、使うならしばらくテスト環境などで寝かせておいてテストした方が良いかもしれません。
また、lazy_classes、lazy_functions は遅延読み込みだとすると性質上、ほんの少しだろうがパフォーマンスの劣化の副作用が伴う可能性があります。

PHPの /** から始まるコメントが、require_once実行時に無駄にメモリを食う問題

知り合いから教えてもらったのだが、PHPでは /** から始まるコメントが、require_once実行時に無駄にメモリを食う問題があるらしい･･･ということで調査してみた

まずは、確認用のコードとして test.php を書く

<?php
echo '         peek     usage'."\n";
echo 'pre    = '.memory_get_peak_usage().' / '.memory_get_usage()."\n";
$x  = '0123456789';
for ($i = 0; $i != 12; $i++) {
    $x = $x . $x; // 適当にメモリを使ってrequire_once 時に新たにメモリを確保する必要があるようにしておく
}
$before = memory_get_peak_usage();
echo 'before = '.$before.' / '.memory_get_usage()."\n";
require_once('hoge.php');
$after = memory_get_peak_usage();
echo 'after  = '.$after.' / '.memory_get_usage()."\n";
echo 'after - before = '.($after - $before)."\n\n";

echo 'strlen = '.strlen($x)."\n";

次に、require_onceするhoge.phpを書く

<?php
class hoge {
    /**
     * aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
     * aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
     * aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
     * aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
     * aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
     */
    public function hogehoge0() {
        return '01234567890123456789012345678901234567890123456789';
    }
    public function hogehoge1() {
        return '01234567890123456789012345678901234567890123456789';
    }
    public function hogehoge2() {
        return '01234567890123456789012345678901234567890123456789';
    }
}

･･･で、test.phpを実行

[user@host ~]$ php  -v
PHP 5.3.10 (cli) (built: Mar 13 2012 10:54:48)
Copyright (c) 1997-2012 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2012 Zend Technologies
    with Xdebug v2.1.4, Copyright (c) 2002-2012, by Derick Rethans

[user@host ~]$ php test.php
         peek     usage
pre    = 670656 / 639032
before = 703808 / 680448
after  = 706328 / 685792
after - before = 2520

strlen = 40960
strlen = 40960

require_once の前後で2520バイトピークのメモリ量が増えている

次に、コメントを /** から /* に変更して再度実行してみる

[user@host ~]$ php test.php
         peek     usage
pre    = 670656 / 639032
before = 703808 / 680448
after  = 705832 / 685296
after - before = 2024

strlen = 40960

require_once の前後で2024バイトピークのメモリ量が増えている

次は、 // コメントに変えてみる

[user@host ~]$ php test.php
         peek     usage
pre    = 670656 / 639032
before = 703808 / 680448
after  = 705832 / 685296
after - before = 2024

strlen = 40960

こちらも、require_once の前後で2024バイトピークのメモリ量が増えている

結果として /** 形式の場合、 /* や // の形式に比べて 496バイトほど無駄にメモリを使っている様子が見て取れ、たしかに/** から始まるコメントが、require_once実行時に無駄にメモリを食う問題が存在するようである。

ちなみに、/** の場合に、コメント自体の長さを増やすとどうなるのかさらに追試してみたところ、一文字増やすごとに増えるわけではないが、文字数が多ければ多いほど無駄にメモリを食っている様が見て取れた

･･･以上検証終わり

たぶん、require_once するときにプリプロセッサで // と /* のコメントは無視しているのに、なぜか /** は無視されないようになっている気がする
なお、requireや、include_once、includeでも起こるかどうかは未検証
･･･PHPのソースを負ったわけではないのであくまで「気がする」
･･･だれかバグか仕様かだけでも調査してくれる人いないかなー

追記(2012-08-16 22:25)：
ブックマークに id:iakio さんよりコメントが有りました

下記の通り、PHPのリフレクションでドキュメントコメントを取得するものがあるそうで、 /** のコメントはその戻り値として用いられるため、この現象は仕様ということで良いようです。
http://jp.php.net/manual/ja/reflectionclass.getdoccomment.php

仕様ということですので、一応 タイトルの「問題」には取り消し線を入れておきます。

羊羹もどき

ついかっとなって作った、後悔はしていない

スーパーで買ってきた、つぶあんと、小豆の缶詰めを600ccほどの水で溶かし、塊が無くなったら砂糖を適当に入れてから、寒天をぶち込み、入れ物に入れて冷蔵庫にしまうだけの超手抜き

･･･まあ、それなりに食えるので良しとしよう
ただ、結構大量に出来るので注意
あと、寒天はあらかじめ水で溶いておいたほうがダマにならない
ダマになると食感がかなり悪いのでマジ注意

定例の買出し

• 小説×19冊
• コミック×6冊
• 雑誌×1冊

･･･いくつかのシリーズの残りを纏め買いしたのもあって冊数がひどいことにｗ
まあ、これでもうほとんどのシリーズは既刊は無くなったはずなので、新しいシリーズを買い始めなければ来月からはちょっとは減るはず･･･きっと、多分