Pythonのprint()って行数も表示されないしいちいち打つの面倒ですよね．
デバッグを便利にするツールとしてIcecreamというライブラリがあるのですが，この動作が重いことに留意しなかったせいでハマったという内容です．
Icecreamとは
Icecreamは，print()の代わりに使えるデバッグ用のツールです．
「Never use print() to debug again」とGitHubのレポジトリにあるように，「print()とは永遠にさよなら」と謳っているだけあって便利さに感動して使っていました．
Qiitaでも紹介されているライブラリです．
https://qiita.com/miyashiiii/items/c0c4c709e096937df906
https://qiita.com/purun/items/c7aca300b970344214cf
ところが結構遅いことに気づかず使ってハマってしまいました．
経緯
先月から業務でicecreamを使い始めたら，やたら動作が重くなったように感じました．
全く思い当たる場所がなかったので１行ずつ処理時間を地道に測定してみると，なんとIcecreamのデバッグに時間がかかっていました．
Mac book pro 2020で1000個程度の要素のリストでデバッグするのに0．5秒程度かかります．コンソールに表示するだけで0．5秒って結構やばいと思います．
実証
いくつかのデータをprintとicでデバッグして時間を計測してみます．
計測に利用したコードはこちら．data変数に格納したものをコンソールに表示する時間を測っています．
# -*- coding: utf-8 -*-
from icecream import ic
from datetime import datetime
import sys
mode = sys.argv[1]#printかic
def main():
data = [i for i in range(10000)]
result = measure_speed(data)
print(result)
def measure_speed(data):
start = datetime.now()
if mode == 'print':
print(data)
elif mode == 'ic':
ic(data)
end = datetime.now()
result = '{0}でデバッグすると1回あたり{1}秒かかりました'.format(
mode,
(end-start).total_seconds()
)
return result
if __name__ == '__main__':
main()
10000個のリストをデバッグしてみる
data = [i for i in range(10000)]
printでデバッグ
% python3 main.py print
> printでデバッグすると1回あたり0.00524秒かかりました
icでデバッグ
% python3 main.py ic
> icでデバッグすると1回あたり0.391693秒かかりました
10000個の要素のリストで0.4秒って．．print()でデバッグした時と比べて80倍の時間がかかっています．
10個連結してみる
先の10000個の要素のリストを10個繋げてみます
data_element = [i for i in range(10000)]
data = [data_element for i in range(10)]
printでデバッグ
% python3 main.py print
> printでデバッグすると1回あたり0.028941秒かかりました
icでデバッグ
% python3 main.py ic
> icでデバッグすると1回あたり4.199099秒かかりました
先ほどが0．４秒だったのでおよそ10倍です．どうもある程度はデータの重さに比例するよるようです．ちなみに，こちらはprint()でのデバッグに比べて150倍の時間がかかっていました．
私の場合，イテレートしている中でicを使っていたので１秒弱のデバックが数十回繰り返されて大きな速度低下に陥っていました．
原因
どこでそんなに時間がかかっているのか不明だったのでGitHubのソースコードをみてみました．
少し長いですが，本体部分はこちら．IcecreamDebugger()というクラスがメインのようでした．
class IceCreamDebugger:
_pairDelimiter = ', ' # Used by the tests in tests/.
lineWrapWidth = DEFAULT_LINE_WRAP_WIDTH
contextDelimiter = DEFAULT_CONTEXT_DELIMITER
def __init__(self, prefix=DEFAULT_PREFIX,
outputFunction=DEFAULT_OUTPUT_FUNCTION,
argToStringFunction=argumentToString, includeContext=False):
self.enabled = True
self.prefix = prefix
self.includeContext = includeContext
self.outputFunction = outputFunction
self.argToStringFunction = argToStringFunction
def __call__(self, *args):
if self.enabled:
callFrame = inspect.currentframe().f_back
try:
out = self._format(callFrame, *args)
except NoSourceAvailableError as err:
prefix = callOrValue(self.prefix)
out = prefix + 'Error: ' + err.infoMessage
self.outputFunction(out)
if not args: # E.g. ic().
passthrough = None
elif len(args) == 1: # E.g. ic(1).
passthrough = args[0]
else: # E.g. ic(1, 2, 3).
passthrough = args
return passthrough
def format(self, *args):
callFrame = inspect.currentframe().f_back
out = self._format(callFrame, *args)
return out
def _format(self, callFrame, *args):
prefix = callOrValue(self.prefix)
callNode = Source.executing(callFrame).node
if callNode is None:
raise NoSourceAvailableError()
context = self._formatContext(callFrame, callNode)
if not args:
time = self._formatTime()
out = prefix + context + time
else:
if not self.includeContext:
context = ''
out = self._formatArgs(
callFrame, callNode, prefix, context, args)
return out
def _formatArgs(self, callFrame, callNode, prefix, context, args):
source = Source.for_frame(callFrame)
sanitizedArgStrs = [
source.get_text_with_indentation(arg)
for arg in callNode.args]
pairs = list(zip(sanitizedArgStrs, args))
out = self._constructArgumentOutput(prefix, context, pairs)
return out
def _constructArgumentOutput(self, prefix, context, pairs):
def argPrefix(arg):
return '%s: ' % arg
pairs = [(arg, self.argToStringFunction(val)) for arg, val in pairs]
# For cleaner output, if <arg> is a literal, eg 3, "string", b'bytes',
# etc, only output the value, not the argument and the value, as the
# argument and the value will be identical or nigh identical. Ex: with
# ic("hello"), just output
#
# ic| 'hello',
#
# instead of
#
# ic| "hello": 'hello'.
#
pairStrs = [
val if isLiteral(arg) else (argPrefix(arg) + val)
for arg, val in pairs]
allArgsOnOneLine = self._pairDelimiter.join(pairStrs)
multilineArgs = len(allArgsOnOneLine.splitlines()) > 1
contextDelimiter = self.contextDelimiter if context else ''
allPairs = prefix + context + contextDelimiter + allArgsOnOneLine
firstLineTooLong = len(allPairs.splitlines()[0]) > self.lineWrapWidth
if multilineArgs or firstLineTooLong:
# ic| foo.py:11 in foo()
# multilineStr: 'line1
# line2'
#
# ic| foo.py:11 in foo()
# a: 11111111111111111111
# b: 22222222222222222222
if context:
lines = [prefix + context] + [
format_pair(len(prefix) * ' ', arg, value)
for arg, value in pairs
]
# ic| multilineStr: 'line1
# line2'
#
# ic| a: 11111111111111111111
# b: 22222222222222222222
else:
arg_lines = [
format_pair('', arg, value)
for arg, value in pairs
]
lines = indented_lines(prefix, '\n'.join(arg_lines))
# ic| foo.py:11 in foo()- a: 1, b: 2
# ic| a: 1, b: 2, c: 3
else:
lines = [prefix + context + contextDelimiter + allArgsOnOneLine]
return '\n'.join(lines)
def _formatContext(self, callFrame, callNode):
filename, lineNumber, parentFunction = self._getContext(
callFrame, callNode)
if parentFunction != '<module>':
parentFunction = '%s()' % parentFunction
context = '%s:%s in %s' % (filename, lineNumber, parentFunction)
return context
def _formatTime(self):
now = datetime.now()
formatted = now.strftime('%H:%M:%S.%f')[:-3]
return ' at %s' % formatted
def _getContext(self, callFrame, callNode):
lineNumber = callNode.lineno
frameInfo = inspect.getframeinfo(callFrame)
parentFunction = frameInfo.function
filename = basename(frameInfo.filename)
return filename, lineNumber, parentFunction
def enable(self):
self.enabled = True
def disable(self):
self.enabled = False
def configureOutput(self, prefix=_absent, outputFunction=_absent,
argToStringFunction=_absent, includeContext=_absent):
if prefix is not _absent:
self.prefix = prefix
if outputFunction is not _absent:
self.outputFunction = outputFunction
if argToStringFunction is not _absent:
self.argToStringFunction = argToStringFunction
if includeContext is not _absent:
self.includeContext = includeContext
ic = IceCreamDebugger()
ソースコードを見てみたものの，とはいえ，私の目には特に問題があるようには思いませんでした．いろんなメソッド呼んでるなーとは思いますが，デバッグをいくつかしただけで数秒から数十秒もかかるようなちょっとメインでは使えないです．何かでハマりまくっている時にピンポイントで使うなら便利ですがね．．
結論
Icecreamは便利だが多用はできなそう．基本はPrint()を使って，ここぞというときに使うのが良さそう．銀の匙はありませんから便利さと処理時間はトレードオフというを実感しました．
GitHubのレポジトリにあるように「GitHubのレポジトリには Never use print() to debug again」とはいきませんでした．