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に作るとかでもいいかもね。

おわり。

Pythonで複数プロセスたちあげて結果を非同期で処理する

ていうのを見かけたので殺伐とした心を癒すためにやってみる心。

やりたい事

  • Pythonスクリプトから複数外部コマンドを実行
  • 実行結果を非同期に処理する
  • 割とお手軽にやりたい。

試してみる

それぞれ 1秒, 2秒, 3秒まってprintするようなスクリプトを3つ用意

# こんな感じ
from time import sleep

sleep(1)
print "echo1"

これを参考のまんま下記のようなコードで動かす。

from subprocess import Popen, PIPE
import time

running_procs = [
    Popen(['python', 'echo3.py'], stdout=PIPE, stderr=PIPE),
    Popen(['python', 'echo2.py'], stdout=PIPE, stderr=PIPE),
    Popen(['python', 'echo1.py'], stdout=PIPE, stderr=PIPE),
    ]

while running_procs:
    for proc in running_procs:
        retcode = proc.poll()
        if retcode is not None: # Process finished.
            running_procs.remove(proc)
            break
    else: # No process is done, wait a bit and check again.
        time.sleep(.1)
        continue

    # Here, `proc` has finished with return code `retcode`
    if retcode != 0:
        """Error handling."""
        print "error"

    print proc.stdout.read()

結果はこうなる

$ python hoge.py
echo1

echo2

echo3

やってること

1. 3つのプロセスをリストにしてfor inでまわす
2. proc.pollでreturn codeをチェック
3. return codeが帰ってきたら自らをプロセスリストから消してfor終了
4. 逆に3つのプロセスどれもがreturn codeかえさなかったら、ほんのちょっぴりまって1にもどる
5. return codeが帰ってきたらerror handling or stdoutから結果を受け取る

お手軽にやるにはいいかもしんない. proc.poll こういう挙動になるんだてのを知った。

備考

  • コマンドが終わるのpollingして、結果が帰ってきた順番に処理してるだけなので正確には非同期で処理してるとは言えない。
  • 例えば最後のstdoutからreadしたものをあれやらこれや処理するとしたら、その間ブロックされるので、その後の結果は処理されるのが待たされる。

はー癒された

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モデルのテーブルを削除

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

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

おわりん

参考

ほんとにあったかもしれない怖いコード (呪いのビデオ風)

納涼!ほんとにあった怖いコード(by CodeIQ×はてな)

http://partner.hatena.ne.jp/codeiq_matsuri2013_2

まずはこちらの画像をご覧いただきたい。

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

お分かりいただけだろうか?

f:id:tell-k:20130826185014p:plain:w700

これは、とあるプログラマが、深夜23時頃に、終電で帰るのを諦めて、とある既存ライブラリを徹夜で書き直しをすることを決意した時に見つけてしまったコードだ。

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

彼はこのコードを見て以来、心身ともにおかしくなってしまった。一部では彼は呪われてしまったという噂もある。

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

当時の彼を知る同僚は、その頃から彼の言動がおかしくなったと証言している。

「BoldがSetされてるはずなのにSetされてないどころかそのままreturnされてる、ていうかCamelなのかunderscoreなのかどっち?。。。何をいってるか分からねぇと思うが、俺も何をいってるかわからねぇry)」

「いやこいつを理解できない俺がおかしい!!きっとこれは名のあるファンタジスタが書いたファンタスティックコードなんだ!ははは。。ひひ。。」

彼はその日から、取り憑かれたように、社内のファンタスティックなコードを探しては社内掲示版にアップし続けていった。彼はもうこの時、目の焦点があってなかったと言う。

ほどなくして彼は「探さないでください」という置き手紙とともに行方が分からなくなった。彼は行方をくらます直前にこんな妄言を吐いていたそうだ。

「俺にはこの記事のファイル名は"いーしーきゃんびー"って読めないし、"いーきゃんびー"、
もしくは、"いーしーあんゔぃー"だろうが!俺じゃない!俺がわるいんじゃない!全てはあいつが悪いだ!みんな呪われろ!ノロワレロ!ノロ。。」

彼はいま現在も行方が分かっていない。

ご注意

  • この記事の大半はフィクションであり、登場人物、画像、リンク先には関しては一切関連がございません。予めご了承ください。
  • また掲載されているコードは本来のコードの一部分だけを、記憶を頼りに再現したものとなっております。そのため呪われたりしませんのでご安心ください。

なんだよこれ。。。

お口直しに僕のお気に入りの動画を貼付けておきますね (´・ω・`)


疾走 - YouTube

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)++

とあるオジサンのサンデー図工(iPad mini SmartCover)

夜更かしてインターネッツばかりみてる不健康なオジサン達。こんばんわ。今日はそんな良い子のオジサン達のために、オジサンが久々に図工してみた話を書くよ。

きっかけ

オジサンは 最近 iPad mini 用のケースを買いました。 monCarbone Mini Smart Mate てヤツです。

これで iPad miniタンの背面が洒落乙になってよかったなぁと思ってたんですが、肝心のフロントのカバーが Apple謹製のSmartCoverでしかも黄緑という残念な事態が発生。

f:id:tell-k:20130707235533j:plain

謹製かどうかは置いておいて黄緑が微妙すぐるので思い切ってフロントも新しいのにしようと思い立ちました。

SmartCover 探し

できればSmartCoverと同じ感じので、monCarboneにあう感じのがいいなぁというの探し始めたんですが、このSmartCoverってヤツはAppleが特許を取得してるので、Apple以外からは基本出されてないという状況。 一応 それっぽいのがありますが、特許侵害してるかも?てのと、ちゃちいというのを見かけたので、謹製で売ってるブラックにすればいいかなと思い、AppleStoreまで足を運んでみる事に。

AppleStoreについて「風呂フタの黒。風呂フタの黒」とつぶやきながら、アクセサリコーナーにいって、SmartCoverのブラックを手に取ってみると「あれ?これ黒じゃない?濃い灰色や。僕の求めてるのと違う」という事で早々に退散

自分で作ろう

というわけで今ある黄緑のださい風呂フタをケースに合わせるために自分で作ろうとと決心しました。今考えてみると、僕は探してる途中から、最適なものを探すという目的から逸脱して、「自分でつくる」という方向に無意識的に自分を誘導していたように思います。

「手段の為ならば目的を選ばないという様などうしようもないオジサンも確実に存在するのだ。つまりはとどのつまりは我々のような」

準備

という訳で、東急ハンズっていうお洒落スポットで、以下を購入

  • ラッカースプレー(つや消し黒)
  • 3M ダイノックフィルム カーボン(CA-421)

最近はこんなお洒落シートが気軽に手に入るですね。

黄緑の風呂フタを黒く塗る

ベランダにビニールを敷いて、風呂フタを寝かせて、ラッカースプレーで黒くする。割と均一に塗るのが難しくて、変なムラが残ってしまったのが残念。

スプレー使う時は、マスクと軍手とか、汚れてもいいTシャツとかでやるんだょぉ。

カーボンシートを貼る

ラッカースプレーで乾いたのを確認したら、風呂フタの三つに出っ張ってる部分に、いい感じで切り取ったシートを貼る。

風呂フタの上にA4の紙を置いて、指でなぞって型紙ぽいのを作って、それに併せてシートをカッターで切ると旨く切れた。とかいいつつ雑な出来になった事は内緒だ。

完成

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

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

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


や。。やったよ。ワクワクさんと天国のノッポさん(死んでない)! 僕にも出来たよ!!!

と胸張って言えれば良かったが、近くで見るとすごいちゃちい、すごい安っぽい、しかも風呂フタをスタンドにしようと折り畳むと随所に黄緑の亀裂ガガガ。。。もうやだ普通のSmartCoverの黒買おう。。。orz

結論

ラッカースプレーを綺麗に塗るのむずいから、もっと別の塗料的なものを吟味した方が良かったなぁと思った。

まぁインターネッツしかしないオジサンもたまに図工とか思い出してやってみると、案外楽しいもんですね。enchantMoonとか発売されたら当初はアクセサリ用品とか少ないだろうから、こういうオジサンが増えるかもしれない。

おわり。

sphinxjp.themes.basicstrap 0.3.0 にしますた

やほー。こんなにいい天気なのにインターネッツの世界にどっぷりな不健康の皆たちー。

この前作った、sphinxテーマをアップグレードしたよー。

ぶっちゃけ殆ど使われてないだろうけど、なんとなく使ってるBootstrapとかがバージョンアップしてたので、もろもろそれに併せてバージョンアップした感じです。

sphinxjp.themes.basicstrap 0.3.0 : Python Package Index

あたらしくinner_themeとしてgeo-bootstrapとbootswatch-flatlyというのが利用できるようになりました。

booswatch-flatlyは割と綺麗なのでお気に入り。

あとは日本語でドキュメントかいてると、なんかテーマによっては「見出しの大きさ」が気になる事が多々あるので、見出しににそれぞれ font-size を設定できるようにしてみました。

何かご意見、ご要望があったら、適当にお知らせくださいー

そんじゃーね。