On 07/24/2012 12:03 PM, Stephen Ingram wrote:
On Mon, Jul 23, 2012 at 11:25 AM, John Dennis <jden...@redhat.com> wrote:
On 07/23/2012 12:37 PM, John Dennis wrote:
Note the timestamps only have 1 second resolution, something
which would be easy to fix, so bear that in mind when looking at the
output of the script.
This is partially as a note to myself, but also to others who want to test.
The following patch should produce timestamps in the debug output with
microsecond resolution.
No one seems to be jumping in on this. Should I run the test again
with this patch? I'm really interested in getting this resolved as I
can't help but think others are experiencing the same problem. I do
have a user in the system that is scheduled for deletion. Would it
help for you to grab a ticket with those credentials so you could
actually see the slowness in action?
It would be good to re-run your test with better timing information.
Attached is a patch that adds more timing information to the debug log
output. Please apply the patch and re-run your test the same way you did
before and email me the contents of /var/log/httpd/error_log. In the
error_log you should see lines with "elapsed_time=xxxx", e.g.
INFO: ad...@xxx.xxx.xxx.xxx.xx: batch(({'params': ((), {}), 'method':
'ping'},)): SUCCESS elapsed_time=0.001663
To apply the patch you'll need to be root to modify the files, this
should work:
% su
% cd /usr/lib/python2.7/site-packages
% patch -p1 -b < path_to_saved_patch_file
If you don't have patch installed:
% sudo yum install patch
Then restart httpd and re-run the test.
--
John Dennis <jden...@redhat.com>
Looking to carve out IT costs?
www.redhat.com/carveoutcosts/
diff --git a/ipalib/session.py b/ipalib/session.py
index 4b783bb..1cff222 100644
--- a/ipalib/session.py
+++ b/ipalib/session.py
@@ -628,9 +628,9 @@ mod_auth_kerb. Everything else remains the same.
default_max_session_duration = 60*60 # number of seconds
-ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S' # FIXME jrd, this should be defined elsewhere
+ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S.%f' # FIXME jrd, this should be defined elsewhere
def fmt_time(timestamp):
- return time.strftime(ISO8601_DATETIME_FMT, time.localtime(timestamp))
+ return datetime.fromtimestamp(timestamp).strftime(ISO8601_DATETIME_FMT)
#-------------------------------------------------------------------------------
diff --git a/ipaserver/plugins/ldap2.py b/ipaserver/plugins/ldap2.py
index 6a3d216..c615a7d 100644
--- a/ipaserver/plugins/ldap2.py
+++ b/ipaserver/plugins/ldap2.py
@@ -715,6 +715,7 @@ class ldap2(CrudBackend, Encoder):
attrs_list = list(set(attrs_list))
# pass arguments to python-ldap
+ start_time = time.time()
try:
id = self.conn.search_ext(
base_dn, scope, filter, attrs_list, timeout=time_limit,
@@ -733,6 +734,9 @@ class ldap2(CrudBackend, Encoder):
except _ldap.LDAPError, e:
_handle_errors(e)
+ end_time = time.time()
+ root_logger.debug('ldap2 find_entries: elapsed_time=%f', end_time-start_time)
+
if not res and not truncated:
raise errors.NotFound(reason='no such entry')
@@ -1363,4 +1367,3 @@ class ldap2(CrudBackend, Encoder):
return (len(output), output)
api.register(ldap2)
-
diff --git a/ipaserver/rpcserver.py b/ipaserver/rpcserver.py
index c770290..d290276 100644
--- a/ipaserver/rpcserver.py
+++ b/ipaserver/rpcserver.py
@@ -305,6 +305,7 @@ class WSGIExecutioner(Executioner):
args = ()
options = {}
+ start_time = time.time()
if not 'HTTP_REFERER' 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:
@@ -349,10 +350,11 @@ class WSGIExecutioner(Executioner):
# get at least some context of what is going on
params = options
principal = getattr(context, 'principal', 'UNKNOWN')
+ end_time = time.time()
if error:
self.info('%s: %s(%s): %s', principal, name, ', '.join(self.Command[name]._repr_iter(**params)), e.__class__.__name__)
else:
- self.info('%s: %s(%s): SUCCESS', principal, name, ', '.join(self.Command[name]._repr_iter(**params)))
+ self.info('%s: %s(%s): SUCCESS elapsed_time=%f', principal, name, ', '.join(self.Command[name]._repr_iter(**params)), end_time-start_time)
else:
self.info('%s: %s', context.principal, e.__class__.__name__)
return self.marshal(result, error, _id)
@@ -791,6 +793,7 @@ class jsonserver_session(jsonserver, KerberosSession):
'''
'''
+ start_time = time.time()
self.debug('WSGI jsonserver_session.__call__:')
# Load the session data
@@ -852,6 +855,8 @@ class jsonserver_session(jsonserver, KerberosSession):
session_mgr.store_session_data(session_data)
destroy_context()
+ end_time = time.time()
+ self.debug('WSGI jsonserver_session.__call__: elapsed_time=%f', end_time-start_time)
return response
class jsonserver_kerb(jsonserver):
_______________________________________________
Freeipa-devel mailing list
Freeipa-devel@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-devel
