kv: log on excessive latch hold duration

[nvanbenschoten]

We have logging for slow latch acquisitions due to conflicts, but not for when a request itself holds on to a latch for an excessive amount of time. This kind of logging would be helpful to avoid bugs and find unexpected slowness in the system which could cascade to other requests had there been contention.

Some notes:

• plumb cluster settings into spanlatch.Manager.
• add new spanlatch/settings.go file.
• in it, add new public cluster setting called kv.concurrency.long_latch_hold_duration (or something better). Give it a default value of 3s.
• add an acquireTime time.Time field to spanlatch.Guard.
• assign in Manager.Acquire and Manager.WaitUntilAcquired after wait succeeds.
• consult in Manager.Release after releasing latches. If acquireTime is set and it was acquired more than kv.concurrency.long_latch_hold_duration ago, log a warning.
• put the warning behind a log.Every(1 * time.Second) to avoid log spam.
• make sure the warning explains some of the possible causes for long latch hold times. Also make sure it includes the request information which is added in kv: include conflicting request information in latch manager traces/logs #114601.

Jira issue: CRDB-33593

Epic CRDB-34227

[lyang24]

Hi Nathan, I have worked on a draft pr on this issue. I have two questions:

1. Is there a good way to test the logger output?
   I could add a test like below when i ran it i can see the output on my ide, but i am not sure how to capture logger output to string

// How to verify logger output in go?
func TestLatchManagerLongLatchHeldLogOutput(t *testing.T) {
	settings := cluster.MakeClusterSettings()
	m := Make(nil, nil, settings)
	gr := &kvpb.GetRequest{
		RequestHeader: kvpb.RequestHeader{
			Key: roachpb.Key("test"),
		},
	}
	ba := &kvpb.BatchRequest{}
	ba.Add(gr)
	// Acquire latches, no conflict.
	lg1, err := m.Acquire(context.Background(), spans("d", "f", write, zeroTS), poison.Policy_Error, ba)
	require.NoError(t, err)
	time.Sleep(4 * time.Second)
	m.Release(lg1)
}

2. make sure the warning explains some of the possible causes for long latch hold times I listed two of the reasons but i do not have sufficient experience let me know if there are major causes i missed on the msg.