core: added more accurate time measurement for called functions

configs/gunicorn_config.py

@@ -130,7 +130,7 b' 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)
 
 

rhodecode/api/views/search_api.py

@@ -101,7 +101,7 b' 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:

rhodecode/apps/repository/views/repo_feed.py

@@ -169,7 +169,7 b' 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 b' 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

rhodecode/apps/repository/views/repo_summary.py

@@ -98,7 +98,7 b' 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
 

rhodecode/apps/search/views.py

@@ -88,7 +88,7 b' 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:

rhodecode/authentication/base.py

@@ -762,7 +762,7 b' 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)
 

rhodecode/lib/auth.py

@@ -1233,7 +1233,7 b' 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

rhodecode/lib/dbmigrate/schema/db_4_16_0_0.py

@@ -2402,7 +2402,7 b' 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):

rhodecode/lib/dbmigrate/schema/db_4_16_0_1.py

@@ -2425,7 +2425,7 b' 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):

rhodecode/lib/dbmigrate/schema/db_4_16_0_2.py

@@ -2425,7 +2425,7 b' 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):

rhodecode/lib/diffs.py

@@ -1178,7 +1178,7 b' 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 b' 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
 

rhodecode/lib/middleware/request_wrapper.py

@@ -45,7 +45,7 b' 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)

rhodecode/lib/middleware/simplevcs.py

@@ -354,7 +354,7 b' 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)
 

rhodecode/lib/rc_cache/utils.py

@@ -251,7 +251,7 b' 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 b' 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):

rhodecode/lib/vcs/backends/git/commit.py

@@ -158,7 +158,8 b' 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])

rhodecode/lib/vcs/client_http.py

@@ -154,7 +154,7 b' 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
 

rhodecode/model/db.py

@@ -2481,7 +2481,7 b' 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):

rhodecode/model/settings.py

@@ -242,7 +242,7 b' 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

rhodecode/tests/load/time_urls.py

@@ -43,7 +43,7 b' 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)))
 
 

rhodecode/tests/scripts/test_concurency.py

@@ -198,6 +198,6 b" 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)