Third party library works slower inside Slicer's Python shell - why? how to do performance profiling?

Development
1

Hi,

I’m trying to use python package lasio. It is geological library and its main purpose is to read textual files of format .las

After installing it (pip install lasio) I can use it as follows:

import lasio
las = lasio.read("path/to/las/file")    # I provide an example file below

The problem is that if I read this .las file (via command las = lasio.read("path/to/las/file")) in Slicer’s python shell then it works noticeably slower (about 5 seconds) than when I open PythonSlicer.exe in Windows 10 cmd and type the same command (it takes less than a second).

Also when I do that in Slicer’s python shell then I get warning:
Opening D:\D\A_Kerbel.las as ascii and treating errors with "replace"
wich is produced by this source code I think.
I don’t get this warning if I work inside cmd in PythonSlicer.exe

What may be the reason of perfomance penalty? If somebody has idea please share it. Probably it is somehow connected with character encoding detection but I tried to turn it off and still Slicer’s python shell works much slower. Or maybe there are many modules loaded to Slicer? Don’t know…

To test it you need relatively big .las file

P.S. I work with this library as I need it in my SlicerCAT and I can see that this problem doesn’t depend whether I use original Slicer or SlicerCAT

2

Lasio runs slower in Slicer because it logs a crazy amount of messages at debug level. You can disable this by temporarily decreasing the log level by running this command:

import logging
logging.getLogger().setLevel(logging.INFO)

After you have finished with lasio, you can restore the log level to logging.DEBUG.

I haven’t experienced this with other Python packages, so you might report this finding to lasio developers. Maybe they could use their own logger instead of using the root logger (which is set to debug level logging in Slicer).

If you are curious how I’ve found out the root cause of the problem: with profiling. Profilers are invented exactly for pinpointing performance bottlenecks. I’ve used cProfile to collect logs and visualized the results using tuna.

Collect data:

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

Plot results:

pip_install('tuna')
slicer.util._executePythonModule("tuna", ["c:/tmp/las.prof"])

Tuna output:

image
image2255×1394 241 KB

After adjusting the log level, the debug message logging function disappeared from the call tree and all the time-consuming functions make sense (they are complex and/or frequent operations):

image
image2255×1397 268 KB

1 Like
3

Thank you very much! It was my first time using profiler utility

I understood your idea (I didn’t know anything about logging before). I checked that according to this table Slicer’s logging level (logging.getLogger().level) is set to 10 DEBUG while when working in cmd I can see that logging level is set to 30 WARNING

I will report that to lasio developers, thank you