Added query duration to debug bar

[Toflar]

No description provided.

[aschempp]

Maybe we should use profiling on the database level for that?
http://stackoverflow.com/questions/2756100/testing-performance-of-queries-in-mysql

We could call SET PROFILES=1; when connecting to the database if debug mode is enabled, and then add the profiling info to the console.

[tristanlins]

Yeah, that would be nice, but this would only calculate the database execution time, not the php-db-layer time and the network transport time. So calculate both (the complete duration by @Toflar and the profiling suggested by @aschempp) would be the best way.

[aschempp]

Apparently it does calculate the network transportation time?

Sending data | 0.001309

[tristanlins]

Seems you are right.

Sending data
The thread is reading and processing rows for a SELECT statement, and sending data to the client. Because operations occurring during this this state tend to perform large amounts of disk access (reads), it is often the longest-running state over the lifetime of a given query.

http://dev.mysql.com/doc/refman/5.0/en/general-thread-states.html

[leofeyer]

If we want to use SHOW PROFILE, we will have to add a new method to the database drivers -> BC break -> Contao 4. If we go for @Toflar's approach, we can add it to Contao 3.4. What do you think?

[leofeyer]

Here's a POC for the database variant: 8ff54fe

[Toflar]

we will have to add a new method to the database drivers -> BC break

This could be easily solved with a SupportsProfilerInterface or the like:

if ($driver instanceof SupportsProfilerInterface)
{
    $foo = $driver->profiler();
}

So if the driver supports it, you'll get the info and if not, you don't. But no BC break ;-)

[aschempp]

Regarding your pull request, I think we should include more/all the information not only the duration in the console.

[leofeyer]

This is the complete output of SHOW PROFILE ALL. I don't think we need all this.

| Status               | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function       | Source_file   | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+
| starting             | 0.000023 | 0.000016 |   0.000007 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL          |        NULL |
| checking permissions | 0.000006 | 0.000004 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_parse.cc  |        4914 |
| Opening tables       | 0.000021 | 0.000016 |   0.000006 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 1 |     0 | open_tables           | sql_base.cc   |        4981 |
| System lock          | 0.000005 | 0.000004 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables     | lock.cc       |         307 |
| Table lock           | 0.000004 | 0.000003 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables     | lock.cc       |         312 |
| init                 | 0.000025 | 0.000024 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_select          | sql_select.cc |        3063 |
| optimizing           | 0.000006 | 0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_select.cc |         983 |
| statistics           | 0.000016 | 0.000014 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_select.cc |        1225 |
| preparing            | 0.000009 | 0.000009 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_select.cc |        1250 |
| executing            | 0.000003 | 0.000001 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_select.cc |        2231 |
| Sending data         | 0.000066 | 0.000053 |   0.000012 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_select.cc |        2862 |
| end                  | 0.000003 | 0.000002 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_select          | sql_select.cc |        3098 |
| query end            | 0.000003 | 0.000002 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc  |        4522 |
| closing tables       | 0.000007 | 0.000006 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc  |        4582 |
| freeing items        | 0.000003 | 0.000002 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse           | sql_parse.cc  |        5813 |
| updating status      | 0.000011 | 0.000002 |   0.000008 |                 0 |                   0 |            0 |             0 |             1 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc  |        1469 |
| cleaning up          | 0.000003 | 0.000003 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc  |        1486 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+

[aschempp]

Personally, I only understand the first column (Duration). But I would include the full list of items. Maybe @LeoUnglaub knows if any of the others is ever useful for a PHP developer to debug something?

[leo-unglaub]

For debugging PHP applications you normaly only need the duration. The other values normaly don't mean anything to PHP developers. However, if you have a query that kills down the database server, the columns SWAPS, SOURCE_FUNCTION, SOURCE_FILE and SOURCE_LINE are important to create bug reports in to the database server developers. Maybe it would make sence to include those values if the user is in a special expert debug mode.

[aschempp]

@LeoUnglaub only a summary of the duration or each individual one?

[leo-unglaub]

I would say both. For 90% of all problems the overall time is enought to find the problem. However, the normal 90% of all problems are not the hard ones to debug. If you really have a 100 line SQL query, you need the individual times to see where exactly your query breaks performence. If it is the sending of the result set (<- maybe to large result set) or the parsing time (<- some missing braces).

I would display the overall time but in a tooltip generate all values.

[leofeyer]

As discussed on Mumble (October 9th), we will be using the initial microtime() approach, which will be sufficient to identify the problematic queries. Those queries can then be debugged manually.