rocksdbjni Multi-thread call RocksDB.get() performance unstable

[beifuyiqiedeqilin]

environment:
rocksdbjni version 5.18.3
Linux version 4.18.0-22-generic (buildd@lgw01-amd64-033) (gcc version 7.3.0 (Ubuntu 7.3.0-16ubuntu3)) #23~18.04.1-Ubuntu SMP Thu Jun 6 08:37:25 UTC 2019

**Test Code: **

import org.rocksdb.*;
import org.rocksdb.util.SizeUnit;

import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.Executors;
import java.util.concurrent.ThreadPoolExecutor;

public class RocksDBGetTest {
    static {
        RocksDB.loadLibrary();
    }

    private static Statistics statistics = new Statistics();
    private static DBOptions dbOpts = new DBOptions() //
            .setCreateMissingColumnFamilies(true) //
            .setAllowConcurrentMemtableWrite(false) //
            .setMaxOpenFiles(-1) //
            .setStatistics(statistics) //
            .setCreateIfMissing(true);

    private static BlockBasedTableConfig tableConfig = new BlockBasedTableConfig()
            .setIndexType(IndexType.kTwoLevelIndexSearch)
            .setNoBlockCache(false)
            .setBlockSize(64 * SizeUnit.KB)
            .setBlockCache(new LRUCache(2 * SizeUnit.GB, 6, true))
            .setCacheIndexAndFilterBlocks(true)
            .setPinTopLevelIndexAndFilter(true)
            .setPinL0FilterAndIndexBlocksInCache(true)
            .setFilter(new BloomFilter(10, false))
            .setWholeKeyFiltering(true);

    private static ColumnFamilyOptions cfOpts = new ColumnFamilyOptions()
            .setTargetFileSizeBase( 32 * SizeUnit.MB )
            .setTableFormatConfig(tableConfig);

    private static RocksDB db;

    private static int TOTAL_NUMBER = 10000000;

    public static void main(String[] args) throws Exception {
        String DATA_DIR = "/home/hyhe/data/test2";
        final List<ColumnFamilyDescriptor> cfNames = new ArrayList<>();
        cfNames.add(new ColumnFamilyDescriptor(RocksDB.DEFAULT_COLUMN_FAMILY, cfOpts));
        final List<ColumnFamilyHandle> columnFamilyHandleList = new ArrayList<>();

        try {
            db = RocksDB.open(dbOpts, DATA_DIR, cfNames, columnFamilyHandleList);

            prepareData();
            System.out.println("Data is ok");

            int threadCount = 8;

            ThreadPoolExecutor threadPoolExecutor = (ThreadPoolExecutor) Executors.newFixedThreadPool(threadCount);
            CountDownLatch latch = new CountDownLatch(200);
            long start = System.currentTimeMillis();
            for (int i = 1; i < TOTAL_NUMBER; i += 50000) {
                threadPoolExecutor.execute(new GetThread(latch, i, i + 50000));
            }
            latch.await();
            long end = System.currentTimeMillis();
            System.out.println("Total cost " + (end - start));
            System.out.println(statistics.getHistogramString(HistogramType.DB_GET));

        } finally {
            for (final ColumnFamilyHandle columnFamilyHandle : columnFamilyHandleList) {
                columnFamilyHandle.close();
            }
            columnFamilyHandleList.clear();

            if (db != null)
                db.close();
            System.exit(0);
        }
    }

    static class GetThread implements Runnable {
        private CountDownLatch latch;
        private int beginIndex;
        private int endIndex;

        GetThread(CountDownLatch latch, int beginIndex, int endIndex) {
            this.latch = latch;
            this.beginIndex = beginIndex;
            this.endIndex = endIndex;
        }

        @Override
        public void run() {
            for (int i = beginIndex; i < endIndex; i++) {
                try {
                    db.get(("This is key" + i).getBytes());
                } catch (RocksDBException e) {
                    e.printStackTrace();
                }
            }
            latch.countDown();
        }
    }

    private static void prepareData() throws RocksDBException {
        if (db.get(("This is key" + TOTAL_NUMBER).getBytes()) != null) {
            return;
        }
        try (WriteBatch writeBatch = new WriteBatch(); WriteOptions writeOptions = new WriteOptions()) {
            for (int i = 1; i <= TOTAL_NUMBER; i++) {
                writeBatch.put(("This is key" + i).getBytes(), ("This is value" + i).getBytes());
            }
            db.write(writeOptions, writeBatch);
        }
    }
}

when i changed threadCount form 2 to 4, then to 8. The statistics for get as follow:

Count: 10000001 Average: 2.3833 StdDev: 16.02
Min: 1 Median: 1.5892 Max: 16047
Percentiles: P50: 1.59 P75: 1.89 P99: 4.71 P99.9: 16.19 P99.99: 239.56

[ 0, 1 ] 95798 0.958% 0.958%
( 1, 2 ] 8322969 83.230% 84.188% #################
( 2, 3 ] 1474415 14.744% 98.932% ###
( 3, 4 ] 5076 0.051% 98.983%
( 4, 6 ] 4895 0.049% 99.032%
( 6, 10 ] 4703 0.047% 99.079%
( 10, 15 ] 81267 0.813% 99.891%
( 15, 22 ] 5152 0.052% 99.943%
( 22, 34 ] 195 0.002% 99.945%
( 34, 51 ] 201 0.002% 99.947%
( 51, 76 ] 78 0.001% 99.947%
( 76, 110 ] 20 0.000% 99.948%
( 110, 170 ] 26 0.000% 99.948%
( 170, 250 ] 4837 0.048% 99.996%
( 250, 380 ] 193 0.002% 99.998%
( 380, 580 ] 40 0.000% 99.999%
( 580, 870 ] 17 0.000% 99.999%
( 870, 1300 ] 18 0.000% 99.999%
( 1300, 1900 ] 19 0.000% 99.999%
( 1900, 2900 ] 21 0.000% 99.999%
( 2900, 4400 ] 27 0.000% 100.000%
( 4400, 6600 ] 20 0.000% 100.000%
( 6600, 9900 ] 10 0.000% 100.000%
( 9900, 14000 ] 3 0.000% 100.000%
( 14000, 22000 ] 1 0.000% 100.000%

Count: 10000001 Average: 2.6902 StdDev: 42.21
Min: 1 Median: 1.6677 Max: 26220
Percentiles: P50: 1.67 P75: 2.01 P99: 2.98 P99.9: 33.84 P99.99: 488.74

[ 0, 1 ] 4092 0.041% 0.041%
( 1, 2 ] 7481876 74.819% 74.860% ###############
( 2, 3 ] 2466740 24.667% 99.527% #####
( 3, 4 ] 15973 0.160% 99.687%
( 4, 6 ] 5172 0.052% 99.739%
( 6, 10 ] 5627 0.056% 99.795%
( 10, 15 ] 4568 0.046% 99.840%
( 15, 22 ] 3599 0.036% 99.876%
( 22, 34 ] 2386 0.024% 99.900%
( 34, 51 ] 1744 0.017% 99.918%
( 51, 76 ] 480 0.005% 99.923%
( 76, 110 ] 995 0.010% 99.933%
( 110, 170 ] 508 0.005% 99.938%
( 170, 250 ] 4281 0.043% 99.980%
( 250, 380 ] 792 0.008% 99.988%
( 380, 580 ] 309 0.003% 99.991%
( 580, 870 ] 206 0.002% 99.993%
( 870, 1300 ] 145 0.001% 99.995%
( 1300, 1900 ] 95 0.001% 99.996%
( 1900, 2900 ] 102 0.001% 99.997%
( 2900, 4400 ] 101 0.001% 99.998%
( 4400, 6600 ] 119 0.001% 99.999%
( 6600, 9900 ] 46 0.000% 100.000%
( 9900, 14000 ] 32 0.000% 100.000%
( 14000, 22000 ] 11 0.000% 100.000%
( 22000, 33000 ] 2 0.000% 100.000%

Count: 10000001 Average: 5.4893 StdDev: 154.91
Min: 1 Median: 1.6948 Max: 32817
Percentiles: P50: 1.69 P75: 2.11 P99: 2.98 P99.9: 211.11 P99.99: 12878.97

[ 0, 1 ] 747 0.007% 0.007%
( 1, 2 ] 7195335 71.953% 71.961% ##############
( 2, 3 ] 2759155 27.592% 99.552% ######
( 3, 4 ] 13301 0.133% 99.685%
( 4, 6 ] 6051 0.061% 99.746%
( 6, 10 ] 4693 0.047% 99.793%
( 10, 15 ] 3961 0.040% 99.832%
( 15, 22 ] 2062 0.021% 99.853%
( 22, 34 ] 1158 0.012% 99.865%
( 34, 51 ] 905 0.009% 99.874%
( 51, 76 ] 327 0.003% 99.877%
( 76, 110 ] 668 0.007% 99.884%
( 110, 170 ] 471 0.005% 99.888%
( 170, 250 ] 2271 0.023% 99.911%
( 250, 380 ] 1319 0.013% 99.924%
( 380, 580 ] 409 0.004% 99.928%
( 580, 870 ] 506 0.005% 99.933%
( 870, 1300 ] 620 0.006% 99.940%
( 1300, 1900 ] 537 0.005% 99.945%
( 1900, 2900 ] 820 0.008% 99.953%
( 2900, 4400 ] 1005 0.010% 99.963%
( 4400, 6600 ] 1645 0.016% 99.980%
( 6600, 9900 ] 655 0.007% 99.986%
( 9900, 14000 ] 523 0.005% 99.991%
( 14000, 22000 ] 175 0.002% 99.993%
( 22000, 33000 ] 22 0.000% 99.993%

Although 99% get cost fast, but the time-consuming get become more.
For my application, one operation contains several get in order, one of them costs longer, the response become slower.
How could i to reduce the time-consuming get() ?

[riversand963]

I suspect that the long Get latency may have been caused by I/O. Can you share your working set size, block cache configuration, storage device info, etc?

[beifuyiqiedeqilin]

@riversand963 @adamretter
I don't down what does 'working set' mean?
block cache configuration already written in test case

    private static BlockBasedTableConfig tableConfig = new BlockBasedTableConfig()
            .setIndexType(IndexType.kTwoLevelIndexSearch)
            .setNoBlockCache(false)
            .setBlockSize(64 * SizeUnit.KB)
            .setBlockCache(new LRUCache(2 * SizeUnit.GB, 6, true))
            .setCacheIndexAndFilterBlocks(true)
            .setPinTopLevelIndexAndFilter(true)
            .setPinL0FilterAndIndexBlocksInCache(true)
            .setFilter(new BloomFilter(10, false))
            .setWholeKeyFiltering(true);

storage device info as follow:

cat /proc/cpuinfo | grep model\ name
model name	: Intel(R) Core(TM) i5-4460  CPU @ 3.20GHz
model name	: Intel(R) Core(TM) i5-4460  CPU @ 3.20GHz
model name	: Intel(R) Core(TM) i5-4460  CPU @ 3.20GHz
model name	: Intel(R) Core(TM) i5-4460  CPU @ 3.20GHz


cat /proc/meminfo | grep MemTotal
MemTotal:       16391368 kB

Memory Device（× 2）
	Array Handle: 0x0007
	Error Information Handle: Not Provided
	Total Width: 64 bits
	Data Width: 64 bits
	Size: 8192 MB
	Form Factor: DIMM
	Set: None
	Locator: ChannelA-DIMM0
	Bank Locator: BANK 0
	Type: DDR3
	Type Detail: Synchronous
	Speed: 1600 MT/s
	Manufacturer: Kingston
	Serial Number: 111AA9C4
	Asset Tag: 9876543210
	Part Number: 99P5471-041.A00LF 
	Rank: 2
	Configured Clock Speed: 1600 MT/s

sudo fdisk -l |grep "Disk /dev/sd"  
Disk /dev/sdb: 931.5 GiB, 1000204886016 bytes, 1953525168 sectors   （NOT SST）

sudo hdparm -i /dev/sdb |grep "Model"
 Model=WDC WD10EZEX-00WN4A0, FwRev=01.01A01, SerialNo=WD-WCC6Y2YA6YXY

without any other jvm arguments configed,

any other configuration needed?