[ENH] Improved output messages/status information of ASSET functions

[kohlerca]

This PR replaces ordinary print statements throughout ASSET with logging calls.

Moreover, steps that use loops also have improved output by using tqdm progress bars.

Any INFO logging is controlled by the usual verbose parameter in the functions. Moreover, the user can use the standard log level setting to enable specific messages, as DEBUG messages were also included.

[coveralls]

coverage: 87.086% (-0.02%) from 87.105% when pulling 3f5211a on INM-6:feature/asset_logging into 9a07224 on NeuralEnsemble:master.

[Moritz-Alexander-Kern]

Hey @kohlerca ,
Thanks for this enhancement of ASSET.

Doctests fail, since the print statements have been removed, so the output of e.g.

elephant/elephant/asset/asset.py

Lines 85 to 88 in 5b464ec

	compute rates by boxcar-kernel convolution...
	compute the prob. that each neuron fires in each pair of bins...
	compute the probability matrix by Le Cam's approximation...
	substitute 0.5 to elements along the main diagonal...

is no longer printed out.

Fix: adapt example code accordingly (?).

Run doctest with:
pytest elephant --doctest-modules --ignore=elephant/test/

[kohlerca]

Yes, I think the examples will also look cleaner with the removal of those text messages. For the doctests, just the final SSEs are the relevant output.

[mdenker]

@Moritz-Alexander-Kern I think this should also be considered with #567

[Moritz-Alexander-Kern]

Hey @kohlerca ,

I have used the following code example to test out the logging feature:

# 1. Simulate two noise synfire chains, shuffle the neurons to destroy the
#    pattern visually, and store shuffled activations in neo.SpikeTrains.
import logging

import neo
import numpy as np
import quantities as pq
from pprint import pprint
from elephant.asset.asset import logger as asset_logger
from elephant import asset

asset_logger.setLevel(logging.DEBUG)
verbosity=True

np.random.seed(10)
spiketrain = np.linspace(0, 50, num=10)
np.random.shuffle(spiketrain)
spiketrains = np.c_[spiketrain, spiketrain + 100]
spiketrains += np.random.random_sample(spiketrains.shape) * 5
spiketrains = [neo.SpikeTrain(st, units='ms', t_stop=1 * pq.s)
                for st in spiketrains]
# 2. Create `ASSET` class object that holds spike trains.
# `ASSET` requires at least one argument - a list of spike trains. If
# `spiketrains_y` is not provided, the same spike trains are used to build an
# intersection matrix with.
asset_obj = asset.ASSET(spiketrains, bin_size=3*pq.ms, verbose=verbosity)
# 3. Build the intersection matrix `imat`:
imat = asset_obj.intersection_matrix()
# 4. Estimate the probability matrix `pmat`, using the analytical method:
pmat = asset_obj.probability_matrix_analytical(imat, kernel_width=50*pq.ms)
# 5. Compute the joint probability matrix `jmat`, using a suitable filter:
jmat = asset_obj.joint_probability_matrix(pmat, filter_shape=(5, 1), n_largest=3)
# 6. Create the masked version of the intersection matrix, `mmat`, from `pmat`
#    and `jmat`:
mmat = asset_obj.mask_matrices([pmat, jmat], thresholds=.9)
# 7. Cluster significant elements of imat into diagonal structures:
cmat = asset_obj.cluster_matrix_entries(mmat, max_distance=11, min_neighbors=3, stretch=5)
# 9. Extract sequences of synchronous events:
sses = asset_obj.extract_synchronous_events(cmat)
# The ASSET found the following sequences of synchronous events:
pprint(sses)

The code snippet demonstrates the usage of logging messages with either the logger.setLevel() or the verbose parameter as input to asset.

Playing around with both the log level and the verbose parameter simultaneously, it seems to me, the current implementation introduces unnecessary complexity and even potential confusion (?).

Maybe we can remove the verbose parameter, since the messages are now controlled by the loglevel? Or use verbose to set the loglevel? Any advice?

Ideas welcome, lets develop this approach. 🙂
See also: #571

[kohlerca]

For the output control, in my opinion, everything should be controlled by the logger object. I kept the verbose parameter as this is already present, but I have no objection to removing it.

For verbose, there are some considerations:

• first, logging always has a slight performance cost. When you call the API function, you exit the current scope, the logging function checks the current log level to make the decision on outputting or not, and then the function returns to the original scope. Therefore using a simple flag would avoid this, as logging would not be attempted. I don't think this performance cost is a problem here, and I agree that this creates confusion as the control on the existence/absence of output in the module would be removed from logging.

• the other use of verbose is to control the progress bars, as they are switched off when it is False. But I guess we could take the logging INFO level or higher and use it to control their display (a brief note in the ASSET class would be enough for the user).

• the last issue is a breaking change of removing the parameter. Currently, the code is expected to have the parameter present in the function calls when the user wants detailed output (as default is False). But we could put a deprecation filter that would advise using logging from now on, and avoid breaking the execution of legacy code. I would not attempt to use verbose to change any status of the logger, as this would have undesired effects. Then I would rather infer verbose as True or False based on a given level set for the logger.

[Moritz-Alexander-Kern]

build wheels

[mdenker]

The parameter is still there, so it should be listed as a deprecated non-functional parameter, also indicating how functionality is now handled.

[mdenker]

Maybe:

    verbose : deprecated
        This parameter is no longer functional. To control the verbosity of log messages, please use the module's logger that is based on the standard logging module. Logging is turned on by default (to level INFO). To restrict logging messages, use a higher logging level to WARNING or ERROR, e.g.,
            
            import logging
            from elephant.asset.asset import logger as asset_logger
            asset_logger.set_level(logging.WARNING)

[kohlerca]

This is a good suggestion. I believe there is a directive for Sphinx so that the deprecation is visible.

.. deprecated:: 0.14.0
        This parameter is no longer .....

[Moritz-Alexander-Kern]

Added deprecation, see: bdeb5e6

[mdenker]

Shouldn't this be info?

Suggested change

	logger.debug("Finding transactions")
	logger.info("Finding transactions")

[kohlerca]

I remember adding this to be able to check if the extraction was working, as it can take a long time and one may suspect everything hung. But looking in more detail now, perhaps the best is to put logger.info calls in the main extract_synchronous_events method, as this may be called twice if spiketrains_j was passed, and the logging would be weird with two identical messages. This way, we could have explicit logging information messages for each list of spike trains being processed.

[Moritz-Alexander-Kern]

Changed logging level to INFO and move logging call to extract_synchronous_events function, see: 3f5211a

[pep8speaks]

Hello @kohlerca! Thanks for updating this PR. We checked the lines you've touched for PEP 8 issues, and found:

There are currently no PEP 8 issues detected in this Pull Request. Cheers! 🍻

Comment last updated at 2023-10-27 09:48:05 UTC