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」とはいきませんでした．