github.com/cockroachdb/cockroach@v20.2.0-alpha.1+incompatible/pkg/kv/kvserver/concurrency/concurrency_manager_test.go (about)

     1  // Copyright 2020 The Cockroach Authors.
     2  //
     3  // Use of this software is governed by the Business Source License
     4  // included in the file licenses/BSL.txt.
     5  //
     6  // As of the Change Date specified in that file, in accordance with
     7  // the Business Source License, use of this software will be governed
     8  // by the Apache License, Version 2.0, included in the file
     9  // licenses/APL.txt.
    10  
    11  package concurrency_test
    12  
    13  import (
    14  	"bytes"
    15  	"context"
    16  	"fmt"
    17  	"io/ioutil"
    18  	"reflect"
    19  	"runtime"
    20  	"sort"
    21  	"strconv"
    22  	"strings"
    23  	"sync/atomic"
    24  	"testing"
    25  	"time"
    26  
    27  	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/batcheval"
    28  	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency"
    29  	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency/lock"
    30  	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/intentresolver"
    31  	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/spanset"
    32  	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/txnwait"
    33  	"github.com/cockroachdb/cockroach/pkg/roachpb"
    34  	clustersettings "github.com/cockroachdb/cockroach/pkg/settings/cluster"
    35  	"github.com/cockroachdb/cockroach/pkg/storage/enginepb"
    36  	"github.com/cockroachdb/cockroach/pkg/testutils"
    37  	"github.com/cockroachdb/cockroach/pkg/util/hlc"
    38  	"github.com/cockroachdb/cockroach/pkg/util/leaktest"
    39  	"github.com/cockroachdb/cockroach/pkg/util/log"
    40  	"github.com/cockroachdb/cockroach/pkg/util/syncutil"
    41  	"github.com/cockroachdb/cockroach/pkg/util/tracing"
    42  	"github.com/cockroachdb/cockroach/pkg/util/uuid"
    43  	"github.com/cockroachdb/datadriven"
    44  	"github.com/cockroachdb/errors"
    45  	"github.com/maruel/panicparse/stack"
    46  	"github.com/petermattis/goid"
    47  )
    48  
    49  // TestConcurrencyManagerBasic verifies that sequences of requests interacting
    50  // with a concurrency manager perform properly.
    51  //
    52  // The input files use the following DSL:
    53  //
    54  // new-txn      name=<txn-name> ts=<int>[,<int>] epoch=<int> [maxts=<int>[,<int>]]
    55  // new-request  name=<req-name> txn=<txn-name>|none ts=<int>[,<int>] [priority] [consistency]
    56  //   <proto-name> [<field-name>=<field-value>...] (hint: see scanSingleRequest)
    57  // sequence     req=<req-name>
    58  // finish       req=<req-name>
    59  //
    60  // handle-write-intent-error  req=<req-name> txn=<txn-name> key=<key>
    61  // handle-txn-push-error      req=<req-name> txn=<txn-name> key=<key>  TODO(nvanbenschoten): implement this
    62  //
    63  // on-lock-acquired  req=<req-name> key=<key> [seq=<seq>] [dur=r|u]
    64  // on-lock-updated   req=<req-name> txn=<txn-name> key=<key> status=[committed|aborted|pending] [ts=<int>[,<int>]]
    65  // on-txn-updated    txn=<txn-name> status=[committed|aborted|pending] [ts=<int>[,<int>]]
    66  //
    67  // on-lease-updated  leaseholder=<bool>
    68  // on-split
    69  // on-merge
    70  // on-snapshot-applied
    71  //
    72  // debug-latch-manager
    73  // debug-lock-table
    74  // debug-disable-txn-pushes
    75  // reset
    76  //
    77  func TestConcurrencyManagerBasic(t *testing.T) {
    78  	defer leaktest.AfterTest(t)()
    79  
    80  	datadriven.Walk(t, "testdata/concurrency_manager", func(t *testing.T, path string) {
    81  		c := newCluster()
    82  		c.enableTxnPushes()
    83  		m := concurrency.NewManager(c.makeConfig())
    84  		m.OnRangeLeaseUpdated(true /* isLeaseholder */) // enable
    85  		c.m = m
    86  		mon := newMonitor()
    87  		datadriven.RunTest(t, path, func(t *testing.T, d *datadriven.TestData) string {
    88  			switch d.Cmd {
    89  			case "new-txn":
    90  				var txnName string
    91  				d.ScanArgs(t, "name", &txnName)
    92  				ts := scanTimestamp(t, d)
    93  
    94  				var epoch int
    95  				d.ScanArgs(t, "epoch", &epoch)
    96  
    97  				maxTS := ts
    98  				if d.HasArg("maxts") {
    99  					maxTS = scanTimestampWithName(t, d, "maxts")
   100  				}
   101  
   102  				txn, ok := c.txnsByName[txnName]
   103  				var id uuid.UUID
   104  				if ok {
   105  					id = txn.ID
   106  				} else {
   107  					id = c.newTxnID()
   108  				}
   109  				txn = &roachpb.Transaction{
   110  					TxnMeta: enginepb.TxnMeta{
   111  						ID:             id,
   112  						Epoch:          enginepb.TxnEpoch(epoch),
   113  						WriteTimestamp: ts,
   114  						MinTimestamp:   ts,
   115  						Priority:       1, // not min or max
   116  					},
   117  					ReadTimestamp: ts,
   118  					MaxTimestamp:  maxTS,
   119  				}
   120  				txn.UpdateObservedTimestamp(c.nodeDesc.NodeID, ts)
   121  				c.registerTxn(txnName, txn)
   122  				return ""
   123  
   124  			case "new-request":
   125  				var reqName string
   126  				d.ScanArgs(t, "name", &reqName)
   127  				if _, ok := c.requestsByName[reqName]; ok {
   128  					d.Fatalf(t, "duplicate request: %s", reqName)
   129  				}
   130  
   131  				var txnName string
   132  				d.ScanArgs(t, "txn", &txnName)
   133  				txn, ok := c.txnsByName[txnName]
   134  				if !ok && txnName != "none" {
   135  					d.Fatalf(t, "unknown txn %s", txnName)
   136  				}
   137  
   138  				ts := scanTimestamp(t, d)
   139  				if txn != nil {
   140  					txn = txn.Clone()
   141  					txn.ReadTimestamp = ts
   142  					txn.WriteTimestamp = ts
   143  				}
   144  
   145  				readConsistency := roachpb.CONSISTENT
   146  				if d.HasArg("inconsistent") {
   147  					readConsistency = roachpb.INCONSISTENT
   148  				}
   149  
   150  				// Each roachpb.Request is provided on an indented line.
   151  				var reqs []roachpb.Request
   152  				singleReqLines := strings.Split(d.Input, "\n")
   153  				for _, line := range singleReqLines {
   154  					req := scanSingleRequest(t, d, line, c.txnsByName)
   155  					reqs = append(reqs, req)
   156  				}
   157  				reqUnions := make([]roachpb.RequestUnion, len(reqs))
   158  				for i, req := range reqs {
   159  					reqUnions[i].MustSetInner(req)
   160  				}
   161  				latchSpans, lockSpans := c.collectSpans(t, txn, ts, reqs)
   162  
   163  				c.requestsByName[reqName] = concurrency.Request{
   164  					Txn:       txn,
   165  					Timestamp: ts,
   166  					// TODO(nvanbenschoten): test Priority
   167  					ReadConsistency: readConsistency,
   168  					Requests:        reqUnions,
   169  					LatchSpans:      latchSpans,
   170  					LockSpans:       lockSpans,
   171  				}
   172  				return ""
   173  
   174  			case "sequence":
   175  				var reqName string
   176  				d.ScanArgs(t, "req", &reqName)
   177  				req, ok := c.requestsByName[reqName]
   178  				if !ok {
   179  					d.Fatalf(t, "unknown request: %s", reqName)
   180  				}
   181  
   182  				c.mu.Lock()
   183  				prev := c.guardsByReqName[reqName]
   184  				delete(c.guardsByReqName, reqName)
   185  				c.mu.Unlock()
   186  
   187  				opName := fmt.Sprintf("sequence %s", reqName)
   188  				mon.runAsync(opName, func(ctx context.Context) {
   189  					guard, resp, err := m.SequenceReq(ctx, prev, req)
   190  					if err != nil {
   191  						log.Eventf(ctx, "sequencing complete, returned error: %v", err)
   192  					} else if resp != nil {
   193  						log.Eventf(ctx, "sequencing complete, returned response: %v", resp)
   194  					} else if guard != nil {
   195  						log.Event(ctx, "sequencing complete, returned guard")
   196  						c.mu.Lock()
   197  						c.guardsByReqName[reqName] = guard
   198  						c.mu.Unlock()
   199  					} else {
   200  						log.Event(ctx, "sequencing complete, returned no guard")
   201  					}
   202  				})
   203  				return c.waitAndCollect(t, mon)
   204  
   205  			case "finish":
   206  				var reqName string
   207  				d.ScanArgs(t, "req", &reqName)
   208  				guard, ok := c.guardsByReqName[reqName]
   209  				if !ok {
   210  					d.Fatalf(t, "unknown request: %s", reqName)
   211  				}
   212  
   213  				opName := fmt.Sprintf("finish %s", reqName)
   214  				mon.runSync(opName, func(ctx context.Context) {
   215  					log.Event(ctx, "finishing request")
   216  					m.FinishReq(guard)
   217  					c.mu.Lock()
   218  					delete(c.guardsByReqName, reqName)
   219  					c.mu.Unlock()
   220  				})
   221  				return c.waitAndCollect(t, mon)
   222  
   223  			case "handle-write-intent-error":
   224  				var reqName string
   225  				d.ScanArgs(t, "req", &reqName)
   226  				prev, ok := c.guardsByReqName[reqName]
   227  				if !ok {
   228  					d.Fatalf(t, "unknown request: %s", reqName)
   229  				}
   230  
   231  				// Each roachpb.Intent is provided on an indented line.
   232  				var intents []roachpb.Intent
   233  				singleReqLines := strings.Split(d.Input, "\n")
   234  				for _, line := range singleReqLines {
   235  					var err error
   236  					d.Cmd, d.CmdArgs, err = datadriven.ParseLine(line)
   237  					if err != nil {
   238  						d.Fatalf(t, "error parsing single intent: %v", err)
   239  					}
   240  					if d.Cmd != "intent" {
   241  						d.Fatalf(t, "expected \"intent\", found %s", d.Cmd)
   242  					}
   243  
   244  					var txnName string
   245  					d.ScanArgs(t, "txn", &txnName)
   246  					txn, ok := c.txnsByName[txnName]
   247  					if !ok {
   248  						d.Fatalf(t, "unknown txn %s", txnName)
   249  					}
   250  
   251  					var key string
   252  					d.ScanArgs(t, "key", &key)
   253  
   254  					intents = append(intents, roachpb.MakeIntent(&txn.TxnMeta, roachpb.Key(key)))
   255  				}
   256  
   257  				opName := fmt.Sprintf("handle write intent error %s", reqName)
   258  				mon.runAsync(opName, func(ctx context.Context) {
   259  					wiErr := &roachpb.WriteIntentError{Intents: intents}
   260  					guard, err := m.HandleWriterIntentError(ctx, prev, wiErr)
   261  					if err != nil {
   262  						log.Eventf(ctx, "handled %v, returned error: %v", wiErr, err)
   263  						c.mu.Lock()
   264  						delete(c.guardsByReqName, reqName)
   265  						c.mu.Unlock()
   266  					} else {
   267  						log.Eventf(ctx, "handled %v, released latches", wiErr)
   268  						c.mu.Lock()
   269  						c.guardsByReqName[reqName] = guard
   270  						c.mu.Unlock()
   271  					}
   272  				})
   273  				return c.waitAndCollect(t, mon)
   274  
   275  			case "on-lock-acquired":
   276  				var reqName string
   277  				d.ScanArgs(t, "req", &reqName)
   278  				guard, ok := c.guardsByReqName[reqName]
   279  				if !ok {
   280  					d.Fatalf(t, "unknown request: %s", reqName)
   281  				}
   282  				txn := guard.Req.Txn
   283  
   284  				var key string
   285  				d.ScanArgs(t, "key", &key)
   286  
   287  				var seq int
   288  				if d.HasArg("seq") {
   289  					d.ScanArgs(t, "seq", &seq)
   290  				}
   291  				seqNum := enginepb.TxnSeq(seq)
   292  
   293  				dur := lock.Unreplicated
   294  				if d.HasArg("dur") {
   295  					dur = scanLockDurability(t, d)
   296  				}
   297  
   298  				// Confirm that the request has a corresponding write request.
   299  				found := false
   300  				for _, ru := range guard.Req.Requests {
   301  					req := ru.GetInner()
   302  					keySpan := roachpb.Span{Key: roachpb.Key(key)}
   303  					if roachpb.IsLocking(req) &&
   304  						req.Header().Span().Contains(keySpan) &&
   305  						req.Header().Sequence == seqNum {
   306  						found = true
   307  						break
   308  					}
   309  				}
   310  				if !found {
   311  					d.Fatalf(t, "missing corresponding write request")
   312  				}
   313  
   314  				txnAcquire := txn.Clone()
   315  				txnAcquire.Sequence = seqNum
   316  
   317  				mon.runSync("acquire lock", func(ctx context.Context) {
   318  					log.Eventf(ctx, "txn %s @ %s", txn.ID.Short(), key)
   319  					acq := roachpb.MakeLockAcquisition(txnAcquire, roachpb.Key(key), dur)
   320  					m.OnLockAcquired(ctx, &acq)
   321  				})
   322  				return c.waitAndCollect(t, mon)
   323  
   324  			case "on-lock-updated":
   325  				var reqName string
   326  				d.ScanArgs(t, "req", &reqName)
   327  				guard, ok := c.guardsByReqName[reqName]
   328  				if !ok {
   329  					d.Fatalf(t, "unknown request: %s", reqName)
   330  				}
   331  
   332  				var txnName string
   333  				d.ScanArgs(t, "txn", &txnName)
   334  				txn, ok := c.txnsByName[txnName]
   335  				if !ok {
   336  					d.Fatalf(t, "unknown txn %s", txnName)
   337  				}
   338  
   339  				var key string
   340  				d.ScanArgs(t, "key", &key)
   341  
   342  				status, verb := scanTxnStatus(t, d)
   343  				var ts hlc.Timestamp
   344  				if d.HasArg("ts") {
   345  					ts = scanTimestamp(t, d)
   346  				}
   347  
   348  				// Confirm that the request has a corresponding ResolveIntent.
   349  				found := false
   350  				for _, ru := range guard.Req.Requests {
   351  					if riReq := ru.GetResolveIntent(); riReq != nil &&
   352  						riReq.IntentTxn.ID == txn.ID &&
   353  						riReq.Key.Equal(roachpb.Key(key)) &&
   354  						riReq.Status == status {
   355  						found = true
   356  						break
   357  					}
   358  				}
   359  				if !found {
   360  					d.Fatalf(t, "missing corresponding resolve intent request")
   361  				}
   362  
   363  				txnUpdate := txn.Clone()
   364  				txnUpdate.Status = status
   365  				txnUpdate.WriteTimestamp.Forward(ts)
   366  
   367  				mon.runSync("update lock", func(ctx context.Context) {
   368  					log.Eventf(ctx, "%s txn %s @ %s", verb, txn.ID.Short(), key)
   369  					span := roachpb.Span{Key: roachpb.Key(key)}
   370  					up := roachpb.MakeLockUpdate(txnUpdate, span)
   371  					m.OnLockUpdated(ctx, &up)
   372  				})
   373  				return c.waitAndCollect(t, mon)
   374  
   375  			case "on-txn-updated":
   376  				var txnName string
   377  				d.ScanArgs(t, "txn", &txnName)
   378  				txn, ok := c.txnsByName[txnName]
   379  				if !ok {
   380  					d.Fatalf(t, "unknown txn %s", txnName)
   381  				}
   382  
   383  				status, verb := scanTxnStatus(t, d)
   384  				var ts hlc.Timestamp
   385  				if d.HasArg("ts") {
   386  					ts = scanTimestamp(t, d)
   387  				}
   388  
   389  				mon.runSync("update txn", func(ctx context.Context) {
   390  					log.Eventf(ctx, "%s %s", verb, txnName)
   391  					if err := c.updateTxnRecord(txn.ID, status, ts); err != nil {
   392  						d.Fatalf(t, err.Error())
   393  					}
   394  				})
   395  				return c.waitAndCollect(t, mon)
   396  
   397  			case "on-lease-updated":
   398  				var isLeaseholder bool
   399  				d.ScanArgs(t, "leaseholder", &isLeaseholder)
   400  
   401  				mon.runSync("transfer lease", func(ctx context.Context) {
   402  					if isLeaseholder {
   403  						log.Event(ctx, "acquired")
   404  					} else {
   405  						log.Event(ctx, "released")
   406  					}
   407  					m.OnRangeLeaseUpdated(isLeaseholder)
   408  				})
   409  				return c.waitAndCollect(t, mon)
   410  
   411  			case "on-split":
   412  				mon.runSync("split range", func(ctx context.Context) {
   413  					log.Event(ctx, "complete")
   414  					m.OnRangeSplit()
   415  				})
   416  				return c.waitAndCollect(t, mon)
   417  
   418  			case "on-merge":
   419  				mon.runSync("merge range", func(ctx context.Context) {
   420  					log.Event(ctx, "complete")
   421  					m.OnRangeMerge()
   422  				})
   423  				return c.waitAndCollect(t, mon)
   424  
   425  			case "on-snapshot-applied":
   426  				mon.runSync("snapshot replica", func(ctx context.Context) {
   427  					log.Event(ctx, "applied")
   428  					m.OnReplicaSnapshotApplied()
   429  				})
   430  				return c.waitAndCollect(t, mon)
   431  
   432  			case "debug-latch-manager":
   433  				global, local := m.LatchMetrics()
   434  				output := []string{
   435  					fmt.Sprintf("write count: %d", global.WriteCount+local.WriteCount),
   436  					fmt.Sprintf(" read count: %d", global.ReadCount+local.ReadCount),
   437  				}
   438  				return strings.Join(output, "\n")
   439  
   440  			case "debug-lock-table":
   441  				return m.LockTableDebug()
   442  
   443  			case "debug-disable-txn-pushes":
   444  				c.disableTxnPushes()
   445  				return ""
   446  
   447  			case "reset":
   448  				if n := mon.numMonitored(); n > 0 {
   449  					d.Fatalf(t, "%d requests still in flight", n)
   450  				}
   451  				mon.resetSeqNums()
   452  				if err := c.reset(); err != nil {
   453  					d.Fatalf(t, "could not reset cluster: %v", err)
   454  				}
   455  				// Reset request and txn namespace?
   456  				if d.HasArg("namespace") {
   457  					c.resetNamespace()
   458  				}
   459  				return ""
   460  
   461  			default:
   462  				return fmt.Sprintf("unknown command: %s", d.Cmd)
   463  			}
   464  		})
   465  	})
   466  }
   467  
   468  // cluster encapsulates the state of a running cluster and a set of requests.
   469  // It serves as the test harness in TestConcurrencyManagerBasic - maintaining
   470  // transaction and request declarations, recording the state of in-flight
   471  // requests as they flow through the concurrency manager, and mocking out the
   472  // interfaces that the concurrency manager interacts with.
   473  type cluster struct {
   474  	nodeDesc  *roachpb.NodeDescriptor
   475  	rangeDesc *roachpb.RangeDescriptor
   476  	st        *clustersettings.Settings
   477  	m         concurrency.Manager
   478  
   479  	// Definitions.
   480  	txnCounter     uint32
   481  	txnsByName     map[string]*roachpb.Transaction
   482  	requestsByName map[string]concurrency.Request
   483  
   484  	// Request state. Cleared on reset.
   485  	mu              syncutil.Mutex
   486  	guardsByReqName map[string]*concurrency.Guard
   487  	txnRecords      map[uuid.UUID]*txnRecord
   488  	txnPushes       map[uuid.UUID]*txnPush
   489  }
   490  
   491  type txnRecord struct {
   492  	mu               syncutil.Mutex
   493  	sig              chan struct{}
   494  	txn              *roachpb.Transaction // immutable, modify fields below
   495  	updatedStatus    roachpb.TransactionStatus
   496  	updatedTimestamp hlc.Timestamp
   497  }
   498  
   499  type txnPush struct {
   500  	ctx            context.Context
   501  	pusher, pushee uuid.UUID
   502  }
   503  
   504  func newCluster() *cluster {
   505  	return &cluster{
   506  		st:        clustersettings.MakeTestingClusterSettings(),
   507  		nodeDesc:  &roachpb.NodeDescriptor{NodeID: 1},
   508  		rangeDesc: &roachpb.RangeDescriptor{RangeID: 1},
   509  
   510  		txnsByName:      make(map[string]*roachpb.Transaction),
   511  		requestsByName:  make(map[string]concurrency.Request),
   512  		guardsByReqName: make(map[string]*concurrency.Guard),
   513  		txnRecords:      make(map[uuid.UUID]*txnRecord),
   514  		txnPushes:       make(map[uuid.UUID]*txnPush),
   515  	}
   516  }
   517  
   518  func (c *cluster) makeConfig() concurrency.Config {
   519  	return concurrency.Config{
   520  		NodeDesc:       c.nodeDesc,
   521  		RangeDesc:      c.rangeDesc,
   522  		Settings:       c.st,
   523  		IntentResolver: c,
   524  		TxnWaitMetrics: txnwait.NewMetrics(time.Minute),
   525  	}
   526  }
   527  
   528  // PushTransaction implements the concurrency.IntentResolver interface.
   529  func (c *cluster) PushTransaction(
   530  	ctx context.Context, pushee *enginepb.TxnMeta, h roachpb.Header, pushType roachpb.PushTxnType,
   531  ) (*roachpb.Transaction, *roachpb.Error) {
   532  	pusheeRecord, err := c.getTxnRecord(pushee.ID)
   533  	if err != nil {
   534  		return nil, roachpb.NewError(err)
   535  	}
   536  	var pusherRecord *txnRecord
   537  	if h.Txn != nil {
   538  		pusherID := h.Txn.ID
   539  		pusherRecord, err = c.getTxnRecord(pusherID)
   540  		if err != nil {
   541  			return nil, roachpb.NewError(err)
   542  		}
   543  
   544  		push, err := c.registerPush(ctx, pusherID, pushee.ID)
   545  		if err != nil {
   546  			return nil, roachpb.NewError(err)
   547  		}
   548  		defer c.unregisterPush(push)
   549  	}
   550  	for {
   551  		// Is the pushee pushed?
   552  		pusheeTxn, pusheeRecordSig := pusheeRecord.asTxn()
   553  		var pushed bool
   554  		switch pushType {
   555  		case roachpb.PUSH_TIMESTAMP:
   556  			pushed = h.Timestamp.Less(pusheeTxn.WriteTimestamp) || pusheeTxn.Status.IsFinalized()
   557  		case roachpb.PUSH_ABORT:
   558  			pushed = pusheeTxn.Status.IsFinalized()
   559  		default:
   560  			return nil, roachpb.NewErrorf("unexpected push type: %s", pushType)
   561  		}
   562  		if pushed {
   563  			return pusheeTxn, nil
   564  		}
   565  		// Or the pusher aborted?
   566  		var pusherRecordSig chan struct{}
   567  		if pusherRecord != nil {
   568  			var pusherTxn *roachpb.Transaction
   569  			pusherTxn, pusherRecordSig = pusherRecord.asTxn()
   570  			if pusherTxn.Status == roachpb.ABORTED {
   571  				log.Eventf(ctx, "detected pusher aborted")
   572  				err := roachpb.NewTransactionAbortedError(roachpb.ABORT_REASON_PUSHER_ABORTED)
   573  				return nil, roachpb.NewError(err)
   574  			}
   575  		}
   576  		// Wait until either record is updated.
   577  		select {
   578  		case <-pusheeRecordSig:
   579  		case <-pusherRecordSig:
   580  		case <-ctx.Done():
   581  			return nil, roachpb.NewError(ctx.Err())
   582  		}
   583  	}
   584  }
   585  
   586  // ResolveIntent implements the concurrency.IntentResolver interface.
   587  func (c *cluster) ResolveIntent(
   588  	ctx context.Context, intent roachpb.LockUpdate, _ intentresolver.ResolveOptions,
   589  ) *roachpb.Error {
   590  	log.Eventf(ctx, "resolving intent %s for txn %s with %s status", intent.Key, intent.Txn.ID.Short(), intent.Status)
   591  	c.m.OnLockUpdated(ctx, &intent)
   592  	return nil
   593  }
   594  
   595  // ResolveIntents implements the concurrency.IntentResolver interface.
   596  func (c *cluster) ResolveIntents(
   597  	ctx context.Context, intents []roachpb.LockUpdate, opts intentresolver.ResolveOptions,
   598  ) *roachpb.Error {
   599  	log.Eventf(ctx, "resolving a batch of %d intent(s)", len(intents))
   600  	for _, intent := range intents {
   601  		if err := c.ResolveIntent(ctx, intent, opts); err != nil {
   602  			return err
   603  		}
   604  	}
   605  	return nil
   606  }
   607  
   608  func (c *cluster) newTxnID() uuid.UUID {
   609  	c.mu.Lock()
   610  	defer c.mu.Unlock()
   611  	return nextUUID(&c.txnCounter)
   612  }
   613  
   614  func (c *cluster) registerTxn(name string, txn *roachpb.Transaction) {
   615  	c.mu.Lock()
   616  	defer c.mu.Unlock()
   617  	c.txnsByName[name] = txn
   618  	r := &txnRecord{txn: txn, sig: make(chan struct{})}
   619  	c.txnRecords[txn.ID] = r
   620  }
   621  
   622  func (c *cluster) getTxnRecord(id uuid.UUID) (*txnRecord, error) {
   623  	c.mu.Lock()
   624  	defer c.mu.Unlock()
   625  	r, ok := c.txnRecords[id]
   626  	if !ok {
   627  		return nil, errors.Errorf("unknown txn %v: %v", id, c.txnRecords)
   628  	}
   629  	return r, nil
   630  }
   631  
   632  func (c *cluster) updateTxnRecord(
   633  	id uuid.UUID, status roachpb.TransactionStatus, ts hlc.Timestamp,
   634  ) error {
   635  	c.mu.Lock()
   636  	defer c.mu.Unlock()
   637  	r, ok := c.txnRecords[id]
   638  	if !ok {
   639  		return errors.Errorf("unknown txn %v: %v", id, c.txnRecords)
   640  	}
   641  	r.mu.Lock()
   642  	defer r.mu.Unlock()
   643  	r.updatedStatus = status
   644  	r.updatedTimestamp = ts
   645  	// Notify all listeners. This is a poor man's composable cond var.
   646  	close(r.sig)
   647  	r.sig = make(chan struct{})
   648  	return nil
   649  }
   650  
   651  func (r *txnRecord) asTxn() (*roachpb.Transaction, chan struct{}) {
   652  	r.mu.Lock()
   653  	defer r.mu.Unlock()
   654  	txn := r.txn.Clone()
   655  	if r.updatedStatus > txn.Status {
   656  		txn.Status = r.updatedStatus
   657  	}
   658  	txn.WriteTimestamp.Forward(r.updatedTimestamp)
   659  	return txn, r.sig
   660  }
   661  
   662  func (c *cluster) registerPush(ctx context.Context, pusher, pushee uuid.UUID) (*txnPush, error) {
   663  	c.mu.Lock()
   664  	defer c.mu.Unlock()
   665  	if _, ok := c.txnPushes[pusher]; ok {
   666  		return nil, errors.Errorf("txn %v already pushing", pusher)
   667  	}
   668  	p := &txnPush{
   669  		ctx:    ctx,
   670  		pusher: pusher,
   671  		pushee: pushee,
   672  	}
   673  	c.txnPushes[pusher] = p
   674  	return p, nil
   675  }
   676  
   677  func (c *cluster) unregisterPush(push *txnPush) {
   678  	c.mu.Lock()
   679  	defer c.mu.Unlock()
   680  	delete(c.txnPushes, push.pusher)
   681  }
   682  
   683  // detectDeadlocks looks at all in-flight transaction pushes and determines
   684  // whether any are blocked due to dependency cycles within transactions. If so,
   685  // the method logs an event on the contexts of each of the members of the cycle.
   686  func (c *cluster) detectDeadlocks() {
   687  	// This cycle detection algorithm it not particularly efficient - at worst
   688  	// it runs in O(n ^ 2) time. However, it's simple and effective at assigning
   689  	// each member of each cycle a unique view of the cycle that it's a part of.
   690  	// This works because we currently only allow a transaction to push a single
   691  	// other transaction at a time.
   692  	c.mu.Lock()
   693  	defer c.mu.Unlock()
   694  	var chain []uuid.UUID
   695  	seen := make(map[uuid.UUID]struct{})
   696  	for orig, origPush := range c.txnPushes {
   697  		pusher := orig
   698  		chain = append(chain[:0], orig)
   699  		for id := range seen {
   700  			delete(seen, id)
   701  		}
   702  		seen[pusher] = struct{}{}
   703  		for {
   704  			push, ok := c.txnPushes[pusher]
   705  			if !ok {
   706  				break
   707  			}
   708  			pusher = push.pushee
   709  			chain = append(chain, pusher)
   710  			if _, ok := seen[pusher]; ok {
   711  				// Cycle detected!
   712  				if pusher == orig {
   713  					// The cycle we were looking for (i.e. starting at orig).
   714  					var chainBuf strings.Builder
   715  					for i, id := range chain {
   716  						if i > 0 {
   717  							chainBuf.WriteString("->")
   718  						}
   719  						chainBuf.WriteString(id.Short())
   720  					}
   721  					log.Eventf(origPush.ctx, "dependency cycle detected %s", chainBuf.String())
   722  				}
   723  				break
   724  			}
   725  			seen[pusher] = struct{}{}
   726  		}
   727  	}
   728  }
   729  
   730  func (c *cluster) enableTxnPushes() {
   731  	concurrency.LockTableLivenessPushDelay.Override(&c.st.SV, 0*time.Millisecond)
   732  	concurrency.LockTableDeadlockDetectionPushDelay.Override(&c.st.SV, 0*time.Millisecond)
   733  }
   734  
   735  func (c *cluster) disableTxnPushes() {
   736  	concurrency.LockTableLivenessPushDelay.Override(&c.st.SV, time.Hour)
   737  	concurrency.LockTableDeadlockDetectionPushDelay.Override(&c.st.SV, time.Hour)
   738  }
   739  
   740  // reset clears all request state in the cluster. This avoids portions of tests
   741  // leaking into one another and also serves as an assertion that a sequence of
   742  // commands has completed without leaking any requests.
   743  func (c *cluster) reset() error {
   744  	c.mu.Lock()
   745  	defer c.mu.Unlock()
   746  	// Reset all transactions to their original state.
   747  	for id := range c.txnRecords {
   748  		r := c.txnRecords[id]
   749  		r.mu.Lock()
   750  		r.updatedStatus = roachpb.PENDING
   751  		r.updatedTimestamp = hlc.Timestamp{}
   752  		r.mu.Unlock()
   753  	}
   754  	// There should be no remaining concurrency guards.
   755  	for name := range c.guardsByReqName {
   756  		return errors.Errorf("unfinished guard for request: %s", name)
   757  	}
   758  	// There should be no outstanding latches.
   759  	global, local := c.m.LatchMetrics()
   760  	if global.ReadCount > 0 || global.WriteCount > 0 ||
   761  		local.ReadCount > 0 || local.WriteCount > 0 {
   762  		return errors.Errorf("outstanding latches")
   763  	}
   764  	// Clear the lock table by transferring the lease away and reacquiring it.
   765  	c.m.OnRangeLeaseUpdated(false /* isLeaseholder */)
   766  	c.m.OnRangeLeaseUpdated(true /* isLeaseholder */)
   767  	return nil
   768  }
   769  
   770  // resetNamespace resets the entire cluster namespace, clearing both request
   771  // definitions and transaction definitions.
   772  func (c *cluster) resetNamespace() {
   773  	c.mu.Lock()
   774  	defer c.mu.Unlock()
   775  	c.txnCounter = 0
   776  	c.txnsByName = make(map[string]*roachpb.Transaction)
   777  	c.requestsByName = make(map[string]concurrency.Request)
   778  	c.txnRecords = make(map[uuid.UUID]*txnRecord)
   779  }
   780  
   781  // collectSpans collects the declared spans for a set of requests.
   782  // Its logic mirrors that in Replica.collectSpans.
   783  func (c *cluster) collectSpans(
   784  	t *testing.T, txn *roachpb.Transaction, ts hlc.Timestamp, reqs []roachpb.Request,
   785  ) (latchSpans, lockSpans *spanset.SpanSet) {
   786  	latchSpans, lockSpans = &spanset.SpanSet{}, &spanset.SpanSet{}
   787  	h := roachpb.Header{Txn: txn, Timestamp: ts}
   788  	for _, req := range reqs {
   789  		if cmd, ok := batcheval.LookupCommand(req.Method()); ok {
   790  			cmd.DeclareKeys(c.rangeDesc, h, req, latchSpans, lockSpans)
   791  		} else {
   792  			t.Fatalf("unrecognized command %s", req.Method())
   793  		}
   794  	}
   795  
   796  	// Commands may create a large number of duplicate spans. De-duplicate
   797  	// them to reduce the number of spans we pass to the spanlatch manager.
   798  	for _, s := range [...]*spanset.SpanSet{latchSpans, lockSpans} {
   799  		s.SortAndDedup()
   800  		if err := s.Validate(); err != nil {
   801  			t.Fatal(err)
   802  		}
   803  	}
   804  	return latchSpans, lockSpans
   805  }
   806  
   807  func (c *cluster) waitAndCollect(t *testing.T, m *monitor) string {
   808  	m.waitForAsyncGoroutinesToStall(t)
   809  	c.detectDeadlocks()
   810  	return m.collectRecordings()
   811  }
   812  
   813  // monitor tracks a set of running goroutines as they execute and captures
   814  // tracing recordings from them. It is capable of watching its set of goroutines
   815  // until they all mutually stall.
   816  //
   817  // It is NOT safe to use multiple monitors concurrently.
   818  type monitor struct {
   819  	seq int
   820  	gs  map[*monitoredGoroutine]struct{}
   821  	buf []byte // avoids allocations
   822  }
   823  
   824  type monitoredGoroutine struct {
   825  	opSeq    int
   826  	opName   string
   827  	gID      int64
   828  	finished int32
   829  
   830  	ctx        context.Context
   831  	collect    func() tracing.Recording
   832  	cancel     func()
   833  	prevEvents int
   834  }
   835  
   836  func newMonitor() *monitor {
   837  	return &monitor{
   838  		gs: make(map[*monitoredGoroutine]struct{}),
   839  	}
   840  }
   841  
   842  func (m *monitor) runSync(opName string, fn func(context.Context)) {
   843  	ctx, collect, cancel := tracing.ContextWithRecordingSpan(context.Background(), opName)
   844  	g := &monitoredGoroutine{
   845  		opSeq:   0, // synchronous
   846  		opName:  opName,
   847  		ctx:     ctx,
   848  		collect: collect,
   849  		cancel:  cancel,
   850  	}
   851  	m.gs[g] = struct{}{}
   852  	fn(ctx)
   853  	atomic.StoreInt32(&g.finished, 1)
   854  }
   855  
   856  func (m *monitor) runAsync(opName string, fn func(context.Context)) {
   857  	m.seq++
   858  	ctx, collect, cancel := tracing.ContextWithRecordingSpan(context.Background(), opName)
   859  	g := &monitoredGoroutine{
   860  		opSeq:   m.seq,
   861  		opName:  opName,
   862  		ctx:     ctx,
   863  		collect: collect,
   864  		cancel:  cancel,
   865  	}
   866  	m.gs[g] = struct{}{}
   867  	go func() {
   868  		atomic.StoreInt64(&g.gID, goid.Get())
   869  		fn(ctx)
   870  		atomic.StoreInt32(&g.finished, 1)
   871  	}()
   872  }
   873  
   874  func (m *monitor) numMonitored() int {
   875  	return len(m.gs)
   876  }
   877  
   878  func (m *monitor) resetSeqNums() {
   879  	m.seq = 0
   880  }
   881  
   882  func (m *monitor) collectRecordings() string {
   883  	// Collect trace recordings from each goroutine.
   884  	type logRecord struct {
   885  		g     *monitoredGoroutine
   886  		value string
   887  	}
   888  	var logs []logRecord
   889  	for g := range m.gs {
   890  		prev := g.prevEvents
   891  		rec := g.collect()
   892  		for _, span := range rec {
   893  			for _, log := range span.Logs {
   894  				for _, field := range log.Fields {
   895  					if prev > 0 {
   896  						prev--
   897  						continue
   898  					}
   899  					logs = append(logs, logRecord{
   900  						g: g, value: field.Value,
   901  					})
   902  					g.prevEvents++
   903  				}
   904  			}
   905  		}
   906  		if atomic.LoadInt32(&g.finished) == 1 {
   907  			g.cancel()
   908  			delete(m.gs, g)
   909  		}
   910  	}
   911  
   912  	// Sort logs by g.opSeq. This will sort synchronous goroutines before
   913  	// asynchronous goroutines. Use a stable sort to break ties within
   914  	// goroutines and keep logs in event order.
   915  	sort.SliceStable(logs, func(i int, j int) bool {
   916  		return logs[i].g.opSeq < logs[j].g.opSeq
   917  	})
   918  
   919  	var buf strings.Builder
   920  	for i, log := range logs {
   921  		if i > 0 {
   922  			buf.WriteByte('\n')
   923  		}
   924  		seq := "-"
   925  		if log.g.opSeq != 0 {
   926  			seq = strconv.Itoa(log.g.opSeq)
   927  		}
   928  		fmt.Fprintf(&buf, "[%s] %s: %s", seq, log.g.opName, log.value)
   929  	}
   930  	return buf.String()
   931  }
   932  
   933  func (m *monitor) hasNewEvents(g *monitoredGoroutine) bool {
   934  	events := 0
   935  	rec := g.collect()
   936  	for _, span := range rec {
   937  		for _, log := range span.Logs {
   938  			for range log.Fields {
   939  				events++
   940  			}
   941  		}
   942  	}
   943  	return events > g.prevEvents
   944  }
   945  
   946  // waitForAsyncGoroutinesToStall waits for all goroutines that were launched by
   947  // the monitor's runAsync method to stall due to cross-goroutine synchronization
   948  // dependencies. For instance, it waits for all goroutines to stall while
   949  // receiving from channels. When the method returns, the caller has exclusive
   950  // access to any memory that it shares only with monitored goroutines until it
   951  // performs an action that may unblock any of the goroutines.
   952  func (m *monitor) waitForAsyncGoroutinesToStall(t *testing.T) {
   953  	// Iterate until we see two iterations in a row that both observe all
   954  	// monitored goroutines to be stalled and also both observe the exact same
   955  	// goroutine state. The goroutine dump provides a consistent snapshot of all
   956  	// goroutine states and statuses (runtime.Stack(all=true) stops the world).
   957  	var status []*stack.Goroutine
   958  	filter := funcName((*monitor).runAsync)
   959  	testutils.SucceedsSoon(t, func() error {
   960  		// Add a small fixed delay after each iteration. This is sufficient to
   961  		// prevents false detection of stalls in a few cases, like when
   962  		// receiving on a buffered channel that already has an element in it.
   963  		defer time.Sleep(1 * time.Millisecond)
   964  
   965  		prevStatus := status
   966  		status = goroutineStatus(t, filter, &m.buf)
   967  		if len(status) == 0 {
   968  			// No monitored goroutines.
   969  			return nil
   970  		}
   971  
   972  		if prevStatus == nil {
   973  			// First iteration.
   974  			return errors.Errorf("previous status unset")
   975  		}
   976  
   977  		// Check whether all monitored goroutines are stalled. If not, retry.
   978  		for _, stat := range status {
   979  			stalled, ok := goroutineStalledStates[stat.State]
   980  			if !ok {
   981  				// NB: this will help us avoid rotting on Go runtime changes.
   982  				t.Fatalf("unknown goroutine state: %s", stat.State)
   983  			}
   984  			if !stalled {
   985  				return errors.Errorf("goroutine %d is not stalled; status %s", stat.ID, stat.State)
   986  			}
   987  		}
   988  
   989  		// Make sure the goroutines haven't changed since the last iteration.
   990  		// This ensures that the goroutines stay stable for some amount of time.
   991  		// NB: status and lastStatus are sorted by goroutine id.
   992  		if !reflect.DeepEqual(status, prevStatus) {
   993  			return errors.Errorf("goroutines rapidly changing")
   994  		}
   995  		return nil
   996  	})
   997  
   998  	// Add a trace event indicating where each stalled goroutine is waiting.
   999  	byID := make(map[int64]*monitoredGoroutine, len(m.gs))
  1000  	for g := range m.gs {
  1001  		byID[atomic.LoadInt64(&g.gID)] = g
  1002  	}
  1003  	for _, stat := range status {
  1004  		g, ok := byID[int64(stat.ID)]
  1005  		if !ok {
  1006  			// If we're not tracking this goroutine, just ignore it. This can
  1007  			// happen when goroutines from earlier subtests haven't finished
  1008  			// yet.
  1009  			continue
  1010  		}
  1011  		// If the goroutine hasn't produced any new events, don't create a new
  1012  		// "blocked on" trace event. It likely hasn't moved since the last one.
  1013  		if !m.hasNewEvents(g) {
  1014  			continue
  1015  		}
  1016  		stalledCall := firstNonStdlib(stat.Stack.Calls)
  1017  		log.Eventf(g.ctx, "blocked on %s in %s", stat.State, stalledCall.Func.PkgDotName())
  1018  	}
  1019  }
  1020  
  1021  func funcName(f interface{}) string {
  1022  	return runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name()
  1023  }
  1024  
  1025  // goroutineStalledStates maps all goroutine states as reported by runtime.Stack
  1026  // to a boolean representing whether that state indicates a stalled goroutine. A
  1027  // stalled goroutine is one that is waiting on a change on another goroutine in
  1028  // order for it to make forward progress itself. If all goroutines enter stalled
  1029  // states simultaneously, a process would encounter a deadlock.
  1030  var goroutineStalledStates = map[string]bool{
  1031  	// See gStatusStrings in runtime/traceback.go and associated comments about
  1032  	// the corresponding G statuses in runtime/runtime2.go.
  1033  	"idle":      false,
  1034  	"runnable":  false,
  1035  	"running":   false,
  1036  	"syscall":   false,
  1037  	"waiting":   true,
  1038  	"dead":      false,
  1039  	"copystack": false,
  1040  	"???":       false, // catch-all in runtime.goroutineheader
  1041  
  1042  	// runtime.goroutineheader may override these G statuses with a waitReason.
  1043  	// See waitReasonStrings in runtime/runtime2.go.
  1044  	"GC assist marking":       false,
  1045  	"IO wait":                 false,
  1046  	"chan receive (nil chan)": true,
  1047  	"chan send (nil chan)":    true,
  1048  	"dumping heap":            false,
  1049  	"garbage collection":      false,
  1050  	"garbage collection scan": false,
  1051  	"panicwait":               false,
  1052  	"select":                  true,
  1053  	"select (no cases)":       true,
  1054  	"GC assist wait":          false,
  1055  	"GC sweep wait":           false,
  1056  	"GC scavenge wait":        false,
  1057  	"chan receive":            true,
  1058  	"chan send":               true,
  1059  	"finalizer wait":          false,
  1060  	"force gc (idle)":         false,
  1061  	// Perhaps surprisingly, we mark "semacquire" as a non-stalled state. This
  1062  	// is because it is possible to see goroutines briefly enter this state when
  1063  	// performing fine-grained memory synchronization, occasionally in the Go
  1064  	// runtime itself. No request-level synchronization points use mutexes to
  1065  	// wait for state transitions by other requests, so it is safe to ignore
  1066  	// this state and wait for it to exit.
  1067  	"semacquire":             false,
  1068  	"sleep":                  false,
  1069  	"sync.Cond.Wait":         true,
  1070  	"timer goroutine (idle)": false,
  1071  	"trace reader (blocked)": false,
  1072  	"wait for GC cycle":      false,
  1073  	"GC worker (idle)":       false,
  1074  }
  1075  
  1076  // goroutineStatus returns a stack trace for each goroutine whose stack frame
  1077  // matches the provided filter. It uses the provided buffer to avoid repeat
  1078  // allocations.
  1079  func goroutineStatus(t *testing.T, filter string, buf *[]byte) []*stack.Goroutine {
  1080  	// We don't know how big the buffer needs to be to collect all the
  1081  	// goroutines. Start with 64 KB and try a few times, doubling each time.
  1082  	// NB: This is inspired by runtime/pprof/pprof.go:writeGoroutineStacks.
  1083  	if len(*buf) == 0 {
  1084  		*buf = make([]byte, 1<<16)
  1085  	}
  1086  	var truncBuf []byte
  1087  	for i := 0; ; i++ {
  1088  		n := runtime.Stack(*buf, true /* all */)
  1089  		if n < len(*buf) {
  1090  			truncBuf = (*buf)[:n]
  1091  			break
  1092  		}
  1093  		*buf = make([]byte, 2*len(*buf))
  1094  	}
  1095  
  1096  	// guesspaths=true is required for Call objects to have IsStdlib filled in.
  1097  	guesspaths := true
  1098  	ctx, err := stack.ParseDump(bytes.NewBuffer(truncBuf), ioutil.Discard, guesspaths)
  1099  	if err != nil {
  1100  		t.Fatalf("could not parse goroutine dump: %v", err)
  1101  		return nil
  1102  	}
  1103  
  1104  	matching := ctx.Goroutines[:0]
  1105  	for _, g := range ctx.Goroutines {
  1106  		for _, call := range g.Stack.Calls {
  1107  			if strings.Contains(call.Func.Raw, filter) {
  1108  				matching = append(matching, g)
  1109  				break
  1110  			}
  1111  		}
  1112  	}
  1113  	return matching
  1114  }
  1115  
  1116  func firstNonStdlib(calls []stack.Call) stack.Call {
  1117  	for _, call := range calls {
  1118  		if !call.IsStdlib {
  1119  			return call
  1120  		}
  1121  	}
  1122  	panic("unexpected")
  1123  }