inconshreveable / sqltap Goto Github PK

View Code? Open in Web Editor NEW

338.0 11.0 48.0 496 KB

SQL profiling and introspection for applications using sqlalchemy

License: Other

Python 77.67% Mako 22.33%

sqltap's Introduction

sqltap - a library for profiling and introspecting SQL queries made through SQLAlchemy

sqltap helps you quickly understand:

how many times a sql query is executed
how much time your sql queries take
where your application is issuing sql queries from

Full Documentation

http://sqltap.inconshreveable.com

Motivation

When you work at a high level of abstraction, it’s more common for your code to be inefficient and cause performance problems. SQLAlchemy’s ORM is excellent and gives you the flexibility to fix these inefficiencies if you know where to look! sqltap is a library that hooks into SQLAlchemy to collect metrics on all queries you send to your databases. sqltap can help you find where in your application you are generating slow or redundant queries so that you can fix them with minimal effort.

Quickstart Example

import sqltap

profiler = sqltap.start()
session.query(Knights).filter_by(who_say = 'Ni').all()
statistics = profiler.collect()
sqltap.report(statistics, "report.html")

WSGI integration

You can easily integrate SQLTap into any WSGI application. This will create an up-to-date report page at /__sqltap__ where you can dynamically enable/disable the profiling so you can easily run it selectively in production. Integrating is super-easy:

import sqltap.wsgi

wsgi_app = sqltap.wsgi.SQLTapMiddleware(wsgi_app)

For example, to integrate with a Flask application:

import sqltap.wsgi

app.wsgi_app = sqltap.wsgi.SQLTapMiddleware(app.wsgi_app)

Text report

Sometimes we want to profile sqlalchemy on remote servers. It's very inconvenient to view HTML format SQLTap report on these servers. Alternatively, SQLTap provides text profiling report in a human-readable way.

import sqltap

profiler = sqltap.start()
session.query(Knights).filter_by(who_say = 'Ni').all()
statistics = profiler.collect()
sqltap.report(statistics, "report.txt", report_format="text")

Advanced Example

import sqltap

def context_fn(*args):
    """ Associate the request path, unique id with each query statistic """
    return (framework.current_request().path,
            framework.current_request().id)

# start the profiler immediately
profiler = sqltap.start(user_context_fn=context_fn)

def generate_reports():
    """ call this at any time to generate query reports reports """
    all_stats = []
    per_request_stats = collections.defaultdict(list)
    per_page_stats = collections.defaultdict(list)

    qstats = profiler.collect()
    for qs in qstats:
        all_stats.append(qs)

        page = qstats.user_context[0]
        per_page_stats[page].append(qs)

        request_id = qstats.user_context[1]
        per_request_stats[request_id].append(qs)

    # report with all queries
    sqltap.report(all_stats, "report_all.html")

    # a report per page
    for page, stats in per_page_stats.items():
        sqltap.report(stats, "report_page_%s.html" % page)

    # a report per request
    for request_id, stats in per_request_stats.items():
        sqltap.report(stats, "report_request_%s.html" % request_id)

Testing

Run the sqltap tests:

python setup.py test

License

Apache

sqltap's People

Contributors

Stargazers

Watchers

sqltap's Issues

Support text profiling result output

Thanks for your great tools first. But many times we are using sqlalchemy on remote servers without web service. It's very inconvenient to use sqltap on these servers. Could you add support for creating profiling result output in raw text format?

SQLTap always returns 0 rows count

Hi,
I noticed that with SQLTap (0.3.10), the displayed rows count is always of 0!!!

Thank you for making this library!

I've just started profiling the queries on a few pages of our app, and this library makes it super easy... Thanks a ton!

External CSS and JS loaded over HTTP instead of HTTPS

While running Safari Technology Preview 14 on OS X El Capitan 10.11.6, sqltap loads several external CSS and JavaScript resources over HTTP instead of HTTPS. When the instrumented web app is running over HTTPS, the non-HTTPS resources requested by sqltap are refused by the browser:

Would it be possible to make external resources always load over HTTPS, or ship them within sqltap?

Thanks so much for making such a great tool. It's one of my go-to debugging tricks!

Update: Chrome 53 behaves in the same way, but additionally reports that sqltap is insecurely loading the parent site's favicon.

latest release

is there a reason why the latest version of master (0.3.11) is not the version on Pypy (0.3.10) ?

Sqltap showing incorrect "Query Count" in certain cases

Sqltap is showing that only a single query was performed, when it fact 43 were.

If I set echo=True for sqlalchemy, the relevant output is:

2019-07-01 16:35:48,649 INFO sqlalchemy.engine.base.Engine DELETE FROM master_steps WHERE master_steps.id = %(id)s
2019-07-01 16:35:48,649 INFO sqlalchemy.engine.base.Engine ({'id': 13701}, {'id': 13702}, {'id': 13703}, {'id': 13704}, {'id': 13705}, {'id': 13706}, {'id': 13707}, {'id': 13708}  ... displaying 10 of 43 total bound parameter sets ...  {'id': 13742}, {'id': 13743})

Turning on postgres logging, we see the actual queries (this was from a different run than the above example with echo=True, so the times and ids are different):

2019-07-01 17:07:34.522 PDT [83440] LOG:  statement: DELETE FROM master_steps WHERE master_steps.id = 39873
2019-07-01 17:07:34.540 PDT [83440] LOG:  statement: DELETE FROM master_steps WHERE master_steps.id = 39874
... (repeat for all bound parameter sets)

The last bound parameter set is the one being shown in sqltap. Based on the timings from the postgres logs, it looks like the "Total time" shown is the correct value for the sum of all the query times. But the mean, median, max, etc are not correct. And the "Query Count" is not correct.

In case it is helpful, here is what the application code looks like (roughly):

for step in steps:
      db_session.delete(step)

# other logic unrelated to steps...

db_session.commit()

KeyError on HTML report

Every time I want to generate a HTML report with the new version (0.3.10) a KeyError(count,) in template rendering happens. I located the error to be here: https://github.com/inconshreveable/sqltap/blob/master/sqltap/sqltap.py#L371

JSONB support?

I'm having some problems running sqltap (version 0.3.10) when there is a JSONB field in one of the models.
It doesn't seem to handle dictionaries very well in general..

Is it a known issue? (could not find it reported)

cls = <class 'sqltap.sqltap.QueryStats'>
params = {'allow_supplier_project_creation': False, 'contribution_edit_reacceptance': True, 'contribution_time_enabled': True, 'created_at': datetime.datetime(2017, 8, 4, 12, 38, 46, 131500), ...}

    @classmethod
    def calculate_params_hash(cls, params):
        h = 0
        for k in sorted(params.keys()):
>           h ^= 10009 * hash(params[k])
E           TypeError: unhashable type: 'dict'

Virtual memory leak

I see unnormal situation.
I use sqltap in flask application (start metrics before request and collect after) for prometheus

    @app.before_request
    def app_before_request():
        if "prometheus" in app.extensions:
            request.sql_profiler = sqltap.start()

    @app.after_request
    def app_after_request(response):
        if "prometheus" in app.extensions:
            app.extensions["prometheus"].ExternalServiceMetric.set_sql_metric(
                metrics=request.sql_profiler.collect(),
                service="{}/{}".format(
                    mdl.db.engine.driver, mdl.db.engine.url.database
                ),
            )

        return response

and then look at the metrics of Prometheus. during operation, the application actively consumes memory and drops (host in GAE)

If I remove the collection of metrics, it will be (11:10)...

No one came across this?

Reported profiling duration is not accurate

The reported profiling duration is actually (time of last query - time of first query), which is not accurate if there is a long period of time between when profiling begins and when the first query is captured (same goes for last query and profile end).

It's not a big deal for now, but it should be changed at some point by possibly modifying the report() API to accept those values.

TypeError: unhashable type: 'NestedMutable'

When using SQLAlchemy and a JSON and/or HSTORE column, SQL tap attempts to hash an unhashable type:

  File "/home/vagrant/local/venv/local/lib/python2.7/site-packages/sqlalchemy/event/attr.py", line 256, in __call__
    fn(*args, **kw)
  File "/home/vagrant/local/venv/local/lib/python2.7/site-packages/sqltap/sqltap.py", line 188, in _after_exec
    context, params_dict, results)
  File "/home/vagrant/local/venv/local/lib/python2.7/site-packages/sqltap/sqltap.py", line 64, in __init__
    self.params_hash = self.calculate_params_hash(self.params)
  File "/home/vagrant/local/venv/local/lib/python2.7/site-packages/sqltap/sqltap.py", line 71, in calculate_params_hash
    h ^= 10009 * hash(params[k])
TypeError: unhashable type: 'NestedMutable'

Current workaround in sqltap.py, line 71:

-            h ^= 10009 * hash(params[k])
+            if isinstance(params[k], collections.Hashable):
+                h ^= 10009 * hash(params[k])

show size(bytes) of sql result

How to import the wsgi - basic question

Hi,

I am trying to use the library to profile sqlalchemy calls.

This may be the most basic question. I am using flask application with Apache httpd server.
in init.py of the application have used the following code

import sqltap.wsgi
app = Flask(name)
app.wsgi_app = sqltap.wsgi.SQLTapMiddleware(app.wsgi_app)

I expected the query information to be present but it was not there

Am i missing something?

Can't print stack trace containing UTF-8 characters

Hi,
I use SQLTap and noticed a small problem: if my source code (encoded in UTF-8) contains hard-coded accentuated characters as SQLAlchemy query arguments, an encoding error is raised in Mako template when displaying the trace...
I quickly corrected by typing "${trace.decode('utf-8')}" in "html.mako" template, but this fix is probably not usable for people using other encodings...

Input output error,in appengine

not able to generate report.html ,

HTML report is not being generated (TypeError: must be str, not bytes)

When generating the report as html the following error occurs:
Traceback (most recent call last):
File "test_ingestion_xmls.py", line 1564, in
sqltap.report(statistics, "report.html", report_format="html")
File "/usr/local/lib/python3.4/dist-packages/sqltap/sqltap.py", line 534, in report
result = reporter.report()
File "/usr/local/lib/python3.4/dist-packages/sqltap/sqltap.py", line 381, in report
f.write(content)
TypeError: must be str, not bytes

Casting content as str makes visible the error:
KeyError: 'ingestion_duration'
/usr/local/lib/python3.4/dist-packages/sqltap/templates/html.mako, line 145:

                % for idx, query in enumerate(reversed(group.queries)):
                <tr class="${'hidden' if idx >= 3 else ''}">
                    <td>${'%.3f' % query.duration}</td>
                    % for param_name in params:
                    <td>${query.params[param_name]}</td> ## Here it seems to be the issue
                    % endfor
                    <td>${'%d' % query.rowcount}</td>
                    <td>${'%d' % query.params_id}</td>
                </tr>
                % endfor

This parameter is never used so I don't really understand why it is trying to use it.

Workaround to fix the issue

                % for idx, query in enumerate(reversed(group.queries)):
                <tr class="${'hidden' if idx >= 3 else ''}">
                    <td>${'%.3f' % query.duration}</td>
                    % for param_name in params:
                    % if param_name in query.params:  ## Enters only if key exists
                    <td>${query.params[param_name]}</td>
                    % endif
                    % endfor
                    <td>${'%d' % query.rowcount}</td>
                    <td>${'%d' % query.params_id}</td>
                </tr>
                % endfor

So, now it is accessing the parameters if they are available.

bug with MSSQL dialect - it's not safe to call str() on the full range of clause constructs

see https://bitbucket.org/zzzeek/sqlalchemy/issue/3179/python-3-mssql-2008r2-exception-in-dialect and 9c83fe8#commitcomment-7627053

SQLAlchemy 1.4 changes the signature of ConnectionEvents before_execute & after_execute

After upgrading to SQLAlchemy 1.4.22 (from 1.3.x), when using ProfilingSession, I now get warnings like:

SADeprecationWarning: The argument signature for the "ConnectionEvents.before_execute" event listener has changed as of version 1.4, and conversion for the old argument signature will be removed in a future release. The new signature is "def before_execute(conn, clauseelement, multiparams, params, execution_options)"

And:

SADeprecationWarning: The argument signature for the "ConnectionEvents.after_execute" event listener has changed as of version 1.4, and conversion for the old argument signature will be removed in a future release. The new signature is "def after_execute(conn, clauseelement, multiparams, params, execution_options, result)"

Requires SQLAlchemy 0.9+

The code assumes SQLAlchemy 0.9+ by depending on the new form of the events API. But setup.py states SQLAlchemy >= 0.8 as a requirement.

You could just change setup.py to say 0.9. If 0.8.x is to be supported, then this is a start:

diff --git a/sqltap/sqltap.py b/sqltap/sqltap.py
index 00d06cb..a1703c9 100644
--- a/sqltap/sqltap.py
+++ b/sqltap/sqltap.py
@@ -298,7 +298,7 @@ def _hotfix_dispatch_remove():
     monkey patch SQLalchemy so that it works """
     import sqlalchemy

-    if sqlalchemy.__version__ >= "0.9.4":
+    if sqlalchemy.__version__ >= "0.9.4" or sqlalchemy.__version__ < "0.9":
         return

     from sqlalchemy.event.attr import _DispatchDescriptor

but some test failures remain:

$ nosetests -x
.....E
======================================================================
ERROR: test_sqltap.TestSQLTap.test_context_manager
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/gthb/pyenv/DJANGO15/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/gthb/extsvn/sqltap/tests/test_sqltap.py", line 213, in test_context_manager
    q.all()
  File "/Users/gthb/extsvn/sqltap/sqltap/sqltap.py", line 180, in __exit__
    self.stop()
  File "/Users/gthb/extsvn/sqltap/sqltap/sqltap.py", line 171, in stop
    sqlalchemy.event.remove(self.engine, "before_execute", self._before_exec)
  File "/Users/gthb/pyenv/DJANGO15/lib/python2.7/site-packages/sqlalchemy/event.py", line 78, in remove
    for tgt in evt_cls._accept_with(target):
TypeError: 'Engine' object is not iterable