Logging on Multi Model Server

In this document we will go through logging mechanism in Multi Model Server. We will also go over how to modify the behavior of logging in model-server. Logging in Multi Model Server also covers metrics, as metrics are logged into a file. To further understand how to customize metrics or define custom logging layouts, refer to the metrics document

Pre-requisites

Before getting into this tutorials, you must familiarize yourself with log4j2 configuration. Refer to this online document on how to configure the log4j2 parameters. Similarly, familiarize yourself with the default log4j2.xml used by Multi Model Server.

Types of logs

Multi Model Server currently provides three types of logs.

1. Access Logs.
2. Model Server Logs.

Access Logs:

These logs collect the access pattern to Multi Model Server. The configuration pertaining to access logs are as follows,

        <RollingFile
                name="access_log"
                fileName="${env:LOG_LOCATION:-logs}/access_log.log"
                filePattern="${env:LOG_LOCATION:-logs}/access_log.%d{dd-MMM}.log.gz">
            <PatternLayout pattern="%d{ISO8601} - %m%n"/>
            <Policies>
                <SizeBasedTriggeringPolicy size="100 MB"/>
                <TimeBasedTriggeringPolicy/>
            </Policies>
            <DefaultRolloverStrategy max="5"/>
        </RollingFile>

As defined in the properties file, the access logs are collected in {LOG_LOCATION}/access_log.log file. When we load the model server with a model and run inference against the server, the following logs are collected into the access_log.log

2018-10-15 13:56:18,976 [INFO ] BackendWorker-9000 ACCESS_LOG - /127.0.0.1:64003 "POST /predictions/resnet-18 HTTP/1.1" 200 118

The above log tells us that a successful POST call to /predictions/resnet-18 was made by remote host 127.0.0.1:64003 it took 118ms to complete this request.

These logs are useful to determine the current performance of the model-server as well as understand the requests received by model-server.

Model Server Logs

These logs collect all the logs from Model Server and from the backend workers (the custom model code). The default configuration pertaining to mms logs are as follows:

        <RollingFile
                name="mms_log"
                fileName="${env:LOG_LOCATION:-logs}/mms_log.log"
                filePattern="${env:LOG_LOCATION:-logs}/mms_log.%d{dd-MMM}.log.gz">
            <PatternLayout pattern="%d{ISO8601} [%-5p] %t %c - %m%n"/>
            <Policies>
                <SizeBasedTriggeringPolicy size="100 MB"/>
                <TimeBasedTriggeringPolicy/>
            </Policies>
            <DefaultRolloverStrategy max="5"/>
        </RollingFile>

This configuration by default dumps all the logs above DEBUG level.

Generating and logging custom logs

As a user of Multi Model Server(MMS), you might want to log custom logs into the log files. This could be for debug purposes or to log any errors. To accomplish this, simply print the required logs to stdout/stderr. MMS will capture the logs generated by the backend workers and log it into the log file. Some examples of logs are as follows

1. Messages printed to stderr

   2018-10-14 16:46:51,656 [WARN ] W-9000-stderr com.amazonaws.ml.mms.wlm.WorkerLifeCycle - [16:46:51] src/nnvm/legacy_json_util.cc:209: Loading symbol saved by previous version v0.8.0. Attempting to upgrad\
   e...
   2018-10-14 16:46:51,657 [WARN ] W-9000-stderr com.amazonaws.ml.mms.wlm.WorkerLifeCycle - [16:46:51] src/nnvm/legacy_json_util.cc:217: Symbol successfully upgraded!
   

2. Messages printed to stdout

   2018-10-14 16:59:59,926 [INFO ] W-9000-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - preprocess time: 3.60
   2018-10-14 16:59:59,926 [INFO ] W-9000-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - inference time: 117.31
   2018-10-14 16:59:59,926 [INFO ] W-9000-stdout com.amazonaws.ml.mms.wlm.WorkerLifeCycle - postprocess time: 8.52
   

Modifying the behavior of the logs

In order to modify the default behavior of the logging, you could define log4j2.xml file. There are two ways of starting model server with custom logs

Provide with config.properties

Once you define custom log4j2.xml, add this to the config.properties file as follows

vmargs=-Dlog4j.configurationFile=file:///path/to/custom/log4j2.xml

Then start the model server as follows

$ multi-model-server --start --mms-config /path/to/config.properties

Provide with CLI

Alternatively, you could start the model server with the following command as well

$ multi-model-server --start --log-config /path/to/custom/log4j2.xml

Enable asynchronous logging

If your model is super lightweight and seeking for high throughput, you can consider enable asynchronous logging. Note that log output maybe delayed and latest log might be lost if MMS is terminated unexpectedly. asynchronous logging is disabled by default. To enable asynchronous logging, add following property in config.properties:

async_logging=true