文章目錄

• • • 內部工具
    • • 包含頭文件
      • 接口使用
      • 核心指標
      • • Perf Context
        • IOStats Context
    • 外部工具
    • • Systemtap 工具
      • Perf工具
      • Ftrace 工具

2020.8.20 23:23 ，又到了夜深人靜學習時，不斷得思考總結總會讓繁忙一天的大腦得到舒緩。

作為單機存儲引擎，Rocksdb總會被嵌入到各個存儲系統之中作為核心數據的存儲，那么有理有據得“甩鍋”便需要一些手段。在業務場景未達到rocksdb自身性能情況下，如何將rocksdb性能在業務中的體現合理展現給使用者，讓他們心服口服得"背鍋"。

本篇通過內部工具 + 外部工具 的介紹 來全面展示rocksdb 整個IO鏈（這個IO的范圍是從rocksdb入，到文件系統write系統調用完成）上的性能獲取，從而更好得決定自己是否可以瀟灑"甩鍋"。

內部工具

facebook頂尖工程師的不斷投入，精心雕琢得社區已經讓rocksdb的各個核心特性及其實現都完整展現給使用者，那么一些profling的狀態也必然存在。

基本的profiling使用方式如下：

包含頭文件

當然這兩種頭文件是不同的profling狀態
iostats_context.h主要是io層面的耗時統計，比如write,read等系統調用的耗時，計數
perf_context.h 主要是內部各個子流程的耗時統計，比如寫wal的耗時/請求計數，寫memtable的耗時/請求計數

#include “rocksdb/iostats_context.h”
#include “rocksdb/perf_context.h”

接口使用

rocksdb::SetPerfLevel(rocksdb::PerfLevel::kEnableTimeExceptForMutex); //開啟profilingrocksdb::get_perf_context()->Reset(); // 初始化perf_context對象
rocksdb::get_iostats_context()->Reset() // 初始化 iostats_context對象// ...... 調用Get/Put ，或者一些其他的IO流程rocksdb::SetPerfLevel(rocksdb::PerfLevel::kDisable); // 關閉profling//獲取具體的profling結果
std::cout << rocksdb::get_perf_context()->ToString() << std::endl; //獲取所有的perf 狀態
std::cout << rocksdb::get_iostats_context()->ToString() << std::endl; //獲取所有的iostats狀態
std::cout << "get_from_memtable_time: " << rocksdb::get_perf_context()->get_from_memtable_time << "write_nanos: "<< rocksdb::get_iostats_context()->write_nanos<< std::endl; // 獲取某一個具體狀態的數值

簡單說一下rocksdb提供的perf級別，在文件perf_level.h中

enum PerfLevel : unsigned char {kUninitialized = 0,             //  什么也不監控，一般不實用這個選項kDisable = 1,                   //  關閉profling功能kEnableCount = 2,               //  僅開啟count計數的profling 功能kEnableTimeExceptForMutex = 3,  //  僅開啟time profiling功能，我們耗時方面分析就直接開啟這個級別。//  不過使用者需要注意這里統計的耗時在不同的系統上是有差異的。kEnableTimeAndCPUTimeExceptForMutex = 4, // 僅開啟cpu 耗時的統計kEnableTime = 5,  // 開啟所有stats的統計，包括耗時和計數 kOutOfBounds = 6  //  這個不太理解。。。。。。。反正也用不到
};

一般耗時的分析直接用kEnableTimeExceptForMutex 這個級別，如果想要抓取所有的stats信息，包括耗時和計數，就可以使用kEnableTime功能。

詳細的實現主要是在perf_context_imp.h 通過宏定義來 實現一些計數和統計的接口，也是為了減少本身統計過程中函數調用的開銷。

核心指標

Perf Context

Ps: 以下的耗時統計都是取決于自己什么時候調用SetPerfLevel(rocksdb::PerfLevel::kDisable);的接口，來終止prifling。

二分查找的耗時

• user_key_comparison_count 統計二分查找的次數，如果次數過多，可能是我們配置的comparator不是很合理。當然這個也與系統中數據量的大小，是否是冷熱數據有關。

block cache或者 page cache的效率

• block_cache_hit_count 我們從block cache中讀取數據的次數
• block_read_count 從page cache中讀取數據的次數，通過和上一個指標的對比來評估block cache的miss rate，從而確定當前配置下的block cache性能。（實現上，block cache是在page cache之上的一層緩存，默認是LRU）

Get 鏈路的耗時統計
一般以get 開頭的指標，如下是比較重要那的幾個

• get_from_memtable_time 從memtable中讀取數據的耗時
• get_from_output_files_time 從sst文件中讀取數據的耗時
• seek_on_memtable_time 查找memtable的耗時

Put 鏈路耗時統計
一般以 write 開頭的指標，如下是幾個比較重要的

• write_wal_time 寫wal的耗時
• write_memtable_time 寫memtable的耗時
• write_pre_and_post_process_time 主要是寫入數據之前的一些準備耗時，不包括wal以及memtale的寫入耗時
  比如在組提交過程中，非leader的寫入需要等待leader完成wal的寫入之后才能開始寫memtble，這一些耗時也會被計算在內
  如下代碼，在開始寫memtale的時候才會停止計時，如果writer是非leader，則writer的狀態并不是能夠寫memtable的，不會進入到這個邏輯，那么非leader就會等待一段時間。
  
  之后還會進入ProcessWrite函數來統計即將寫入前的write delay 部分的耗時
  

IOStats Context

如下幾個重要的耗時指標,統計的總時間取決于什么時候關閉profiling接口，也可以每一個請求都統計一次。

• write_nanos 調用write 和 pwrite系統調用的耗時
• read_nanos 調用read和 pread系統調用的耗時統計
• fsync_nanos 調用fsync系統調用的耗時
• cpu_write_nanos 官方給的描述是 ： cpu在write 和 pwrite的耗時
  這里應該是統計cpu的寫入key-value到文件的計算耗時，因為看代碼是在compaction的最終由cpu處理 ProcessKeyValueCompaction函數的起始和末尾計算了一下耗時
• cpu_read_nanos cpu在read 和 pread的耗時
  同樣read也是在上文中的函數中進行統計的，因為ProcessKeyValueCompaction的處理過程中會涉及key-value 從底層sst文件中的讀取

一個簡單的demo之前的統計信息：

	.......rocksdb::get_perf_context()->Reset();rocksdb::get_iostats_context()->Reset();std::vector<string> keys, values;rocksdb::WriteOptions write_option;rocksdb::Status s;/*執行具體IO操作，stats的統計是兩次put，一個get的總和*/s = binlog_vec[n_db]->Put(write_option, k, rand_value);assert(s.ok());s = db_vec[n_db]->Get(rocksdb::ReadOptions(), k, &value); assert(s.ok());s = db_vec[n_db]->Put(write_option, k, rand_value);assert(s.ok());req_num ++; buff_num ++; if (!s.ok()){   cerr << "Put failed: " << s.ToString() << endl;exit(1);}   //if ( thread_id==21 && (now() - ts) >= 1.00 )if ( (now() - ts) >= 1.00 ) //每隔一秒打印一次{   time_t temp;temp = time(NULL); printf("time is :%s thread_id %ld db%d :  count=%ld, speed=%ld\n", \ctime(&temp),thread_id, n_db, req_num, buff_num);ts = now();buff_num = 0;g_time += 10; // 關閉profilingrocksdb::SetPerfLevel(rocksdb::PerfLevel::kDisable);std::cout << "get_perf_context: \n get_from_memtable_time: " << rocksdb::get_perf_context()->get_from_memtable_time<< "\nget_from_output_files_time: " << rocksdb::get_perf_context()->get_from_output_files_time << "\nblock_read_time: " << rocksdb::get_perf_context()->block_read_time << "\nseek_on_memtable_time "<< rocksdb::get_perf_context()->seek_on_memtable_time << "\nseek_min_heap_time "<< rocksdb::get_perf_context()->seek_min_heap_time << "\neek_max_heap_time "<< rocksdb::get_perf_context()->seek_max_heap_time << "\nseek_internal_seek_time "<< rocksdb::get_perf_context()->seek_internal_seek_time << "\nwrite_wal_time "<< rocksdb::get_perf_context()->write_wal_time << "\nwrite_memtable_time "<< rocksdb::get_perf_context()->write_memtable_time << "\nwrite_delay_time "<< rocksdb::get_perf_context()->write_delay_time << "\nwrite_scheduling_flushes_compactions_time "<< rocksdb::get_perf_context()->write_scheduling_flushes_compactions_time << "\n write_pre_and_post_process_time "<< rocksdb::get_perf_context()->write_pre_and_post_process_time << "\nwrite_nanos "<< rocksdb::get_iostats_context()-> write_nanos<< "\nread_nanos "<< rocksdb::get_iostats_context()-> read_nanos<< std::endl;std::string out;db_vec[n_db]->GetProperty("rocksdb.estimate-pending-compaction-bytes", &out);fprintf(stdout, "rocksdb.estimate-pending-compaction-bytes : %s\n", out.c_str());if(g_time == 60) {std::cout << "begin write" << std::endl;judge_read = false;}   } ......

輸出如下，以下的耗時統計單位都是微妙:

get_perf_context: get_from_memtable_time: 838
get_from_output_files_time: 0
block_read_time: 0
seek_on_memtable_time 0
seek_min_heap_time 0
eek_max_heap_time 0
seek_internal_seek_time 0
write_wal_time 5947
write_memtable_time 2050
write_delay_time 0
write_scheduling_flushes_compactions_time 261write_pre_and_post_process_time 899
write_nanos 4513
read_nanos 0

這樣，我們就可以通過簡單的rocksdb內部已有的工具來進行引擎層的profiling過程排查分析，比如上層存儲系統調用rocksdb接口，我們可以將我們rocksdb內部耗時完整展示出來，那么是不是我們的問題就一目了然了。

當然這樣的調試過程還會有一些麻煩，我們需要侵入業務的代碼，增加一些狀態統計，不過結果是精確的，即使因為統計本事的耗時所產生的誤差也基本都是us級的，并不影響宏觀上的性能比對。

外部工具

結合內部調試工具，我們再通過外部工具進行一些rocksdb流程上耗時的抓取，這里需要對rocksdb內部實現有一定的了解， 我們需要知道抓取一些rocksdb的IO鏈上的函數。

抓取之前需要應用的二進制文件中包含rocksdb的符號表，即編譯rocksdb需要加入-g或者-gd b參數來編譯。

大體思路上，還是說先集中在rocksdb內部的耗時之上，因為我們需要明確rocksdb自己的性能上限，處理一個key的過程中，內部各個字階段的耗時大概是什么樣子的量級，相關的測試都是基于Centos7.4 3.10內核。

Systemtap 工具

Systemtap 工具是一種可以通過腳本進行自由擴展的動態追蹤技術，但是因為長時間游離于內核之外，所以在RHEL系統中是比較穩定，而其他系統則容易出現異常。

反過來說，在3.x 等舊版本內核中，systemtap 相比于eBPF 是一個巨大的優勢。

首先通過systemtap 來獲取我們rocksdb內部子流程上的關鍵函數調用棧，從而幫助大家更好的分析。

如果沒有stap命令，則可以通過sudo yum install system tap -y來安裝systemtap工具。

比如我們抓取寫WAL 函數的調用棧，編寫call_trace.stp 如下

#!/bin/stapprobe process("/home/test_binary").function("rocksdb::DBImpl::WriteToWAL")  print("------------------------------------\n")print_ubacktrace()print("------------------------------------\n")}

通過sudo stap call_trace.stp | c++filt 將每次調用WriteToWAL函數的調用棧打印出來。這里如果編譯rocksdb的時候采用demangle的方式，那么就不需要c++filt了， 否則會出現一些亂碼，這里使用c++filt進行過濾。

最終可以看到很多wal相關的調用棧信息如下

通過調用棧，我們就大概知道了從rocksdb的IO鏈路到上層應用鏈路的調用關系， 取到了這條路徑上的函數，再逐層從下向上結合后面的stap腳本進行耗時統計。

以下是一個案例，可以在binary中增加多個探針，來打印對應函數的耗時情況。

!#/bin/stapglobal timesprobe process("/home/test_binary").function("rocksdb::DBImpl::WriteImpl").return,process("/home/test_binary").function("rocksdb::DBImpl::WriteToWAL").return,process("/home/test_binary").function("rocksdb::WriteBatchInternal::InsertInto").return,process("/home/test_binary").function("rocksdb::WriteBatchInternal::Iterate").return,process("/home/test_binary").function("rocksdb::MemTable::Add").return {times[pid(), ppfunc()] += gettimeofday_us() - @entry(gettimeofday_us()) #耗時及耗時信息放在times 數組之中
}probe timer.s(10) { #每隔十秒打印一次println("========%s", execname())foreach([pid, pp] in times - limit 10) {printf("pid:%5d %50s %10ld(us)\n", pid, pp, times[pid, pp])}delete times
}

最終結果如下（這個結果顯然偏高了）:

========%sswapper/42
pid:98097                         rocksdb::DBImpl::WriteImpl    1510686(us)
pid:98097                        rocksdb::DBImpl::WriteToWAL    1153604(us)
pid:98097            rocksdb::WriteBatchInternal::InsertInto     574674(us)
pid:98097               rocksdb::WriteBatchInternal::Iterate     437807(us)
pid:98097                             rocksdb::MemTable::Add     257805(us)

一般不建議使用這種多個探針方式進行探測，這樣會對應用程序性能有比較大的影響，systemtap的執行方式是 先轉換成C代碼，編譯成內核模塊，加載到內核中，對指定的用戶程序添加探針，根據指定的行為做對應的返回。如果同時有過多的探針，那肯定會對性能有比較大的影響。

所以這里抓取 的 耗時能夠和rocksdb內部統計的耗時數據核對上之后（比如writeToWAL函數的消耗），再進行逐層向上抓取，當然也可以向下抓取。

比如writeToWAL之下會調用AddRecord函數進行log文件的寫入，再之下會通過Flush函數進行數據的寫入，通過PosixWritableFile::Append函數 調用 PosixWrite函數，最終執行到文件系統的write系統調用之上。詳細的寫WAL的實現可以參考Rocksdb Wal機制 底層探索。

System tap 這個工具本身還是有很多可以研究的地方，能夠極大得節省內核的調試效率（本身的執行方式就是編譯成對應的內核模塊，加載到系統中執行的），但是在調試用戶態應用過程中除了會對應用本身性能有影響之外，其他功能方面的影響還好。

Perf工具

Perf 同樣是google開發出來的可以調試用戶態以及內核態應用的工具，這里還是挑一些簡單的子工具來用作我們rocksdb層面的性能分析。

首先Perf 能夠抓取On CPU的進程消耗調用棧，且提供一個火焰圖來展示調用棧的信息。

下載FlameGraph到服務器之上，進入FlameGraph目錄之后通過root用戶執行如下腳本抓取對應進程的On CPU消耗，并且是調用棧的形式。

#!/bin/bashpid=$1if [ -z "$pid" ];thenperf record -F 99 -g -- sleep 180 
elseperf record -F 99 -p $pid -g -- sleep 180 
fiperf script > out.perf./stackcollapse-perf.pl out.perf > out.folded
./flamegraph.pl out.folded > kernel-"$pid".svg

傳入進程PID,即可生成一個可視化的.svg文件，包含on cpu的進程內部各個函數的消耗情況。

當然這個只能看到一個大體的百分比，我們想要看到具體的耗時情況需要切換一下子工具。

使用perf probe來增加類似于systemtap的探針功能，不過perf的采樣更加輕量級，關于內核態的調試這里也是類似的，可以提前perf list來查看 可調試的探針。

• perf probe增加探針
  這里需要提前說明一下，因為perf probe向用戶態應用增加探針時可能因為編譯選項的一些問題（C++工程沒有demangle），則無法找到對應探測的函數地址。建議先手動找一下函數地址，直接使用函數地址進行探測。
  通過objdump工具查看函數所處二進制文件中的偏移地址，位于打印出來的第一列

  objdump /home/test_binary --syms | c++filt | grep -i "rocksdb::rocksdb::log::Writer::AddRecord"

  增加perf 探針

  sudo perf probe -x /home/test_binary '0x0000000000f7d59c'
  

  增加成功之后會給一個類似于這樣的地址 probe_test_binary:abs_f7d59c，直接復制進行接下來的采樣即可。
  如果是探測內核函數，更換一下命令選項即可。

  $ perf probe --add do_sys_open
  Added new event:probe:do_sys_open    (on do_sys_open)
  You can now use it in all perf tools, such as:
  perf record -e probe:do_sys_open -aR sleep 1
  

• perf record進行采樣

  sudo perf record -e probe_test_binary:abs_f7d59c -aR sleep 60

• perf script生成可讀性報告，查看采樣結果

  sudo perf script
  當然這里調試內核的時候可以增加一些參數選項：

  $ perf probe -V do_sys_openAvailable variables at do_sys_open@<do_sys_open+0>char* filenameint dfdint flagsstruct open_flags opumode_t mode
  

  從而能夠使用帶參數的探測選項來完成更加詳細的探測信息展示：

  perf probe --add 'do_sys_open filename:string'

• perf brobe --del 探針用完之后需要刪除掉

  sudo perf probe --del probe_test_binary:abs_f7d59c

  這里的perf probe還是追蹤一些調用關系的邏輯，在火焰圖的分析中可以再關注rocksdb層面在當前進程中的消耗占比，大體是能夠看出我們rocksdb在當前CPU下的一個壓力情況。

  不過很多情況，我們還是想要更加精確得了解到系統硬件以及一些系統調用執行到情況，這個時候就需要探測一些硬件相關到事件，比如cpu cache-misses,context-switches,cpu-migrations 等CPU相關的事件，這一些數據的升高，可能系統存在大量的無效線程切換，從而導致整個CPU消耗在非IO鏈路之上。

  或者說我們想追蹤某一個內核函數的執行情況，也可以通過perf 的tracepoints進行追蹤。
  接下來簡單演示一下這個perf 組合命令的使用詳情：

• perf list查看可追蹤的事件
  
  或者通過perf list的子命令來查看具體的可采樣的事件

  • perf list hw 查看可以采樣的具體硬件事件,像cpu 的cache-misses,branch-misses,ref-cycle等重要指標

    簡單說一下CPU cache, 它是操作系統設計的局部性原理的體現，利用CPU L1-cache（訪問速度遠高于內存，但是容量小）來保存近期CPU處理過的數據，CPU再次進行計算時，需要重新加載參與計算的數據，此時會先從L1-cache中查找，如果找到了就不去內存中找了。這樣的一個優化在有大量局部性特性的數據處理過程中會極大得提升處理效率。

    如下簡單的代碼

    #include <stdio.h>
    #include <unistd.h>int a[10000][10000];int main(int argc, char **argv)
    {int i,j;printf("%d \n",argc);if(argc == 1){for(i = 0; i < 10000; ++i){for(j = 0; j < 10000; ++j){a[i][j] = 0;}}}else{for(i = 0; i < 10000; ++i){for(j = 0; j < 10000; ++j){a[j][i] = 0;}}}return 0;
    }
    

    這里兩種相同功能，但不同賦值順序的循環，CPU處理性能差異還是比較大的。
    第二個循環性能會比較差，因為第二個循環的j 數據每次都會變化，j控制的是行的訪問，每次賦值都需要重新加載一整行的數據到CPU cache之中，所以這樣的循環下CPU cache的局部性優化就不怎么明顯了，而且存在大量的cache-misses

    性能差異：
    可以看到在相同環境下見到操作一億條數據時的執行效率有兩倍的差異
    

    通過perf 驗證如下:
    對應的cpu cache-misses也有接近七倍的差異，在CPU cache這里的空間局部性非常差，性能自然就會差。相當于CPU 每次加載不到cpu-cache的時候就需要訪存，自然帶來更大的開銷。
    那就會有人問，為什么不把cpu cache再增大一點呢，這樣不就有更多的空間存放更多的數據來靠近CPU執行了。

    CPU的設計工藝上 就是核心芯片，無數的功能集中在數平方厘米的地盤（計算，存儲，肯定是以計算為主），為了一增大一部分的存儲的性能，而讓計算變得更加擁擠，自然是得不償失。
    

• perf stat 實時進行events的采樣
  以上案例展示了通過perf stat來 抓取具體的事件執行情況，我們也可以抓取具體進程的某個事件指標
  perf stat -e $events -p $pid sleep $time 抓取一段時時間內指定進程的指定events情況。
  這里的time單位是s
  詳細的events還包括具體內核模塊的函數，可以通過perf list tracepoint查看
  

• perf record 對給定的evets采樣一段時間，做一個數據記錄
  perf record -e $events -p $pid -o $output_filename sleep $time
  如果沒有指定-o 參數，采樣完成后會生成一個perf.data文件，否則會將針對events的采樣數據存放在當前目錄下自己指定的文件之中
  

• perf report 將record記錄的數據生成可讀性的報告
  perf report -i $input_file 通過 -i 參數指定自己record生成的數據文件，如果不用-i參數，則默認會加載 perf.data數據
  接下來看到的report中的數據就類似perf top中的每個函數的消耗占用情況

Ftrace 工具

ftrace 工具通過擴展支持了各種事件的跟蹤功能，來以普通文件的形式，向用戶提供抓取內核系統調用的接口。
主要是通過類似于procfs的debugfs進行文件訪問 。
這樣 不需要額外的工具，只需要掛載/sys/kernel/debug/tracing目錄，對內部的文件進行讀寫，來跟ftrace進行交互。

• 一般交互是需要進入/sys/kernel/debug/tracing目錄，所以第一步 root用戶 執行cd /sys/kernel/debug/tracing
• 如果該目錄不存在，則用進行掛載 mount -t debugfs nodev /sys/kernel/debug
• 設置追蹤函數 echo SyS_write > set_graph_function
  通過cat available_filter_functions 能夠看到當前可以追蹤的內核函數，有大量的不同模塊的內核函數以及系統調用
  通過cat available_events 可以看到支持追蹤的事件,這個事件是內核源碼中事先定義好的追蹤點
• 配置追蹤選項，echo function_graph > current_tracer
  其中查看支持的追蹤器可以通過cat available_tracers

  # cat available_tracers
  hwlat blk function_graph wakeup_dl wakeup_rt wakeup function nop
  

  這其中，function 表示跟蹤函數的執行，function_graph 則是跟蹤函數的調用關系，也就是生 成直觀的調用關系圖，這便是最常用的兩種跟蹤器。
• 配置追蹤進程選項，echo funcgraph-proc > trace_options
• 開啟追蹤
  echo 1 > tracing_on
• 關閉追蹤
  echo 0 > tracing_on
• 查看追蹤結果 cat trace
  可以看到SyS_write 整體執行到底層的調用鏈，甚至將每一個函數的耗時都展示出來了
  
  以上的輸出含義如下：
  • 第一列表示運行的 CPU
  • 第二列是任務名稱和進程 PID或者主線程ID
  • 第三列是函數執行延遲，單位是 us
  • 最后一列，則是函數調用關系圖。

可以看到以上執行的整個過程還是比較復雜的，需要操作很多的文件，所以這里ftrace開發者提供了trace-cmd工具進行追蹤步驟的簡化。

通過yum install trace-cmd -y即可安裝。
使用方式:

#追蹤系統所有執行`SyS_write`  系統調用的進程
trace-cmd record -p function_graph -g SyS_write -O funcgraph-proc
trace-cmd start # 開啟追蹤
trace-cmd stop # 結束追蹤
trace-cmd reset # 重置所有配置信息

其他詳細的使用可以參考trace-cmd -h

這里有一個性能文件需要提前說明一下，因為ftrace 追蹤的是內核的函數，采樣的頻率很高，實際的內核函數的執行耗時大概只有ftrace抓取的十分之一，不過并不影響我們來確認具體的執行邏輯和耗時比對（相同環境下）。

通過如上的內部工具 + 外部工具基本能夠觀察到整個rocksdb 引擎層的耗時情況，這個時候即使不能甩鍋，也能輕松定位到具體耗時的函數，來讓我們的問題分析排查過程更加精確簡單。

總結

以上是生活随笔為你收集整理的关于 Rocksdb 性能分析 需要知道的一些“小技巧“ -- perf_context的“内功” ，systemtap、perf、 ftrace的颜值的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。