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.
Top comments (0)