Log message for revision 115048: Merged andig-catalog-report branch Changed: U Zope/trunk/src/Products/ZCatalog/Catalog.py U Zope/trunk/src/Products/ZCatalog/ZCatalog.py A Zope/trunk/src/Products/ZCatalog/dtml/catalogReport.dtml A Zope/trunk/src/Products/ZCatalog/report.py A Zope/trunk/src/Products/ZCatalog/tests/test_report.py
-=- Modified: Zope/trunk/src/Products/ZCatalog/Catalog.py =================================================================== --- Zope/trunk/src/Products/ZCatalog/Catalog.py 2010-07-24 18:23:38 UTC (rev 115047) +++ Zope/trunk/src/Products/ZCatalog/Catalog.py 2010-07-24 18:40:23 UTC (rev 115048) @@ -28,6 +28,7 @@ from BTrees.IOBTree import IOBTree from Lazy import LazyMap, LazyCat, LazyValues from CatalogBrains import AbstractCatalogBrain, NoBrainer +from .report import CatalogReport LOG = logging.getLogger('Zope.ZCatalog') @@ -468,12 +469,18 @@ # Note that if the indexes find query arguments, but the end result # is an empty sequence, we do nothing + cr = self.getCatalogReport(request) + cr.start() + for i in self.indexes.keys(): index = self.getIndex(i) _apply_index = getattr(index, "_apply_index", None) if _apply_index is None: continue + + cr.split(i) r = _apply_index(request) + cr.split(i) if r is not None: r, u = r @@ -481,6 +488,8 @@ if not rs: break + cr.stop() + if rs is None: # None of the indexes found anything to do with the request # We take this to mean that the query was empty (an empty filter) @@ -738,7 +747,14 @@ __call__ = searchResults + def getCatalogReport(self, request=None): + """Reports about the duration of queries. + """ + parent = Acquisition.aq_base(Acquisition.aq_parent(self)) + threshold = getattr(parent, 'long_query_time', 0.1) + return CatalogReport(self, request, threshold) + class CatalogSearchArgumentsMap: """Multimap catalog arguments coming simultaneously from keywords and request. Modified: Zope/trunk/src/Products/ZCatalog/ZCatalog.py =================================================================== --- Zope/trunk/src/Products/ZCatalog/ZCatalog.py 2010-07-24 18:23:38 UTC (rev 115047) +++ Zope/trunk/src/Products/ZCatalog/ZCatalog.py 2010-07-24 18:40:23 UTC (rev 115048) @@ -16,6 +16,7 @@ """ import logging +import operator import sys import string import time @@ -109,6 +110,9 @@ 'action': 'manage_catalogFind'}, {'label': 'Advanced', # TAB: Advanced 'action': 'manage_catalogAdvanced'}, + {'label': 'Query Report', + 'action': 'manage_catalogReport', + }, {'label': 'Undo', # TAB: Undo 'action': 'manage_UndoForm'}, {'label': 'Security', # TAB: Security @@ -140,6 +144,11 @@ manage_catalogAdvanced = DTMLFile('dtml/catalogAdvanced', globals()) security.declareProtected(manage_zcatalog_entries, + 'manage_catalogReport') + manage_catalogReport = DTMLFile('dtml/catalogReport', + globals()) + + security.declareProtected(manage_zcatalog_entries, 'manage_objectInformation') manage_objectInformation = DTMLFile('dtml/catalogObjectInformation', globals()) @@ -147,6 +156,8 @@ Indexes = ZCatalogIndexes() threshold=10000 + long_query_time = 0.1 + _v_total=0 _v_transaction = None @@ -170,6 +181,8 @@ self._catalog = Catalog() self._migrated_280 = True + self.long_query_time = 0.1 # in seconds + def __len__(self): # Perform a migration of _catalog.__len__ to _catalog._length # to avoid with new-style class caching issues (see #1332) @@ -966,7 +979,41 @@ def delColumn(self, name): return self._catalog.delColumn(name) + # + # Catalog report methods + # + security.declareProtected(manage_zcatalog_entries, 'getCatalogReport') + def getCatalogReport(self): + """ Reports about the duration of queries """ + rval = self._catalog.getCatalogReport().report() + rval.sort(key=operator.itemgetter('duration'), reverse=True) + return rval + + security.declareProtected(manage_zcatalog_entries, + 'manage_resetCatalogReport') + def manage_resetCatalogReport(self, REQUEST=None): + """ resets the catalog report """ + self._catalog.getCatalogReport().reset() + + if REQUEST is not None: + REQUEST.response.redirect(REQUEST.URL1 + + '/manage_catalogReport?manage_tabs_message=Report%20cleared') + + security.declareProtected(manage_zcatalog_entries, + 'manage_editCatalogReport') + def manage_editCatalogReport(self, long_query_time=0.1, REQUEST=None): + """ edit the long query time """ + if not isinstance(long_query_time, float): + long_query_time = float(long_query_time) + self.long_query_time = long_query_time + + if REQUEST is not None: + REQUEST.response.redirect(REQUEST.URL1 + + '/manage_catalogReport?manage_tabs_message=' + + 'Long%20query%20time%20changed') + + InitializeClass(ZCatalog) Copied: Zope/trunk/src/Products/ZCatalog/dtml/catalogReport.dtml (from rev 115047, Zope/branches/andig-catalog-report/src/Products/ZCatalog/dtml/catalogReport.dtml) =================================================================== --- Zope/trunk/src/Products/ZCatalog/dtml/catalogReport.dtml (rev 0) +++ Zope/trunk/src/Products/ZCatalog/dtml/catalogReport.dtml 2010-07-24 18:40:23 UTC (rev 115048) @@ -0,0 +1,117 @@ +<dtml-var manage_page_header> +<dtml-var manage_tabs> + +<p class="form-help"> + The <strong>query report</strong> shows catalog queries that + perform slowly. +</p> + +<table width="100%" cellspacing="0" cellpadding="2" border="0"> + <tr class="list-header" > + <td align="left" valign="top"> + <div class="list-nav"> + Mean duration [ms] + </div> + </td> + <td align="left" valign="top"> + <div class="list-nav"> + Hits + </div> + </td> + <td align="left" valign="top"> + <div class="list-nav"> + Query key + </div> + </td> + <td align="left" valign="top"> + <div class="list-nav"> + Recent duration [ms] + </div> + </td> + </tr> + <dtml-if getCatalogReport> + <dtml-in getCatalogReport mapping> + <dtml-if sequence-odd> + <tr class="row-normal"> + <dtml-else> + <tr class="row-hilite"> + </dtml-if> + <td align="left" valign="top"> + <div class="list-item"> + <dtml-var expr="'%3.2f' % duration"> + </div> + </td> + <td align="left" valign="top"> + <div class="list-item"> + &dtml-counter; + </div> + </td> + <td align="left" valign="top"> + <div class="list-item"> + &dtml-query; + </div> + </td> + <td align="left" valign="top"> + <div class="list-item"> + <dtml-var expr="'%3.2f' % last['duration']"> + [<dtml-in expr="last['details']" sort mapping> + &dtml-id;: <dtml-var expr="'%3.2f' % duration"> + </dtml-in>] + + </div> + </td> + </tr> + </dtml-in> + <tr> + <td colspan="2" align="left" valign="top"> + <p class="form-help">Resetting the catalog report will reinitialize the report log.</p> + </td> + <td colspan="2" align="right" valign="top"> + <form action="manage_resetCatalogReport" method=POST> + <div class="form-element"> + <input class="form-element" type="submit" value="Reset Report"> + </div> + </form> + </td> + </tr> + <dtml-else> + <tr> + <td colspan="4" > + <div class="list-item"> + Report is empty. + </div> + </td> + </tr> + </dtml-if> +</table> + +<form action="manage_editCatalogReport" method="post"> + <table width="100%" style="padding-top:1em;" cellspacing="0" cellpadding="2" border="0"> + <tr class="section-bar"> + <td colspan="3" align="left"> + <div class="form-label"> + Settings + </div> + </td> + </tr> + <tr> + <td align="right" valign="middle"> + <div class="list-item"> + Threshold (in seconds) + </div> + </td> + <td align="left" valign="middle"> + <div class="form-element"> + <input name="long_query_time:float" value="&dtml-long_query_time;" /> + </div> + </td> + <td align="left" valign="middle"> + <p class="form-help">Only queries whose execution + takes longer than the configured threshold are considered + being slow. (Default 0.1 seconds).</p> + </tr> + </table> + <input class="form-element" type="submit" value="Apply settings"> +</form> + +<dtml-var manage_page_footer> Copied: Zope/trunk/src/Products/ZCatalog/report.py (from rev 115047, Zope/branches/andig-catalog-report/src/Products/ZCatalog/report.py) =================================================================== --- Zope/trunk/src/Products/ZCatalog/report.py (rev 0) +++ Zope/trunk/src/Products/ZCatalog/report.py 2010-07-24 18:40:23 UTC (rev 115048) @@ -0,0 +1,261 @@ +############################################################################## +# +# Copyright (c) 2010 Zope Foundation and Contributors. +# +# This software is subject to the provisions of the Zope Public License, +# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution. +# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED +# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED +# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS +# FOR A PARTICULAR PURPOSE +# +############################################################################## + +import time +from thread import allocate_lock + +from Acquisition import aq_base +from Acquisition import aq_parent +from Products.PluginIndexes.interfaces import IUniqueValueIndex + +reports_lock = allocate_lock() +reports = {} + +value_indexes_lock = allocate_lock() +value_indexes = frozenset() + +MAX_DISTINCT_VALUES = 10 + + +def determine_value_indexes(indexes): + # This function determines all indexes whose values should be respected + # in the report key. The number of unique values for the index needs to be + # lower than the MAX_DISTINCT_VALUES watermark. + + # TODO: Ideally who would only consider those indexes with a small number + # of unique values, where the number of items for each value differs a + # lot. If the number of items per value is similar, the duration of a + # query is likely similar as well. + global value_indexes + if value_indexes: + # Calculating all the value indexes is quite slow, so we do this once + # for the first query. Since this is an optimization only, slightly + # outdated results based on index changes in the running process + # can be ignored. + return value_indexes + + new_value_indexes = set() + for name, index in indexes.items(): + if IUniqueValueIndex.providedBy(index): + values = index.uniqueValues() + if values and len(values) < MAX_DISTINCT_VALUES: + # Only consider indexes which actually return a number + # greater than zero + new_value_indexes.add(name) + try: + value_indexes_lock.acquire() + value_indexes = frozenset(new_value_indexes) + finally: + value_indexes_lock.release() + + return value_indexes + + +def clear_value_indexes(): + global value_indexes + try: + value_indexes_lock.acquire() + value_indexes = frozenset() + finally: + value_indexes_lock.release() + + +from zope.testing.cleanup import addCleanUp +addCleanUp(clear_value_indexes) +del addCleanUp + + +def make_query(indexes, request): + # This is a bit of a mess, but the ZCatalog API supports passing + # in query restrictions in almost arbitary ways + if isinstance(request, dict): + query = request.copy() + else: + query = {} + query.update(request.keywords) + real_req = request.request + if isinstance(real_req, dict): + query.update(real_req) + + known_keys = query.keys() + # The request has too many places where an index restriction might be + # specified. Putting all of request.form, request.other, ... into the + # key isn't what we want either, so we iterate over all known indexes + # instead and see if they are in the request. + for iid in indexes.keys(): + if iid in known_keys: + continue + value = real_req.get(iid) + if value: + query[iid] = value + return query + + +def make_key(catalog, request): + indexes = catalog.indexes + valueindexes = determine_value_indexes(indexes) + + query = make_query(indexes, request) + key = keys = query.keys() + + values = [name for name in keys if name in valueindexes] + if values: + # If we have indexes whose values should be considered, we first + # preserve all normal indexes and then add the keys whose values + # matter including their value into the key + key = [name for name in keys if name not in values] + for name in values: + + v = query.get(name, []) + if isinstance(v, (tuple, list)): + v = list(v) + v.sort() + + # We need to make sure the key is immutable, repr() is an easy way + # to do this without imposing restrictions on the types of values + key.append((name, repr(v))) + + key = tuple(sorted(key)) + return key + + +class StopWatch(object): + """ Simple stopwatch class """ + + def __init__(self): + self.init() + + def init(self): + self.res = [] + self.start_time = None + self.interim = {} + self.stop_time = None + + def start(self): + self.init() + self.start_time = time.time() + + def split(self, label): + current = time.time() + start_time, stop_time = self.interim.get(label, (None, None)) + + if start_time is None: + self.interim[label] = (current, None) + return + + self.interim[label] = (start_time, current) + self.res.append((label, current - start_time)) + + def stop(self): + self.end_time = time.time() + + def result(self): + return (self.end_time - self.start_time, tuple(self.res)) + + +class CatalogReport(StopWatch): + """Catalog report class to meassure and identify catalog queries. + """ + + def __init__(self, catalog, request=None, threshold=0.1): + super(CatalogReport, self).__init__() + + self.catalog = catalog + self.request = request + self.threshold = threshold + + parent = aq_parent(catalog) + path = getattr(aq_base(parent), 'getPhysicalPath', None) + if path is None: + path = ('', 'NonPersistentCatalog') + else: + path = tuple(parent.getPhysicalPath()) + self.cid = path + + def stop(self): + super(CatalogReport, self).stop() + self.log() + + def log(self): + # result of stopwatch + res = self.result() + if res[0] < self.threshold: + return + + # The key calculation takes a bit itself, we want to avoid that for + # any fast queries. This does mean that slow queries get the key + # calculation overhead added to their runtime. + key = make_key(self.catalog, self.request) + + reports_lock.acquire() + try: + if self.cid not in reports: + reports[self.cid] = {} + + previous = reports[self.cid].get(key) + if previous: + counter, mean, last = previous + mean = (mean * counter + res[0]) / float(counter + 1) + reports[self.cid][key] = (counter + 1, mean, res) + else: + reports[self.cid][key] = (1, res[0], res) + + finally: + reports_lock.release() + + def reset(self): + reports_lock.acquire() + try: + reports[self.cid] = {} + finally: + reports_lock.release() + + def report(self): + """Returns a statistic report of catalog queries as list of dicts as + follows: + + [{'query': <query_key>, + 'counter': <hits> + 'duration': <mean duration>, + 'last': <details of recent query>, + }, + ... + ] + + <details of recent query> := {'duration': <duration of last query>, + 'details': <duration of single indexes>, + } + + <duration of single indexes> := [{'id': <index_name1>, + 'duration': <duration>, + }, + ... + ] + + The duration is provided in millisecond. + """ + rval = [] + for k, v in reports.get(self.cid, {}).items(): + info = { + 'query': k, + 'counter': v[0], + 'duration': v[1] * 1000, + 'last': {'duration': v[2][0] * 1000, + 'details': [dict(id=i[0], + duration=i[1]*1000) + for i in v[2][1]], + }, + } + rval.append(info) + + return rval Copied: Zope/trunk/src/Products/ZCatalog/tests/test_report.py (from rev 115047, Zope/branches/andig-catalog-report/src/Products/ZCatalog/tests/test_report.py) =================================================================== --- Zope/trunk/src/Products/ZCatalog/tests/test_report.py (rev 0) +++ Zope/trunk/src/Products/ZCatalog/tests/test_report.py 2010-07-24 18:40:23 UTC (rev 115048) @@ -0,0 +1,112 @@ +############################################################################## +# +# Copyright (c) 2002 Zope Corporation and Contributors. All Rights Reserved. +# +# This software is subject to the provisions of the Zope Public License, +# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution. +# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED +# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED +# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS +# FOR A PARTICULAR PURPOSE. +# +############################################################################## + +import unittest + + +class dummy(object): + + def __init__(self, num): + self.num = num + + def big(self): + return self.num > 5 + + def numbers(self): + return (self.num, self.num + 1) + + +class TestCatalogReport(unittest.TestCase): + + def setUp(self): + from Products.ZCatalog.ZCatalog import ZCatalog + self.zcat = ZCatalog('catalog') + self.zcat.long_query_time = 0.0 + self.zcat.addIndex('num', 'FieldIndex') + self.zcat.addIndex('big', 'FieldIndex') + self.zcat.addIndex('numbers', 'KeywordIndex') + + for i in range(9): + obj = dummy(i) + self.zcat.catalog_object(obj, str(i)) + + def tearDown(self): + from Products.ZCatalog.report import clear_value_indexes + clear_value_indexes() + + def test_ReportLength(self): + """ tests the report aggregation """ + self.zcat.manage_resetCatalogReport() + + self.zcat.searchResults(numbers=4,sort_on='num') + self.zcat.searchResults(numbers=1,sort_on='num') + self.zcat.searchResults(numbers=3,sort_on='num') + + self.zcat.searchResults(big=True,sort_on='num') + self.zcat.searchResults(big=True,sort_on='num') + self.zcat.searchResults(big=False,sort_on='num') + + self.zcat.searchResults(num=[5,4,3],sort_on='num') + self.zcat.searchResults(num=(3,4,5),sort_on='num') + self.assertEqual(4, len(self.zcat.getCatalogReport())) + + def test_ReportCounter(self): + """ tests the counter of equal queries """ + self.zcat.manage_resetCatalogReport() + + self.zcat.searchResults(numbers=5,sort_on='num') + self.zcat.searchResults(numbers=6,sort_on='num') + self.zcat.searchResults(numbers=8,sort_on='num') + + r = self.zcat.getCatalogReport()[0] + self.assertEqual(r['counter'],3) + + def test_ReportKey(self): + """ tests the query keys for uniqueness """ + # query key 1 + key = ('sort_on', ('big', 'True')) + self.zcat.manage_resetCatalogReport() + + self.zcat.searchResults(big=True,sort_on='num') + self.zcat.searchResults(big=True,sort_on='num') + r = self.zcat.getCatalogReport()[0] + + self.assertEqual(r['query'],key) + self.assertEqual(r['counter'],2) + + # query key 2 + key = ('sort_on', ('big', 'False')) + self.zcat.manage_resetCatalogReport() + + self.zcat.searchResults(big=False,sort_on='num') + r = self.zcat.getCatalogReport()[0] + + self.assertEqual(r['query'],key) + self.assertEqual(r['counter'], 1) + + # query key 3 + key = ('sort_on', ('num', '[3, 4, 5]')) + self.zcat.manage_resetCatalogReport() + + self.zcat.searchResults(num=[5,4,3], sort_on='num') + self.zcat.searchResults(num=(3,4,5), sort_on='num') + r = self.zcat.getCatalogReport()[0] + + self.assertEqual(r['query'], key) + self.assertEqual(r['counter'], 2) + + +def test_suite(): + suite = unittest.TestSuite() + suite.addTest(unittest.makeSuite(TestCatalogReport)) + return suite _______________________________________________ Zope-Checkins maillist - Zope-Checkins@zope.org https://mail.zope.org/mailman/listinfo/zope-checkins