Improve developer habits by showing time cost of DB queries

Love things like this.

Here's a screenshot expanded version of our staff bar on GitHub.com:

http://cl.ly/image/0O0N183x2F44

Most of those numbers are clickable. The graphs button on the left links to a flame graph (https://www.google.com/search?q=flame+graph) Ruby calls of the page. The microscope button is a sorted listing of CPU time and idle time by file that went into the page's render. The template number links to a timing breakdown of all the partials that went into the view. The SQL timing links to a breakdown of MySQL queries for that page, calling out N+1 queries, slow queries, or otherwise horrible database decisions. Depending on the page, we'll also have numbers for duration and queries spent in redis, elasticsearch, and gitrpc.

Our main github.com stuff is pretty tied into our stack, but one of our employees, Garrett Bjerkhoel, extracted a lot of this into peek, a very similar implementation of what we have on GitHub. We use peek in a ton of our smaller apps around the company. Here's the org: https://github.com/peek

I recently developed a profiler for my company's web application. It uses dynamic introspection to profile (nearly) all function calls on the server side. It automatically picks up any SQL queries and profiles them as well. It's all packaged up in a web interface which can be invoked on any page on the site. You can see the exact queries, sort functions by time or number of calls, etc. It also shows a full reconstruction of the call tree, with individual branches expandable and collapsible.

It was a lot of fun to write and has been just as fun to use. We've found a number of simple changes that led to big performance gains on some of the pages.

As much as people like to make fun of PHP, symfony2 has the best development toolbar I've ever seen, with the previous winner from symfony1.

Sometimes what bothers me is I sometimes have no idea if a query is slow or not. This holds more true since I've been developing on Rails with Postgres. With MySQL it seems the bottleneck queries seem a lot more exponentially progressively degrading in correlation to the amount of records in a set. With Postgres this seems to be a lot more linear.

I have just made some crafty work in rails to make use of hstore datatypes in Rails. It stores an array of hashes, which I have not found a way to index the keys of yet.

Is this slow or fast for example? I'm doing a full-text search over all unnested (hstore) array values over a given column in a table wih 35k records.

    development=# SELECT "leads".* FROM "leads"  WHERE ( exists ( select * from  (SELECT svals(unnest("address"))) x(item) where x.item LIKE '%mst%') );

Time: 57.257 ms

I'm used to MySQL, and this kind of query over unindexed records seems fast, but it also seems this might be slow for Postgres standards ?:/ Bear in mind.. no indices.

Great tip! For rails devs, I strongly recommend rack-mini-profiler [0]. It gives you an in-browser view of rendering time (which you can expand to break out by partial) with query time listed for each query. Each query also includes a stacktrace to make it easy to fix offensive queries. Great for identifying N+1 query bugs as well. There's a railscast for it, too [1].

[0] https://github.com/MiniProfiler/rack-mini-profiler

[1] http://railscasts.com/episodes/368-miniprofiler

The .net world has http://miniprofiler.com/ and http://getglimpse.com/ which work really well.

They will also show you the sql (useful when it is generated by an orm) and breakdown each queries time cost.

For Django, there's https://github.com/django-debug-toolbar/django-debug-toolbar .

For Rails, there's https://github.com/josevalim/rails-footnotes.

Forgive/correct me if there are newer or better alternatives.

If you do significant work with databases, you should have a DBA.

When I was in that role, I combined education, public humiliation, cajoling and various administrative means to discourage bad database behaviors or optimize databases for necessary workloads. The median developer can barely spell SQL... Adult supervision helps.

Whatever I was making then, I probably recovered 3-5x my income by avoiding needless infrastructure and licensing investments.

If you use App Engine you can use https://github.com/kamens/gae_mini_profiler ==> modeled after the Stack Overflow folks' miniprofiler.

MiniProfiler supports this and more. It exists for:

ruby: https://github.com/MiniProfiler/rack-mini-profiler

.net: https://github.com/MiniProfiler/dotnet

go: https://github.com/MiniProfiler/go (w/ support for app engine, revel, martini, and others)

If there is a python dev who wants to port MiniProfiler to python, I would love to help (I'm a MiniProfiler maintainer and did the go port). The UI is all done, you just spit out some JSON and include the js file. Kamens has a good port, but it's not based on this new UI library.

I wrote sqltap not too long ago to solve this problem for users of SQLAlchemy, complete with pretty web UI for visualizing not just the queries, but also where they originated in the application:

It also lets you dynamically enable/disable the introspection so you could run it in production.

https://github.com/inconshreveable/sqltap

I have the following on localhost at the bottom of every page:

<!--

    head in <?php echo number_format($head_microttime, 4); ?> s

    body in <?php echo number_format(microtime(true) - $starttime, 4); ?> s

    <?php echo count($database->run_queries); ?> queries

    <?php if (DEBUG) print_r($database->run_queries); ?>

-->

Example output:

<!--

    head in 0.3452 s

    body in 0.7256 s

    32 queries

    Array(

    [/Volumes/data/Sites/najnehnutelnosti/framework/initialize.php25] => SELECT name,value FROM settings

    [/Volumes/data/Sites/najnehnutelnosti/framework/initialize.php45] => SELECT * FROM mod_captcha_control LIMIT 1

    [/Volumes/data/Sites/najnehnutelnosti/framework/class.frontend.php123] => SELECT * FROM pages WHERE page_id = '1'

    [/Volumes/data/Sites/najnehnutelnosti/framework/class.wb.php96] => SELECT publ_start,publ_end FROM sections WHERE page_id = '1'

    [/Volumes/data/Sites/najnehnutelnosti/framework/frontend.functions.php28] => SELECT directory FROM addons WHERE type = 'module' AND function = 'snippet'
    ...etc

) -->

The array keys are the file from which the query originates with line number and the value is the query. I made it due duplicate queries. Query method in my class.database.php for the above output: public $run_queries = array();

    function query($statement) {
        $mysql = new mysql();
        $mysql->query($statement);
        $backtrace = debug_backtrace();
        $this->run_queries[$backtrace[0]['file'].$backtrace[0]['line']] = $statement;
        $this->set_error($mysql->error());
        if($mysql->error()) {
            return null;
        } else {
            return $mysql;
        }
    }

We've been using NewRelic at my work for a few months now and this is capability is incredibly helpful. When a page is slow you can see which of the numerous queries may be at fault (or if it's being spent in code Ina bad loop, etc.)

That's a fine and good idea, but don't exclude the front end time.

SQL servers can be faster places to carry out certain types of operations on data, and it may be quicker to write the right kind of query for the server, than choose a very quick query and have to spend time on the front end processing that data.

The ultimate goal is time to eyeballs, not fastest query time. The best achieve that is to measure every stage not just queries, and spend time profiling and experimenting with various operations.

CakePHP has the DebugKit Toolbar[1] which I've ported internally to our symfony application at work (it's quite a bit better than the symfony debugbar).

Example from google: http://blog.japanesetesting.com/wp-content/uploads/2009/11/d...

[1] https://github.com/cakephp/debug_kit/

This is okay, but what about showing the actual queries? What about showing how long each query took? I wrote some code that actually logs all this information directly to Chromes Console log. Pretty awesome: http://bakery.cakephp.org/articles/systematical/2013/05/08/h...

I've been fortunate enough to work for a company that develop performance monitoring so I always dogfood the latest cutting edge stuff that we do.

Best part of the performance monitoring is that if the Request spans multiple Servers (load balancer/proxy, web-app, microservices, DB, etc), I can see it as a single transaction so that I can easily track down which Microservice that caused the performance slowness. For example, we have a web-app written in Python and a Microservice written in Java. A single request can end up at the Microservice level and our tool can see truly end-to-end => load balancer to web-app to microservice to database.

On top of that, we also have an app that performs synthetic monitoring where I can set to automate certain User workflow and set it to run every 5 minutes. Combining both performance monitoring and synthetic monitoring give us a leg up on automating performance monitoring!

Disclaimer: I work for AppNeta.

Ironically the destination site is now down. I'll just leave this here: http://research.google.com/pubs/pub36356.html

New Relic's application monitoring and transaction traces were invaluable for us. For particularly slow transactions it provides a detailed view of the time spent in each function call and each SQL query.

If you're rolling an SQL timer of your own, be a bit careful. On most relational databases it's quite possible for your first result(s) to come back extremely quickly, but additional processing to be required to retrieve subsequent results - effectively a lazy evaluation. If you measure time to first result you may get an inaccurate picture of the cost of certain classes of query.

In the debugtoolbar queries through SQLAlchemy are picked up and logged, and it shows the query, as well as how long it took.

https://github.com/pylons/pyramid_debugtoolbar

The cool thing is that you can also click on EXPLAIN and get back information from the DB directly on what indexes it is using/maybe not using.

For Rails apps I use Peek: https://github.com/peek/peek

My tip is to watch the queries "live". Just enable "general query log", and "tail -f" the log file

With Flask + SQLAlchemy you can either set app.config['SQLALCHEMY_ECHO'] to True (which will output SQLAlchemy's queries to the console) or you can use http://flask-debugtoolbar.readthedocs.org/en/latest/

I actually use something like this in every asp.net project (it's called miniprofiler).

But most of us create small projects, pre-optimizing would be a hassle and useless for the client (pre-omitizing just costs more).

If you're a startup, you should use this, not for creating smb client software/webapps.

For what it's worth, this is easily done if you're coding something with PHP on top of WordPress:

    - add `define( 'SAVEQUERIES', true );` to your wp-config.php
    - add `global $wp;var_dump( $wp->queries );` at the bottom of your script

We built Speedbar for django which does this as part of its summary information, but also provides full page profiles as well in production.

https://github.com/theospears/django-speedbar

In addition, I would track with a web analytics tool the number of queries and the time they took for each page, so I could easily have them as metrics in the Pages Report.

Next, sort pages by query time and optimize them first.

Any suggestions for something similar with CodeIgniter or even native PHP?

Has anyone got a way to do this for API calls? I'd love to be able to get some json back at the end of a call that shows how many queries/how long they took.

For Rails I use Bullet to warn me about slow N+1 queries.

https://github.com/flyerhzm/bullet

Maatkit is great for profiling your MySql queries in production. http://www.maatkit.org/

More often than not, the slowness end users experience is problems in the front end - not the database. Think uncompressed assets, cache misses, or unused javascript and stylesheets. It's very likely most pages in your application are (or should) be served entirely from cache, so end users will benefit much more from front end optimizations.

I use mini-profiler from the guys @ Stackoverlow

How about starting with a blog that doesn't need a database so it can survive HN front page? jekyll + s3 works.