Skip to content

Conversation

@vonzshik
Copy link

@vonzshik vonzshik commented Feb 4, 2021

Fixes #277

The problem here is if multiple queries ("BEGIN TRANSACTION ...", "UPDATE ...") are sent together (that is, we're not waiting for a response from "BEGIN TRANSACTION ..." and immediately send another query to save a roundtrip), the query's query_time is set to 0 on the first query response, so there will be a warning for the second one.
The proposed solution is to reset the query_time only on the last RFQ. While it's not actually correct, the only other idea I have is to add a queue, which seems like a lot of overhead.

@nathan-c
Copy link

Is there any news on when this might be merged/released?

petere added a commit to petere/pgbouncer that referenced this pull request Jul 9, 2021
Running multiple queries in a pipelined way would trigger the dreaded
"FIXME: query end, but query_start == 0" log messages because when the
first query finishes, we reset the query_start, and then the return of
the second query gets upset.  To fix that, only compute the time when
all queries in flight have finished.

solution by @vonzshik

closes pgbouncer#39, closes pgbouncer#144, closes pgbouncer#215, closes pgbouncer#277, closes pgbouncer#376, closes pgbouncer#565
@petere
Copy link
Member

petere commented Jul 9, 2021

Well, this certainly explains a lot. Especially how many people persistently see this and it's hard to reproduce for others, since it requires queries to be sent in this pipelined kind of way. I was now able to reproduce this with PostgreSQL 15's new libpq pipeline mode.

I agree your solution is sensible. I have also taken this opportunity to restructure this code a bit and linked in all the related GitHub issues in #628.

@vonzshik
Copy link
Author

@petere great, thank you! Then I'm closing this pr in favor of #628.

@vonzshik vonzshik closed this Jul 12, 2021
petere added a commit that referenced this pull request Jul 13, 2021
Running multiple queries in a pipelined way would trigger the dreaded
"FIXME: query end, but query_start == 0" log messages because when the
first query finishes, we reset the query_start, and then the return of
the second query gets upset.  To fix that, only compute the time when
all queries in flight have finished.

solution by @vonzshik

closes #39, closes #144, closes #215, closes #277, closes #376, closes #565
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Logs spammed with FIXME: query end, but query_start == 0 and now also FIXME: transaction end, but xact_start == 0

3 participants