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

**URL:** <https://discourse.slicer.org/t/third-party-library-works-slower-inside-slicers-python-shell-why-how-to-do-performance-profiling/18742>\
**Category:** Development\
**Tags:** performance\
**Created:** [July 15, 2021, 12:34am UTC](https://discourse.slicer.org/t/third-party-library-works-slower-inside-slicers-python-shell-why-how-to-do-performance-profiling/18742 "2021-07-15T00:34:46Z")\
**Posts on this page:** 3\
**Page:** 1

<div class="post-metadata">

**Author:** ![keri](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/keri/32/11618_2.png) [@keri](https://discourse.slicer.org/u/keri)\
**Post date:** [July 15, 2021, 12:34am UTC](https://discourse.slicer.org/t/third-party-library-works-slower-inside-slicers-python-shell-why-how-to-do-performance-profiling/18742/1 "2021-07-15T00:34:46Z")

</div>

Hi,

I’m trying to use python package [lasio](https://github.com/kinverarity1/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:

```python
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](https://lasio.readthedocs.io/en/latest/_modules/lasio/reader.html#:~:text=%23%20Now%20open%20and%20return%20the%20file-like%20object) 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](https://lasio.readthedocs.io/en/latest/encodings.html) 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](https://drive.google.com/file/d/1ZTRs68wHi1M4rPDsgswiNXAkK_0c-Vp0/view?usp=sharing)

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

---

<div class="post-metadata">

**Author:** ![lassoan](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/lassoan/32/13_2.png) [@lassoan](https://discourse.slicer.org/u/lassoan)\
**Post date:** [July 15, 2021, 4:44am UTC](https://discourse.slicer.org/t/third-party-library-works-slower-inside-slicers-python-shell-why-how-to-do-performance-profiling/18742/2 "2021-07-15T04:44:10Z")

</div>

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:

```python
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](https://docs.python.org/3/library/profile.html) to collect logs and visualized the results using [tuna](https://github.com/nschloe/tuna).

Collect data:

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

```

Plot results:

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

```

Tuna output:

 ![image](https://us1.discourse-cdn.com/flex002/uploads/slicer/original/3X/9/0/90e3f56d3559d6e705f130f9c50d79d2a6c4a336.png)

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](https://us1.discourse-cdn.com/flex002/uploads/slicer/original/3X/8/1/81d583739ba71663acd30c2a82dde23695b7a616.png)

---

<div class="post-metadata">

**Author:** ![keri](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/keri/32/11618_2.png) [@keri](https://discourse.slicer.org/u/keri)\
**Post date:** [July 15, 2021, 10:24am UTC](https://discourse.slicer.org/t/third-party-library-works-slower-inside-slicers-python-shell-why-how-to-do-performance-profiling/18742/3 "2021-07-15T10:24:24Z")

</div>

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](https://docs.python.org/3/library/logging.html#logging-levels) 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