7.4. Logging and Debugging#
Collections of tools for logging and debugging Python code.
7.4.1. rich.inspect: Produce a Beautiful Report on any Python Object#
Show code cell content
!pip install rich
If you want to quickly see which attributes and methods of a Python object are available, use rich’s inspect method.
rich’s inspect method allows you to create a beautiful report for any Python object, including a string.
from rich import inspect
print(inspect('hello', methods=True))
╭────────────────────────────────────── <class 'str'> ──────────────────────────────────────╮ │ str(object='') -> str │ │ str(bytes_or_buffer[, encoding[, errors]]) -> str │ │ │ │ ╭───────────────────────────────────────────────────────────────────────────────────────╮ │ │ │ 'hello' │ │ │ ╰───────────────────────────────────────────────────────────────────────────────────────╯ │ │ │ │ capitalize = def capitalize(): Return a capitalized version of the string. │ │ casefold = def casefold(): Return a version of the string suitable for caseless │ │ comparisons. │ │ center = def center(width, fillchar=' ', /): Return a centered string of length │ │ width. │ │ count = def count(...) S.count(sub[, start[, end]]) -> int │ │ encode = def encode(encoding='utf-8', errors='strict'): Encode the string using the │ │ codec registered for encoding. │ │ endswith = def endswith(...) S.endswith(suffix[, start[, end]]) -> bool │ │ expandtabs = def expandtabs(tabsize=8): Return a copy where all tab characters are │ │ expanded using spaces. │ │ find = def find(...) S.find(sub[, start[, end]]) -> int │ │ format = def format(...) S.format(*args, **kwargs) -> str │ │ format_map = def format_map(...) S.format_map(mapping) -> str │ │ index = def index(...) S.index(sub[, start[, end]]) -> int │ │ isalnum = def isalnum(): Return True if the string is an alpha-numeric string, False │ │ otherwise. │ │ isalpha = def isalpha(): Return True if the string is an alphabetic string, False │ │ otherwise. │ │ isascii = def isascii(): Return True if all characters in the string are ASCII, │ │ False otherwise. │ │ isdecimal = def isdecimal(): Return True if the string is a decimal string, False │ │ otherwise. │ │ isdigit = def isdigit(): Return True if the string is a digit string, False │ │ otherwise. │ │ isidentifier = def isidentifier(): Return True if the string is a valid Python │ │ identifier, False otherwise. │ │ islower = def islower(): Return True if the string is a lowercase string, False │ │ otherwise. │ │ isnumeric = def isnumeric(): Return True if the string is a numeric string, False │ │ otherwise. │ │ isprintable = def isprintable(): Return True if the string is printable, False │ │ otherwise. │ │ isspace = def isspace(): Return True if the string is a whitespace string, False │ │ otherwise. │ │ istitle = def istitle(): Return True if the string is a title-cased string, False │ │ otherwise. │ │ isupper = def isupper(): Return True if the string is an uppercase string, False │ │ otherwise. │ │ join = def join(iterable, /): Concatenate any number of strings. │ │ ljust = def ljust(width, fillchar=' ', /): Return a left-justified string of │ │ length width. │ │ lower = def lower(): Return a copy of the string converted to lowercase. │ │ lstrip = def lstrip(chars=None, /): Return a copy of the string with leading │ │ whitespace removed. │ │ maketrans = def maketrans(...) Return a translation table usable for str.translate(). │ │ partition = def partition(sep, /): Partition the string into three parts using the │ │ given separator. │ │ replace = def replace(old, new, count=-1, /): Return a copy with all occurrences of │ │ substring old replaced by new. │ │ rfind = def rfind(...) S.rfind(sub[, start[, end]]) -> int │ │ rindex = def rindex(...) S.rindex(sub[, start[, end]]) -> int │ │ rjust = def rjust(width, fillchar=' ', /): Return a right-justified string of │ │ length width. │ │ rpartition = def rpartition(sep, /): Partition the string into three parts using the │ │ given separator. │ │ rsplit = def rsplit(sep=None, maxsplit=-1): Return a list of the words in the │ │ string, using sep as the delimiter string. │ │ rstrip = def rstrip(chars=None, /): Return a copy of the string with trailing │ │ whitespace removed. │ │ split = def split(sep=None, maxsplit=-1): Return a list of the words in the │ │ string, using sep as the delimiter string. │ │ splitlines = def splitlines(keepends=False): Return a list of the lines in the string, │ │ breaking at line boundaries. │ │ startswith = def startswith(...) S.startswith(prefix[, start[, end]]) -> bool │ │ strip = def strip(chars=None, /): Return a copy of the string with leading and │ │ trailing whitespace removed. │ │ swapcase = def swapcase(): Convert uppercase characters to lowercase and lowercase │ │ characters to uppercase. │ │ title = def title(): Return a version of the string where each word is titlecased. │ │ translate = def translate(table, /): Replace each character in the string using the │ │ given translation table. │ │ upper = def upper(): Return a copy of the string converted to uppercase. │ │ zfill = def zfill(width, /): Pad a numeric string with zeros on the left, to fill │ │ a field of the given width. │ ╰───────────────────────────────────────────────────────────────────────────────────────────╯
None
7.4.2. Rich’s Console: Debug your Python Function in One Line of Code#
Show code cell content
!pip install rich
Sometimes, you might want to know which elements in the function created a certain output. Instead of printing every variable in the function, you can simply use Rich’s Console object to print both the output and all the variables in the function.
from rich import console
from rich.console import Console
import pandas as pd
console = Console()
data = pd.DataFrame({'a': [1, 2, 3], 'b': [4, 5, 6]})
def edit_data(data):
var_1 = 45
var_2 = 30
var_3 = var_1 + var_2
data['a'] = [var_1, var_2, var_3]
console.log(data, log_locals=True)
edit_data(data)
[08:12:24] a b 1165738010.py:14 0 45 4 1 30 5 2 75 6 ╭───── locals ─────╮ │ data = a b │ │ 0 45 4 │ │ 1 30 5 │ │ 2 75 6 │ │ var_1 = 45 │ │ var_2 = 30 │ │ var_3 = 75 │ ╰──────────────────╯
7.4.3. Simplify Python Logging with Loguru#
Are you struggling with the complexity of configuring a logger object before logging in Python? With Loguru, you can skip this step and use the logger object directly with pre-built color and format settings.
Here is the comparison between the standard Python logging library and Loguru:
Standard Python logging library:
# loguru_vs_logging/logging_example.py
import logging
logging.basicConfig(format='%(asctime)s | %(levelname)s | %(module)s:%(funcName)s:%(lineno)d | %(message)s', level=logging.DEBUG)
def main():
logging.debug('This is a debug message')
logging.info('This is an info message')
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')
if __name__ == '__main__':
main()
$ python loguru_vs_logging/logging_example.py
2023-03-13 08:46:30,802 | DEBUG | logging_example:main:6 | This is a debug message
2023-03-13 08:46:30,802 | INFO | logging_example:main:7 | This is an info message
2023-03-13 08:46:30,802 | WARNING | logging_example:main:8 | This is a warning message
2023-03-13 08:46:30,802 | ERROR | logging_example:main:9 | This is an error message
2023-03-13 08:46:30,802 | CRITICAL | logging_example:main:10 | This is a critical message
Loguru:
# loguru_vs_logging/loguru_example.py
from loguru import logger
def main():
logger.debug("This is a debug message")
logger.info("This is an info message")
logger.warning("This is a warning message")
logger.error("This is an error message")
logger.critical("This is a critical message")
if __name__ == '__main__':
main()
$ python loguru_vs_logging/loguru_example.py
7.4.4. loguru: Print Readable Traceback in Python#
Show code cell content
!pip install loguru
Loguru also allows you to print a readable traceback by adding decorator logger.catch to a function.
from sklearn.metrics import mean_squared_error
import numpy as np
from loguru import logger
logger.add("file_{time}.log", format="{time} {level} {message}")
@logger.catch
def evaluate_result(y_true: np.array, y_pred: np.array):
mean_square_err = mean_squared_error(y_true, y_pred)
root_mean_square_err = mean_square_err ** 0.5
y_true = np.array([1, 2, 3])
y_pred = np.array([1.5, 2.2])
evaluate_result(y_true, y_pred)
> File "/tmp/ipykernel_174022/1865479429.py", line 14, in <module>
evaluate_result(y_true, y_pred)
│ │ └ array([1.5, 2.2])
│ └ array([1, 2, 3])
└ <function evaluate_result at 0x7f279588f430>
File "/tmp/ipykernel_174022/1865479429.py", line 9, in evaluate_result
mean_square_err = mean_squared_error(y_true, y_pred)
│ │ └ array([1.5, 2.2])
│ └ array([1, 2, 3])
└ <function mean_squared_error at 0x7f27958bfca0>
File "/home/khuyen/book/venv/lib/python3.8/site-packages/sklearn/utils/validation.py", line 63, in inner_f
return f(*args, **kwargs)
│ │ └ {}
│ └ (array([1, 2, 3]), array([1.5, 2.2]))
└ <function mean_squared_error at 0x7f27958bfb80>
File "/home/khuyen/book/venv/lib/python3.8/site-packages/sklearn/metrics/_regression.py", line 335, in mean_squared_error
y_type, y_true, y_pred, multioutput = _check_reg_targets(
│ │ └ <function _check_reg_targets at 0x7f27958b7af0>
│ └ array([1.5, 2.2])
└ array([1, 2, 3])
File "/home/khuyen/book/venv/lib/python3.8/site-packages/sklearn/metrics/_regression.py", line 88, in _check_reg_targets
check_consistent_length(y_true, y_pred)
│ │ └ array([1.5, 2.2])
│ └ array([1, 2, 3])
└ <function check_consistent_length at 0x7f279676e040>
File "/home/khuyen/book/venv/lib/python3.8/site-packages/sklearn/utils/validation.py", line 319, in check_consistent_length
raise ValueError("Found input variables with inconsistent numbers of"
ValueError: Found input variables with inconsistent numbers of samples: [3, 2]
7.4.5. Icecream: Never use print() to debug again#
Show code cell content
!pip install icecream
If you use print or log to debug your code, you might be confused about which line of code creates the output, especially when there are many outputs.
You might insert text to make it less confusing, but it is time-consuming.
from icecream import ic
def plus_one(num):
return num + 1
print('output of plus_on with num = 1:', plus_one(1))
print('output of plus_on with num = 2:', plus_one(2))
output of plus_on with num = 1: 2
output of plus_on with num = 2: 3
Try icecream instead. Icrecream inspects itself and prints both its own arguments and the values of those arguments like below.
ic(plus_one(1))
ic(plus_one(2))
Show code cell output
ic| plus_one(1): 2
ic| plus_one(2): 3
3
Output:
ic| plus_one(1): 2
ic| plus_one(2): 3
7.4.6. heartrate — Visualize the Execution of a Python Program in Real-Time#
Show code cell content
!pip install heartrate
If you want to visualize which lines are executed and how many times they are executed, try heartrate.
You only need to add two lines of code to use heartrate.
import heartrate
heartrate.trace(browser=True)
def factorial(x):
if x == 1:
return 1
else:
return (x * factorial(x-1))
if __name__ == "__main__":
num = 5
print(f"The factorial of {num} is {factorial(num)}")
Show code cell output
* Serving Flask app 'heartrate.core'
* Debug mode: off
Address already in use
Port 9999 is in use by another program. Either identify and stop that program, or start the server with a different port.
The factorial of 5 is 120
You should see something similar to the below when opening the browser:
7.4.7. pyheat: Simplify Code Profiling with Heatmap Visualization#
Show code cell content
!pip install py-heat
Profiling your code is helpful, but looking at data in a table can be a real headache. Wouldn’t it be nice if you could see your code’s time distribution as a heatmap? That is when pyheat comes in handy.
%%writefile pyheat_example.py
def factorial(x):
if x == 1:
return 1
else:
return (x * factorial(x-1))
if __name__ == "__main__":
num = 5
factorial(num)
Writing pyheat_example.py
from pyheat import PyHeat
ph = PyHeat("pyheat_example.py") # file you want to profile
ph.create_heatmap()
ph.show_heatmap()
7.4.8. snoop : Smart Print to Debug your Python Function#
Show code cell content
!pip install snoop
If you want to figure out what is happening in your code without adding many print statements, try snoop.
To use snoop, simply add the @snoop decorator to a function you want to understand.
import snoop
@snoop
def factorial(x):
if x == 1:
return 1
else:
return (x * factorial(x-1))
if __name__ == "__main__":
num = 5
print(f"The factorial of {num} is {factorial(num)}")
10:19:00.73 >>> Call to factorial in File "<ipython-input-2-57aff36d5f6d>", line 4
10:19:00.73 ...... x = 5
10:19:00.73 4 | def factorial(x):
10:19:00.73 5 | if x == 1:
10:19:00.73 8 | return (x * factorial(x-1))
10:19:00.74 >>> Call to factorial in File "<ipython-input-2-57aff36d5f6d>", line 4
10:19:00.74 ...... x = 4
10:19:00.74 4 | def factorial(x):
10:19:00.74 5 | if x == 1:
10:19:00.74 8 | return (x * factorial(x-1))
10:19:00.74 >>> Call to factorial in File "<ipython-input-2-57aff36d5f6d>", line 4
10:19:00.74 ...... x = 3
10:19:00.74 4 | def factorial(x):
10:19:00.74 5 | if x == 1:
10:19:00.75 8 | return (x * factorial(x-1))
10:19:00.75 >>> Call to factorial in File "<ipython-input-2-57aff36d5f6d>", line 4
10:19:00.75 ...... x = 2
10:19:00.75 4 | def factorial(x):
10:19:00.75 5 | if x == 1:
10:19:00.75 8 | return (x * factorial(x-1))
10:19:00.75 >>> Call to factorial in File "<ipython-input-2-57aff36d5f6d>", line 4
10:19:00.75 ...... x = 1
10:19:00.75 4 | def factorial(x):
10:19:00.76 5 | if x == 1:
10:19:00.76 6 | return 1
10:19:00.76 <<< Return value from factorial: 1
10:19:00.76 8 | return (x * factorial(x-1))
10:19:00.77 <<< Return value from factorial: 2
10:19:00.77 8 | return (x * factorial(x-1))
10:19:00.77 <<< Return value from factorial: 6
10:19:00.77 8 | return (x * factorial(x-1))
10:19:00.77 <<< Return value from factorial: 24
10:19:00.78 8 | return (x * factorial(x-1))
10:19:00.78 <<< Return value from factorial: 120
The factorial of 5 is 120
7.4.9. Logging in Pandas Pipelines#
Show code cell content
!pip install scikit-lego
When using pandas pipe, you might want to check whether each pipeline transforms your pandas DataFrame correctly. To automatically log the information of a pandas DataFrame after each pipeline, use the decorator sklego.pandas_utils.log_step.
import pandas as pd
from sklego.pandas_utils import log_step
import logging
df = pd.DataFrame({"col1": [1, 2, 3], "col2": ["a", "b", "c"]})
To use log_step, simply use it as a decorator for functions being applied to your DataFrame.
@log_step(print_fn=logging.info)
def make_copy(df: pd.DataFrame):
return df.copy()
@log_step(print_fn=logging.info)
def drop_column(df: pd.DataFrame):
return df[["col2"]]
@log_step(print_fn=logging.info)
def encode_cat_variables(df: pd.DataFrame):
df["col2"] = df["col2"].map({"a": 1, "b": 2, "c": 3})
return df
df = df.pipe(make_copy).pipe(drop_column).pipe(encode_cat_variables)
INFO:root:[make_copy(df)] time=0:00:00.000239 n_obs=3, n_col=2
INFO:root:[drop_column(df)] time=0:00:00.002117 n_obs=3, n_col=1
INFO:root:[encode_cat_variables(df)] time=0:00:00.003217 n_obs=3, n_col=1
Find more ways to customize your logging here
7.4.10. Add Progress Bar to Your List Comprehension#
Show code cell content
!pip install tqdm
If your for loop or list comprehension takes a long time to run, you might want to know which element is being processed. You can add clarity to your for-loop by using tqdm. Using tqdm with an iterable will show a progress bar.
from tqdm.notebook import tqdm
from time import sleep
def lower(word):
sleep(1)
print(f"Processing {word}")
return word.lower()
words = tqdm(["Duck", "dog", "Flower", "fan"])
[lower(word) for word in words]
Processing Duck
Processing dog
Processing Flower
Processing fan
['duck', 'dog', 'flower', 'fan']
7.4.11. Hyperfine: Compare the Speed of Two Commands#
If you want to compare the speed of two arbitrary commands, use hyperfine. hyperfine creates a statistical analysis across multiple runs and detects outliers.
In the code below, I use hyperfine to compare the execution speed of two Python files.
$ hyperfine 'python example1.py' 'python example2.py'
7.4.12. Timeline View of the Execution of Your Python Functions#
Have you ever wanted to see a timeline graph showing how the execution of your functions takes place in time? Prefect now allows you to do exactly that.
To use Prefect, simply add @task and @flow to your Python functions.
from prefect import task, flow
from time import sleep
@task
def task1(secs):
sleep(secs)
@task
def task2(secs):
sleep(secs)
@flow
def my_flow():
task1(2)
task2.submit(10)
task2.submit(2)
my_flow()
When running this code, you should see the following on your Prefect UI.
Check out the getting started tutorials for basic concepts of Prefect.