Add SQL queries profiler in Debug zone with backtrace of call and EXPLAIN hovers

[beat]

This implements FR #31087 (only active in debug-mode).
Pretty handy in improving SQL queries and database scheme for speed.
Made a quick hack for my JAB13 talk, and re-did it on my return trip from JAB13 cleanly.

http://joomlacode.org/gf/project/joomla/tracker/?action=TrackerItemEdit&tracker_item_id=31087

Feel free to improve upon it by issuing pull requests on my fork (on my branch mysqlprofiling).

[mahagr]

Is there any specific reason why you store two values of microtime() instead of just using local variable and storing the difference?

[beat]

Yes, it is for also displaying the delay between 2 queries: That allows to see the time taken to fetch the data from the previous query and to handle it in PHP.

Btw, I'm continuing work on this to add the very detailed profiling information for each query: That way there will be no reasons to copy-paste the query into PhpMyAdmin to see the internal MySQL profiling, and that will win additional time in analysis. Also highlighted NULL keys, so it's immediately visible which parts run without using indexes.

So please wait for my next commit and next comment here before testing and accepting pull request.

[ghost]

Very cool.
Would also be more useful if there was some visual indication of which queries are the time-hoggers. Maybe color-label them based on their time vs the average query time. Or show a time bar representing the time it took.
And maybe an ordering option to show the longest times first.

Side note: Ordering of the stuff under Profile Information would be good to have flipped too. So afterRender is at the top of the list.

[beat]

Ok, added visual indications for problems and time-hoggers (color-based). Sorting is not really needed with the visible red-on-yellow color-indications.

Improvements as always welcome with pull request now here, or later on CMS.

I'm considering now this pull request final for now. It is already a much better output for SQL optimizations than in any other CMS I know of.

[beat]

Just to complete the instructions:

• hover on query shows EXPLAIN table (with red highlighting of NULL keys)
• hover on time shows SHOW PROFILE information (with red highlighting of 2 slowest times when more than 1 ms)
• hover on filename shows call-stack (outside JDatabase)

[roland-d]

Just applied the PR to the joomla-cms master branch and all works as explained except for the hovers. The tables are not rendered in the tooltip and just shows the html code. Can someone reproduce that?

[ghost]

There is a fix for that here: #1239

[roland-d]

Indeed, it fixes it but it still doesn't look pretty to me. Attached is the screenshot as it shows now:

[ghost]

@beat Could you take a look at this branch? https://github.com/nonumber/joomla-cms/tree/debug

Changed output. Bootstrapped it a bit and added a nice visual bar thing:

[beat]

@roland-d,
Does function work as expected before we speak of style ?

Regarding styling of tooltips: Please feel free to contribute improvements. I have looked at styling them the best I could, however without any specific class for that dynamically added div at end of body by the tooltip code it looks like not possible to style them specifically to the debug module tooltips. E.g. the tooltip itself is fixed 200px max-width and can't be changed, it also has that oppacity of 0.8 that doesn't look great. The way I found to get rid of the 200px width is to CSS-float the div inside the tooltip. the very small black rectangle at top is the remaining part of the tooltip.

Also make sure to clear your cache before testing, as the debug.css file is changed by this patch and Joomla doesn't have a "?r=revisionXYZ" differenciator to make sure caches do not stay with new releases.

Also debug module executes at very of the php lifetime. Actually even after the mysql database is disconnected by the destructor of JDatabaseDriver called by PHP ending! So it is way too late to add javascript into the header. I'm also reluctant to add debug-specific Javascript to the document head or end of body too, as we want the debug ON behavior to be as near as possible from the normal one. That's also why I do EXPLAIN and SHOW PROFILE statements in a new database disconnectHandler at very end of PHP execution, to not change the execution timing and behavior of the rest of the page. I believe that for the backtrace popup, we can live with it for a few weeks/months, before the tooltip is changed from Mootools to jQuery.

@nonumber, 👍
Thanks for the improvement, great! I will be looking at it as soon as I get a bit more time. So if needed, you have a bit more time to refine it and get feedbacks from @roland-d

Please make a pull-request towards my branch beat:mysqlprofiling so I can review diffs and merge into the existing pull-request to joomla:master.

[ghost]

@beat can't seem to be able to PR towards your branch :S
I see a lot of different joomla-cms branches in the pulldown, but yours ain't there...
Trying to create a PR via online edit of file on your branch, gives a 404 page after send.

PS: Can you merge your branch with latest J master? It seems to be behind a bit...

[roland-d]

@beat: Functional wise it is good, I see all the info in tables. Just a little hard to read at the moment. I will see what I can do about the styling. I just wasn't sure if this was supposed to look like. Maybe you already added some cool styling and if I would change it, it would be useless ;)

Peter's addition looks finger licking good ;)

[ghost]

Maybe good to have the EXPLAIN and other stuff in sliders or tabs instead of in tooltips...
Maybe I'll play with it some more.

[elkuku]

This looks awesome. Seems like Joomla! is finally reaching the pro league ;)
Normally good coders are not good designers, so don't worry about the styling right now - we have some good designers in our community :)

One small remark about the file links: I already implemented the "xdebug:// protocol" that is set using the php.ini., and does basically the same as the "editor:// protocol".
See: http://xdebug.org/docs/all_settings#file_link_format
This way the links are only displayed, if the user has set up his/her system to use them.
See: https://github.com/joomla/joomla-cms/blob/master/plugins/system/debug/debug.php#L866
And you will save some lines of code ;)

Another idea that came to my mind is using the logger to pass the information to the plugin (or whoever set the logger), so it doesn't have to be stored in the internal log of the database driver.
I'm playing with it right now in our JTracker thingy and it looks nice.

Also I've implemented it with tabs instead of tooltips. Seems that I'm getting old or I need some new glasses, because the tooltips are way to small 👅

Excellent work 👍

[beat]

@elkuku : Great find, I'm fine with myide://%f@%l

@nonumber : Tabs are not loaded by default on most pages, to the contrary of tooltips, and tabs are not suitable here, as when analyzing you want to look at same time at EXPLAIN and at query, otherwise it's not understandable. I believe we can tweak a bit more the table's CSS to make it less tall (if last column doesn't wrap it would do it).

@nonumber and others with improvement proposals: Please fork my fork, then change only the files changed and do pull request towards my mysqlprofiling branch, so I can merge them.

@elkuku : The logger arrays don't eat space when not used, and when used they eat the same space. Keep in mind that there is normally only one JDatabaseDriver instance. Also the log and Disconnect handler could be useful for other applications (e.g. to make sure that session handler gets always the chance to store the session before database is closed ;-) ).

[ghost]

@beat It is not possible to simply fork a fork. And like stated earlier, the other methods of creating a PR towards your branch fail.

[beat]

@nonumber wierd. A year back @elkuku added a pull request to my other fork here https://github.com/joomla/joomla-platform/pull/736/commits (but it was the "master" branch of the fork)... That's why I thought it was possible here too.

You can attach here a patch file as well (hm :-D no attach function here either, looks like GitHub lacks features that GitLabs (open-source!) has LOL.

You can email or skype me a patch file (my mail is my username here "at" our website). That should work :-)

[ghost]

Easiest to just copy/paste code from: https://github.com/nonumber/joomla-cms/blob/debug/plugins/system/debug/debug.php

[elkuku]

Well, I believe the easiest way to do stuff like this is communication.
Git allows you to add multiple "remotes" to your local clone.
For example: @beat opened this pull request, so he is basically "the owner".
Now while this PR is open, other people could manifest in some way that they might also have to contribute something.

Example:
@nonumber

Hi @beat, I did some changes in my debug branch, have a look at 8ff8f17

(Note: the last link is written as 8ff8f177b782307330147d4de7b30f71e842bedc and automagically converted by GitHub to the correct href. See: github-flavored-markdown#references)

Now what @beat does (if he has the time and will to do so) is just adding @nonumber as a new remote to his local clone.

cd path/to/repo
git remote add nonumber git://github.com/nonumber/joomla-cms.git
git fetch nonumber

From here on @beat uses his favorite git tool to examine @nonumber's repo and do whatever he feels apropiate.
For example he wants to merge the changes from @nonumber's debug branch into his mysqprofiling branch:

cd path/to/repo
git checkout mysqlprofiling
git merge nonumber/debug

Now @beat pushes to his mysqlprofiling branch to GitHub, so his pull request will include also @nonumber's additions.

git push origin mysqlprofiling

That would be it.

(Note on the example: It might have been easier if @nonumber had added @beat's repo as a remote first, and then based his work off @beat's mysqlprofiling branch if both are working on the same "feature" ;) )

I admit that this process might seem a bit complicated and if you only have one contribution, a simple pull request would be much easier.
But if you work on some feature over some period of time, this form of collaboration is really awesome.

Of course, this implies that all persons involved in this process "have time" - not like me right now - see ya ;)

[elkuku]

Oh - BTW..... this could be a nice example of a contribution of several persons. It would be really cool if our new tracker could reflect this in "some way", so everybody gets his/her credits. (I know that nobody cares, but yes they do..)
Any ideas ?

[elkuku]

Another BTW: I can't send a PR to beat either. Seems like GitHub limits the list to the most active repos or something like that... that's really bad :(

[beat]

@elkuku 👍
You wrote:

One small remark about the file links: I already implemented the "xdebug:// protocol" that is set using the php.ini., and does basically the same as the "editor:// protocol".
See: http://xdebug.org/docs/all_settings#file_link_format

Did you mean by this of reading php.ini setting "xdebug.file_link_format" (how?) and then replace %f with the filename and %l with the line number in that string ?

[elkuku]

Sure, the setting is just read with ini_get() here: debug.php#L67 in the __construct() method and stored to the $linkFormat member, so you call the formatLink() function which gives you back a link or just the plain file route if the setting is not found.

The debug plugn really needs refactoring as it is about to reach the 1k line limit ;)

[elinw]

I've had that issue with sending PRS to @davidhurley and @andreatarr before, it was very mysterious but eventually magically resolved..

[ghost]

I have sent this support request to github: http://quick-markup.com/p/51b3112230d85

[roland-d]

@nonumber The work was already done but go ahead. I won't touch anything anymore.

[ghost]

Tadaaa: beat#3

See live demo: http://ndev.nl/debug

[beat]

@nonumber 👍 Just seen demo, looks awesome!

Commenting on the pull request.

[elkuku]

It's getting better and better.
The live demo looks awesome.
What do you think if we include the query itself also in a slider ? that would make things more compact ;)

[ghost]

I think the actual query is something you always want to see. As that is what you are inspecting. So when viewing the Explain or Profile Info, you still want to see the specific query to see what it refers to and see if you can spot why the info in there is like it is.
So I don't really see it as a useful/necessary thing to be able to hide the query.

[beat]

I agree with @nonumber :) : Queries should always stay visible.

[elkuku]

correct, bad idea. :(

[beat]

Ok, I've now merged after review this new version and many improvements suggestions that @nonumber implemented brilliantly (Thank you)

I'm now declaring this pull request feature-complete and tested by its authors.
Si we are now doing a features-freeze on this pull request. ;-)

Warning: It has become a powerful tool to show that a page is slow-loading and to help pinpoint reasons for slow-loading pages :D

So we are ready for final testing at tracker, so that it can be committed.

[roland-d]

Tested and commented on the tracker. All looks great :)

[beat]

Updated branch (merged from latest joomla-cms/master), solving trivial conflicts (a variable has been renamed in some of the drivers in joomla-cms/master).

[ghost]

The $sql to $query? :) That was my doing in a global database cleanup PR: #856

[beat]

Ok, as language tests had failed and new tests are required, I fixed those, and also added a handy display of size of database query result in memory and rows for each query. :-)

Ready for final tests and review.

[elkuku]

I believe that for PRs like this one, it would be nice if actually all commits would be included when merging. But well, it has been merged 👍