Waiting for lease timeout

Using GORM automigrate for my tables which works fine unless and only occasionally there is another process trying to list from the table at exactly the right time. Then what we see is sometimes the system ends up waiting for a lease expiration for 5 minutes and I cannot figure out why… Here is an example of the issue any ideas how to troubleshoot this?

I201210 12:28:42.191799 1553 sql/event_log.go:132  [n1,client=,hostssl,user=admin] Event: "create_table", target: 56, info: {TableName:c_db.public.aws_accounts Statement:CREATE TABLE aws_accounts (id STRING, name STRING NOT NULL UNIQUE, type STRING NOT NULL, data_plane_id STRING NOT NULL, connected BOOL NOT NULL, status STRING NOT NULL, account_id STRING, regions STRING[], PRIMARY KEY (id)) User:cookie_admin}
I201210 12:28:42.195060 5773 kv/kvserver/replica_command.go:397  [n1,split,s1,r45/1:/{Table/55/7-Max}] initiating a split of this range at key /Table/56 [r46] (zone config)
I201210 12:28:42.209242 1553 sql/table.go:981  [n1,client=,hostssl,user=admin] queued new schema change job 614507879491731457 for table 56, mutation 1
I201210 12:28:42.209588 1553 sql/sqlbase/structured.go:1554  [n1,client=,hostssl,user=cookie_admin] publish: descID=56 (aws_accounts) version=2 mtime=1970-01-01 00:00:00 +0000 UTC
I201210 12:28:42.223440 1553 sql/event_log.go:132  [n1,client=,hostssl,user=admin] Event: "create_index", target: 56, info: {TableName:c_db.public.aws_accounts IndexName:idx_
aws_accounts_name Statement:CREATE INDEX idx_aws_accounts_name ON aws_accounts (name) User:cookie_admin MutationID:1}
I201210 12:28:42.223935 1553 jobs/registry.go:285  [n1,client=,hostssl,user=admin] scheduled jobs [614507879491731457]
I201210 12:28:42.248367 293 jobs/registry.go:1187  job 614507879491731457: resuming execution
I201210 12:28:42.251919 5791 jobs/registry.go:806  [n1] job 614507879491731457: stepping through state running with error <nil>
I201210 12:28:42.252470 5791 sql/schema_changer.go:436  [n1,job=614507879491731457,scExec,table=56,mutation=1] schema change on "aws_accounts" (v2) starting execution...
I201210 12:28:42.259333 5791 sql/schema_changer.go:653  [n1,job=614507879491731457,scExec,table=56,mutation=1] stepping through state machine
I201210 12:28:42.260997 5791 sql/lease.go:337  [n1,job=614507879491731457,scExec,table=56,mutation=1] waiting for 1 leases to expire: desc=[{aws_accounts 56 1}]

Will then wait for 5 min for lease to expire

What version are you running? The way I’d debug this is look at the output of SELECT * FROM crdb_internal.cluster_transactions and SELECT * FROM crdb_internal.cluster_sessions.

This will happen if there’s an open transaction that has used the table being changed. Is there any chance that you have a tendency to hold open transactions? Are there tools that you use to introspect the database which might? Can you correlate this behavior to any sort of time of day?