From d2ccb12f36951ef55eee2a4efd1c81a299bc2a54 Mon Sep 17 00:00:00 2001 From: Bogdan Kanivets Date: Wed, 15 Feb 2023 01:12:55 -0800 Subject: [PATCH] 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 --- tests/linearizability/client.go | 48 +++++++-------- tests/linearizability/linearizability_test.go | 2 +- tests/linearizability/model/history.go | 58 +++++++++---------- 3 files changed, 55 insertions(+), 53 deletions(-) diff --git a/tests/linearizability/client.go b/tests/linearizability/client.go index ad95942c6..1d2e72ef7 100644 --- a/tests/linearizability/client.go +++ b/tests/linearizability/client.go @@ -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 } diff --git a/tests/linearizability/linearizability_test.go b/tests/linearizability/linearizability_test.go index 69ef54a4d..5890e3594 100644 --- a/tests/linearizability/linearizability_test.go +++ b/tests/linearizability/linearizability_test.go @@ -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) } diff --git a/tests/linearizability/model/history.go b/tests/linearizability/model/history.go index ea5556072..e614a5c6b 100644 --- a/tests/linearizability/model/history.go +++ b/tests/linearizability/model/history.go @@ -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. })