Added log message to the begining and ending of every functions

[Daniel-olaO]

close #838

[ma-sadeghi]

@Daniel-olaO Thanks for the PR. Quick question: why do you use inspect to get function name? That's 2 extra lines of code per function (3 instead of 1), why not just hardcode the function name?

Also, please capitalize "start" and "end" for consistency. I think you also need to add a space between "start of" and function name.

[jgostick]

Hi @ma-sadeghi, I suggested that the inspect module could be used to get the function name. That way if we every change the function name or just cut-paste the code it will be self-healing.

[ma-sadeghi]

Hey @jgostick, I see. What do you think about wrapping the "start" and "end" snippets in two private helpers, and just call them at the start/end of function calls, like _log_enter_func(), and _log_exit_func. There's a way to find the caller name:

import inspect

def caller_function():
    # Get the frame of the caller function
    frame = inspect.currentframe().f_back

    # Get the name of the caller function
    caller_name = frame.f_code.co_name

    return caller_name

def test_function():
    caller = caller_function()
    print("Caller function:", caller)

test_function()

This would get rid of ~300-400 extra lines.

[jgostick]

@Daniel-olaO I appreciate how thorough you were! I didn't realize you were going to be so quick to implement this, and figured we'd have time to discuss and plan a bit.

I think that we should be a bit more judicous with this feature an only put it in the "front-line" functions, and especially those that have the potential to be slow. For instance, anything that starts with an underscore is a hidden function that is called by something else and anything that is @jit or @njit decorated is probably also not going to work with a logger inside. Some for things that involve dask.

Another thought...maybe we could jam all the inspect code into a single line? That would make it harder to read, but easier to maintain. Then we can cut-paste the code to new functions as needed for instance.

[jgostick]

Not to make this overly complicated, but I wonder if this could be done as a decoarator? I know we could do the 'start' but not sure about the 'end'. Like:

@functimer
def function_name(args, kwargs):
    <code here>


def functimer():
   <code here>

I have not really dove into decorators so don't know the ins-and-outs, but this seems like a possibility.

[Daniel-olaO]

Hey @jgostick, thank you for your input. I am considering implementing the solution suggested by @ma-sadeghi as it appears more apparent to me. What do you think about this?

[ma-sadeghi]

@jgostick @Daniel-olaO I found an elegant workaround; the good thing about it is that it leaves all of our functions untouched, and requires a small modification to our modules' __init__.py:

Basically, what we need to do is to write a decorator (as @jgostick suggested) to be added to function entry/exit, and then apply it automatically to all our top-level functions as attribute. I've tested it on generators and it worked like a charm. We only need to add this snippet at the end of our __init__.py files:

import sys
import logging
import functools

logger = logging.getLogger(__name__)

def log_entry_exit(func):
    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        logger.info(f"Entering {func.__name__}")
        result = func(*args, **kwargs)
        logger.info(f"Exiting {func.__name__}")
        return result
    return wrapper

current_module = sys.modules[__name__]
for func_name, func in vars(current_module).copy().items():
    if callable(func):
        setattr(current_module, func_name, log_entry_exit(func))

@jgostick What do you think?

@Daniel-olaO In case we want to move forward, move log_entry_exit to porespy.tools so we don't need to redefine it for every module, then import it from porespy.tools import log_entry_exit.

[jgostick]

@ma-sadeghi, wow that is slick. Will it apply to EVERY function? That could be a problem for functions that are called repeatedly. Do you think this will be a problem, and if so is there any way to specify which functions it can be applied to?

[ma-sadeghi]

@ma-sadeghi, wow that is slick. Will it apply to EVERY function? That could be a problem for functions that are called repeatedly. Do you think this will be a problem, and if so is there any way to specify which functions it can be applied to?

Good point. Currently, it'll apply to every accessible "top level" function within that module, both with or without underscore. I tried it on networks module, and here's the list of functions it gets applied to:

add_boundary_regions
generate_voxel_image
label_phases
label_boundaries
map_to_regions
maximal_ball_wrapper
regions_to_network
snow2
_net_dict
_parse_pad_width
diffusive_size_factor_AI
create_model
find_conns

We could add a check like not func_name.startswith("_"), but there might still be functions without underscore that get called repeatedly (is this the case? If so, maybe it's a sign those should be underscored as well?).

If we want to have more control, we can add a list of functions we want to profile to __init__.py, and add a check inside the for loop: if func_name in func_list. It's a bit manual, but if there's no way to differentiate between "actual top level" functions vs. "helper" ones, this seems to be a good compromise.

[Daniel-olaO]

Hey @ma-sadeghi, and @jgostick I have created the log_entry_exit in the tools module and added the import statement, just a quick question, how about calling the log_entry_exit for each function

[ma-sadeghi]

Hey @ma-sadeghi, and @jgostick I have created the log_entry_exit in the tools module and added the import statement, just a quick question, how about calling the log_entry_exit for each function

Great. You mean adding the decorator to each function? (before function header)

[Daniel-olaO]

oh thanks, work on it

[Daniel-olaO]

Hello everyone, I apologize for creating another PR with the number #839. I had to do this to resolve the logger issue. The reason for this is because I created a new branch from the dev branch to eliminate all the changes I made.