"^L" is 何?

割とどうでもいい話。python2.7 の 標準ライブラリのemail/message.pyの中で"^L"ていう制御コードを見つけた時の話。

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

そもそも "^L"てなんだっけ。。。から始まり、調べてみたら改ページだった。

vimエディタの印刷で改ページ : サイト更新停滞ちうっ [ 名無しのVIM使い ]

それは良いとしてなんでこんな所に改ページの制御コード入ってるんだろうと思ってさらに調べたら、下記のような同じような疑問をもったヒトが書いたスレを見つけた。

Issue 7513: many source files contaminated with form feed (\f) characters - Python tracker

こんな事が書いてあった。

  • ivank 「Python 2.7の r76831 をチェックアウトしたら、大量のファイルに改ページが入ってるんやけど(震え声) ... 」
  • lemburg 「俺の覚えてる限り、Barryがそれ好きなんだよね。理由はよー知らんけど ;-) 」
  • barry 「それEmacsの次ページ、前ページへのナビゲーションコマンドなんだよね。 Pythonは空白扱いするけど、何か問題ある? :)」
  • amaury.forgeotdarc 「それPEP8でも許容されてっから。。。」

えw マジで? そんな事書いてありましたっけ?とPEP8を見に行く。

Python accepts the control-L (i.e. ^L) form feed character as whitespace; Many tools treat these characters as page separators, so you may use them to separate pages of related sections of your file. Note, some editors and web-based code viewers may not recognize control-L as a form feed and will show another glyph in its place.

via http://legacy.python.org/dev/peps/pep-0008/

Python は Control-L (^L: From Feed) 文字を空白文字として受け入れます。 多くのツールはこの文字をページ区切りに使うので、この文字をファイル内の セクションを分けるページに使うことができるかもしれません。 しかし、いくつかのエディターや Web ベースのコードビューアは Control-L を認識せず、その場所に別の文字を表示するかもしれません。

via https://dl.dropboxusercontent.com/u/555254/pep-0008.ja.html

ナルホディウス。

なんどかPEP8に目を通してるつもりだったけど、まったくもって頭に入ってないという事が良くわかったオジサンなのでした。

おわり。

Pythonのloggingで手出しできない所のhandlerを差し替える

元ネタ。コレをを見た時、確かにどうやったらいいんだろう? と思ってちょっと調べてみた。

やりたい事

  • ライブラリやらなんやらで書き出してるロギング部分を、自前で用意したロガーというかハンドラーに差し替えたい。

手出し出来ない例

例えば下記のような、hoge.py は手出しできないスクリプトだったとして、以下のようにログ取りになっていたとします。

# hoge.py 
# -*- coding: utf-8 -*-

from logging import warn

spam = u"スパム"
ham = u"ハムの人"

warn("%s %s", spam, ham)

handlerを差し替える

loggingモジュールの中を漁った結果、どうやら logging.root.handlersを弄れば、上記のような場合でも好きな LoggingHandlerに差し替えられるらしい。

1. root.handlers を強引に書き換える

# -*- coding: utf-8 -*-
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
logging.root.handlers = [ltsv_handler] # root.handlersを上書きする

# hogeが呼ばれる前にloggingの設定をする
import hoge # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

行儀が悪い感じがとても怒られそうです。addHandlerというメソッドがあるのでそちらにしましょう。

2. addHandlerを使う

# -*- coding: utf-8 -*-
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
logging.root.addHandler(ltsv_handler) # addHandlerに変えた。

# hogeが呼ばれる前にloggingの設定をする
import hoge  # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

というかそもそも、logging.getLogger()ていう風にやるとrootロガーだったのでそいつに対してaddHandlerすれば良かったという事実

3. rootロガーにaddHandlerを使う

# -*- coding: utf-8 -*-
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(ltsv_handler) # logging.getLogger() => rootロガー

# hogeが呼ばれる前にloggingの設定をする
import hoge  # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

ここまで書いて気がつきましたが、fileConfigでrootロガーを書き換えたらいいのでは???

4. fileConfigを使う

  • logger.iniを用意
[loggers]
keys = root

[handlers]
keys = ltsvhdr

[formatters]
keys = ltsvfmt

[logger_root]
level = DEBUG
handlers = ltsvhdr

[handler_ltsvhdr]
class = StreamHandler
args = (sys.stderr,)
level = DEBUG
formatter = ltsvfmt

[formatter_ltsvfmt]
format = time:%(asctime)s\tmessage:%(message)s
datefmt = %Y-%m-%dT%H:%M:%S%z
class = ltsvlogger.LTSVFormatter

script側ではfileConfigするだけ。

# -*- coding: utf-8 -*-
import logging.config
logging.config.fileConfig('logger.ini')

# hogeが呼ばれる前にloggingの設定をする
import hoge  # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

大体終わりです。

いろいろ怒られそうなので、書こうか迷うましたが、hogeを利用するスコープが限定的なら、mock.patchすればいいのでは!???とかいう愚行を一番最初に思いついた事を告白しておきます。石は投げないでください。

# -*- coding: utf-8 -*-
import mock
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
logger = logging.getLogger("nonrootlogger")
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
logger.addHandler(ltsv_handler)

with mock.patch("logging.warn", side_effect=logger.warn):
   import hoge # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

ではではアデュー

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

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

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

おわりん

参考

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

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 を設定できるようにしてみました。

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

そんじゃーね。