tests: use monotonic clock for linearizability test history

Problem: time.Now() uses wall clock reading. See https://github.com/golang/go/blob/master/src/time/time.go#L17
"later time-telling operations use the wall clock reading, but later time-measuring operations, specifically comparisons and subtractions, use the monotonic clock reading."
This can cause 'Return' to be before 'Call' and wrong order of operations from different clients.

Solution: use same base time for all clients and only use 'time-measuring' operations to record timestamps for history.
Signed-off-by: Bogdan Kanivets <bkanivets@apple.com>
This commit is contained in:
Bogdan Kanivets 2023-02-15 01:12:55 -08:00
parent 202d813c7b
commit d2ccb12f36
3 changed files with 55 additions and 53 deletions

View File

@ -27,11 +27,12 @@ import (
)
type recordingClient struct {
client clientv3.Client
history *model.AppendableHistory
client clientv3.Client
history *model.AppendableHistory
baseTime time.Time
}
func NewClient(endpoints []string, ids identity.Provider) (*recordingClient, error) {
func NewClient(endpoints []string, ids identity.Provider, baseTime time.Time) (*recordingClient, error) {
cc, err := clientv3.New(clientv3.Config{
Endpoints: endpoints,
Logger: zap.NewNop(),
@ -42,8 +43,9 @@ func NewClient(endpoints []string, ids identity.Provider) (*recordingClient, err
return nil, err
}
return &recordingClient{
client: *cc,
history: model.NewAppendableHistory(ids),
client: *cc,
history: model.NewAppendableHistory(ids),
baseTime: baseTime,
}, nil
}
@ -52,9 +54,9 @@ func (c *recordingClient) Close() error {
}
func (c *recordingClient) Get(ctx context.Context, key string) ([]*mvccpb.KeyValue, error) {
callTime := time.Now()
callTime := time.Since(c.baseTime)
resp, err := c.client.Get(ctx, key)
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
if err != nil {
return nil, err
}
@ -63,23 +65,23 @@ func (c *recordingClient) Get(ctx context.Context, key string) ([]*mvccpb.KeyVal
}
func (c *recordingClient) Put(ctx context.Context, key, value string) error {
callTime := time.Now()
callTime := time.Since(c.baseTime)
resp, err := c.client.Put(ctx, key, value)
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendPut(key, value, callTime, returnTime, resp, err)
return err
}
func (c *recordingClient) Delete(ctx context.Context, key string) error {
callTime := time.Now()
callTime := time.Since(c.baseTime)
resp, err := c.client.Delete(ctx, key)
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendDelete(key, callTime, returnTime, resp, err)
return nil
}
func (c *recordingClient) CompareAndSet(ctx context.Context, key, expectedValue, newValue string) error {
callTime := time.Now()
callTime := time.Since(c.baseTime)
txn := c.client.Txn(ctx)
var cmp clientv3.Cmp
if expectedValue == "" {
@ -92,28 +94,28 @@ func (c *recordingClient) CompareAndSet(ctx context.Context, key, expectedValue,
).Then(
clientv3.OpPut(key, newValue),
).Commit()
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendCompareAndSet(key, expectedValue, newValue, callTime, returnTime, resp, err)
return err
}
func (c *recordingClient) Txn(ctx context.Context, cmp []clientv3.Cmp, ops []clientv3.Op) error {
callTime := time.Now()
callTime := time.Since(c.baseTime)
txn := c.client.Txn(ctx)
resp, err := txn.If(
cmp...,
).Then(
ops...,
).Commit()
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendTxn(cmp, ops, callTime, returnTime, resp, err)
return err
}
func (c *recordingClient) LeaseGrant(ctx context.Context, ttl int64) (int64, error) {
callTime := time.Now()
callTime := time.Since(c.baseTime)
resp, err := c.client.Lease.Grant(ctx, ttl)
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendLeaseGrant(callTime, returnTime, resp, err)
var leaseId int64
if resp != nil {
@ -123,26 +125,26 @@ func (c *recordingClient) LeaseGrant(ctx context.Context, ttl int64) (int64, err
}
func (c *recordingClient) LeaseRevoke(ctx context.Context, leaseId int64) error {
callTime := time.Now()
callTime := time.Since(c.baseTime)
resp, err := c.client.Lease.Revoke(ctx, clientv3.LeaseID(leaseId))
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendLeaseRevoke(leaseId, callTime, returnTime, resp, err)
return err
}
func (c *recordingClient) PutWithLease(ctx context.Context, key string, value string, leaseId int64) error {
callTime := time.Now()
callTime := time.Since(c.baseTime)
opts := clientv3.WithLease(clientv3.LeaseID(leaseId))
resp, err := c.client.Put(ctx, key, value, opts)
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendPutWithLease(key, value, int64(leaseId), callTime, returnTime, resp, err)
return err
}
func (c *recordingClient) Defragment(ctx context.Context) error {
callTime := time.Now()
callTime := time.Since(c.baseTime)
resp, err := c.client.Defragment(ctx, c.client.Endpoints()[0])
returnTime := time.Now()
returnTime := time.Since(c.baseTime)
c.history.AppendDefragment(callTime, returnTime, resp, err)
return err
}

View File

@ -350,7 +350,7 @@ func simulateTraffic(ctx context.Context, t *testing.T, lg *zap.Logger, clus *e2
for i := 0; i < config.clientCount; i++ {
wg.Add(1)
endpoints := []string{endpoints[i%len(endpoints)]}
c, err := NewClient(endpoints, ids)
c, err := NewClient(endpoints, ids, startTime)
if err != nil {
t.Fatal(err)
}

View File

@ -44,7 +44,7 @@ func NewAppendableHistory(ids identity.Provider) *AppendableHistory {
}
}
func (h *AppendableHistory) AppendGet(key string, start, end time.Time, resp *clientv3.GetResponse) {
func (h *AppendableHistory) AppendGet(key string, start, end time.Duration, resp *clientv3.GetResponse) {
var readData string
if len(resp.Kvs) == 1 {
readData = string(resp.Kvs[0].Value)
@ -56,13 +56,13 @@ func (h *AppendableHistory) AppendGet(key string, start, end time.Time, resp *cl
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: getRequest(key),
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: getResponse(readData, revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) AppendPut(key, value string, start, end time.Time, resp *clientv3.PutResponse, err error) {
func (h *AppendableHistory) AppendPut(key, value string, start, end time.Duration, resp *clientv3.PutResponse, err error) {
request := putRequest(key, value)
if err != nil {
h.appendFailed(request, start, err)
@ -75,13 +75,13 @@ func (h *AppendableHistory) AppendPut(key, value string, start, end time.Time, r
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: putResponse(revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) AppendPutWithLease(key, value string, leaseID int64, start, end time.Time, resp *clientv3.PutResponse, err error) {
func (h *AppendableHistory) AppendPutWithLease(key, value string, leaseID int64, start, end time.Duration, resp *clientv3.PutResponse, err error) {
request := putWithLeaseRequest(key, value, leaseID)
if err != nil {
h.appendFailed(request, start, err)
@ -94,13 +94,13 @@ func (h *AppendableHistory) AppendPutWithLease(key, value string, leaseID int64,
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: putResponse(revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) AppendLeaseGrant(start, end time.Time, resp *clientv3.LeaseGrantResponse, err error) {
func (h *AppendableHistory) AppendLeaseGrant(start, end time.Duration, resp *clientv3.LeaseGrantResponse, err error) {
var leaseID int64
if resp != nil {
leaseID = int64(resp.ID)
@ -117,13 +117,13 @@ func (h *AppendableHistory) AppendLeaseGrant(start, end time.Time, resp *clientv
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: leaseGrantResponse(revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) AppendLeaseRevoke(id int64, start time.Time, end time.Time, resp *clientv3.LeaseRevokeResponse, err error) {
func (h *AppendableHistory) AppendLeaseRevoke(id int64, start, end time.Duration, resp *clientv3.LeaseRevokeResponse, err error) {
request := leaseRevokeRequest(id)
if err != nil {
h.appendFailed(request, start, err)
@ -136,13 +136,13 @@ func (h *AppendableHistory) AppendLeaseRevoke(id int64, start time.Time, end tim
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: leaseRevokeResponse(revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) AppendDelete(key string, start, end time.Time, resp *clientv3.DeleteResponse, err error) {
func (h *AppendableHistory) AppendDelete(key string, start, end time.Duration, resp *clientv3.DeleteResponse, err error) {
request := deleteRequest(key)
if err != nil {
h.appendFailed(request, start, err)
@ -157,13 +157,13 @@ func (h *AppendableHistory) AppendDelete(key string, start, end time.Time, resp
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: deleteResponse(deleted, revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) AppendCompareAndSet(key, expectValue, newValue string, start, end time.Time, resp *clientv3.TxnResponse, err error) {
func (h *AppendableHistory) AppendCompareAndSet(key, expectValue, newValue string, start, end time.Duration, resp *clientv3.TxnResponse, err error) {
request := compareAndSetRequest(key, expectValue, newValue)
if err != nil {
h.appendFailed(request, start, err)
@ -176,13 +176,13 @@ func (h *AppendableHistory) AppendCompareAndSet(key, expectValue, newValue strin
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: compareAndSetResponse(resp.Succeeded, revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) AppendTxn(cmp []clientv3.Cmp, onSuccess []clientv3.Op, start, end time.Time, resp *clientv3.TxnResponse, err error) {
func (h *AppendableHistory) AppendTxn(cmp []clientv3.Cmp, onSuccess []clientv3.Op, start, end time.Duration, resp *clientv3.TxnResponse, err error) {
conds := []EtcdCondition{}
for _, cmp := range cmp {
conds = append(conds, toEtcdCondition(cmp))
@ -207,9 +207,9 @@ func (h *AppendableHistory) AppendTxn(cmp []clientv3.Cmp, onSuccess []clientv3.O
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: txnResponse(results, resp.Succeeded, revision),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
@ -267,7 +267,7 @@ func toEtcdOperationResult(resp *etcdserverpb.ResponseOp) EtcdOperationResult {
}
}
func (h *AppendableHistory) AppendDefragment(start, end time.Time, resp *clientv3.DefragmentResponse, err error) {
func (h *AppendableHistory) AppendDefragment(start, end time.Duration, resp *clientv3.DefragmentResponse, err error) {
request := defragmentRequest()
if err != nil {
h.appendFailed(request, start, err)
@ -276,17 +276,17 @@ func (h *AppendableHistory) AppendDefragment(start, end time.Time, resp *clientv
h.successful = append(h.successful, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: defragmentResponse(),
Return: end.UnixNano(),
Return: end.Nanoseconds(),
})
}
func (h *AppendableHistory) appendFailed(request EtcdRequest, start time.Time, err error) {
func (h *AppendableHistory) appendFailed(request EtcdRequest, start time.Duration, err error) {
h.failed = append(h.failed, porcupine.Operation{
ClientId: h.id,
Input: request,
Call: start.UnixNano(),
Call: start.Nanoseconds(),
Output: failedResponse(err),
Return: 0, // For failed writes we don't know when request has really finished.
})