Monitors

Djem provides a simple monitoring system for tracking runtime, and database query counts (subject to the caveats noted below), and memory usage during code execution. This is useful for profiling and optimising performance-critical code paths.

The monitoring system consists of three main components:

M - A monitor class that tracks statistics for a single code section. This rarely needs to be used directly.
Mon - A manager class for M instances that handles monitor lifecycle and nesting.
mon() - A decorator for automatically monitoring individual functions.

Monitors can be nested to provide hierarchical profiling of complex operations, providing additional statistics such as:

Total number of times the same monitor is activated (e.g. if it exists within a loop).
Min, max, and average for all three metrics (time, queries, memory) if the monitor is activated multiple times.
Percentage of parent monitor’s total value used by each child monitor.

Typical usage is via the Mon management class, with the mon() decorator available as a shortcut when monitoring discrete functions. Both perform nesting automatically when a monitor is started while another is already active.

Caveats

Use of the monitoring system has several caveats to be aware of:

Monitors are not free. They do add some overhead, so code will run slower with monitors in place than it will without. This is especially pronounced when using monitors in large loops. So for statistics like total time taken, the absolute value is often less important than the percentage of a parent’s total that a child uses. This still allows easy identification of bottlenecks within a process.
There is a limitation on the number of queries that can be counted, as Django caps their query log to the most recent 9000. Once that log is full, monitors will stop noticing new queries. That will obviously affect the total query count included in the output, but it will also throw off other statistics such as averages. Nevertheless, by the time that number of queries has been executed, the major contributors to that query count should have been identified and the results will still highlight the offenders. If the number of queries exceeds 9000, you’ll see the following warning, indicating the results for query counts may not be entirely accurate:
```
UserWarning: Limit for query logging exceeded, only the last 9000 queries will be returned.
```
The query log noted above is only populated when Django’s debug mode is enabled (i.e. the DEBUG setting is True). Therefore, query counts can only be monitored in debug mode. Timing and memory usage monitors will work regardless of the DEBUG setting.

Using the decorator

The simplest way to use the monitoring system is with the mon() decorator:

from djem import mon

@mon('fetch_users')
def fetch_users():

    return User.objects.all()

users = fetch_users()

This will transparently start and stop a monitor named fetch_users when the fetch_users() function is called. After the function completes, the monitor’s results will be printed to the console.

Handling recursion

By default, the mon() decorator raises an error if a monitored function is called recursively:

@mon('recursive_process')
def process_tree(node):

    result = process_node(node)

    for child in node.children:
        process_tree(child)  # RuntimeError!

    return result

To allow recursion, use the allow_recursion parameter:

@mon('recursive_process', allow_recursion=True)
def process_tree(node):

    result = process_node(node)

    for child in node.children:
        process_tree(child)  # OK

    return result

Results will show suffixed monitor names for each recursive invocation (e.g. recursive_process, recursive_process_1, recursive_process_2, etc.) nested within each other. Note that excessive amounts of recursion will make the results difficult to read.

Nesting

Any use of Mon (see Using Mon below) within the context of the decorated function will be nested within the monitor created by the decorator. So this is valid:

from djem import Mon, mon

@mon('complex_operation')
def complex_operation():

    Mon.start('part_one')
    # ... code for part one ...
    Mon.stop('part_one')

    Mon.start('part_two')
    # ... code for part two ...
    Mon.stop('part_two')

complex_operation()

Using `Mon`

For more targeted monitoring, you can use the Mon class directly:

from djem import Mon

Mon.start('some_process')

# ... code to monitor ...

print(Mon.stop('some_process'))

Nesting

Nesting monitors allows profiling different parts of a complex operation. Only the outermost monitor needs to output its results:

from djem import Mon

Mon.start('complex_operation')

# Monitor part one
Mon.start('fetch_data')
# ... code to fetch data ...
Mon.stop('fetch_data')

# Monitor part two
Mon.start('transform_data')
# ... code to transform data ...
Mon.stop('transform_data')

# Monitor part three
Mon.start('save_results')
# ... code to save results ...
Mon.stop('save_results')

m = Mon.stop('complex_operation')
print(m.get_results(queries=True))

By default, only timing statistics are included when calling get_results(). In the above example, query counts are also included, via the queries=True flag. A mem=True flag is also available to include memory usage statistics.

Query Logging

Mon can also be used to enable console logging of executed database queries, via the django.db.backends logger. This is useful for debugging inefficient query usage.

from djem import Mon

Mon.start_qlog()

users = User.objects.filter(is_active=True)

Mon.stop_qlog()

Monitors

Caveats

Using the decorator

Handling recursion

Nesting

Using Mon

Nesting

Query Logging

Using `Mon`