URL: https://github.com/freeipa/freeipa/pull/5634
Author: antoniotorresm
Title: #5634: Extend logging to include execution time
Action: opened
PR body:
"""
Adding execution time in logs provides useful information
for identifying API operations that impact IPA performance.
Signed-off-by: Antonio Torres <antor...@redhat.com>
"""
To pull the PR as Git branch:
git remote add ghfreeipa https://github.com/freeipa/freeipa
git fetch ghfreeipa pull/5634/head:pr5634
git checkout pr5634
From 4b8929ba0d7f56d2d3194e7478b8d6589a0bc3c8 Mon Sep 17 00:00:00 2001
From: Antonio Torres <antor...@redhat.com>
Date: Thu, 11 Mar 2021 17:43:10 +0100
Subject: [PATCH] Extend logging to include execution time
Adding execution time in logs provides useful information
for identifying API operations that impact IPA performance.
Signed-off-by: Antonio Torres <antor...@redhat.com>
---
ipaserver/rpcserver.py | 12 ++++++++++--
1 file changed, 10 insertions(+), 2 deletions(-)
diff --git a/ipaserver/rpcserver.py b/ipaserver/rpcserver.py
index ed775170e48..19b1620953d 100644
--- a/ipaserver/rpcserver.py
+++ b/ipaserver/rpcserver.py
@@ -28,6 +28,7 @@
import logging
from xml.sax.saxutils import escape
import os
+import time
import traceback
from io import BytesIO
from urllib.parse import parse_qs
@@ -368,12 +369,15 @@ def wsgi_execute(self, environ):
args = ()
options = {}
command = None
+ time_start = None
+ time_end = None
e = None
if 'HTTP_REFERER' not in environ:
return self.marshal(result, RefererError(referer='missing'), _id)
if not environ['HTTP_REFERER'].startswith('https://%s/ipa' % self.api.env.host) and not self.env.in_tree:
return self.marshal(result, RefererError(referer=environ['HTTP_REFERER']), _id)
+ time_start = time.perf_counter()
try:
if ('HTTP_ACCEPT_LANGUAGE' in environ):
lang_reg_w_q = environ['HTTP_ACCEPT_LANGUAGE'].split(',')[0]
@@ -414,6 +418,7 @@ def wsgi_execute(self, environ):
try:
params = command.args_options_2_params(*args, **options)
except Exception as e:
+ time_end = time.perf_counter()
logger.info(
'exception %s caught when converting options: %s',
e.__class__.__name__, str(e)
@@ -421,16 +426,19 @@ def wsgi_execute(self, environ):
# get at least some context of what is going on
params = options
error = e
+ else:
+ time_end = time.perf_counter()
if error:
result_string = type(error).__name__
else:
result_string = 'SUCCESS'
- logger.info('[%s] %s: %s(%s): %s',
+ logger.info('[%s] %s: %s(%s): %s %s',
type(self).__name__,
principal,
name,
', '.join(command._repr_iter(**params)),
- result_string)
+ result_string,
+ str(time_end - time_start))
else:
logger.info('[%s] %s: %s: %s',
type(self).__name__,
_______________________________________________
FreeIPA-devel mailing list -- freeipa-devel@lists.fedorahosted.org
To unsubscribe send an email to freeipa-devel-le...@lists.fedorahosted.org
Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives:
https://lists.fedorahosted.org/archives/list/freeipa-devel@lists.fedorahosted.org
Do not reply to spam on the list, report it:
https://pagure.io/fedora-infrastructure
