Quickly get short stack from a YugabyteDB tserver
Tags: yugabytedb, distributed, sql, database
Published: 2022-06-07 13:01:04

In the [previous blog post](https://dev.to/yugabyte/yugabytedb-range-sharding-asc-or-desc-57bn) 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:

```sh
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:
```C
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()](https://github.com/yugabyte/yugabyte-db/blob/2.13.2/src/yb/tserver/tablet_service.cc#L1684) and measured `rocksdb_number_db_seek`, which is incremented in [rocksdb::DBIter::Seek()](https://github.com/yugabyte/yugabyte-db/blob/2.13.2/src/yb/rocksdb/db/db_iter.cc#L762). 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.