engineering/unrhodecode
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

core: added more accurate time measurement for called functions

Browse source
This commit is contained in:
Marcin Kuzminski 2019-07-17 16:28:41 +02:00
parent bc3efc1553
commit 928652312a
20 changed files with 25 additions and 23 deletions
Download patch file Download diff file Expand all files Collapse all files

2
configs/gunicorn_config.py
View file

@ -130,7 +130,7 @@ def pre_request(worker, req):
def post_request(worker, req, environ, resp):
total_time = time.time() - worker.start_time
worker.log.debug(
"GNCRN POST WORKER [cnt:%s]: %s %s resp: %s, Load Time: %.3fs",
"GNCRN POST WORKER [cnt:%s]: %s %s resp: %s, Load Time: %.4fs",
worker.nr, req.method, req.path, resp.status_code, total_time)

2
rhodecode/api/views/search_api.py
View file

@ -101,7 +101,7 @@ def search(request, apiuser, search_query, search_type, page_limit=Optional(10),
searcher.cleanup()
if not search_result['error']:
data['execution_time'] = '%s results (%.3f seconds)' % (
data['execution_time'] = '%s results (%.4f seconds)' % (
search_result['count'],
search_result['runtime'])
else:

4
rhodecode/apps/repository/views/repo_feed.py
View file

@ -169,7 +169,7 @@ class RepoFeedView(RepoAppView):
else:
mime_type, feed = generate_atom_feed(*args)
log.debug('Repo ATOM feed computed in %.3fs',
log.debug('Repo ATOM feed computed in %.4fs',
inv_context_manager.compute_time)
response = Response(feed)
@ -235,7 +235,7 @@ class RepoFeedView(RepoAppView):
else:
mime_type, feed = generate_rss_feed(*args)
log.debug(
'Repo RSS feed computed in %.3fs', inv_context_manager.compute_time)
'Repo RSS feed computed in %.4fs', inv_context_manager.compute_time)
response = Response(feed)
response.content_type = mime_type

2
rhodecode/apps/repository/views/repo_summary.py
View file

@ -98,7 +98,7 @@ class RepoSummaryView(RepoAppView):
instance = generate_repo_readme(*args)
log.debug(
'Repo readme generated and computed in %.3fs',
'Repo readme generated and computed in %.4fs',
inv_context_manager.compute_time)
return instance

2
rhodecode/apps/search/views.py
View file

@ -88,7 +88,7 @@ def perform_search(request, tmpl_context, repo_name=None, repo_group_name=None):
search_tags = searcher.extract_search_tags(search_query)
if not search_result['error']:
execution_time = '%s results (%.3f seconds)' % (
execution_time = '%s results (%.4f seconds)' % (
search_result['count'],
search_result['runtime'])
elif not errors:

2
rhodecode/authentication/base.py
View file

@ -762,7 +762,7 @@ def authenticate(username, password, environ=None, auth_type=None,
plugin_user = compute_auth('auth', plugin.name, username, (password or ''))
auth_time = time.time() - start
log.debug('Authentication for plugin `%s` completed in %.3fs, '
log.debug('Authentication for plugin `%s` completed in %.4fs, '
'expiration time of fetched cache %.1fs.',
plugin.get_id(), auth_time, cache_ttl)

2
rhodecode/lib/auth.py
View file

@ -1233,7 +1233,7 @@ class AuthUser(object):
for k in result:
result_repr.append((k, len(result[k])))
total = time.time() - start
log.debug('PERMISSION tree for user %s computed in %.3fs: %s',
log.debug('PERMISSION tree for user %s computed in %.4fs: %s',
user, total, result_repr)
return result

2
rhodecode/lib/dbmigrate/schema/db_4_16_0_0.py
View file

@ -2402,7 +2402,7 @@ class Repository(Base, BaseModel):
instance = get_instance_cached(*args)
log.debug(
'Repo instance fetched in %.3fs', inv_context_manager.compute_time)
'Repo instance fetched in %.4fs', inv_context_manager.compute_time)
return instance
def _get_instance(self, cache=True, config=None):

2
rhodecode/lib/dbmigrate/schema/db_4_16_0_1.py
View file

@ -2425,7 +2425,7 @@ class Repository(Base, BaseModel):
instance = get_instance_cached(*args)
log.debug(
'Repo instance fetched in %.3fs', inv_context_manager.compute_time)
'Repo instance fetched in %.4fs', inv_context_manager.compute_time)
return instance
def _get_instance(self, cache=True, config=None):

2
rhodecode/lib/dbmigrate/schema/db_4_16_0_2.py
View file

@ -2425,7 +2425,7 @@ class Repository(Base, BaseModel):
instance = get_instance_cached(*args)
log.debug(
'Repo instance fetched in %.3fs', inv_context_manager.compute_time)
'Repo instance fetched in %.4fs', inv_context_manager.compute_time)
return instance
def _get_instance(self, cache=True, config=None):

4
rhodecode/lib/diffs.py
View file

@ -1178,7 +1178,7 @@ def cache_diff(cached_diff_file, diff, commits):
log.warn('Failed to save cache', exc_info=True)
_cleanup_cache_file(cached_diff_file)
log.debug('Saved diff cache under %s in %.3fs', cached_diff_file, time.time() - start)
log.debug('Saved diff cache under %s in %.4fs', cached_diff_file, time.time() - start)
def load_cached_diff(cached_diff_file):
@ -1221,7 +1221,7 @@ def load_cached_diff(cached_diff_file):
_cleanup_cache_file(cached_diff_file)
return default_struct
log.debug('Loaded diff cache from %s in %.3fs', cached_diff_file, time.time() - start)
log.debug('Loaded diff cache from %s in %.4fs', cached_diff_file, time.time() - start)
return data

2
rhodecode/lib/middleware/request_wrapper.py
View file

@ -45,7 +45,7 @@ class RequestWrapperTween(object):
end = time.time()
total = end - start
log.info(
'IP: %s %s Request to %s time: %.3fs [%s]',
'IP: %s %s Request to %s time: %.4fs [%s]',
get_ip_addr(request.environ), request.environ.get('REQUEST_METHOD'),
safe_str(get_access_path(request.environ)), total,
get_user_agent(request. environ)

2
rhodecode/lib/middleware/simplevcs.py
View file

@ -354,7 +354,7 @@ class SimpleVCS(object):
'vcs_permissions', plugin_id, action, user.user_id, repo_name, ip_addr)
auth_time = time.time() - start
log.debug('Permissions for plugin `%s` completed in %.3fs, '
log.debug('Permissions for plugin `%s` completed in %.4fs, '
'expiration time of fetched cache %.1fs.',
plugin_id, auth_time, cache_ttl)

5
rhodecode/lib/rc_cache/utils.py
View file

@ -251,7 +251,7 @@ class InvalidationContext(object):
result = heavy_compute(*args)
compute_time = inv_context_manager.compute_time
log.debug('result computed in %.3fs', compute_time)
log.debug('result computed in %.4fs', compute_time)
# To send global invalidation signal, simply run
CacheKey.set_invalidate(invalidation_namespace)
@ -289,7 +289,8 @@ class InvalidationContext(object):
log.debug('Fetched cache obj %s using %s cache key.', cache_obj, self.cache_key)
invalidation_namespace = invalidation_namespace or self.invalidation_namespace
if not cache_obj:
cache_obj = CacheKey(self.cache_key, cache_args=invalidation_namespace)
new_cache_args = invalidation_namespace
cache_obj = CacheKey(self.cache_key, cache_args=new_cache_args)
return cache_obj
def __enter__(self):

3
rhodecode/lib/vcs/backends/git/commit.py
View file

@ -158,7 +158,8 @@ class GitCommit(base.BaseCommit):
@LazyProperty
def branch(self):
branches = safe_unicode(self._remote.branch(self.raw_id))
branches = self._remote.branch(self.raw_id)
if branches:
# actually commit can have multiple branches in git
return safe_unicode(branches[0])

2
rhodecode/lib/vcs/client_http.py
View file

@ -154,7 +154,7 @@ class RemoteRepo(object):
self.url, name, args, context_uid)
result = _remote_call(self.url, payload, EXCEPTIONS_MAP, self._session)
if self._call_with_logging:
log.debug('Call %s@%s took: %.3fs. wire_context: %s',
log.debug('Call %s@%s took: %.4fs. wire_context: %s',
self.url, name, time.time()-start, context_uid)
return result

2
rhodecode/model/db.py
View file

@ -2481,7 +2481,7 @@ class Repository(Base, BaseModel):
else:
instance = get_instance_cached(*args)
log.debug('Repo instance fetched in %.3fs', inv_context_manager.compute_time)
log.debug('Repo instance fetched in %.4fs', inv_context_manager.compute_time)
return instance
def _get_instance(self, cache=True, config=None, repo_state_uid=None):

2
rhodecode/model/settings.py
View file

@ -242,7 +242,7 @@ class SettingsModel(BaseModel):
region.invalidate()
result = _get_all_settings('rhodecode_settings', key)
log.debug('Fetching app settings for key: %s took: %.3fs', key,
log.debug('Fetching app settings for key: %s took: %.4fs', key,
inv_context_manager.compute_time)
return result

2
rhodecode/tests/load/time_urls.py
View file

@ -43,7 +43,7 @@ def main(server, repeat, pages):
t = timeit.Timer(stmt=stmt, setup="import requests")
result = t.repeat(repeat=repeat, number=1)
print(" %.3f (min) - %.3f (max) - %.3f (avg)\n" %
print(" %.4f (min) - %.4f (max) - %.4f (avg)\n" %
(min(result), max(result), sum(result) / len(result)))

2
rhodecode/tests/scripts/test_concurency.py
View file

@ -198,6 +198,6 @@ if __name__ == '__main__':
print('take {}'.format(i))
test_clone_with_credentials(repo=sys.argv[1], method=METHOD,
seq=seq, backend=backend)
print('time taken %.3f' % (time.time() - s))
print('time taken %.4f' % (time.time() - s))
except Exception as e:
sys.exit('stop on %s' % e)