Client side reports: org.tikv.common.exception.TiKVException: TimeOut Exceeded for current operation.

[yyongycy]

Bug Report

1. Describe the bug

v5.4.3

What operating system and CPU are you using?
ec2 instance, r6a.4xlarge
16c128GB

org.tikv.common.exception.TiKVException: TimeOut Exceeded for current operation.
at org.tikv.common.util.ClientUtils.getTasks(ClientUtils.java:181)
at org.tikv.raw.RawKVClient.doSendBatchPut(RawKVClient.java:756)
at org.tikv.raw.RawKVClient.batchPut(RawKVClient.java:260)
at org.tikv.raw.RawKVClient.batchPut(RawKVClient.java:243)

2. Minimal reproduce step (Required)

Single node environment, all-in-one,
Single pd-server/tikv-server

System.out.println("Begin to put batch");
Map<ByteString, ByteString> map = new HashMap<ByteString, ByteString>();
pair = createFileEntryKey(100, "first_batch", 15);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
    pair.getFirst().toByteArray()),
    org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getSecond().toByteArray()));
pair = createFileEntryKey(100, "second_batch", 16);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getFirst().toByteArray()),
    org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getSecond().toByteArray()));
tiKVStoreMetaRaw.putEntryBatchAtomic(map);

Create batch entries that could be in different region.

3. What did you see instead (Required)

What did happened?
Client side:
2022-12-15 15:03:01,043 WARN RawKVClient - Retry for get error
org.tikv.common.exception.RegionException: Region Exception occurred EpochNotMatch current epoch of region 2 is conf_ver: 1 version: 12, but you sent conf_ver: 1 version: 11
at org.tikv.common.region.RegionStoreClient.rawGetHelper(RegionStoreClient.java:897)
at org.tikv.common.region.RegionStoreClient.rawGet(RegionStoreClient.java:881)
at org.tikv.raw.RawKVClient.get(RawKVClient.java:288)

2022-12-15 15:05:56,873 WARN SlowLogImpl - A request spent 6003 ms. start=15:05:50.856, end=15:05:56.859, SlowLog:{"trace_id":13915657205484037136,"error":"TimeOut Exceeded for current operation.","spans":[{"event":"batchPut","begin":"15:05:50.856","duration_ms":6003,"properties":{"keySize":"2"}},{"event":"getRegionByKey","begin":"15:05:50.856","duration_ms":0},{"event":"getRegionByKey","begin":"15:05:50.856","duration_ms":0},{"event":"callWithRetry","begin":"15:05:50.856","duration_ms":3,"properties":{"method":"tikvpb.Tikv/RawBatchPut"}},{"event":"gRPC","begin":"15:05:50.856","duration_ms":3,"properties":{"method":"tikvpb.Tikv/RawBatchPut"}}],"pd_addresses":["http://127.0.0.1:2379"],"cluster_id":"7177389456460076655"}

org.tikv.common.exception.TiKVException: TimeOut Exceeded for current operation.
at org.tikv.common.util.ClientUtils.getTasks(ClientUtils.java:181)
at org.tikv.raw.RawKVClient.doSendBatchPut(RawKVClient.java:756)
at org.tikv.raw.RawKVClient.batchPut(RawKVClient.java:260)
at org.tikv.raw.RawKVClient.batchPut(RawKVClient.java:243)

Server side, no obvious error:
TiKV log:
[2022/12/15 15:02:51.013 +00:00] [INFO] [region.go:528] ["region Version changed"] [region-id=2] [detail="StartKey Changed:{080310858080B8BBDD161A06313732383130} -> {080310858080B8BBDD161A06313932353037}, EndKey:{}"] [old-version=10] [new-version=11]
[2022/12/15 15:02:51.013 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=2] [origin="id:22 start_key:"080310858080B8BBDD161A06313732383130" end_key:"080310858080B8BBDD161A06313932353037" region_epoch:<conf_ver:1 version:11 > peers:<id:23 store_id:1 >"] [total=1]
[2022/12/15 15:03:01.017 +00:00] [INFO] [cluster_worker.go:128] ["alloc ids for region split"] [region-id=24] [peer-ids="[25]"]
[2022/12/15 15:03:01.022 +00:00] [INFO] [region.go:528] ["region Version changed"] [region-id=2] [detail="StartKey Changed:{080310858080B8BBDD161A06313932353037} -> {080310858080B8BBDD161A06323132323933}, EndKey:{}"] [old-version=11] [new-version=12]
[2022/12/15 15:03:01.022 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=2] [origin="id:24 start_key:"080310858080B8BBDD161A06313932353037" end_key:"080310858080B8BBDD161A06323132323933" region_epoch:<conf_ver:1 version:12 > peers:<id:25 store_id:1 >"] [total=1]

pd log:
[2022/12/15 15:03:01.022 +00:00] [INFO] [raft.rs:1200] ["became leader at term 6"] [term=6] [raft_id=25] [region_id=24]
[2022/12/15 15:03:01.022 +00:00] [INFO] [peer.rs:4517] ["require updating max ts"] [initial_status=25769803800] [region_id=24]
[2022/12/15 15:03:01.022 +00:00] [INFO] [endpoint.rs:233] ["Resolver initialized"] [pending_data_index=0] [snapshot_index=145833] [observe_id=ObserveID(21)] [region=2]
[2022/12/15 15:03:01.023 +00:00] [INFO] [pd.rs:1437] ["succeed to update max timestamp"] [region_id=24]
[2022/12/15 15:03:01.023 +00:00] [INFO] [scheduler.rs:517] ["get snapshot failed"] [err="Error(Request(message: "EpochNotMatch current epoch of region 2 is conf_ver: 1 version: 12, but you sent conf_ver: 1 version: 11" epoch_not_match { current_regions { id: 2 start_key: 080310858080B8BBDD161A06323132323933 region_epoch { conf_ver: 1 version: 12 } peers { id: 3 store_id: 1 } } current_regions { id: 24 start_key: 080310858080B8BBDD161A06313932353037 end_key: 080310858080B8BBDD161A06323132323933 region_epoch { conf_ver: 1 version: 12 } peers { id: 25 store_id: 1 } } }))"] [cid=344336]
[2022/12/15 15:03:01.024 +00:00] [INFO] [endpoint.rs:314] ["register observe region"] [region="id: 24 start_key: 080310858080B8BBDD161A06313932353037 end_key: 080310858080B8BBDD161A06323132323933 region_epoch { conf_ver: 1 version: 12 } peers { id: 25 store_id: 1 }"]
[2022/12/15 15:03:01.024 +00:00] [INFO] [endpoint.rs:233] ["Resolver initialized"] [pending_data_index=0] [snapshot_index=6] [observe_id=ObserveID(22)] [region=24]
[2022/12/15 15:06:46.614 +00:00] [INFO] [util.rs:547] ["connecting to PD endpoint"] [endpoints=http://127.0.0.1:2379]

4. What did you expect to see? (Required)

The batchPut should be successfully

5. What are your Java Client and TiKV versions? (Required)

• Client Java: v3.3.0
• TiKV: v5.4.3

[sunxiaoguang]

It looks like region got split during put and backoff didn't get new region metadata before it timeout.

Now sure how big is your request, but it looks like to be very large to trigger region split in the middle. Did you try use smaller batch size and longer timeout.

[yyongycy]

It can be easily reproduced by the following program:

> map.clear();
> pair = createFileEntryKey(1000, “first_batch1”, 150);
> map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
> pair.getFirst().toByteArray()),
> org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
> pair.getSecond().toByteArray()));
> pair = createFileEntryKey(800000, “second_batch2”, 1600);
> map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
> pair.getFirst().toByteArray()),
> org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
> pair.getSecond().toByteArray()));
> tiKVStoreMetaRaw.putEntryBatchAtomic(map);

As long as the batch contains data in different regions. Aforementioned program has two records.

[pingyu]

It said timeout. How much data do you put ?

What's tiKVStoreMetaRaw.putEntryBatchAtomic(map) ? Please show a minimal reproducible example.

[yyongycy]

Each record has about 20 Bytes? Or 40 Bytes. And two records as you can see.

Proto like:
message FileEntryKey {
required KVStoreTable tableType = 1;
optional int64 parentID = 2;
optional string name = 3;
}

message FileEntryValue {
required int64 id = 1;
required KVEntryType entryType = 2;
optional bytes entryValue = 3;
}

public boolean putEntryBatchAtomic(Map<ByteString, ByteString> kvPairs) {
RawKVClient rawKVClient = mRawKVClientPool.acquire();
try {
rawKVClient.batchPut(kvPairs);
return true;
} finally {
mRawKVClientPool.release(rawKVClient);
}
}

[pingyu]

A single batch put for tens of bytes should not last more than 6 seconds.

I see log of raw get. What's your test scenario ? Do you have other workload on the cluster ?

[yyongycy]

no, just this test program

[yyongycy]

Regarding the 6 seconds, it is in another program, and most likely hung somewhere. The system load is very low.

[pingyu]

Please collect and upload the cluster diagnosis data, cover the period of your test when the 6 second timeout occur. It would be great help if there are only requests of such timeout batch puts.

See https://docs.pingcap.com/tidb/stable/quick-start-with-clinic for how to collect and upload. Note that the cluster must be deployed by tiup cluster.

[yyongycy]

The environment has been destroyed. and it can be reproduced by the following program, just make sure the two records are in different regions.

public static Pair<FileEntryKey, FileEntryValue> createFileEntryKey(long pid, String name, long cid) {
FileEntryKey key = FileEntryKey.newBuilder()
.setTableType(KVStoreTable.FILE_ENTRY)
.setParentID(pid)
.setName(name).build();
FileEntryValue value = FileEntryValue.newBuilder().setId(cid)
.setEntryType(KVEntryType.FILE).build();
return new Pair<>(key, value);
}

public static void main(String [] args) throws Exception {
TiKVStoreMetaRaw tiKVStoreMetaRaw = new TiKVStoreMetaRaw();

Map<ByteString, ByteString> map = new HashMap<ByteString, ByteString>(); 
pair = createFileEntryKey(1000, "first_batch1", 150);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getFirst().toByteArray()),
    org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getSecond().toByteArray()));
pair = createFileEntryKey(800000, "second_batch2", 1600);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getFirst().toByteArray()),
    org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getSecond().toByteArray()));
tiKVStoreMetaRaw.putEntryBatchAtomic(map);

results = tiKVStoreMetaRaw
    .scanFileEntryKV(pair.getFirst(), pairEnd.getFirst(), 100);
printResults(results);

tiKVStoreMetaRaw.close();

}

public boolean putEntryBatchAtomic(Map<ByteString, ByteString> kvPairs) {
RawKVClient rawKVClient = mRawKVClientPool.acquire();
try {
rawKVClient.batchPut(kvPairs);
return true;
} finally {
mRawKVClientPool.release(rawKVClient);
}
}

Proto like:
message FileEntryKey {
required KVStoreTable tableType = 1;
optional int64 parentID = 2;
optional string name = 3;
}

message FileEntryValue {
required int64 id = 1;
required KVEntryType entryType = 2;
optional bytes entryValue = 3;
}

[pingyu]

How you make sure the two records are in different regions ?

[yyongycy]

Ingest some values, and make sure the two new entries' delta is large engouh.

And I also tried two other values, if the delta is small, that works.

[pingyu]

The environment has been destroyed. and it can be reproduced by the following program, just make sure the two records are in different regions.

public static Pair<FileEntryKey, FileEntryValue> createFileEntryKey(long pid, String name, long cid) {
FileEntryKey key = FileEntryKey.newBuilder()
.setTableType(KVStoreTable.FILE_ENTRY)
.setParentID(pid)
.setName(name).build();
FileEntryValue value = FileEntryValue.newBuilder().setId(cid)
.setEntryType(KVEntryType.FILE).build();
return new Pair<>(key, value);
}

public static void main(String [] args) throws Exception {
TiKVStoreMetaRaw tiKVStoreMetaRaw = new TiKVStoreMetaRaw();

Map<ByteString, ByteString> map = new HashMap<ByteString, ByteString>(); 
pair = createFileEntryKey(1000, "first_batch1", 150);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getFirst().toByteArray()),
    org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getSecond().toByteArray()));
pair = createFileEntryKey(800000, "second_batch2", 1600);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getFirst().toByteArray()),
    org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
        pair.getSecond().toByteArray()));
tiKVStoreMetaRaw.putEntryBatchAtomic(map);

results = tiKVStoreMetaRaw
    .scanFileEntryKV(pair.getFirst(), pairEnd.getFirst(), 100);
printResults(results);

tiKVStoreMetaRaw.close();

}

public boolean putEntryBatchAtomic(Map<ByteString, ByteString> kvPairs) {
RawKVClient rawKVClient = mRawKVClientPool.acquire();
try {
rawKVClient.batchPut(kvPairs);
return true;
} finally {
mRawKVClientPool.release(rawKVClient);
}
}

Proto like: message FileEntryKey { required KVStoreTable tableType = 1; optional int64 parentID = 2; optional string name = 3; }

message FileEntryValue { required int64 id = 1; required KVEntryType entryType = 2; optional bytes entryValue = 3; }

It would be great help if you can provide complete (other than code segments), and minimal (remove unrelated business logics) source code.

[yyongycy]

@pingyu @sunxiaoguang Following is the program:

public class TiKVStoreMetaRaw {
static final int DEFAULT_TTL = 10;
private TiSession mTiSession;
private RawKVClient mRawKVClient;

public TiKVStoreMetaRaw() {
String pdAddrsStr = getEnv("TXNKV_PD_ADDRESSES");
pdAddrsStr = pdAddrsStr == null ? "localhost:2379" : pdAddrsStr;
TiConfiguration conf = TiConfiguration.createRawDefault(pdAddrsStr);
// conf.setEnableAtomicForCAS(true);
mTiSession = TiSession.create(conf);
mRawKVClient = mTiSession.createRawClient();
}

protected static String getEnv(String key) {
String tmp = System.getenv(key);
if (tmp != null && !tmp.equals("")) {
return tmp;
}

tmp = System.getProperty(key);
if (tmp != null && !tmp.equals("")) {
  return tmp;
}

return null;

}

public boolean putEntryBatchAtomic(Map<ByteString, ByteString> kvPairs) {
RawKVClient rawKVClient = mRawKVClientPool.acquire();
try {
rawKVClient.batchPut(kvPairs);
return true;
} finally {
mRawKVClientPool.release(rawKVClient);
}
}
}

public class Test {
public static Pair<FileEntryKey, FileEntryValue> createFileEntryKey(long pid, String name, long cid) {
FileEntryKey key = FileEntryKey.newBuilder()
.setTableType(KVStoreTable.FILE_ENTRY)
.setParentID(pid)
.setName(name).build();
FileEntryValue value = FileEntryValue.newBuilder().setId(cid)
.setEntryType(KVEntryType.FILE).build();
return new Pair<>(key, value);
}

public static void main(String [] args) throws Exception {
TiKVStoreMetaRaw tiKVStoreMetaRaw = new TiKVStoreMetaRaw();

Map<ByteString, ByteString> map = new HashMap<ByteString, ByteString>();
pair = createFileEntryKey(1000, "first_batch1", 150);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
pair.getFirst().toByteArray()),
org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
pair.getSecond().toByteArray()));
pair = createFileEntryKey(800000, "second_batch2", 1600);
map.put(org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
pair.getFirst().toByteArray()),
org.tikv.shade.com.google.protobuf.ByteString.copyFrom(
pair.getSecond().toByteArray()));
tiKVStoreMetaRaw.putEntryBatchAtomic(map);

results = tiKVStoreMetaRaw
.scanFileEntryKV(pair.getFirst(), pairEnd.getFirst(), 100);
printResults(results);

tiKVStoreMetaRaw.close();
}
}

Proto like:
message FileEntryKey {
required KVStoreTable tableType = 1;
optional int64 parentID = 2;
optional string name = 3;
}

message FileEntryValue {
required int64 id = 1;
required KVEntryType entryType = 2;
optional bytes entryValue = 3;
}

[pingyu]

It must be an issue in RawKVClient.doSendBatchPut:

    while (!taskQueue.isEmpty()) {
      List<Batch> task = taskQueue.poll();
      for (Batch batch : task) {
        completionService.submit(
            () -> doSendBatchPutInBatchesWithRetry(batch.getBackOffer(), batch, ttl));

        try {
          getTasks(completionService, taskQueue, task, deadline - System.currentTimeMillis());
        } catch (Exception e) {
          for (Future<List<Batch>> future : futureList) {
            future.cancel(true);
          }
          throw e;
        }
      }
    }

The getTasks(...) should be outside the loop of for (Batch batch : task), otherwise when task.size() > 1, it will hang as keeping waiting for batches which have not submitted.