Vo Minh Thu (OpenERP) has proposed merging
lp:~openerp-dev/openobject-server/trunk-simple-table-stats-vmt into
lp:openobject-server.
Requested reviews:
OpenERP Core Team (openerp)
For more details, see:
https://code.launchpad.net/~openerp-dev/openobject-server/trunk-simple-table-stats-vmt/+merge/122685
--
https://code.launchpad.net/~openerp-dev/openobject-server/trunk-simple-table-stats-vmt/+merge/122685
Your team OpenERP R&D Team is subscribed to branch
lp:~openerp-dev/openobject-server/trunk-simple-table-stats-vmt.
=== modified file 'openerp/modules/registry.py'
--- openerp/modules/registry.py 2012-08-13 15:05:01 +0000
+++ openerp/modules/registry.py 2012-09-14 14:47:22 +0000
@@ -182,6 +182,8 @@
try:
registry.do_parent_store(cr)
registry.get('ir.actions.report.xml').register_all(cr)
+ if openerp.tools.config['query_count_file']:
+ openerp.sql_db.write_query_count(openerp.tools.config['query_count_file'], False)
cr.commit()
finally:
cr.close()
=== modified file 'openerp/sql_db.py'
--- openerp/sql_db.py 2012-02-06 20:31:51 +0000
+++ openerp/sql_db.py 2012-09-14 14:47:22 +0000
@@ -35,13 +35,21 @@
__all__ = ['db_connect', 'close_db']
+from datetime import datetime as mdt
+from datetime import timedelta
from functools import wraps
+from inspect import currentframe
import logging
import psycopg2.extensions
from psycopg2.extensions import ISOLATION_LEVEL_AUTOCOMMIT, ISOLATION_LEVEL_READ_COMMITTED, ISOLATION_LEVEL_REPEATABLE_READ
from psycopg2.pool import PoolError
from psycopg2.psycopg1 import cursor as psycopg1cursor
-from threading import currentThread
+import re
+import threading
+
+import tools
+from tools import config
+from tools.func import frame_codeinfo
psycopg2.extensions.register_type(psycopg2.extensions.UNICODE)
@@ -65,19 +73,114 @@
psycopg2.extensions.register_type(psycopg2.extensions.new_type(typeoid, name, lambda x, cr: x))
psycopg2.extensions.register_type(psycopg2.extensions.new_type((700, 701, 1700,), 'float', undecimalize))
-
-import tools
-from tools.func import frame_codeinfo
-from datetime import datetime as mdt
-from datetime import timedelta
-import threading
-from inspect import currentframe
-
-import re
-re_from = re.compile('.* from "?([a-zA-Z_0-9]+)"? .*$');
-re_into = re.compile('.* into "?([a-zA-Z_0-9]+)"? .*$');
-
-sql_counter = 0
+re_query = re.compile('.*(update|from|into) "?([a-zA-Z_0-9]+)"?.*');
+
+re_alter_query = re.compile('\s*alter\s+table\s+"?([a-zA-Z_0-9]+)"?.*', re.MULTILINE);
+re_select_query = re.compile('\s*select\s+.*\s+from\s+"?([a-zA-Z_0-9]+)"?.*', re.MULTILINE);
+re_delete_query = re.compile('\s*delete\s+from\s+"?([a-zA-Z_0-9]+)"?.*', re.MULTILINE);
+re_insert_query = re.compile('\s*insert\s+into\s+"?([a-zA-Z_0-9]+)"?.*', re.MULTILINE);
+re_select_no_table_query = re.compile('\s*select\s+.*', re.MULTILINE);
+re_update_query = re.compile('\s*update\s+.*\s+set\s+"?([a-zA-Z_0-9]+)"?.*', re.MULTILINE);
+re_create_sequence_query = re.compile('\s*create\s+sequence.*"?.*', re.MULTILINE);
+re_drop_sequence_query = re.compile('\s*drop\s+sequence.*', re.MULTILINE);
+re_comment_query = re.compile('\s*comment.*', re.MULTILINE);
+
+query_count_lock = threading.RLock()
+query_count = 0
+query_counts = {}
+
+query_types = ('alter', 'select', 'delete', 'insert', 'update', 'create_seq', 'drop_seq', 'comment', 'other')
+
+def query_type(query):
+ q = query.lower()
+ types = [
+ (re_alter_query, 'alter', 1),
+ (re_select_query, 'select', 1),
+ (re_delete_query, 'delete', 1),
+ (re_insert_query, 'insert', 1),
+ (re_select_no_table_query, 'select', '<no_table>'),
+ (re_update_query, 'update', 1),
+ (re_create_sequence_query, 'create_seq', '<no_table>'),
+ (re_drop_sequence_query, 'drop_seq', '<no_table>'),
+ (re_comment_query, 'comment', '<no_table>'),
+ ]
+ for r, typ, table in types:
+ m = r.match(q)
+ if m:
+ return typ, table if isinstance(table, str) else m.group(table)
+ return 'other', 'zzz_unknown'
+
+def count_query(query, delay):
+ """
+ Collect a few statistics about database usage. They can be later written
+ to file using the `write_query_count` function.
+
+ :param string query: the query being observed.
+ :param int delay: the time used to run the query against the database.
+ :returns: nothing
+ """
+ global query_count_lock
+ global query_count
+ global query_counts
+ with query_count_lock:
+ m = query_type(query)
+ query_count += 1
+ typ, table = m
+ d = dict.fromkeys(query_types, (0, 0))
+ table_counts = query_counts.setdefault(table, d)
+ calls, elapsed_time = table_counts[typ]
+ table_counts[typ] = (calls + 1, elapsed_time + delay)
+
+def add_query_total():
+ """
+ Add a virtual table called `zzz_total` to sum all table counts, and add a
+ virtual query type `total` to each table.
+ """
+ with query_count_lock:
+ total = query_counts['zzz_total'] = dict.fromkeys(query_types, (0, 0))
+ for table, counts in query_counts.iteritems():
+ counts['total'] = (0, 0)
+ for x in query_types:
+ count, delay = counts[x]
+ total_count, total_delay = counts['total']
+ counts['total'] = (total_count + count, total_delay + delay)
+ total_count, total_delay = total[x]
+ total[x] = (total_count + count, total_delay + delay)
+ counts = query_counts['zzz_total']
+ counts['total'] = (0, 0)
+ for x in query_types:
+ count, delay = counts[x]
+ total_count, total_delay = counts['total']
+ counts['total'] = (total_count + count, total_delay + delay)
+
+def write_query_count(file_name, header):
+ """
+ Write a few statistics about database table usage as CSV. The statistics
+ are collected using the `count_query` function.
+
+ Assuming a `here.txt` filename: a possible command to display the results
+ is:
+ > cat here.txt | column -s, -t | sort -n -k 2
+
+ :param string file_name: file name to write the data.
+ :param bool header: specify whether a header is written before the data.
+ :returns: nothing
+ """
+ with query_count_lock:
+ add_query_total()
+ with open(file_name, 'w') as w:
+ if header:
+ w.write("Table,Elapsed time (FROM),Elapsed time (FROM),Calls (FROM),Elapsed time (INTO),Elapsed time (INTO),Calls (INTO)\n")
+ for table, counts in query_counts.iteritems():
+ w.write('%s,' % table)
+ for x in query_types + ('total',):
+ count, delay = counts[x]
+ delay_ = timedelta(microseconds=delay)
+ w.write('%s,' % count)
+ w.write('%s,' % delay)
+ w.write(('%s' if x == 'total' else '%s,') % delay_)
+ w.write("\n")
+
class Cursor(object):
"""Represents an open transaction to the PostgreSQL DB backend,
@@ -141,26 +244,18 @@
"""
IN_MAX = 1000 # decent limit on size of IN queries - guideline = Oracle limit
- def check(f):
- @wraps(f)
- def wrapper(self, *args, **kwargs):
- if self.__closed:
- msg = 'Unable to use a closed cursor.'
- if self.__closer:
- msg += ' It was closed at %s, line %s' % self.__closer
- raise psycopg2.OperationalError(msg)
- return f(self, *args, **kwargs)
- return wrapper
+ def check(self):
+ if self.__closed:
+ msg = 'Unable to use a closed cursor.'
+ if self.__closer:
+ msg += ' It was closed at %s, line %s' % self.__closer
+ raise psycopg2.OperationalError(msg)
def __init__(self, pool, dbname, serialized=True):
- self.sql_from_log = {}
- self.sql_into_log = {}
-
# default log level determined at cursor creation, could be
# overridden later for debugging purposes
- self.sql_log = _logger.isEnabledFor(logging.DEBUG)
+ self.sql_log = True
- self.sql_log_count = 0
self.__closed = True # avoid the call of close() (by __del__) if an exception
# is raised by any of the following initialisations
self._pool = pool
@@ -197,14 +292,15 @@
_logger.warning(msg)
self._close(True)
- @check
+
def execute(self, query, params=None, log_exceptions=None):
+ self.check()
if '%d' in query or '%f' in query:
_logger.warning(query)
_logger.warning("SQL queries cannot contain %d or %f anymore. "
"Use only %s")
- if self.sql_log:
+ if self.sql_log or config['query_count_file']:
now = mdt.now()
try:
@@ -219,22 +315,12 @@
_logger.exception("bad query: %s", self._obj.query or query)
raise
- if self.sql_log:
+ if self.sql_log or config['query_count_file']:
+ _logger.debug("query: %s", self._obj.query)
delay = mdt.now() - now
delay = delay.seconds * 1E6 + delay.microseconds
+ count_query(query, delay)
- _logger.debug("query: %s", self._obj.query)
- self.sql_log_count+=1
- res_from = re_from.match(query.lower())
- if res_from:
- self.sql_from_log.setdefault(res_from.group(1), [0, 0])
- self.sql_from_log[res_from.group(1)][0] += 1
- self.sql_from_log[res_from.group(1)][1] += delay
- res_into = re_into.match(query.lower())
- if res_into:
- self.sql_into_log.setdefault(res_into.group(1), [0, 0])
- self.sql_into_log[res_into.group(1)][0] += 1
- self.sql_into_log[res_into.group(1)][1] += delay
return res
@@ -243,36 +329,8 @@
safe for IN conditions, after uniquifying them."""
return tools.misc.split_every(self.IN_MAX, set(ids))
- def print_log(self):
- global sql_counter
- sql_counter += self.sql_log_count
- if not self.sql_log:
- return
- def process(type):
- sqllogs = {'from':self.sql_from_log, 'into':self.sql_into_log}
- sum = 0
- if sqllogs[type]:
- sqllogitems = sqllogs[type].items()
- sqllogitems.sort(key=lambda k: k[1][1])
- _logger.debug("SQL LOG %s:", type)
- sqllogitems.sort(lambda x,y: cmp(x[1][0], y[1][0]))
- for r in sqllogitems:
- delay = timedelta(microseconds=r[1][1])
- _logger.debug("table: %s: %s/%s",
- r[0], delay, r[1][0])
- sum+= r[1][1]
- sqllogs[type].clear()
- sum = timedelta(microseconds=sum)
- _logger.debug("SUM %s:%s/%d [%d]",
- type, sum, self.sql_log_count, sql_counter)
- sqllogs[type].clear()
- process('from')
- process('into')
- self.sql_log_count = 0
- self.sql_log = False
-
- @check
def close(self):
+ self.check()
return self._close(False)
def _close(self, leak=False):
@@ -281,7 +339,6 @@
if self.sql_log:
self.__closer = frame_codeinfo(currentframe(),3)
- self.print_log()
self._obj.close()
@@ -299,13 +356,13 @@
if leak:
self._cnx.leaked = True
else:
- chosen_template = tools.config['db_template']
+ chosen_template = config['db_template']
templates_list = tuple(set(['template0', 'template1', 'postgres', chosen_template]))
keep_in_pool = self.dbname not in templates_list
self._pool.give_back(self._cnx, keep_in_pool=keep_in_pool)
- @check
def autocommit(self, on):
+ self.check()
if on:
isolation_level = ISOLATION_LEVEL_AUTOCOMMIT
else:
@@ -324,20 +381,20 @@
else ISOLATION_LEVEL_READ_COMMITTED
self._cnx.set_isolation_level(isolation_level)
- @check
def commit(self):
""" Perform an SQL `COMMIT`
"""
+ self.check()
return self._cnx.commit()
- @check
def rollback(self):
""" Perform an SQL `ROLLBACK`
"""
+ self.check()
return self._cnx.rollback()
- @check
def __getattr__(self, name):
+ self.check()
return getattr(self._obj, name)
""" Set the mode of postgres operations for all cursors
@@ -480,7 +537,7 @@
def dsn(db_name):
_dsn = ''
for p in ('host', 'port', 'user', 'password'):
- cfg = tools.config['db_' + p]
+ cfg = config['db_' + p]
if cfg:
_dsn += '%s=%s ' % (p, cfg)
@@ -499,8 +556,8 @@
def db_connect(db_name):
global _Pool
if _Pool is None:
- _Pool = ConnectionPool(int(tools.config['db_maxconn']))
- currentThread().dbname = db_name
+ _Pool = ConnectionPool(int(config['db_maxconn']))
+ threading.currentThread().dbname = db_name
return Connection(_Pool, db_name)
def close_db(db_name):
@@ -508,7 +565,7 @@
""" You might want to call openerp.modules.registry.RegistryManager.delete(db_name) along this function."""
if _Pool:
_Pool.close_all(dsn(db_name))
- ct = currentThread()
+ ct = threading.currentThread()
if hasattr(ct, 'dbname'):
delattr(ct, 'dbname')
=== modified file 'openerp/tools/config.py'
--- openerp/tools/config.py 2012-09-12 11:19:10 +0000
+++ openerp/tools/config.py 2012-09-14 14:47:22 +0000
@@ -74,7 +74,8 @@
# Not exposed in the configuration file.
self.blacklist_for_save = set(
['publisher_warranty_url', 'load_language', 'root_path',
- 'init', 'save', 'config', 'update', 'stop_after_init'])
+ 'init', 'save', 'config', 'update', 'stop_after_init',
+ 'query_count_file'])
# dictionary mapping option destination (keys in self.options) to MyOptions.
self.casts = {}
@@ -191,6 +192,9 @@
group.add_option('--log-level', dest='log_level', type='choice', choices=levels,
my_default='info', help='specify the level of the logging. Accepted values: ' + str(levels) + ' (deprecated option).')
+ group.add_option("--query-count-file", dest="query_count_file", my_default=False,
+ help="Specify if some SQL query statistics are saved in a given file.")
+
parser.add_option_group(group)
# SMTP Group
@@ -375,7 +379,8 @@
'netrpc', 'xmlrpc', 'syslog', 'without_demo', 'timezone',
'xmlrpcs_interface', 'xmlrpcs_port', 'xmlrpcs',
'static_http_enable', 'static_http_document_root', 'static_http_url_prefix',
- 'secure_cert_file', 'secure_pkey_file', 'dbfilter', 'log_handler', 'log_level'
+ 'secure_cert_file', 'secure_pkey_file', 'dbfilter', 'log_handler', 'log_level',
+ 'query_count_file'
]
for arg in keys:
_______________________________________________
Mailing list: https://launchpad.net/~openerp-dev-gtk
Post to : openerp-dev-gtk@lists.launchpad.net
Unsubscribe : https://launchpad.net/~openerp-dev-gtk
More help : https://help.launchpad.net/ListHelp
