Symfony(phpのフレームワーク)にて気になる部分があったので若手ホープのhonda-hに調査してもらった。 ※データベースはMySQL5、InnoDBを利用。 気になった部分 以下のコードサンプルのように 明示的にトランザクション処理を行ったとする。 Symfonyのログを見ると何故か4回づつbeginやcommitが行われたように sfCreoleのログが出力されている。 これでは、以下のコードサンプルの更新2の部分で エラーとなった場合に更新1も含めてロールバックしてほしいのに 更新1はコミットされたように見える。 しかし、SQLログを見るとサンプルコードで期待する結果となっている。 (begin ⇒ 更新1⇒ 更新2 ⇒ commit) コードサンプル:
    // 実際はもう少し処理をしているがコアな部分以外は割愛する
...
    $bookmark = new Bookmark();
    $bookmark->setTitle($this->getRequestParameter('title'));
    $bookmark->setUrl($this->getRequestParameter('url'));

    if ($this->getRequestParameter('category_id'))
    {
        $bookmark->setCategoryId($this->getRequestParameter('category_id'));
        $category = CategoryPeer::retrieveByPk($this->getRequestParameter('category_id'));
        $category->incrementSize();
    }

    $con = Propel::getConnection();  // DBコネクションオブジェクト取得

    try
    {
        $con->begin();  // トランザクション開始
        if ($this->getRequestParameter('category_id'))
        {
            $this->logMessage('{sfAction} save category.', 'info');
            $category->save($con);  // 更新1
        }
    
        $this->logMessage('{sfAction} save bookmark.', 'info');
        $bookmark->save($con);  // 更新2
    
        $this->logMessage('{sfAction} commit transaction.', 'info');
        $con->commit();  // コミット
    }
    catch (Exception $e)
    {
        $con->rollback();  // ロールバック
...
Symfonyログサンプル
Oct 28 11:29:51 symfony [info] {sfCreole} prepareStatement(): SELECT category.ID, category.TITLE, category.SIZE FROM category WHERE category.ID=?
Oct 28 11:29:51 symfony [info] {sfCreole} executeQuery(): [0.47 ms] SELECT category.ID, category.TITLE, category.SIZE FROM category WHERE category.ID=5
Oct 28 11:29:51 symfony [info] {sfCreole} connect(): DSN: array (   'compat_assoc_lower' => NULL,   'compat_rtrim_string' => NULL,   'database' => 'criteria_test',   'encoding' => 'cp932',   'hostspec' => 'localhost',   'password' => 'criteria_test',   'persistent' => NULL,   'phptype' => 'mysql',   'port' => NULL,   'protocol' => NULL,   'socket' => NULL,   'username' => 'criteria_test', ), FLAGS: 0
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfAction} save category.
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} prepareStatement(): UPDATE category SET SIZE = ? WHERE category.ID=?
Oct 28 11:29:51 symfony [info] {sfCreole} executeUpdate(): UPDATE category SET SIZE = 5 WHERE category.ID=5
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.
Oct 28 11:29:51 symfony [info] {sfAction} save bookmark.
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} beginning transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} prepareStatement(): INSERT INTO bookmark (CATEGORY_ID,TITLE,URL,CREATED_AT,UPDATED_AT) VALUES (?,?,?,?,?)
Oct 28 11:29:51 symfony [info] {sfCreole} executeUpdate(): INSERT INTO bookmark (CATEGORY_ID,TITLE,URL,CREATED_AT,UPDATED_AT) VALUES (5,'koreha hidoi','http://korea.hidoi/','2008-10-28 11:29:51','2008-10-28 11:29:51')
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.
Oct 28 11:29:51 symfony [info] {sfAction} commit transaction.
Oct 28 11:29:51 symfony [info] {sfCreole} committing transaction.
SQLログサンプル:
# at 3946
#081028 11:29:51 server id 1  end_log_pos 4023 	Query	thread_id=47	exec_time=0	error_code=0
SET TIMESTAMP=1225160991/*!*/;
BEGIN
/*!*/;
# at 4023
#081028 11:29:51 server id 1  end_log_pos 4143 	Query	thread_id=47	exec_time=0	error_code=0
SET TIMESTAMP=1225160991/*!*/;
UPDATE category SET SIZE = 5 WHERE category.ID=5
/*!*/;
# at 4143
#081028 11:29:51 server id 1  end_log_pos 4171 	Intvar
SET INSERT_ID=40/*!*/;
# at 4171
#081028 11:29:51 server id 1  end_log_pos 4401 	Query	thread_id=47	exec_time=0	error_code=0
SET TIMESTAMP=1225160991/*!*/;
INSERT INTO bookmark (CATEGORY_ID,TITLE,URL,CREATED_AT,UPDATED_AT) VALUES (5,'koreha hidoi','http://koreha.hidoi/','2008-10-28 11:29:51','2008-10-28 11:29:51')
/*!*/;
# at 4401
#081028 11:29:51 server id 1  end_log_pos 4428 	Xid = 334
COMMIT/*!*/;
DELIMITER ;
ということで、honda-hの調査結果を次に書きます。 ではhonnda-h、あとはよろしく~ 調査結果