Looking at logging for SQL, SUM, TXN (to support "conditional transaction logging")

[rbygrave]

Right, I know that Roland and co use SpiLogger in development to A) Detect lazy loading queries B) Support a development UI that can provide something like "For a given request, show me all the SQL, SUM, TXN logs that occurred"

I'm also aware of desires to do something like conditional logging in production where on an exception that rolls back a transaction log the proceeding SQL (& SUM?) logs related to that transaction (if we can do this without consuming too much cpu and memory).

Looking at SpiLogger and how it's used I think we can do better and support existing uses of SpiLogger and perhaps new uses that would be ok to use in production. In order to support use cases that run in production imo we specifically should delay string appending - log var args of Strings instead so that they can be appended later only when actually necessary which should get costs to mostly around building the bindLog string and passing and holding arrays of strings for the duration of a transaction (or only some transactions).

Anyway, that is my initial thought and I'll look to create a branch for this. I believe the first thing will be to look to remove the trace() level logging as we only use that for 2 cases. The following step might be to define some API that combines logging SQL, SUM and TXN rather than 3 separate SpiLogger. Then the following step would be to try and use var args to support delaying the string appending that occurs and maybe look to ditch the replacement of any newline characters.

Anyway, if you are using SpiLogger of have interests in this please watch this space and the PR/Branch I'll create and let me know.

Thanks, Rob.

[rbygrave]

PR - #2912

[jnehlmeier]

I'm also aware of desires to do something like conditional logging in production where on an exception that rolls back a transaction log the proceeding SQL (& SUM?) logs related to that transaction (if we can do this without consuming too much cpu and memory).

At least for this use case I don't see much benefit of having a solution only targeting persistence/transactions provided by the persistence framework. Personally I use the logging framework to do it for the whole app to capture debug logs (which include queries) into a ring buffer (one buffer per user session) and dumping that buffer once a logger.error is called. This has the advantage that you see a complete debug level picture of the request that causes the error and depending on the ring buffer size also some requests before that request.

So you might end up with doubling the memory consumption for query logs if similar mechanisms are already in place for the whole app. So it should probably have an on/off flag.

[rbygrave]

have an on/off

Well yes but maybe to clarify a bit the "default" would be no actual change to the current default behavior which is just to log using a logger (which is a System.Logger these days). So no change to the default for folks working on the logger level and for example any logging like what you have already will work the same.

The change to the API provides us with the optional ability to change to an implementation that operates on a more "logging per transaction" basis. We have this in the PR prototype now as the new interface SpiTxnLogger (and the default implementation of this just logs as per normal).

doubling the memory consumption for query logs

Not the case thankfully, just works as currently.

benefit of having a solution only targeting persistence/transactions provided by the persistence framework

IF folks are instead only interested in the SQL when the transaction fails or "relatively rarely" then there should be relative benefit around being cheaper cost wise with some options like including the bind log or not. It could potentially open up the option of dealing specifically with lazy loading along the lines of failing tests that invoke lazy loading in a given transaction / scope.