I think that the weirdness really comes from the way transactions times
are measured, their interactions with throttling, and latent bugs in the
code.
measurement times, no; interactions with throttling, no. If it was either of
those I'd have finished this off days ago. Latent bugs, possibly. We may
discover there's nothing wrong with your code at the end here,
To summarize my point: I think my v10 code does not take into account all
of the strangeness in doCustom, and I'm pretty sure that there is no point
in including thottle sleeps into latency measures, which was more or less
the case. So it is somehow a "bug" which only shows up if you look at the
latency measures, but the tps are fine.
that it just makes hitting this bug more likely. Unfortunately today is
the day *some* bug is popping up, and I want to get it squashed before
I'll be happy.
The lag is actually happening during a kernel call that isn't working as
expected. I'm not sure whether this bug was there all along if \sleep was
used, or if it's specific to the throttle sleep.
The throttle sleep is inserted out of the state machine. That is why in
the "test" patch I added a goto to ensure that it is always taken at the
right time, that is when state==0 and before txn_begin is set, and not
possibly between other states when doCustom happens to be recalled after a
return.
I added a bunch more logging as pgbench steps through its work to track down
where it's stuck at. Until the end all transactions look like this:
1371238832.084783 client 10 throttle lag 2 us
1371238832.084783 client 10 executing \setrandom aid 1 :naccounts
1371238832.084803 client 10 sending SELECT abalance FROM pgbench_accounts
WHERE aid = 753099;
1371238832.084840 calling select
1371238832.086539 client 10 receiving
1371238832.086539 client 10 finished
All clients who hit lag spikes at the end are going through this sequence
> instead:
1371238832.085912 client 13 throttle lag 790 us
1371238832.085912 client 13 executing \setrandom aid 1 :naccounts
1371238832.085931 client 13 sending SELECT abalance FROM pgbench_accounts
WHERE aid = 564894;
1371238832.086592 client 13 receiving
1371238832.086662 calling select
1371238832.235543 client 13 receiving
1371238832.235543 client 13 finished
Note the "calling select" here that wasn't in the normal length transaction
before it. The client is receiving something here, but rather than it
finishing the transaction it falls through and ends up at the select() system
call outside of doCustom. All of the clients that are sleeping when the
system slips into one of these long select() calls are getting stuck behind
it. I'm not 100% sure, but I think this only happens when all remaining
clients are sleeping.
Note: in both the slow cases there is a "receiving" between "sending" and
"select". This suggests that the "goto top" at the very end of doCustom is
followed in one case but not the other.
ISTM that there is a timeout passed to select which is computed based on
the current sleeping time of each client. I'm pretty sure that not a well
tested path...
--
Fabien.
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
