Profiling calculation

It can be interesting to know where a calculation is spending its time. To this end, featomic includes self-profiling code that can record and display which part of the calculation takes time, and which function called long-running functions. All the example should output something similar to the table below.

╔════╦══════════════════════════════╦════════════╦═══════════╦══════════╦═════════════╗
║ id ║ span name                    ║ call count ║ called by ║ total    ║ mean        ║
╠════╬══════════════════════════════╬════════════╬═══════════╬══════════╬═════════════╣
║  2 ║ Full calculation             ║          1 ║         — ║ 660.58ms ║    660.58ms ║
╠════╬══════════════════════════════╬════════════╬═══════════╬══════════╬═════════════╣
║  3 ║ SoapPowerSpectrum::compute   ║          1 ║         2 ║ 584.02ms ║    584.02ms ║
╠════╬══════════════════════════════╬════════════╬═══════════╬══════════╬═════════════╣
║  1 ║ Calculator::prepare          ║          2 ║      3, 2 ║ 148.15ms ║     74.08ms ║
╠════╬══════════════════════════════╬════════════╬═══════════╬══════════╬═════════════╣
║  0 ║ NeighborsList                ║         20 ║         1 ║  20.82ms ║      1.04ms ║
╠════╬══════════════════════════════╬════════════╬═══════════╬══════════╬═════════════╣
║  5 ║ SphericalExpansion::compute  ║          1 ║         3 ║ 196.38ms ║    196.38ms ║
╠════╬══════════════════════════════╬════════════╬═══════════╬══════════╬═════════════╣
║  4 ║ GtoRadialIntegral::compute   ║      74448 ║         5 ║ 117.04ms ║      1.57µs ║
╠════╬══════════════════════════════╬════════════╬═══════════╬══════════╬═════════════╣
║  6 ║ SphericalHarmonics::compute  ║      74448 ║         5 ║   9.95ms ║ 133.00ns ⚠️ ║
╚════╩══════════════════════════════╩════════════╩═══════════╩══════════╩═════════════╝

In this table, the first columns assign a unique numeric identifier to each section of the code. The second one displays the name of the section. Then come the number of time this section of the code have been executed, which other function/section called the current one, and finally the total and mean time spent in this function.

The ⚠️ symbol is added when the mean cost of the function is close to the profiling overhead (30 to 80ns per function call), and thus the measurement might not be very reliable.

Some of the most important sections are:

  • Calculator::prepare: building the list of samples/properties that will be in the descriptor

  • XXX::compute: building blocks for the overall calculation

  • NeighborsList: construction of the list of neighbors

You can obtain a dataset for profiling from our website.

import chemfiles

import featomic
from featomic import SoapPowerSpectrum


def compute_soap(path):
    """Compute SOAP power spectrum.

    This is the same code as the 'compute-soap' example
    """
    with chemfiles.Trajectory(path) as trajectory:
        frames = [f for f in trajectory]

    HYPER_PARAMETERS = {
        "cutoff": {
            "radius": 5.0,
            "smoothing": {"type": "ShiftedCosine", "width": 0.5},
        },
        "density": {
            "type": "Gaussian",
            "width": 0.3,
        },
        "basis": {
            "type": "TensorProduct",
            "max_angular": 4,
            "radial": {"type": "Gto", "max_radial": 6},
        },
    }

    calculator = SoapPowerSpectrum(**HYPER_PARAMETERS)
    descriptor = calculator.compute(frames, gradients=["positions"])
    descriptor = descriptor.keys_to_samples("center_type")
    descriptor = descriptor.keys_to_properties(["neighbor_1_type", "neighbor_2_type"])

    return descriptor

Run the calculation with profiling enabled.

with featomic.Profiler() as profiler:
    descriptor = compute_soap("dataset.xyz")

Display the recorded profiling data as table.

print(profiler.as_short_table())
╔════╦══════════════════════════════════════════════╦════════════╦═══════════╦══════════╦══════════════╗
║ id ║ span name                                    ║ call count ║ called by ║ total    ║ mean         ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  4 ║ SoapPowerSpectrum::compute                   ║          1 ║         — ║ 755.87ms ║     755.87ms ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  5 ║ SphericalExpansion::compute                  ║          1 ║         4 ║ 305.89ms ║     305.89ms ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  1 ║ SoapRadialIntegralSpline::with_accuracy      ║         30 ║         5 ║ 134.86ms ║       4.50ms ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  0 ║ GtoRadialIntegral::compute                   ║      19230 ║         1 ║ 126.93ms ║       6.60µs ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  3 ║ Calculator::prepare                          ║          2 ║         4 ║  55.33ms ║      27.67ms ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  2 ║ NeighborsList                                ║         40 ║         3 ║  12.05ms ║     301.26µs ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  6 ║ SplinedRadialIntegral::compute               ║     176531 ║         5 ║  44.87ms ║ 254.00ns ⚠️  ║
╠════╬══════════════════════════════════════════════╬════════════╬═══════════╬══════════╬══════════════╣
║  7 ║ SphericalHarmonics::compute                  ║      35307 ║         5 ║  21.27ms ║ 602.00ns ⚠️  ║
╚════╩══════════════════════════════════════════════╩════════════╩═══════════╩══════════╩══════════════╝

You can also save this data as json for future usage

print(profiler.as_json())
{"timings":{"featomic::calculators::soap::radial_integral::gto::GtoRadialIntegral::compute":{"id":0,"elapsed":"126.934515ms","called":19230},"featomic::calculators::soap::radial_integral::spline::SoapRadialIntegralSpline::with_accuracy":{"id":1,"elapsed":"134.861249ms","called":30},"featomic::systems::neighbors::NeighborsList":{"id":2,"elapsed":"12.050559ms","called":40},"featomic::calculator::Calculator::prepare":{"id":3,"elapsed":"55.333432ms","called":2},"featomic::calculators::soap::power_spectrum::SoapPowerSpectrum::compute":{"id":4,"elapsed":"755.865221ms","called":1},"featomic::calculators::soap::spherical_expansion::SphericalExpansion::compute":{"id":5,"elapsed":"305.889944ms","called":1},"featomic::calculators::soap::radial_integral::spline::SplinedRadialIntegral::compute":{"id":6,"elapsed":"44.873864ms","called":176531},"featomic::math::spherical_harmonics::SphericalHarmonics::compute":{"id":7,"elapsed":"21.267505ms","called":35307}},"calls":[{"caller":0,"callee":1,"count":19230},{"caller":2,"callee":3,"count":40},{"caller":3,"callee":4,"count":1},{"caller":1,"callee":5,"count":5},{"caller":6,"callee":5,"count":1},{"caller":7,"callee":5,"count":1},{"caller":5,"callee":4,"count":1}]}