# HG changeset patch
# User Laurent Peuch <cortex@worlddomination.be>
# Date 1564684216 -7200
# Node ID 10b8352b0208de3f29c37df46dcebef0bf4f49da
# Parent  d5ae5abd0876e91f1d935113befe32b56dfe5f80
[debug-toolbar/rql] display sql queries generated by rql ones

diff -r d5ae5abd0876 -r 10b8352b0208 cubicweb/debug.py
--- a/cubicweb/debug.py	Wed Jul 31 04:16:20 2019 +0200
+++ b/cubicweb/debug.py	Thu Aug 01 20:30:16 2019 +0200
@@ -23,6 +23,7 @@
 
 SUBSCRIBERS = {
     "rql": [],
+    "sql": [],
 }
 
 
diff -r d5ae5abd0876 -r 10b8352b0208 cubicweb/pyramid/debug_toolbar_templates/rql.dbtmako
--- a/cubicweb/pyramid/debug_toolbar_templates/rql.dbtmako	Wed Jul 31 04:16:20 2019 +0200
+++ b/cubicweb/pyramid/debug_toolbar_templates/rql.dbtmako	Thu Aug 01 20:30:16 2019 +0200
@@ -5,6 +5,7 @@
             <th class="table-col-2">Time (ms)</th>
             <th class="table-col-3">RQL</th>
             <th class="table-col-5">Result</th>
+            <th class="table-col-6">SQL</th>
             <th class="table-col-7">Description</th>
             <th class="table-col-8">Stack</th>
         </tr>
@@ -29,6 +30,15 @@
                 % else:
                 <td class="table-col-5">${highlight(query["result"], "python3") | n}</td>
                 % endif
+                <td>
+                    % for sql in query["generated_sql_queries"]:
+                    <div class="well" style="padding: 3px">
+                        ${highlight(sql['sql'], "SQL") | n}
+                        <br>
+                        ${highlight(sql['args'], "python3") | n}
+                    </div>
+                    % endfor
+                </td>
                 <td class="table-col-7">${highlight(query["description"], "python3") | n}</td>
                 <td class="table-col-8">
                     <a class="btn btn-default" id="show-stack-${i}" href="javascript:show_stack(${i})">show stack</a>
diff -r d5ae5abd0876 -r 10b8352b0208 cubicweb/pyramid/debugtoolbar_panels.py
--- a/cubicweb/pyramid/debugtoolbar_panels.py	Wed Jul 31 04:16:20 2019 +0200
+++ b/cubicweb/pyramid/debugtoolbar_panels.py	Thu Aug 01 20:30:16 2019 +0200
@@ -16,6 +16,8 @@
 # You should have received a copy of the GNU Lesser General Public License along
 # with CubicWeb.  If not, see <http://www.gnu.org/licenses/>.
 
+from collections import defaultdict
+
 from pyramid_debugtoolbar.panels import DebugPanel
 from cubicweb.debug import subscribe_to_debug_channel, unsubscribe_to_debug_channel
 from cubicweb.misc.source_highlight import highlight_html, generate_css
@@ -25,6 +27,18 @@
     """
     CubicWeb RQL debug panel
     """
+
+    """
+    Excepted formats:
+    SQL: {
+        'rql_query_tracing_token': 'some_token',
+        'args': {dict with some args},
+        'rollback': False|True,
+        'time': time_in_float,
+        'sql':_sql_query_as_a_string,
+    }
+    """
+
     name = 'RQL'
     title = 'RQL queries'
     nav_title = 'RQL'
@@ -36,20 +50,33 @@
     def __init__(self, request):
         self.data = {
             'rql_queries': [],
+            'sql_queries': [],
             'highlight': highlight_html,
             'generate_css': generate_css,
         }
         subscribe_to_debug_channel("rql", self.collect_rql_queries)
+        subscribe_to_debug_channel("sql", self.collect_sql_queries)
 
     @property
     def nav_subtitle(self):
         return '%d' % len(self.data['rql_queries'])
 
     def collect_rql_queries(self, rql_query):
+        rql_query["generated_sql_queries"] = []
+
+        # link sql queries to rql's one
+        for sql_query in self.data["sql_queries"]:
+            if sql_query["rql_query_tracing_token"] == rql_query["rql_query_tracing_token"]:
+                rql_query["generated_sql_queries"].append(sql_query)
+
         self.data["rql_queries"].append(rql_query)
 
+    def collect_sql_queries(self, sql_query):
+        self.data["sql_queries"].append(sql_query)
+
     def process_response(self, response):
         unsubscribe_to_debug_channel("rql", self.collect_rql_queries)
+        unsubscribe_to_debug_channel("sql", self.collect_sql_queries)
 
 
 def includeme(config):
diff -r d5ae5abd0876 -r 10b8352b0208 cubicweb/server/sources/native.py
--- a/cubicweb/server/sources/native.py	Wed Jul 31 04:16:20 2019 +0200
+++ b/cubicweb/server/sources/native.py	Thu Aug 01 20:30:16 2019 +0200
@@ -24,6 +24,7 @@
 import pickle
 import re
 import itertools
+import time
 import zipfile
 import logging
 import sys
@@ -39,6 +40,7 @@
                       UniqueTogetherError, UndoTransactionException, ViolatedConstraint)
 from cubicweb import transaction as tx, server, neg_role, _
 from cubicweb.utils import QueryCache
+from cubicweb.debug import emit_to_debug_channel
 from cubicweb.schema import VIRTUAL_RTYPES
 from cubicweb.cwconfig import CubicWebNoAppConfiguration
 from cubicweb.server import hook
@@ -684,6 +686,16 @@
         """Execute a query.
         it's a function just so that it shows up in profiling
         """
+
+        query_debug_informations = {
+            "sql": query,
+            "args": args,
+            "rollback": False,
+            "rql_query_tracing_token": rql_query_tracing_token,
+        }
+
+        start = time.time()
+
         cursor = cnx.cnxset.cu
         if server.DEBUG & server.DBG_SQL:
             print('exec', highlight_terminal(query, "SQL"), args, cnx.cnxset.cnx)
@@ -699,6 +711,7 @@
             if rollback:
                 try:
                     cnx.cnxset.rollback()
+                    query_debug_informations["rollback"] = True
                     if self.repo.config.mode != 'test':
                         self.debug('transaction has been rolled back')
                 except Exception:
@@ -741,6 +754,9 @@
                         raise ViolatedConstraint(cnx, cstrname=mo.group(1),
                                                  query=query)
             raise
+        finally:
+            query_debug_informations["time"] = (time.time() - start) * 1000
+            emit_to_debug_channel("sql", query_debug_informations)
         return cursor
 
     @statsd_timeit