Issues

ZF-10486: Zend_Db_Profiler doesn't take into account the DESCRIBE queries used internally

Description

If I have a class like this one...

class Application_Model_DbTable_Languages extends Zend_Db_Table_Abstract
{

    protected $_name = 'languages';
    protected $_primary = 'id_lang';

}

... the framework will do a DESCRIBE TABLE query (at least on MySQL) before using it to gather info about the table. I can see those queries piling up on the MySQL log but the profiler won't take them into account using:

$adapter = Zend_Db_Table::getDefaultAdapter();
$profiler = $adapter->getProfiler();
var_dump($profiler->getTotalNumQueries());
var_dump($profiler->getQueryProfiles(null, true));

When I set up the metadata cache the queries are not executed and the profiler still shows the same amount of queries as before.

Comments

This is by design as you would not want to hide anything that might happening between your application and the database by default.

There are two work arounds for you: the first is to extend the profiler and check the first few characters of each query to determine if you want to log it. The second is to give Zend_Db_Table a cache object so that it can cache the results of the DESCRIBE table lookup that it is doing.

If anything, this is a feature request of Zend_Db_Profiler to selectively "listen in" on specific query types.

{quote}you would not want to hide anything that might happening between your application and the database by default.{quote}

But it is hiding all the DESCRIBE queries. I think I might have not explained the problem correctly.

Let me tell you how I came across this which might explain why I reported it as a bug rather than a feature request.

A website I did got a popularity spike and MySQL started maxing out on its number of connections. The first thing I did was fire the profiler and do some math based on the result of getTotalNumQueries() and the hits reported by apache. The math didn't add up so I put the app in a sandbox and found that my ZF app was executing more queries than the profiler was reporting! This ended up having nothing to do with the actual website problem but it is how I learned that the DESCRIBE queries where not getting logged by the profiler.

It thought that this was an odd default ZF behavior and started looking whether I could enable full logging in the profiler but apparently the profiler was set to show all the queries (but was obviously failing to log the DESCRIBE ones).

I made the metadata cache comment as a sort of test case to provide some proof that the profiler wasn't logging correctly (according to my understandind of what it should do, that is). Basically what I meant was that for a single database fetchAll() operation:

||_||Actual Query Count in MySQL log||Query Count on Profiler|| |Without metadata cache|2|1| |With metadata cache|1|1|

I don't think I'm ZF savvy enough yet to extend the profiler, but sounds like a fun enough challenge!

Are you using Mysqli or PDO_Mysql adapter?

Ralph, I completely forgot that there was another adapter available to me!

My tests were using the mysqli adapter and also I wasn't specifying any charset. The MySQL version I'm using is 5.1.36. Here are the results of some more tests I've made, this time specifying a charset. Instead of giving you the query count I'll just copy paste the queries straight from the mysql log and profiler.

I removed the timestamps and connection number from the mysql logs to make it more readable.


class IndexController extends Zend_Controller_Action
{

    public function indexAction()
    {
        $languageTable = new Application_Model_DbTable_Languages();
        $languageTable->fetchAll();

        $profiler = $languageTable->getAdapter()->getProfiler();
        Zend_Debug::dump($profiler->getQueryProfiles(null, true));

        die();
    }

}

I've marked in {color:red}red{color} all the things I believe the profiler is failing to log.

h2. mysqli (without metadata cache)

|| MySQL log || Profiler || |{color:red} Connect root@localhost on test{color} Query {color:red} SET NAMES utf8{color} Query {color:red} DESCRIBE languages{color} Prepare SELECT languages.* FROM languages Execute SELECT languages.* FROM languages Reset stmt
Close stmt
Quit|SELECT languages.* FROM languages

h2. mysqli (with metadata cache)

|| MySQL log || Profiler || |{color:red}Connect root@localhost on test{color} Query {color:red}SET NAMES utf8{color} Prepare SELECT languages.* FROM languages Execute SELECT languages.* FROM languages Reset stmt Close stmt Quit|SELECT languages.* FROM languages


h2. pdo_mysql (without metadata cache)

|| MySQL log || Profiler || |Connect root@localhost on test Query {color:red}SET NAMES 'utf8'{color} Query DESCRIBE languages Query SELECT languages.* FROM languages Quit|connect DESCRIBE languages SELECT languages.* FROM languages

h2. pdo_mysql (with metadata cache)

|| MySQL log || Profiler || |Connect root@localhost on test Query {color:red}SET NAMES 'utf8'{color} Query SELECT languages.* FROM languages Quit|connect SELECT languages.* FROM languages