[YSQL] [Perf][TPCC] TPCC 150k WH load failed with tpcc clients getting "PSQLException: This connection has been closed."

[sonalsagarwal]

Jira Link: DB-574

Description

YB version : 2.13.2.0-b18
Universe details : 90 node universe (3 master and 87 tserver nodes) of c5d.9xlarge instance type.

The TPCC 150k WH load failed with client getting the following connection closed exception :

Exception in thread "main" java.lang.RuntimeException: Failed to execute threads: org.postgresql.util.PSQLException: This connection has been closed.
	at com.oltpbenchmark.util.ThreadUtil.runNewPool(ThreadUtil.java:81)
	at com.oltpbenchmark.api.BenchmarkModule.loadDatabase(BenchmarkModule.java:221)
	at com.oltpbenchmark.DBWorkload.runLoader(DBWorkload.java:458)
	at com.oltpbenchmark.DBWorkload.main(DBWorkload.java:358)
Caused by: java.lang.RuntimeException: org.postgresql.util.PSQLException: This connection has been closed.
	at com.oltpbenchmark.api.Loader$LoaderThread.run(Loader.java:70)
	at com.oltpbenchmark.util.ThreadUtil$LatchRunnable.run(ThreadUtil.java:117)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:750)
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
	at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:793)
	at org.postgresql.jdbc.PgConnection.commit(PgConnection.java:779)
	at com.oltpbenchmark.api.Loader$LoaderThread.run(Loader.java:63)
	... 4 more

On analysis found core dumps for priority_worker threads, on one of the tserver nodes node-73(172.151.30.249). This core dump is generated at the same time (May 26 20:25 UTC) when the clients have failed. and also this tserver had restarted. The stack trace from dump :

Core was generated by `/home/yugabyte/tserver/bin/yb-tserver --flagfile /home/yugabyte/tserver/conf/se'.
Program terminated with signal 11, Segmentation fault.
Dwarf Error: Cannot find DIE at 0xd13a referenced from DIE at 0x1eca63 [in module /home/yugabyte/yb-software/yugabyte-2.13.2.0-b18-centos-x86_64/bin/yb-tserver]
#-1 DecodeFixed32 (ptr=<optimized out>) at ../../src/yb/rocksdb/util/coding.h:110
110	../../src/yb/rocksdb/util/coding.h: No such file or directory.
(gdb) bt
#-1 DecodeFixed32 (ptr=<optimized out>) at ../../src/yb/rocksdb/util/coding.h:110
#0  DecodeFixed32 (ptr=<optimized out>) at ../../src/yb/rocksdb/util/coding.h:110
#1  NumRestarts (this=0x2640df590) at ../../src/yb/rocksdb/table/block.cc:495
#2  rocksdb::Block::NewIterator(rocksdb::Comparator const*, rocksdb::KeyValueEncodingFormat, rocksdb::BlockIter*, bool) (this=0x2640df590, cmp=0xd1155d8, key_value_encoding_format=1, iter=0x0, total_order_seek=true)
    at ../../src/yb/rocksdb/table/block.cc:526
#3  0x0000000003434c0a in rocksdb::BlockBasedTable::NewDataBlockIterator(rocksdb::ReadOptions const&, yb::Slice const&, rocksdb::BlockType, rocksdb::BlockIter*) (this=0x749146db0, ro=..., index_value=..., block_type=<optimized out>, input_iter=0x0)
    at ../../src/yb/rocksdb/table/block_based_table_reader.cc:1255
#4  0x0000000003456d47 in rocksdb::(anonymous namespace)::TwoLevelIterator::InitDataBlock() (this=0x8b51960) at ../../src/yb/rocksdb/table/two_level_iterator.cc:207
#5  0x000000000345654e in rocksdb::(anonymous namespace)::TwoLevelIterator::SeekToFirst() (this=0x8b51960) at ../../src/yb/rocksdb/table/two_level_iterator.cc:126
#6  0x00000000034440b7 in SeekToFirst (this=<optimized out>) at ../../src/yb/rocksdb/table/iterator_wrapper.h:127
#7  rocksdb::MergingIterator::SeekToFirst() (this=0x771b7af00) at ../../src/yb/rocksdb/table/merger.cc:98
#8  0x0000000003369023 in rocksdb::CompactionJob::ProcessKeyValueCompaction(rocksdb::FileNumbersHolder*, rocksdb::CompactionJob::SubcompactionState*) (this=0x7fb885db3e70, holder=0x7fb885db33b0, sub_compact=0x153abb400)
    at ../../src/yb/rocksdb/db/compaction_job.cc:633
#9  0x0000000003367ee2 in rocksdb::CompactionJob::Run() (this=0x7fb885db3e70) at ../../src/yb/rocksdb/db/compaction_job.cc:463
#10 0x0000000003399b9b in rocksdb::DBImpl::BackgroundCompaction(bool*, rocksdb::JobContext*, rocksdb::LogBuffer*, rocksdb::DBImpl::ManualCompaction*, std::__1::unique_ptr<rocksdb::Compaction, std::__1::default_delete<rocksdb::Compaction> >) (
    this=0x14df6d00, made_progress=0x7fb885db5067, job_context=<optimized out>, log_buffer=0x7fb885db4510, manual_compaction=0x0, compaction=...) at ../../src/yb/rocksdb/db/db_impl.cc:3640
#11 0x0000000003397ba0 in rocksdb::DBImpl::BackgroundCallCompaction(rocksdb::DBImpl::ManualCompaction*, std::__1::unique_ptr<rocksdb::Compaction, std::__1::default_delete<rocksdb::Compaction> >, rocksdb::DBImpl::CompactionTask*) (this=0x14df6d00, 
    m=0x0, compaction=..., compaction_task=<optimized out>) at ../../src/yb/rocksdb/db/db_impl.cc:3364
#12 0x00000000033a691a in rocksdb::DBImpl::CompactionTask::DoRun(yb::PriorityThreadPoolSuspender*) (this=0x0, suspender=<optimized out>) at ../../src/yb/rocksdb/db/db_impl.cc:261
#13 0x00000000038419f1 in yb::(anonymous namespace)::PriorityThreadPoolWorker::Run() (this=0x660894d8) at ../../src/yb/util/priority_thread_pool.cc:268
#14 0x000000000385a2db in operator() (this=0x2775eb90) at /opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20220223071628-16e9b7854d-almalinux8-x86_64-clang12-linuxbrew/installed/uninstrumented/libcxx/include/c++/v1/functional:1885
#15 operator() (this=0x2775eb90) at /opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20220223071628-16e9b7854d-almalinux8-x86_64-clang12-linuxbrew/installed/uninstrumented/libcxx/include/c++/v1/functional:2560
#16 yb::Thread::SuperviseThread(void*) (arg=0x2775eb40) at ../../src/yb/util/thread.cc:774
#17 0x00007fbb82842694 in start_thread (arg=0x7fb885dbd700) at pthread_create.c:333
#18 0x00007fbb82d4441d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

The logs are copied at : /home/centos/sagarwal/150k on [email protected]

[sonalsagarwal]

Also see similar issue : #13109

[sonalsagarwal]

Another occurrence in the 100k run on 2.15.1.0-b91, with tablet splitting on.

*** Aborted at 1656591152 (unix time) try "date -d @1656591152" if you are using GNU date ***
PC: @                0x0 (unknown)
*** SIGSEGV (@0x0) received by PID 20248 (TID 0x7f70d0b51700) from PID 0; stack trace: ***
    @          0x3364449 rocksdb::Block::NewIterator()
    @          0x3387a79 rocksdb::BlockBasedTable::NewDataBlockIterator()
    @          0x33af087 rocksdb::(anonymous namespace)::TwoLevelIterator::InitDataBlock()
    @          0x33ae88e rocksdb::(anonymous namespace)::TwoLevelIterator::SeekToFirst()
    @          0x339b534 rocksdb::MergingIterator::SeekToFirst()
    @          0x32a4637 rocksdb::CompactionJob::ProcessKeyValueCompaction()
    @          0x32a3533 rocksdb::CompactionJob::Run()
    @          0x32d1b5a rocksdb::DBImpl::BackgroundCompaction()
    @          0x32cef1f rocksdb::DBImpl::BackgroundCallCompaction()
    @          0x32df89a rocksdb::DBImpl::CompactionTask::DoRun()
    @          0x3a7bbe2 yb::(anonymous namespace)::PriorityThreadPoolWorker::Run()
    @          0x3a96514 yb::Thread::SuperviseThread()
    @     0x7f744bae1694 start_thread
    @     0x7f744bfe341d __clone

[rthallamko3]

This is a duplicate of #20852