Show the originating PHP file in the SQL log

[thinkingmedia]

Overview

When we execute a pr("some data here") to display debug messages the output includes the file path to the PHP file that generated the output.

When we look at the SQL log panel in the DebugKit we don't get the context of the query. We just know it was executed, how many results and the duration. As a programmer, I ask myself this "Why is the SQL being executed?" and I don't know the answer. You either recognize the query or you don't.

The originating PHP file would help, but it's not that simple.

Challenges

You can't easily tell which PHP file in a stack trace is the true author responsible for creating the query. Furthermore, a programmer might argue he/she prefers to see the Controller instead of the Model, but both are in the call stack.

So we should include a stack trace, but stack traces are really big. We could reduced the stack trace (filtering out CakePHP core files) and attach it to the Query as metadata. This would be a configured feature (i.e. debug only) as it has obvious performance impacts. Where and when we do this is open to debate. If we do this in the Query constructor (obvious location) then we're adding core changes to one of the most used objects. So I prefer to generate this data and attach it to the Query object, and if somehow make this purely a DebugKit activity.

The problem here is that we want to track Query creation and not execution. There are no events or behaviors in CakePHP that will allow you to monitor those moments.

CakePHP Core

I don't see how something like this could be implemented unless changes were made in the CakePHP core. Specially, how do we attach metadata to a Query object? How do we monitor the creation of Query objects?

Some possible approaches:

• event model: Change the CakePHP core to broadcast events about Query object creation.
• factory: Change CakePHP core to use a Query factory class, and configure a DebugKit factory class.
• extension: Add a Table class to DebugKit that logs Query creation, and tell people to extend this Table class.
• mixin: Same as above, but as a mixin.
• behavior: Add a DebugKit behavior that mutates the owning Table instance and replaces the find() method with it's own (a kind of mocking behavior).
• unknown: Something I've missed that maybe uses one of the above (i.e. an event listener that attaches behaviors to Tables automatically, and hacks what we need)

Feedback

I'm looking to experiment with some of the above ideas, and hope to hear from other people different approaches or opinions about such changes.

[markstory]

Query creation events will be the path of least resistance, as we already use events as a pattern. Is query object creation the important part? Is it useful to know where/when the query was executed?

[thinkingmedia]

@markstory I'm having success with a trait you attach to a Table which injects a SQL comment showing the source file. This approach has the benefit where subqueries attached to a parent query contain comments of the file that created the sub-query. It's proving to be more informative than I had expected. I'll post some screenshots later showing what it looks like.

[jtraulle]

I was just about to ask for that feature, so it is great that something has already been started. Thanks @thinkingmedia :+1:

[LordSimal]

This feature was added in the 5.x version which requires CakePHP 5. https://book.cakephp.org/debugkit/5/en/index.html#tracing-query-execution