Log message for revision 115386: Actually expose the query plan TTW Changed: U Zope/trunk/src/Products/ZCatalog/ZCatalog.py U Zope/trunk/src/Products/ZCatalog/__init__.py U Zope/trunk/src/Products/ZCatalog/dtml/catalogPlan.dtml A Zope/trunk/src/Products/ZCatalog/dtml/catalogReport.dtml U Zope/trunk/src/Products/ZCatalog/plan.py U Zope/trunk/src/Products/ZCatalog/tests/test_plan.py
-=- Modified: Zope/trunk/src/Products/ZCatalog/ZCatalog.py =================================================================== --- Zope/trunk/src/Products/ZCatalog/ZCatalog.py 2010-08-02 19:23:40 UTC (rev 115385) +++ Zope/trunk/src/Products/ZCatalog/ZCatalog.py 2010-08-02 20:14:54 UTC (rev 115386) @@ -48,6 +48,7 @@ from Products.ZCatalog.interfaces import IZCatalog from Products.ZCatalog.ProgressHandler import ZLogHandler from Products.ZCatalog.ZCatalogIndexes import ZCatalogIndexes +from .plan import PriorityMap LOG = logging.getLogger('Zope.ZCatalog') @@ -103,7 +104,8 @@ {'label': 'Metadata', 'action': 'manage_catalogSchema'}, {'label': 'Find Objects', 'action': 'manage_catalogFind'}, {'label': 'Advanced', 'action': 'manage_catalogAdvanced'}, - {'label': 'Query Report', 'action': 'manage_catalogPlan'}, + {'label': 'Query Report', 'action': 'manage_catalogReport'}, + {'label': 'Query Plan', 'action': 'manage_catalogPlan'}, {'label': 'Undo', 'action': 'manage_UndoForm'}, {'label': 'Security', 'action': 'manage_access'}, {'label': 'Ownership', 'action': 'manage_owner'}, @@ -127,6 +129,9 @@ 'manage_catalogAdvanced') 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_catalogPlan') manage_catalogPlan = DTMLFile('dtml/catalogPlan', globals()) @@ -877,24 +882,39 @@ security.declareProtected(manage_zcatalog_entries, 'getCatalogPlan') def getCatalogPlan(self): - """Query time reporting and planning.""" + """Get a string representation of a query plan""" + plan = PriorityMap.get_plan() + output = [] + output.append('queryplan = {') + for querykey, details in sorted(plan.items()): + output.append(' %s: {' % repr(querykey)) + for indexname, benchmark in sorted(details.items()): + tuplebench = repr(tuple(benchmark)) + output.append(' %r:\n %s,' % (indexname, tuplebench)) + output.append(' },') + output.append('}') + return '\n'.join(output) + + security.declareProtected(manage_zcatalog_entries, 'getCatalogReport') + def getCatalogReport(self): + """Query time reporting.""" rval = self._catalog.getCatalogPlan().report() rval.sort(key=operator.itemgetter('duration'), reverse=True) return rval security.declareProtected(manage_zcatalog_entries, - 'manage_resetCatalogPlan') - def manage_resetCatalogPlan(self, REQUEST=None): - """Resets the catalog plan.""" + 'manage_resetCatalogReport') + def manage_resetCatalogReport(self, REQUEST=None): + """Resets the catalog report.""" self._catalog.getCatalogPlan().reset() if REQUEST is not None: REQUEST.response.redirect(REQUEST.URL1 + - '/manage_catalogPlan?manage_tabs_message=Plan%20cleared') + '/manage_catalogReport?manage_tabs_message=Report%20cleared') security.declareProtected(manage_zcatalog_entries, - 'manage_editCatalogPlan') - def manage_editCatalogPlan(self, long_query_time=0.1, REQUEST=None): + '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) @@ -902,7 +922,7 @@ if REQUEST is not None: REQUEST.response.redirect(REQUEST.URL1 + - '/manage_catalogPlan?manage_tabs_message=' + + '/manage_catalogReport?manage_tabs_message=' + 'Long%20query%20time%20changed') InitializeClass(ZCatalog) Modified: Zope/trunk/src/Products/ZCatalog/__init__.py =================================================================== --- Zope/trunk/src/Products/ZCatalog/__init__.py 2010-08-02 19:23:40 UTC (rev 115385) +++ Zope/trunk/src/Products/ZCatalog/__init__.py 2010-08-02 20:14:54 UTC (rev 115386) @@ -17,6 +17,10 @@ def initialize(context): + # Load a default map + from Products.ZCatalog.plan import PriorityMap + PriorityMap.load_default() + context.registerClass( ZCatalog.ZCatalog, permission='Add ZCatalogs', Modified: Zope/trunk/src/Products/ZCatalog/dtml/catalogPlan.dtml =================================================================== --- Zope/trunk/src/Products/ZCatalog/dtml/catalogPlan.dtml 2010-08-02 19:23:40 UTC (rev 115385) +++ Zope/trunk/src/Products/ZCatalog/dtml/catalogPlan.dtml 2010-08-02 20:14:54 UTC (rev 115386) @@ -2,117 +2,12 @@ <dtml-var manage_tabs> <p class="form-help"> - The <strong>query report</strong> shows catalog queries that - perform slowly. + The <strong>query plan</strong> shows the actual query plan of the + current process. </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 - </div> - </td> - </tr> - <dtml-if getCatalogPlan> - <dtml-in getCatalogPlan 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']">ms - [<dtml-in expr="last['details']" sort mapping> - &dtml-id;: - <dtml-var expr="'%3.2f' % duration">ms / - &dtml-length; objects, - </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_resetCatalogPlan" 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> +<textarea name="queryplan" cols="70" rows="25" readonly="readonly"> +&dtml-getCatalogPlan; +</textarea> -<form action="manage_editCatalogPlan" 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/dtml/catalogReport.dtml (from rev 115378, Zope/trunk/src/Products/ZCatalog/dtml/catalogPlan.dtml) =================================================================== --- Zope/trunk/src/Products/ZCatalog/dtml/catalogReport.dtml (rev 0) +++ Zope/trunk/src/Products/ZCatalog/dtml/catalogReport.dtml 2010-08-02 20:14:54 UTC (rev 115386) @@ -0,0 +1,118 @@ +<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 + </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']">ms + [<dtml-in expr="last['details']" sort mapping> + &dtml-id;: + <dtml-var expr="'%3.2f' % duration">ms / + &dtml-length; objects, + </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> Modified: Zope/trunk/src/Products/ZCatalog/plan.py =================================================================== --- Zope/trunk/src/Products/ZCatalog/plan.py 2010-08-02 19:23:40 UTC (rev 115385) +++ Zope/trunk/src/Products/ZCatalog/plan.py 2010-08-02 20:14:54 UTC (rev 115386) @@ -42,6 +42,10 @@ value = {} @classmethod + def get_plan(cls): + return cls.value.copy() + + @classmethod def get(cls, key): return cls.value.get(key, None) @@ -63,15 +67,18 @@ pmap = resolve(location) logger.info('loaded priority %d map(s) from %s', len(pmap), location) + # Convert simple benchmark tuples to namedtuples + new_plan = {} + for querykey, details in pmap.items(): + new_plan[querykey] = {} + for indexname, benchmark in details.items(): + new_plan[querykey][indexname] = Benchmark(*benchmark) with cls.lock: - cls.value = pmap.copy() + cls.value = new_plan except ImportError: logger.warning('could not load priority map from %s', location) -# Load a default map -PriorityMap.load_default() - class Reports(object): """This holds a structure of nested dicts. Modified: Zope/trunk/src/Products/ZCatalog/tests/test_plan.py =================================================================== --- Zope/trunk/src/Products/ZCatalog/tests/test_plan.py 2010-08-02 19:23:40 UTC (rev 115385) +++ Zope/trunk/src/Products/ZCatalog/tests/test_plan.py 2010-08-02 20:14:54 UTC (rev 115386) @@ -46,7 +46,7 @@ def test_ReportLength(self): """ tests the report aggregation """ - self.zcat.manage_resetCatalogPlan() + self.zcat.manage_resetCatalogReport() self.zcat.searchResults(numbers=4, sort_on='num') self.zcat.searchResults(numbers=1, sort_on='num') @@ -58,49 +58,49 @@ 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.getCatalogPlan())) + self.assertEqual(4, len(self.zcat.getCatalogReport())) def test_ReportCounter(self): """ tests the counter of equal queries """ - self.zcat.manage_resetCatalogPlan() + 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.getCatalogPlan()[0] + 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_resetCatalogPlan() + self.zcat.manage_resetCatalogReport() self.zcat.searchResults(big=True, sort_on='num') self.zcat.searchResults(big=True, sort_on='num') - r = self.zcat.getCatalogPlan()[0] + 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_resetCatalogPlan() + self.zcat.manage_resetCatalogReport() self.zcat.searchResults(big=False, sort_on='num') - r = self.zcat.getCatalogPlan()[0] + 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_resetCatalogPlan() + 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.getCatalogPlan()[0] + r = self.zcat.getCatalogReport()[0] self.assertEqual(r['query'], key) self.assertEqual(r['counter'], 2) _______________________________________________ Zope-Checkins maillist - Zope-Checkins@zope.org https://mail.zope.org/mailman/listinfo/zope-checkins