Django で unittest を高速化する(主にDBの話し)

yuheiさんが書き残してくれたありがたい記事を参考にゴニョゴニョしてて気になって事があったので、調べてみた時のメモ

この記事には以下の対応が書かれていました。

  • 対応2 sqlite3のin-memory databaseにしてみる
  • 対応3 southでテスト時にmigrateを使わず、syncdbでテーブル作成を行わせる

この記事の結果を見た時に、あれ?これってそんなに効果ないんだっけ?て気になったのでちょっと調べてみた次第。

前提&環境

  • Djangoは1.4系
  • South(DBマイグレーションツール)を利用
  • Migrationファイルは79ファイルある
  • テストランナーはカスタマイズして、Django本体&サードパーティライブラリのテストは動かないようにしている。
  • MySQL5.6.13を使用(homebrewでインスコ)..my.cnfとか特にチューニングしたりしてない。
  • SQLite3.7.12を使用(homebrewでインスコ)
  • テーブル数は70位
  • 使用マシン
    • OS: Mac OSX 10.8.5
    • CPU: 3.2GHz Core i3
    • メモリ: 4GB
    • HDD: 1TB

やりたい事

  • ローカルでテスト全体を走らせた時に速く終らせたい(コミット&プッシュ前とかに良くするので)
  • 主に利用するDBを変えてみる事でどれくらい実行時間が変わるか知りたい
  • Southのマイグレーションをテスト時にオフする事で実行時間が短縮されるか知りたい

1. MySQL(Migration有り)

  • まずは素のMySQLでテストを走らせる
  • manage.py testで出力されるテスト実行時間と体感時間にかなり差があるのでtimeコマンド付きで実行する。
 $ time python manage.py test --settings=hoge.settings.test

結果

# manage.py testが吐き出す結果
Ran 265 tests in 29.224s

# timeコマンドで計測した結果
real    3m10.899s
user    0m17.511s
sys     0m1.450s
  • テスト実行は29秒で終ってんのに、実際は3分もかかってやがる。
  • Djangoはテスト時にtest_で始まるテスト用のDB作成/破棄してる。多分その時間はmanage.py testで吐き出される時間にはインクルードされてない。

2. MySQL(Migration無し)

  • 次にSouthのマイグレーションをOFFにしてやってみる
  • 設定ファイル(settings/test.py)に以下の設定を書くだけ
SOUTH_TESTS_MIGRATE=False

結果

# manage.py test 
Ran 265 tests in 18.015s

# time
real    1m57.275s
user    0m10.954s
sys     0m1.049s
  • テストの実行自体も早くなったが、コマンドの実行時間自体も1分以上早くなった。体感的に全然ちがう。

3. MySQL on ramdisk (Migration有り)

 $ hdid -nomount ram://10670000
 $ newfs_hfs /dev/disk2 # -> 大体6GBのヤツできる
 $ mkdir /tmp/mnt
 $ mount -t hfs /dev/disk2 /tmp/mnt
 $ cp -pr /usr/local/var/mysql /tmp/mnt/

 $ mysql.server stop
 $ mysql.server start --datadir=/tmp/mnt/mysql

結果

# manage.py test 
Ran 265 tests in 17.435s

# time
real    0m34.779s
user    0m19.037s
sys     0m1.342s
  • やだー速いじゃないですかーやだーもー。
  • テスト実行自体は大して速くなってないけど、コマンドの実行時間は大分短くなってストレスなくなってきた。

4. MySQL on ramdisk (Migration無し)

  • さっきと同じようにMigrationをオフってみる

結果

# manage.py test 
Ran 265 tests in 16.330s

# time
real    0m28.271s
user    0m13.639s
sys     0m1.067s
  • 僅かではあるがMigration有りの時より速くなってる。

5. SQLite(Migration有り)

  • こんどは単純にSQLiteにしてやってみる
  • 設定ファイル(settings/test.py)でDATABASEの設定をSQLiteにするだけ
DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.sqlite3',
        'NAME': 'unittest.db',
    },
}

結果

# manage.py test 
Ran 265 tests in 12.166s

# time
real    0m22.653s
user    0m14.788s
sys     0m0.810s
  • MigrationがあってもMySQLより速くなった

6. SQLite(Migration無し)

  • 例によってMigrationをOFFる

結果

# manage.py test 
Ran 265 tests in 11.209s

# time
real    0m17.247s
user    0m14.788s
sys     0m0.810s
  • 今までと同様にMigration無い方が実行時間は短くなった

7. SQLite in-memory (Migration有り)

  • 最終形態。SQLiteをin-memoryで利用する
  • さっきのDATABASE設定のNAMEを":memory:"にするだけ
DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.sqlite3',
        'NAME': ':memory:',
    },
}

結果

# manage.py test 
Ran 265 tests in 10.511s

# time
real    0m16.613s
user    0m14.579s
sys     0m0.647s
  • SQLiteのMigration無しと大差ない結果だった。

8. SQLite in-memory (Migration無し)

  • 最後にMigration無しの試す

結果

# manage.py test 
Ran 265 tests in 10.208s

# time
real    0m11.963s
user    0m10.202s
sys     0m0.456s
  • テスト実行時間自体は大して変わらんけど、コマンド実行時間は10秒前後にまで縮まって、ほぼテスト実行時間とイコールになった。

まとめ

8パターンの計測を行った、最後にそれぞれのパターンを複数回(10回程度)実行して、その中央値を表にしてみた。

f:id:tell-k:20131010154753p:plain

  • mange.py test が出してるテスト実行時間には、テストDBの作成/破棄の時間は含まれない
  • 同様にMigrationしてる間の時間も含まれないのでMigrationをOFFにした方が実際の時間は短縮される
  • テーブル数、Migration数が多いほど、SQLite in-memoryでテスト実行時間が短くなってるのが実感できるのでオヌヌメ
  • ストレスフリーになってよかったな > 俺

余談

  • MySQLSQLiteに変更する事でテストが失敗するケースがあった。
    • Modelのテストで自動で日付を挿入するようなDatetime型のカラムをorder byしてselectしようとした。
    • その時テストデータ作成時に連続して createしたりすると、MySQLだと全く同じ時間になってしまって、結果の順序がSQLiteと違ってたりした。
    • テストで順序を保証したかったりしたら工夫する必要がある。
  • 実環境に近い所でテストがしたかったら、mysqld_multiとかでテスト用インスタンスramdiskに作るとかでもいいかもね。

おわり。

Djangoの抽象モデル(Abstract Model)の単体テスト

DjangoでAbstractなモデルの単体テストってどう書くんだろうなって思って調べたときのメモ。

継承した先のモデルをテストすればいいとかあるかもしれないけど、抽象モデルなので実装を持つ事ができる。その実装を独立してテストしたいなぁと思った。

簡単な例を書く。こんな論理削除用の抽象モデルがあったとする。

class BaseModel(models.Model):

    del_flg = models.BooleanField(u'削除フラグ', default=False)

    def remove(self):
        self.del_flg = True
        self.save()

    def unremove(self):
        self.del_flg = False
        self.save()

    class Meta(models.Model):
        abstract = True

この場合、remove, unremove が意図した通りに動くかテストしたい。
それをやる時は以下のようなコードを書く。

from django.test import TestCase
from django.db import connection
from django.core.management.color import no_style

class BaseModelTest(TestCase):

    def _getTargetClass(self):
        from core.models import BaseModel # <= 上のヤツ
        from django.db import models

        class BaseDummy(BaseModel):
            pass

        return BaseDummy

    def _makeOne(self, *args, **kw):
        return self._getTargetClass().objects.create(*args, **kw)

    def setUp(self):
        self._style = no_style()
        sql, _ = connection.creation.sql_create_model(self._getTargetClass(), self._style)
        self._cursor = connection.cursor()
        for statement in sql:
            self._cursor.execute(statement)

    def tearDown(self):
        sql = connection.creation.sql_destroy_model(self._getTargetClass(), (), self._style)
        for statement in sql:
            self._cursor.execute(statement)

    def test_remove_unremove(self):
        base_dummy = self._makeOne()

        self.assertTrue(hasattr(base_dummy, 'del_flg'))
        self.assertEqual(base_dummy.del_flg, 0)

        base_dummy.remove()
        self.assertEqual(base_dummy.del_flg, 1)

        base_dummy.unremove()
        self.assertEqual(base_dummy.del_flg, 0)

簡単に説明すると

1. setUpで抽象モデル(BaseModel)を継承したBaseDummyモデル作成
2. BaseDummyのモデル定義から吐き出されるモデル生成用のSQLを取得(sql_create_model)
3. そのSQLを実行してDBにBaseDummyモデルのテーブルを作成
4. テスト実行
5. tearDownでモデル定義から吐き出される削除用のSQLを取得(sql_destroy_model)
6. そのSQLを実行してDBからBaseDummyモデルのテーブルを削除

て事をやってる。なんか面倒だけど、アドホックにこんな感じの事もできるんだなと思った。

こんな欲求に直面したとき、他の人たちはどんな風にしてるだろうかとふと気になった。

おわりん

参考

task.delayからへんじがない。ただのしかばねのようだ(Celery+RabbitMQ)

とある開発環境でCelery + RabbitMQを動かしてたら、いつのまにかtask.delay()が息をしてないというかハングアップしてる感じになった時の調査と対処のメモ

環境

  • Debian squeeze
  • RabbitMQ 3.1.3 (apt-getでinstall)

現象

  • DjangoアプリからCelelyのtask.delayでジョブを実行してるけど処理された気配がない
  • 特にアプリ、Celery、RabbitMQで目立ったエラーは出ていない
  • Celery起動時にRabbitMQの接続は出来てるというログは出てる
[2013-07-25 16:08:55,270: WARNING/MainProcess] celery@hogehoge ready.
[2013-07-25 16:08:55,284: INFO/MainProcess] consumer: Connected to amqp://guest@127.0.0.1:5672//
  • task.delayを実行するとRabbitMQのログには受け付けた旨のログは残る。
=WARNING REPORT==== 25-Jul-2013::17:10:59 ===
closing AMQP connection <0.304.0> (127.0.1.1:45367 -> 127.0.1.1:5672):
  • ところがどっこい結果を見に行こうとするとハングアップする (hangs up)
>> from tasks import add
>> result = add.delay(1, 2)
>> result.get()
(ここでハングアップ。なんのへんじもない。ただのしかばねのようだ)
  • なんでハングアップになったのか全くわからない。なんでや。しばらく頭ひねる。

原因

原因はこのissueの最後の方の話しと同じ感じだった

https://github.com/celery/celery/issues/1312

  • RabbitMQは disk_free_limit という設定がある
  • disk_free_limit は disk_free(ディスクの空き容量) が disk_free_limitを下回ったら、RabbitMQへのPublishをブロックするという設定値
  • disk_free_limitはデフォルトで1GBに設定されている

今回の仮想マシンはディスク容量が8GBバイトと比較的少なめのディスク容量だった。
そしたらログやら、DBやらでいつのまにか1GBを切っていたため、突然ジョブキューが音も無くブロックされて死んだ様に見えた。

よくよく調べるとRabbitMQを再起動したりするとログに以下のようなメッセージが書き込まれてた...orz

=WARNING REPORT==== 25-Jul-2013::16:03:15 ===
disk resource limit alarm set on node rabbit@hogehoge.

Publishers will be blocked until this alarm clears

まじかー。再起動のコマンド叩いた時に教えて欲しかったわー。欲しかったわー

対処

といわけで対処方法。まぁ単純にdisk_free_limit以上の空き容量を作ればいいんですが、
そもそも8GBしかないし、開発用だし、disk_free_limitを小さく設定すればいいよねて感じで設定します。

$ sudo vi /etc/rabbitmq/rabbitmq.config

# write this.
[
 {rabbit, [{disk_free_limit, {mem_relative, 0.1}}]}
].
  • 設定ファイル(rabbitmq.config)を所定の位置に作成
  • disk_free_limitを{mem_relative, 0.1}(メモリ容量の10%)に設定
  • メモリが500MBくらいだったので、大体50MBに設定された。
  • 単純に0にする事もできるけど、無限にディスク容量を喰わないためのセーフティ機能なのであまりお勧めしない。

あとはrabbitmq-serverを再起動してstatusを確認すればOK

$ sudo service rabbitmq-server restart
$ sudo service rabbitmq-server status
Status of node rabbit@hogehoge ...
.
.
 {disk_free_limit,52212122}, <- コレね

おわり。

余談

  • いやー本当に1日ってあっという間におわっちゃいますね。ハハハッハハハッ(白目)

追記(2013/07/26)

無知をさらけ出すとイケメンにチヤホヤされる職場です。

[2013/07/26 8:10:54] イケメンCTO: @tell-k かなり前にもしかしたら聞いたカモですが
http://tell-k.hatenablog.com/entry/2013/07/25/211848
[2013/07/26 8:10:54] イケメンCTO: CELERY_IGNORE_RESULT = True とかって設定しています?
[2013/07/26 8:12:26] tell-k: 設定してなかったです。
[2013/07/26 8:18:10] イケメンCTO: @tell-k 上 or CELERYのログのEXPIREを指定しないとログがどんどんBROKERにたまっていて、
[2013/07/26 8:18:28] イケメンCTO: Rabittmqだとまさに反応がなくなるってことが昔何度かありました。
[2013/07/26 8:19:15] tell-k: なるほど。
[2013/07/26 8:19:21] tell-k: ありがとうございます。
[2013/07/26 8:19:31] tell-k: 設定しないと!
[2013/07/26 8:20:14] イケメンCTO: これ設定例 -> 設定例のコピペをくれる
[2013/07/26 8:20:09] tell-k: おぉぉぉ
[2013/07/26 8:20:26] tell-k: ありがとうございます。
[2013/07/26 8:20:29] tell-k: cto++
[2013/07/26 8:20:48] イケメンCTO: >CELERY_SEND_TASK_ERROR_EMAILS = True
これやると、エラーメールが飛んでくるので解析が便利になりやす、これはいれたほうがいいっすね、CELERY_IGNORE_RESULTと合わせて
[2013/07/26 8:20:58] イケメンCTO: まぁ、設定したのはイケメンエンジニア(ike4)っす
[2013/07/26 8:20:59] イケメンCTO: イケメンエンジニア(ike4)++

Django と localflavor の 都道府県コード の話 (ドラクエコピペ風)

注意喚起(2013/02/27)

localflavorは、Django1.5までにしか含まれていません。1.5では非推奨になっています。1.6では削除される予定です。Django1.5以上を利用している、しようと検討されている方は、利用しない方が良いでしょう。

また、他にもdjango.contribの中から

  • django.contrib.databrowse
  • django.contrib.markup

などが1.6で削除される予定です。

大声:Djangoで開発プロジェクトやりますプログラマ以外× @2 今プログラマ2人
プログラミング経験は最低でも10年ある方のみでサクサク行きます。

‐最初のスプリント終了‐

刹那:なんで、てるけーさん都道府県コードをいちいち書いてたの?
killer:ふん…
カオス:wwwwwww
てるけー:え?
刹那:何調べる労力けちってんの?
刹那:普通に「django.contrib.localflavor.jp.jp_prefectures」で一発だから
刹那:都道府県コード一個一個定義してたら47回書くけどlocalflavorなら0回。常識でしょ
killer:常識だな…
カオス:ケチるなよww
てるけー:すいません、知らなかったんです
刹那:しかも最初は全員Django開発経験アリで、理解者のみって言ったのに
killer:無知は…万死に値する……
カオス:どんまい てるけー www
てるけー:すいません次からやります
刹那:実装者はsettingsで諸々設定して、対象のフォームのフィールドの
刹那:Widget として「JPPrefectureSelect」を設定した後
刹那:Redbull(200円)飲んで、諸々動き確かめて、テストを書く。基本だから
刹那:まぁ知ってたんだろうけど
刹那:調べる労力ケチってんじゃねーよカス

‐てるけーさんが開発プロジェクトから追放されました‐

すいません。知りませんでした。

f:id:tell-k:20130215102555p:plain

注意

localflavorにある都道府県コードを何が何でも採用する必要はない。既存、別システムで既に採用しているコード体系と整合性を保ちたい場合や、独自で「海外」などの項目を追加したい場合などには、特に採用する強い理由は無いだろう。参考リンクにある記事の中では、「ISO 3166-2:JP」に併せてほしかったなどの意見もあったりする。

ただコピペだとしても毎回自分で定義するの面倒だからあると嬉しいですね。

本記事は単純に「あるの!?」ていう驚きと僕の情弱っぷりを表現してみたかっただけです。なので知らなかったり、使わなかったとしても、万死には値しない……

またlocalflavor.jpの中には、日本の 郵便番号 用のフォームフィールドも用意されていたりします。

Django Template で for でループしたい

プロトタイプとか作ってて、単純に部分的なHTMLを、ループで表示させたい。そんな時、Django テンプレートで 単純に指定の回数だけforでループする方法。

  {% for i in "xxxxx" %}                                                                                                       
  <div>                                                     
       box                                       
  </div>                                                                                                               
  {% endfor %}                                                                  

酷くバッドノウハウだけど、その発想は無かった的なトキメキは感じた。

DjangoのMasterSlaveRouterの話し(稲川淳二風)

これは最近Djangoを使い始めた人の話しなんですけどね。Djangoは複数DBが扱えるんですよ。ええ。それでMaster/Slaveなレプリケーションを扱いたいなーなんて思ってたんです。

ところがね。ドキュメントに書いてあるMasterSlaveRouterを使った時に不思議な現象に遭遇しちゃったんですよ。

https://docs.djangoproject.com/en/dev/topics/db/multi-db/

ドキュメントに書いてあるとおり「MasterSlaveRouter」を実装しておそるおそるsyncdbして、そーと見たら、フッと出た。出たんですよ!エラー

$ python manage.py syncdb
 .
 .
 django.db.utils.IntegrityError: (1062, "Duplicate entry 'contenttypes-contenttype' for key 'app_label'")

あれー。おかしいなー。おかしいなー。 なんどsyncdbし直してもずーと出るなー。てしばらく怖くて動けなかったんですよ。

このままじゃいけないなー。なんとかしなくちゃなー。て強く念じたら、なんとか動けるようになって、例の先生に頼ったら、出て来たんですよ。下記のURLが。

http://stackoverflow.com/questions/10497418/django-syncdb-trying-to-insert-duplicate-rows-when-multiple-databases-are-specif

どうやら、この現象は、djangoがデフォルト作るモデルの中に、独自のキャッシュ機構を備えた、Managerオブジェクトを使ってるっていうが原因ぽいなーてのが分かったんですよ。そう曰く付きだったんですよ。怖いなー怖いなー。

お祓いの方法も書いてあって、MasterSlaveRouterのdb_for_readで、そういった独自のキャッシュ機構を持ってる奴らは、必ずMasterを見る様にしてやれば、その現象は収まるらしいんですよー。

  def db_for_read(self, model, **hints):
        if model._meta.app_label in ('contenttypes', 'sites'):
            return 'master'
        else:
            return 'slave' 


いやー。これで安心して眠れるなーて、胸を撫で下ろしたんですけど、よく考えるとこれって微妙なお祓いの仕方だなーて思って、ゾッとしました。

なんか他に良い方法ないのかなーって今でもその人は夜な夜な探してるらしいですよ。。

。。。なんだよこれ。