nav[aria-label="Primary Navigation"] { padding: 0; & ul { list-style: none; width: 100%; display: flex; flex-direction: row; justify-content: start; align-items: start; gap: 30px; padding: 0; & li { margin: 0; } & ul li { list-style: none; } } }

logging script performance

clt_cabq

I'd like to add some logging to my scripts that capture how long different processes are taking, are there built in arcpy capabilities for this or is it best to use more general Python tools? Any tips or tricks you all might recommend?

Najděte více příspěvků označených jako

Accepted answers

DeanAnderson2

I am pretty explicit when I do python and I write stuff out to a log file for scheduled jobs. I print results as well as write them to a text file. Is a bit redundant but oh well. Below is the code (I did not include the traceback stuff but that is also pretty easy to add...

Here is the code....

import arcpy,os,time,datetime,traceback

# Log File - makes my log file and records start time

logfile = "C:\\GISLogs\\01APImportAnno.txt"
arcpy.Delete_management (logfile)
logfile = open(logfile, "w")
starttime = datetime.datetime.now()
logfile.write ('\n' + '\n' + "StartTime:" + str(starttime) + '\n' + '\n')
print ("StartTime:" + str(starttime))

CODE GOES HERE

# Time stuff and close of log file

endtime = datetime.datetime.now()
timepassed = endtime - starttime

print ("Run Time: " + str(timepassed))
print ( "Start-End Time: " + str(starttime) + "---" + str(endtime))
logfile.write ('\n' + '\n' + "AnnImport Succesful" + '\n' + '\n' )
logfile.write ('\n' + '\n' + "Run Time: " + str(timepassed) + '\n' + '\n' )
logfile.write ('\n' + '\n' + str(starttime) + "---" + str(endtime))

logfile.close()

All comments

blake.terhune

Certainly more processing is going to impact the run time, but in my experience, this logging has not had a noticeable impact on any scripts. The benefit of logging far outweighs any negatives.

As far as understanding it all, it is a lot to take in, but it's because I have it modularized and in an example with other stuff (a whole task script) for the example. If you look at the docs for the logging module, it can be implemented very simply!

logging — Logging facility for Python — Python 3.11.4 documentation

clt_cabq

this is nice and simple, I like that! Thanks for sharing this approach.

clt_cabq

This is super, thank you for posting, there is quite honestly a fair bit here I don't completely understand but that just gives me something to chew on. Do you think logging can impact the time it takes for your scripts to run?

ThomasHoman

I end up throwing my logging into a function so I can just make calls to logging - writelog('...')

I use the pipe character as a delimiter to I can pull the log into Excel or similar if I need to do analysis. Overhead is probably higher due to recurring file open, write, close cycles but it works for what I'm doing.

#function to write to an archive log to document the process of copying the features
#removed + "\n\r" from write statement to get rid of extra lines
#pipe | used for delmimiter
def writelog(message):
archive_log_path = archives_location + "\ArchiveLog.txt"
timestamp = datetime.datetime.now()
logfile = open(archive_log_path, "a")
logfile.write(str(timestamp) + "|" + message + "\n")
logfile.close()
return

blake.terhune

This is a great topic. Maybe I should create a more formal article for this, but here's what we have started doing. It's a modular approach that utilizes the Python built-in Logging module. The logging module is cool because when you log an exception, it automatically includes the traceback. However, I noticed that the ArcGIS API for Python also uses the logging module, which is why I had to make some custom log levels so my log messages could be filtered out from the Esri ones.

First, we have a helper framework script that all of our scheduled scripts import. To make it easy, this is saved in the same directory as the scripts that use it. In this example, it's named _helperLibrary.py

I've included only two functions: initLogging() and sendEmail()

def initLogging(
    log_level="CUSTOM_INFO", # default to CUSTOM_INFO log level
    filemode="w",
    msg_format="%(asctime)s %(levelname)s at line %(lineno)s in %(funcName)s(): %(message)s\n",
    date_format="%Y-%m-%d %H:%M:%S"
):
    """Creates a standard logging object for use by a requesting script to log information.
    Requires modules are
        import inspect
        from pathlib import Path
        import logging

    Uses some black magic with inspect to get the file name path
    of the origin script that imported and called this.

    for log_level:
        NOTSET (0)
        CUSTOM_DEBUG (5): Custom logging level mimicking DEBUG but slightly lower level so as
            to differentiate from logging produced by the ArcGIS API for Python.
        DEBUG (10): Detailed information, typically of interest only when diagnosing problems.
        INFO (20): Confirmation that things are working as expected.
        CUSTOM_INFO (25): Custom logging level mimicking INFO but slightly higher level so as
            to exclude redundant logging produced by the ArcGIS API for Python.
        WARNING (30): An indication that something unexpected happened, or indicative of some
            problem in the near future (e.g. 'disk space low'). The software is still working as expected.
        ERROR (40): Due to a more serious problem, the software has not been able to perform some function.
        CRITICAL (50): A serious error, indicating that the program itself may be unable to continue running.

    All parameters are optional.

    :param str log_level: Set the root logger level to the specified level.
    :param str filemode: determines the mode in which the log file has to be opened, i.e., read, write, append, etc.
    :param str msg_format: Use the specified format string for the handler.
    :param str date_format: Use the specified date/time format, as accepted by time.strftime().
    :return: logger object
    :rtype: class
    """
    import inspect
    from pathlib import Path
    import logging

    # Define custom CUSTOM_INFO log level.
    # Set log level
    CUSTOM_INFO_LEVEL = 25
    # "Register" new logging level.
    logging.addLevelName(CUSTOM_INFO_LEVEL, "CUSTOM_INFO")
    def custom_info(self, message, *args, **kwargs):
        if self.isEnabledFor(CUSTOM_INFO_LEVEL):
            self._log(CUSTOM_INFO_LEVEL, message, args, **kwargs)
    # Make custom_info() available in the logger.
    logging.Logger.custom_info = custom_info

    # Define custom CUSTOM_DEBUG log level.
    # Set log level
    CUSTOM_DEBUG_LEVEL = 5
    # "Register" new logging level.
    logging.addLevelName(CUSTOM_DEBUG_LEVEL, "CUSTOM_DEBUG")
    def custom_debug(self, message, *args, **kwargs):
        if self.isEnabledFor(CUSTOM_DEBUG_LEVEL):
            self._log(CUSTOM_DEBUG_LEVEL, message, args, **kwargs)
    # Make custom_debug() available in the logger.
    logging.Logger.custom_debug = custom_debug

    # Get file name path of the origin script that imported and called this.
    # Use the last (origin) frame's file name.
    previous_frame = inspect.currentframe().f_back
    origin_file_path = inspect.getframeinfo(previous_frame).filename
    # Set log file name and output folder for the log file.
    log_file_path = Path(origin_file_path).parent / "logs" / f"{Path(origin_file_path).stem}.log"
    Path(log_file_path).parent.mkdir(parents=True, exist_ok=True)
    # Create logging object and return it to the origin script.
    logging.basicConfig(
        filename=log_file_path,
        filemode=filemode,
        level=log_level.upper(),
        format=msg_format,
        datefmt=date_format
    )
    return logging.getLogger(log_file_path.name)


def sendEmail(subject="", body_content="", to=[], cc=[], bcc=[], from_addr="PythonScript@yourdomain.gov"):
    """Send a plain text email. Returns a dictionary of recipients.

    Required imports:
        from email.message import EmailMessage # for a text/plain email message
        import smtplib # for sending email

    :param str subject: Subject line of email.
    :param str body_content: Main message in the body of the email.
    :param list to: A list of email addresses as strings for sending the email to.
    :param list cc: A list of email addresses as strings for CC'ing the email.
    :param list bcc: A list of email addresses as strings for BCC'ing the email.
    :param str from_addr: The email address from which to send the email.
    :return: All email addresses that received the email (to, cc, bcc).
    :rtype: Dictionary
    """
    from email.message import EmailMessage
    import smtplib

    # Validate email recipient args
    for recipient in [to, cc, bcc]:
        if not isinstance(recipient, list):
            raise TypeError(f"Recipients (to, cc, bcc) must each be a list of strings; not {type(recipient)}")
    # Create email message object and content.
    msg = EmailMessage()
    msg.set_content(body_content)
    # Set recipients
    msg["Subject"] = subject
    msg["From"] = from_addr
    msg["To"] = ", ".join(to)
    msg["Cc"] = ", ".join(cc)
    msg["Bcc"] = ", ".join(bcc)
    # Send the message via our own SMTP server.
    with smtplib.SMTP("your.mail.server.here") as smtp:
        smtp.send_message(msg)
    # Confirmation messaging.
    recipients = {"to": to, "cc": cc, "bcc": bcc}
    print(f"sendEmail() successful for recipients {recipients}")
    return recipients

Then this is what a scheduled script might look like. Notice it's importing the _helperLibrary script. this makes initializing the logging very simple.

import _helperLibrary as helper # assumes the py file is in this same directory
import arcpy
import os
from socket import gethostname
from tempfile import TemporaryDirectory

def main():
    #
    # Some example code to demonstrate logging.
    #
    logging.custom_info("Starting description of code block.")
    # Get something from the database. In this case, a list of fields
    logging.custom_debug("Something very specific for CUSTOM_DEBUG")
    logging.debug("Here's a general DEBUG level log message.")
    logging.info("An INFO level log message.")
    logging.custom_info("A CUSTOM_INFO level log message.")
    logging.warning("A sample WARNING message")
    bad_func() # demonstrate getting an error from another function.
    logging.custom_info("Finished description of code block.")


def bad_func():
    try:
        return this_does_not_exist
    except Exception as e:
        raise Exception("Here you can add more context to the error message.") from e


# Script start
if __name__ == "__main__":
    # Initialize file logging.
    logging = helper.initLogging()
    logging.custom_info(f"{os.path.basename(__file__)} started on {gethostname()}")

    # Create basic email subject line with name of script
    email_subject = os.path.basename(__file__)

    try:
        # Run core functions
        with TemporaryDirectory() as temp_dir:
            main()

    except Exception as e:
        print(e)
        logging.exception("An Exception Occurred.")

    finally:
        # Cleanup
        try:
            # Delete the memory workspace (if applicable)
            # https://pro.arcgis.com/en/pro-app/2.9/help/analysis/geoprocessing/basics/the-in-memory-workspace.htm
            arcpy.management.Delete("memory")
            # Ensure the geoprocessor object no longer has any hold on
            # the enterprise geodatabase workspace that has been cleared.
            arcpy.management.ClearWorkspaceCache()
        except Exception as e:
            print(e)
            logging.exception("Error with cleaning up.")
            pass
        # Send log file as email
        try:
            logging.custom_info("Send log file as email.")
            log_file_path = logging.root.handlers[0].baseFilename
            with open(log_file_path) as log_file:
                log_file_content = log_file.read()
                # Build email subject line with noteworthy log levels.
                email_subject = os.path.basename(__file__)
                for log_level in ["WARNING", "ERROR", "CRITICAL"]:
                    if log_level in log_file_content:
                        email_subject = f"[{log_level}] {email_subject}"
                # Send the email.
                recipients = helper.sendEmail(
                    subject=email_subject,
                    body_content=log_file_content,
                    to=["some_recipient@mydomain.gov"]
                )
                logging.custom_info(f"Email sent to {recipients}")
        except Exception as e:
            print(e)
            logging.exception("Error sending email.")
            pass

When everything is finished, the log file is saved in a "logs" subdirectory where the script runs and the contents of the log file is emailed. The log file is overwritten each time the script runs.

clt_cabq

Again, thanks!

DeanAnderson2

The example fits around the entire script but you can use the same concept using python for each step. At the start of the step record your start time:

starttime = datetime.datetime.now()

At the end of the step record your endtime and calc the difference.

endtime = datetime.datetime.now()
timepassed = endtime - starttime

clt_cabq

Thanks Dean, I'll check it out and see how this works for me. Just off the cuff, this looks like it sort of wraps around an entire script.. can it be put in place around different function calls?

DeanAnderson2

Here is the code....

import arcpy,os,time,datetime,traceback

CODE GOES HERE

# Time stuff and close of log file

Připojte se k diskusi

Přihlášení členové mohou přispívat, sledovat aktualizace a další. Jste tu noví? Zaregistrujte si bezplatný účet.

Rychlé odkazy

Community Help
Find useful guides, FAQs, and documents to help you navigate and make the most of Esri Community.