How to record the time spent in the sanic request

[dalianzhu]

The time spend on each visit is recorded in tornado, like this:

200 GET /new4/session?1499139673177 ... 2.57ms

Can sanic do it with an efficient way? Thanks for your help.

[yunstanford]

Are you talking about the lat ?

[lixxu]

Sanic seems not provide this feature, you may need use middleware to do it. like this:

@app.middleware('request')
async def add_start_time(request):
    request['start_time'] = datetime.now()

@app.middleware('response')
async def add_spent_time(request, response):
    request['spent_time'] = datetime.now() - request['start_time']

[dalianzhu]

@yunstanford sorry, i dont know what lat is.

[dalianzhu]

@lixxu Yes, it works.Thanks a lot.

[yunstanford]

lat stands for latency, i think it's roughly describing what you wanna. If you are using gunicorn, you can get that from access log for free. You may also get that from your reverse proxy layer if you have one.

[dalianzhu]

@yunstanford yes, i can get the access log from my nginx, and @lixxu 's idea can also solve my issue.I just want to use this data to simply measure the performance of a handler.

[victorandree]

Can I re-open this issue? I want to log latency as part of my access logs, but doesn't seem like I can right now because:

1. It doesn't seem like the Gunicorn worker does access logging -- I have tried a number of logging configurations and Gunicorn remains silent. The built-in Gunicorn workers all contain calls to self.log.access which are missing from sanic.worker.GunicornWorker so I'm not sure if we get it for free that way (@yunstanford ?)
2. There is no straightforward way to override the log call in sanic.server.HttpProtocol.log_response in order to add additional fields (for example, request['spent_time']

It doesn't seem entirely straightforward to add response time taken to just the worker, as its response handling is dealt with elsewhere...

[dalianzhu]

@victorandree sanic does not seem to have the default configuration. i have to use logging in the response middleware like:

@app.middleware('request')
async def add_start_time(request):
    request['start_time'] = time.time()

@app.middleware('response')
async def add_spent_time(request, response):
    spend_time = round((time.time() - request['start_time']) * 1000)
    logging.info("{} {} {} {} {}ms".format(response.status, request.method,
                                           request.path, request.query_string, spend_time))

The daily visit of this project is about 10 million, it seems no problem. because of i am not use gunicorn, I can not give any other help. you can reopen it if you think it is necessary.

[junyeong-huray]

Based on the solution of @dalianzhu, I added some extra fields to support default access log fields. I referred to sanic.http.Http.log_response.

@app.middleware('request')
async def add_start_time(request):
    """Add start time."""
    request.ctx.start_time = time.perf_counter()

@app.middleware('response')
async def write_access_log(request, response):
    """Log access log."""
    spent_time = round((time.perf_counter() - request.ctx.start_time) * 1000)
    remote = f'{request.remote_addr or request.ip}:{request.port}'
    # response.body is bytes or None
    print(response.body)
    if response.body:
        body_byte = len(response.body)
    else:
        body_byte = 0
    logger.info('%s %s %s %d %dB %dms', remote, request.method, request.url,
                response.status, body_byte, spent_time)

[Tronic]

Rather than datetime.now() or time.time() as has been suggested in the first replies, the appropriate timer for performance timings is time.perf_counter() used in the last one. Also you shouldn't format with round() but rather via f strings.

start = time.perf_counter()
...
seconds = start - time.perf_counter()
spent_time = f"{1000 * seconds:.0f}ms"