diff --git a/openerp/netsvc.py b/openerp/netsvc.py index 37de4dd5b8b..533b1659191 100644 --- a/openerp/netsvc.py +++ b/openerp/netsvc.py @@ -36,6 +36,11 @@ import time import types from pprint import pformat +try: + import psutil +except ImportError: + psutil = None + # TODO modules that import netsvc only for things from loglevels must be changed to use loglevels. from loglevels import * import tools @@ -273,6 +278,9 @@ def dispatch_rpc(service_name, method, params): rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG) if rpc_request_flag or rpc_response_flag: start_time = time.time() + start_rss, start_vms = 0, 0 + if psutil: + start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info() if rpc_request and rpc_response_flag: log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params)) @@ -282,10 +290,14 @@ def dispatch_rpc(service_name, method, params): if rpc_request_flag or rpc_response_flag: end_time = time.time() + end_rss, end_vms = 0, 0 + if psutil: + end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info() + logline = '%s.%s time:%.3fs mem: %sk -> %sk (diff: %sk)' % (service_name, method, end_time - start_time, start_vms / 1024, end_vms / 1024, (end_vms - start_vms)/1024) if rpc_response_flag: - log(rpc_response,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), result) + log(rpc_response,logging.DEBUG, logline, result) else: - log(rpc_request,logging.DEBUG,'%s.%s time:%.3fs '%(service_name,method,end_time - start_time), replace_request_password(params), depth=1) + log(rpc_request,logging.DEBUG, logline, replace_request_password(params), depth=1) return result except openerp.exceptions.AccessError: diff --git a/openerp/service/workers.py b/openerp/service/workers.py index 0a54a80b963..a4a0397287f 100644 --- a/openerp/service/workers.py +++ b/openerp/service/workers.py @@ -355,12 +355,17 @@ class WorkerCron(Worker): time.sleep(interval) def process_work(self): + rpc_request = logging.getLogger(__name__ + '.rpc.request') + rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG) _logger.debug("WorkerCron (%s) polling for jobs", self.pid) if config['db_name']: db_names = config['db_name'].split(',') else: db_names = openerp.netsvc.ExportService._services['db'].exp_list(True) for db_name in db_names: + if rpc_request_flag: + start_time = time.time() + start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info() while True: # acquired = openerp.addons.base.ir.ir_cron.ir_cron._acquire_job(db_name) # TODO why isnt openerp.addons.base defined ? @@ -371,7 +376,12 @@ class WorkerCron(Worker): # dont keep cursors in multi database mode if len(db_names) > 1: openerp.sql_db.close_db(db_name) - # TODO Each job should be considered as one request instead of each db + if rpc_request_flag: + end_time = time.time() + end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info() + logline = '%s time:%.3fs mem: %sk -> %sk (diff: %sk)' % (db_name, end_time - start_time, start_vms / 1024, end_vms / 1024, (end_vms - start_vms)/1024) + _logger.debug("WorkerCron (%s) %s", self.pid, logline) + # TODO Each job should be considered as one request instead of each run self.request_count += 1 def start(self):