Quickly get short stack from a YugabyteDB tserver

In the previous blog post I looked at the call stack for RocksDB seeks with a flamegraph. If, for whatever reason, you don't have access to run perf on the tserver node, the current stacks are exposed in the tserver endpoint :9000/threadz. Here is a quick script that samples them for 60 seconds, keeps only the calls from yb::tserver::PerformRead to rocksdb::DBIter::Seek() and displays the different code path with the number of samples for each:

end=$(( $SECONDS + 60 ))
while [ $SECONDS -lt $end ]
do
curl -Ls http://$(hostname):9000/threadz?group=rpc_thread_pool | awk '
/rocksdb::DBIter::Seek/,/yb::tserver::PerformRead/{
 sub(/^.* 0x[^ ]+ */,"")
 sub(/[<][/].*/,"")
 stack=$0" @ "stack
}/Total number of threads/ && stack!=""{
 #print NF" samples of:\t"stack
 samples[stack]=samples[stack]+NF
 stack=""
}
END{
 for (i in samples) print samples[i]" samples of: @ "i
}'
done | sort -n | uniq -c | awk '
{ $1=$1+$2;$2="" ; print }
' | sort -n | sed -e 's/ @/\n/g'

The output for the same run as the previous blog post about Index Scan Backwards shows the different PerformRocksDBSeek calls:

9  samples of:
 yb::tserver::PerformRead()
 yb::tserver::(anonymous namespace)::ReadQuery::Complete()
 yb::tablet::Tablet::HandlePgsqlReadRequest()
 yb::tablet::AbstractTablet::ProcessPgsqlReadRequest()
 yb::docdb::PgsqlReadOperation::Execute()
 yb::docdb::PgsqlReadOperation::ExecuteScalar()
 yb::docdb::(anonymous namespace)::CreateIterator()
 yb::docdb::QLRocksDBStorage::GetIterator()
 yb::docdb::DocRowwiseIterator::Init()
 yb::docdb::IntentAwareIterator::PreparePrev()
 yb::docdb::PerformRocksDBSeek()
 rocksdb::DBIter::Seek()

30  samples of:
 yb::tserver::PerformRead()
 yb::tserver::(anonymous namespace)::ReadQuery::Complete()
 yb::tablet::Tablet::HandlePgsqlReadRequest()
 yb::tablet::AbstractTablet::ProcessPgsqlReadRequest()
 yb::docdb::PgsqlReadOperation::Execute()
 yb::docdb::PgsqlReadOperation::ExecuteScalar()
 yb::docdb::DocRowwiseIterator::HasNext()
 yb::docdb::DocDBTableReader::Get()
 yb::docdb::IntentAwareIterator::SeekForward()
 yb::docdb::IntentAwareIterator::SeekForwardRegular()
 yb::docdb::PerformRocksDBSeek()
 rocksdb::DBIter::Seek()

61  samples of:
 yb::tserver::PerformRead()
 yb::tserver::(anonymous namespace)::ReadQuery::Complete()
 yb::tablet::Tablet::HandlePgsqlReadRequest()
 yb::tablet::AbstractTablet::ProcessPgsqlReadRequest()
 yb::docdb::PgsqlReadOperation::Execute()
 yb::docdb::PgsqlReadOperation::ExecuteScalar()
 yb::docdb::DocRowwiseIterator::HasNext()
 yb::docdb::DocRowwiseIterator::AdvanceIteratorToNextDesiredRow()
 yb::docdb::IntentAwareIterator::SeekToLatestDocKeyInternal()
 yb::docdb::IntentAwareIterator::Seek()
 yb::docdb::PerformRocksDBSeek()
 rocksdb::DBIter::Seek()

72  samples of:
 yb::tserver::PerformRead()
 yb::tserver::(anonymous namespace)::ReadQuery::Complete()
 yb::tablet::Tablet::HandlePgsqlReadRequest()
 yb::tablet::AbstractTablet::ProcessPgsqlReadRequest()
 yb::docdb::PgsqlReadOperation::Execute()
 yb::docdb::PgsqlReadOperation::ExecuteScalar()
 yb::docdb::DocRowwiseIterator::HasNext()
 yb::docdb::DocRowwiseIterator::AdvanceIteratorToNextDesiredRow()
 yb::docdb::IntentAwareIterator::PreparePrev()
 yb::docdb::PerformRocksDBSeek()
 rocksdb::DBIter::Seek()

In this example, I was running a read (a SELECT with Index Scan Backward), served by yb::tserver::PerformRead() and measured rocksdb_number_db_seek, which is incremented in rocksdb::DBIter::Seek(). This is why I was interested by the stack going to those seeks. In those short samples I can see the reason for the two seeks per row: one is AdvanceIteratorToNextDesiredRow to go to the previous key, and the other is SeekToLatestDocKeyInternal to go to right read time.