Debug timings are potentially confusing

[timkurvers]

Spelunker uses debug for logging debug messages during operation.

One of its features, millisecond diffing, is potentially confusing:

When actively developing an application it can be useful to see when the time spent between one debug() call and the next. Suppose for example you invoke debug() before requesting a resource, and after as well, the "+NNNms" will show you how much time was spent between calls.

Given that Spelunker uses separate namespaces for timed operations – such as caching, DBC and database queries – these diffs may be interpret as query timers, which couldn't be further from the truth depending on the order of operations.

[timkurvers]

The easy solution here would be to log both before and after an operation as suggested by the debug docs. This may cause issues due to the asynchronous nature of GraphQL resolvers.