New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DatabaseLogFormatter logs incorrect sql query execution times #22

Closed
rowanmiller opened this Issue Jul 29, 2016 · 1 comment

Comments

Projects
None yet
2 participants
@rowanmiller
Member

rowanmiller commented Jul 29, 2016

If you new up multiple DbContext and make queries in parallel, each context's DatabaseLogFormatter receives interception notifications of every other DbContext!
It confuses the DatabaseLogFormatter, which seems to have been written without that scenario in mind.
Therefore DatabaseLogFormatter will stop its StopWatch even though the event comes from the query from another context.
I guess it's a bug at the interception level. A DbContext should only received interceptions events relating to queries/commands issued against that particular context.
Sorry I don't have time to build a repro, but if that's not clear I can provide additional details...

@rowanmiller rowanmiller added this to the 6.2.0 milestone Jul 29, 2016

@rowanmiller

This comment has been minimized.

Member

rowanmiller commented Jul 29, 2016

ajcvickers added a commit that referenced this issue Dec 14, 2016

Use separate timer per interception context when DatabaseLogFormatter…
… is used without a context

Issue #22

In the most common use, the DatabaseLogFormatter is used for a single DbContext, which means that there can be no interleaving between starting and finishing an execution. However, if the formatter is being used for multiple contexts, then these calls can be interleaved, which means that each pair needs its own timing.

Since each call has its own interception context, this can be used to store the timer. We accepted a pull request to store this kind of data, but I realized that if there are multiple interceptors and each want to use this data slot, the result would be one clobbering the other. Therefore, I obsoleted that mechanism in favor of a mechanism that can be used by multiple interceptors.

The change required that Stopwatch be obsoleted. However, the existing functionality has been retained so that an in-place update or ignoring of the obsolete warning will not make working code break.

ajcvickers added a commit that referenced this issue Dec 19, 2016

Use separate timer per interception context when DatabaseLogFormatter…
… is used without a context

Issue #22

In the most common use, the DatabaseLogFormatter is used for a single DbContext, which means that there can be no interleaving between starting and finishing an execution. However, if the formatter is being used for multiple contexts, then these calls can be interleaved, which means that each pair needs its own timing.

Since each call has its own interception context, this can be used to store the timer. We accepted a pull request to store this kind of data, but I realized that if there are multiple interceptors and each want to use this data slot, the result would be one clobbering the other. Therefore, I obsoleted that mechanism in favor of a mechanism that can be used by multiple interceptors.

The change required that Stopwatch be obsoleted. However, the existing functionality has been retained so that an in-place update or ignoring of the obsolete warning will not make working code break.

@ajcvickers ajcvickers closed this Dec 19, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment