Large performance overhead due to logging

[kmnhan]

While profiling, I noticed that most of the overhead in loading files actually comes from the pprint module used in logging. The following test demonstrates this by comparing the time it takes to load test files with and without logging.

import igor2.binarywave
import igor2.packed
import logging

igor2_test_data_dir = "path/to/igor2/tests/data/"

ibw_file = igor2_test_data_dir + "mac-double.ibw"
pxp_file = igor2_test_data_dir + "polar-graphs-demo.pxp"

# ibw, logging enabled
logging.getLogger("igor2.struct").setLevel(logging.NOTSET)
%timeit igor2.binarywave.load(ibw_file)
# 6.81 ms ± 111 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)

# ibw, logging disabled
logging.getLogger("igor2.struct").setLevel(logging.CRITICAL)
%timeit igor2.binarywave.load(ibw_file)
# 320 µs ± 5.69 µs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

# pxp, logging enabled
logging.getLogger("igor2.struct").setLevel(logging.NOTSET)
%timeit igor2.packed.load(pxp_file)
# 249 ms ± 2.23 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

# pxp, logging disabled
logging.getLogger("igor2.struct").setLevel(logging.CRITICAL)
%timeit igor2.packed.load(pxp_file)
# 9.24 ms ± 65.7 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)

The time it takes to load the files without logging is significantly faster than with logging. Would it be possible to disable logging by default?

[paulmueller]

Interesting, there are a lot of debug statements in that module. I guess logging.WARNING or logging.INFO would also be sufficient in this case. I am happy to merge a PR with a fix.