Perfomance decrease in DEBUG logging level

[kerim371]

Describe the bug
When logging is set to DEBUG:

import logging
logging.getLogger().setLevel(logging.DEBUG)

then perfomance is greatly decrease and more than 80% of time is spent on logging.

To Reproduce
Steps to reproduce the behavior:

• download las file big enough to feel the problem
• set log level to DEBUG:

import logging
logging.getLogger().setLevel(logging.DEBUG)

• collect data:

import cProfile
cProfile.run("las=lasio.read(r'c:\Users\username\Downloads\A_Kerbel.las')", "c:/tmp/las.prof")

• install tuna to display results:

pip install tuna

• display results:

python -m tuna c:/tmp/las.prof

• now you can see that about 80% is spent on debug. Is that ok?

Expected behavior
I guess debug should take less than 80% of the time

Software versions (please complete the following information):

• Python 3.6.7 (default, Jun 26 2021, 18:30:45) [MSC v.1929 64 bit (AMD64)] on win32
• lasio version 0.29

Additional context
Please see my topic dedicated to this problem. Here you can simply find all the information needed to understand the problem.

P.S. I'm not much expert in profiling and I only have little experience of working in python so I appologize if I explained some staff cumbersome

[kinverarity1]

Thanks for raising this. From what I've read in the Python documentation, we are using logging in the recommended way:

logger = logging.getLogger(__name__)

https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial

The statement on the thread you linked to says we are using the root logger, which I don't think we are - that would be logger = logging.getLogger().

However I'm wondering if we could add a NullHandler to silence messages unless a user or application explicitly enables them by adding a handler... Per discussion here:

https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library

[kerim371]

The statement on the thread you linked to says we are using the root logger, which I don't think we are - that would be logger = logging.getLogger().

@kinverarity1 agree but maybe @lassoan simply meant to explicitely set another logging level to lasio (WARNING for example)?
To test it I just tried to find any occurence of logging.getLogger in lasio package (examples.py, las.py, las_items.py, las_version.py, reader.py, writer.py) and after linecode in reader.py:

logger = logging.getLogger(__name__)

I added few lines (it is enough to change only reader.py to overcome this problem when reading .las but I don't know, maybe it is needed in other files too to completely overcome the problem):

print('reader.py, logger level before set: ' + str(logger.level))    # the output tells me that logger.level = 0
logger.setLevel(logging.INFO)
print('reader.py, logger level after set: ' + str(logger.level))    # the output tells me that logger.level = 20

As you can see by default the logger.level is set to 0 which corresponds to NOTSET log level according to predefined log level table. Maybe lasio needs explicetely set this value to some of the predefined?

With this line logger.setLevel(logging.INFO) I can see that there is no problem to fast read .las file from Slicer embedded python with DEBUG log level.

However I'm wondering if we could add a NullHandler to silence messages unless a user or application explicitly enables them by adding a handler...

according to documentation that could solve the problem

[lassoan]

I can confirm that logging.getLogger('lasio').setLevel(logging.WARNING) fixes the performance issue. So, indeed, not the root logger is used, probably just the default log level is taken from the root logger, as it is not set to anything else.

So, it seems that the only unusual behavior of lasio is that it logs tons of messages at debug level, which can significantly slow down the execution.

A few potential solutions:

• reduce the granularity of debug-level log messages (log less)
• keep logging this many messages but at lower level (e.g., specify TRACE level)
• define a callback function for progress reporting (which has an additional advantage that long-running operations can be cancelled, e.g., when you use lasio from a GUI)

[kinverarity1]

I'm happy to change some of these messages to TRACE - thanks for the suggestion and help @lassoan!

[kinverarity1]

@kerim371 if you are able to test the master branch of lasio to see if it helps that would be appreciated. I have moved the offending logger call to a custom level which is set below the standard DEBUG level.

[kerim371]

@kinverarity1 thank you very much, it seems now it works fast as expected.
To test it I did:

pip install git+https://github.com/kinverarity1/lasio.git

then inside my Slicer's python shell (wich sets DEBUG log level):

import lasio
las=lasio.read(r'd:d\A_Kerbel.las')

less than a second has past to perform these two lines of code

[kinverarity1]

Thanks for the update!