diff --git a/configs/gunicorn_config.py b/configs/gunicorn_config.py --- a/configs/gunicorn_config.py +++ b/configs/gunicorn_config.py @@ -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) diff --git a/rhodecode/api/views/search_api.py b/rhodecode/api/views/search_api.py --- a/rhodecode/api/views/search_api.py +++ b/rhodecode/api/views/search_api.py @@ -101,7 +101,7 @@ def search(request, apiuser, search_quer 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: diff --git a/rhodecode/apps/repository/views/repo_feed.py b/rhodecode/apps/repository/views/repo_feed.py --- a/rhodecode/apps/repository/views/repo_feed.py +++ b/rhodecode/apps/repository/views/repo_feed.py @@ -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 diff --git a/rhodecode/apps/repository/views/repo_summary.py b/rhodecode/apps/repository/views/repo_summary.py --- a/rhodecode/apps/repository/views/repo_summary.py +++ b/rhodecode/apps/repository/views/repo_summary.py @@ -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 diff --git a/rhodecode/apps/search/views.py b/rhodecode/apps/search/views.py --- a/rhodecode/apps/search/views.py +++ b/rhodecode/apps/search/views.py @@ -88,7 +88,7 @@ def perform_search(request, tmpl_context 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: diff --git a/rhodecode/authentication/base.py b/rhodecode/authentication/base.py --- a/rhodecode/authentication/base.py +++ b/rhodecode/authentication/base.py @@ -762,7 +762,7 @@ def authenticate(username, password, env 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) diff --git a/rhodecode/lib/auth.py b/rhodecode/lib/auth.py --- a/rhodecode/lib/auth.py +++ b/rhodecode/lib/auth.py @@ -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 diff --git a/rhodecode/lib/dbmigrate/schema/db_4_16_0_0.py b/rhodecode/lib/dbmigrate/schema/db_4_16_0_0.py --- a/rhodecode/lib/dbmigrate/schema/db_4_16_0_0.py +++ b/rhodecode/lib/dbmigrate/schema/db_4_16_0_0.py @@ -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): diff --git a/rhodecode/lib/dbmigrate/schema/db_4_16_0_1.py b/rhodecode/lib/dbmigrate/schema/db_4_16_0_1.py --- a/rhodecode/lib/dbmigrate/schema/db_4_16_0_1.py +++ b/rhodecode/lib/dbmigrate/schema/db_4_16_0_1.py @@ -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): diff --git a/rhodecode/lib/dbmigrate/schema/db_4_16_0_2.py b/rhodecode/lib/dbmigrate/schema/db_4_16_0_2.py --- a/rhodecode/lib/dbmigrate/schema/db_4_16_0_2.py +++ b/rhodecode/lib/dbmigrate/schema/db_4_16_0_2.py @@ -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): diff --git a/rhodecode/lib/diffs.py b/rhodecode/lib/diffs.py --- a/rhodecode/lib/diffs.py +++ b/rhodecode/lib/diffs.py @@ -1178,7 +1178,7 @@ def cache_diff(cached_diff_file, diff, c 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 diff --git a/rhodecode/lib/middleware/request_wrapper.py b/rhodecode/lib/middleware/request_wrapper.py --- a/rhodecode/lib/middleware/request_wrapper.py +++ b/rhodecode/lib/middleware/request_wrapper.py @@ -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) diff --git a/rhodecode/lib/middleware/simplevcs.py b/rhodecode/lib/middleware/simplevcs.py --- a/rhodecode/lib/middleware/simplevcs.py +++ b/rhodecode/lib/middleware/simplevcs.py @@ -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) diff --git a/rhodecode/lib/rc_cache/utils.py b/rhodecode/lib/rc_cache/utils.py --- a/rhodecode/lib/rc_cache/utils.py +++ b/rhodecode/lib/rc_cache/utils.py @@ -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): diff --git a/rhodecode/lib/vcs/backends/git/commit.py b/rhodecode/lib/vcs/backends/git/commit.py --- a/rhodecode/lib/vcs/backends/git/commit.py +++ b/rhodecode/lib/vcs/backends/git/commit.py @@ -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]) diff --git a/rhodecode/lib/vcs/client_http.py b/rhodecode/lib/vcs/client_http.py --- a/rhodecode/lib/vcs/client_http.py +++ b/rhodecode/lib/vcs/client_http.py @@ -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 diff --git a/rhodecode/model/db.py b/rhodecode/model/db.py --- a/rhodecode/model/db.py +++ b/rhodecode/model/db.py @@ -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): diff --git a/rhodecode/model/settings.py b/rhodecode/model/settings.py --- a/rhodecode/model/settings.py +++ b/rhodecode/model/settings.py @@ -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 diff --git a/rhodecode/tests/load/time_urls.py b/rhodecode/tests/load/time_urls.py --- a/rhodecode/tests/load/time_urls.py +++ b/rhodecode/tests/load/time_urls.py @@ -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))) diff --git a/rhodecode/tests/scripts/test_concurency.py b/rhodecode/tests/scripts/test_concurency.py --- a/rhodecode/tests/scripts/test_concurency.py +++ b/rhodecode/tests/scripts/test_concurency.py @@ -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)