背景
數據庫的性能優化是一個非常經典的話題，數據庫的優化手段以及優化的角度也各不相同。
例如，可以從OS內核、網絡、塊設備、編譯器、文件系統、SQL、數據庫參數、業務邏輯、源碼等各個方面去進行優化。
但是如果在優化前了解瓶頸在什么地方，可以向打鼴鼠一樣，先打大的，起到事半功倍的效果。
本文將針對Linux平台下的PostgreSQL服務，講解如何診斷PostgreSQL 數據庫服務的瓶頸，了解瓶頸在哪個方面，甚至可以了解到瓶頸在哪段代碼？
有了比較詳細的性能診斷報告，可以給出比較好的指導優化建議。
我們要用到的工具是 《Linux 性能診斷(profiling) perf使用指南》
使用perf跟蹤PostgreSQL的前提
要輸出完備的跟蹤信息，如符號表，call stack traces, 匯編指令。必須在編譯PostgreSQL時設置相應的編譯開關，例如GCC需要開啟如下
CFLAGS="-g -ggdb -fno-omit-frame-pointer" 建議Linux內核編譯時加上
CONFIG_KALLSYMS=y CONFIG_FRAME_POINTER=y 編譯perf時需要支持libunwind, 並加上
gcc -g dwarf
man gcc
-gdwarf-version
Produce debugging information in DWARF format (if that is supported). This is the format used by DBX on IRIX 6. The value of version may be either 2 or 3; the default version is 3. Note that with DWARF version 2 some ports require, and will always use, some non-conflicting DWARF 3 extensions in the unwind tables. 如果是yum安裝的軟件，可以安裝對應的debuginfo包。
例子
wget https://ftp.postgresql.org/pub/source/v9.6.1/postgresql-9.6.1.tar.bz2 tar -jxvf postgresql-9.6.1.tar.bz2 cd postgresql-9.6.1 export USE_NAMED_POSIX_SEMAPHORES=1 LIBS=-lpthread CC="/home/digoal/gcc6.2.0/bin/gcc" CFLAGS="-O3 -flto -g -ggdb -fno-omit-frame-pointer" ./configure --prefix=/home/digoal/pgsql9.6 LIBS=-lpthread CC="/home/digoal/gcc6.2.0/bin/gcc" CFLAGS="-O3 -flto -g -ggdb -fno-omit-frame-pointer" make world -j 64 LIBS=-lpthread CC="/home/digoal/gcc6.2.0/bin/gcc" CFLAGS="-O3 -flto -g -ggdb -fno-omit-frame-pointer" make install-world 常用跟蹤手段
1. benchmark
首先，需要定一個目標，比如insert only的場景，如何找到其瓶頸。
創建測試表
postgres=# create table perf_test_ins(id serial8 primary key, info text, crt_time timestamp); alCREATE TABLE postgres=# alter sequence perf_test_ins_id_seq cache 10000; ALTER SEQUENCE 創建測試腳本，不停插入
vi test.sql
insert into perf_test_ins(info,crt_time) values ('test',now()); 疲勞壓測開始
pgbench -M prepared -n -r -P 1 -f ./test.sql -h $PGDATA -c 32 -j 32 -T 600 2. 實時跟蹤
pgbench壓測的同時，實時觀測。
su - root
perf top -agv -F 1000 解釋 perf top --help NAME perf-top - System profiling tool. SYNOPSIS perf top [-e <EVENT> | --event=EVENT] [<options>] DESCRIPTION This command generates and displays a performance counter profile in real time. -F <freq>, --freq=<freq> Profile at this frequency. -a, --all-cpus System-wide collection. (default) -g, --group Put the counters into a counter group. -K, --hide_kernel_symbols Hide kernel symbols. -U, --hide_user_symbols Hide user symbols. -v, --verbose Be more verbose (show counter open errors, etc). 輸出
PerfTop: 23287 irqs/sec kernel:31.2% exact: 0.0% [1000Hz cycles], (all, 24 CPUs) -------------------------------------------------------------------------------------------------------------- samples pcnt RIP function DSO _______ _____ ________________ _________________________________________ _____________________________________ 4179.00 1.6% 0000000000524e10 AllocSetAlloc.lto_priv.1186 /home/digoal/pgsql9.6/bin/postgres 3966.00 1.5% 0000000000043d10 __GI_vfprintf /lib64/libc-2.12.so 3822.00 1.5% ffffffff8150bb50 schedule [kernel.kallsyms] 3659.00 1.4% 0000000000082e10 __memset_sse2 /lib64/libc-2.12.so 3523.00 1.4% 00000000005782d0 LWLockAcquire.constprop.931 /home/digoal/pgsql9.6/bin/postgres 3219.00 1.2% 00000000002c9390 LWLockRelease /home/digoal/pgsql9.6/bin/postgres 3114.00 1.2% 0000000000332e10 PostgresMain /home/digoal/pgsql9.6/bin/postgres 3042.00 1.2% ffffffff8150e8b0 _spin_lock [kernel.kallsyms] 2948.00 1.1% 0000000000573fe0 hash_search_with_hash_value.constprop.930 /home/digoal/pgsql9.6/bin/postgres 2901.00 1.1% 00000000005746d0 hash_search_with_hash_value.constprop.928 /home/digoal/pgsql9.6/bin/postgres 2848.00 1.1% 00000000002db5f0 GetSnapshotData /home/digoal/pgsql9.6/bin/postgres 2471.00 1.0% 00000000005338b0 hash_seq_search /home/digoal/pgsql9.6/bin/postgres 2275.00 0.9% 0000000000579ad0 LWLockAcquire.constprop.932 /home/digoal/pgsql9.6/bin/postgres 2244.00 0.9% 0000000000078460 _int_malloc /lib64/libc-2.12.so 2215.00 0.9% 0000000000088aa0 memcpy /lib64/libc-2.12.so 2163.00 0.8% 00000000002df050 LockAcquireExtended /home/digoal/pgsql9.6/bin/postgres 2057.00 0.8% 0000000000131a70 __strlen_sse42 /lib64/libc-2.12.so 2017.00 0.8% 00000000002ba2d0 _bt_compare /home/digoal/pgsql9.6/bin/postgres 1977.00 0.8% 0000000000006e40 doCustom.lto_priv.13 /home/digoal/pgsql9.6/bin/pgbench 1951.00 0.8% ffffffff8100a630 __switch_to [kernel.kallsyms] 1855.00 0.7% 000000000053d5e0 hash_search_with_hash_value /home/digoal/pgsql9.6/bin/postgres 1767.00 0.7% 00000000001c6670 hash_any /home/digoal/pgsql9.6/bin/postgres 1726.00 0.7% 00000000002c8310 PinBuffer.isra.3.lto_priv.2340 /home/digoal/pgsql9.6/bin/postgres 1668.00 0.6% 00000000000ee570 XLogInsertRecord /home/digoal/pgsql9.6/bin/postgres 1604.00 0.6% 0000000000250500 pgstat_report_activity /home/digoal/pgsql9.6/bin/postgres 1572.00 0.6% ffffffff81189c00 fget_light [kernel.kallsyms] 1565.00 0.6% 0000000000426970 SearchCatCache /home/digoal/pgsql9.6/bin/postgres 1460.00 0.6% ffffffff810e03a0 __audit_syscall_exit [kernel.kallsyms] 1415.00 0.5% ffffffff81057e80 update_curr [kernel.kallsyms] 1409.00 0.5% 00000000000777f0 _int_free /lib64/libc-2.12.so 1386.00 0.5% 00000000000fbc10 CommitTransaction.lto_priv.2946 /home/digoal/pgsql9.6/bin/postgres 1296.00 0.5% ffffffff8119f6d0 do_select [kernel.kallsyms] 1285.00 0.5% 00000000002c8690 LWLockWaitListLock.lto_priv.1265 /home/digoal/pgsql9.6/bin/postgres 1268.00 0.5% ffffffff8150e790 _spin_lock_irqsave [kernel.kallsyms] 1247.00 0.5% 0000000000577650 hash_search_with_hash_value.constprop.929 /home/digoal/pgsql9.6/bin/postgres 1220.00 0.5% 0000000000538a10 AllocSetFree.lto_priv.1187 /home/digoal/pgsql9.6/bin/postgres 1201.00 0.5% 0000000000389660 ExecModifyTable /home/digoal/pgsql9.6/bin/postgres 1185.00 0.5% 000000000009b6d0 gettimeofday /lib64/libc-2.12.so 1171.00 0.5% ffffffff81278a60 copy_user_generic_string [kernel.kallsyms] 1142.00 0.4% 000000000013cb10 __memcmp_sse4_1 /lib64/libc-2.12.so 1124.00 0.4% 0000000000032620 __GI___sigsetjmp /lib64/libc-2.12.so 1123.00 0.4% 00000000000ef2b0 XLogInsert /home/digoal/pgsql9.6/bin/postgres 1112.00 0.4% 00000000002d29e0 LockReleaseAll /home/digoal/pgsql9.6/bin/postgres 1108.00 0.4% 00000000003c7620 ExecInitExpr /home/digoal/pgsql9.6/bin/postgres 1056.00 0.4% 000000000000ac80 threadRun.lto_priv.20 /home/digoal/pgsql9.6/bin/pgbench 1052.00 0.4% ffffffff81062a40 select_task_rq_fair [kernel.kallsyms] 1033.00 0.4% 0000000000017710 pqParseInput3 /home/digoal/pgsql9.6/lib/libpq.so.5.9 按Enter鍵彈出可以配置的選項以及當前狀態。
Mapped keys:
[d] display refresh delay. (2)
[e] display entries (lines). (47)
[f] profile display filter (count). (5)
[F] annotate display filter (percent). (5%)
[s] annotate symbol. (NULL)
[S] stop annotation. [K] hide kernel_symbols symbols. (no) 是否顯示kernel symbols [U] hide user symbols. (no) 是否顯示user symbols [z] toggle sample zeroing. (0) [qQ] quit. 調整壓測命令，連接回環地址，(前面連接的是unix socket)
pgbench -M prepared -n -r -P 1 -f ./test.sql -h 127.0.0.1 -c 32 -j 32 -T 600 再次觀測perf top結果, 采樣消耗排名第一的變成了這條，找到了一個瓶頸，關閉iptables，這條就消失了，TPS也提升了。
5871.00 1.7% 0000000000002e40 ipt_do_table /lib/modules/2.6.32-358.23.2.ali1195.el6.x86_64/kernel/net/ipv4/netfilter/ip_tables.ko 3. 跟蹤事件計數（指定事件）
指定命令進行跟蹤，或者指定PID進行跟蹤。
NAME
perf-stat - Run a command and gather performance counter statistics SYNOPSIS perf stat [-e <EVENT> | --event=EVENT] [-a] <command> perf stat [-e <EVENT> | --event=EVENT] [-a] — <command> [<options>] DESCRIPTION This command runs a command and gathers performance counter statistics from it. -a, --all-cpus system-wide collection from all CPUs -c, --scale scale/normalize counter values -B, --big-num print large numbers with thousands′ separators according to locale -v, --verbose be more verbose (show counter open errors, etc) -p, --pid=<pid> stat events on existing process id -t, --tid=<tid> stat events on existing thread id -r, --repeat=<n> repeat command and print average + stddev (max: 100) 跟蹤批量插入一批記錄的事件調用統計
event來自perf list的輸出
perf stat -e block:*,syscalls:*,xfs:* -a -B -v -c -- /home/digoal/pgsql9.6/bin/psql -h 127.0.0.1 -p 5288 -q -U postgres postgres -c "drop table if exists x; create table x as select a FROM generate_series(1,1000000) a;"; 輸出
0 block:block_rq_abort [98.79%] 0 block:block_rq_requeue [98.79%] 995 block:block_rq_complete [98.79%] 993 block:block_rq_insert [98.79%] 997 block:block_rq_issue [98.79%] 0 block:block_bio_bounce [98.79%] 0 block:block_bio_complete [98.79%] 18 block:block_bio_backmerge [98.79%] 1 block:block_bio_frontmerge [98.79%] 1,011 block:block_bio_queue [98.79%] 992 block:block_getrq [98.79%] 2 block:block_sleeprq [98.79%] 250 block:block_plug [98.79%] 2 block:block_unplug_timer [98.79%] 361 block:block_unplug_io [98.79%] 0 block:block_split [98.79%] 1,011 block:block_remap [98.79%] 0 block:block_rq_remap [98.79%] 5 syscalls:sys_enter_socket [98.79%] 5 syscalls:sys_exit_socket [98.79%] 0 syscalls:sys_enter_socketpair [98.79%] 0 syscalls:sys_exit_socketpair [98.79%] ... 略 ... 計數例子
perf stat -a -B -v -c -- /home/digoal/pgsql9.6/bin/psql -h 127.0.0.1 -p 5288 -q -U postgres postgres -c "drop table if exists x; create table x as select a FROM generate_series(1,1000000) a;"; 22433.920027 task-clock # 24.042 CPUs utilized [100.00%] 4,275 context-switches # 0.000 M/sec [100.00%] 98 CPU-migrations # 0.000 M/sec [100.00%] 56,484 page-faults # 0.003 M/sec 2,687,623,473 cycles # 0.120 GHz [80.73%] 2,747,044,652 stalled-cycles-frontend # 102.21% frontend cycles idle [92.42%] 2,358,755,489 stalled-cycles-backend # 87.76% backend cycles idle [81.89%] 3,373,693,967 instructions # 1.26 insns per cycle 越高越好，說明CPU沒閑着。至少要大於1，但是注意同步鎖等待這個值也可能很高，CPU空轉，這就不好了。 # 0.81 stalled cycles per insn [91.50%] 越低越好，說明CPU沒有閑着。 632,351,270 branches # 28.187 M/sec [91.82%] 1,236,798 branch-misses # 0.20% of all branches [53.19%] 0.933128299 seconds time elapsed perf stat重點看的是instructions，判斷CPU是否充分被利用，如果沒有，說明系統有其他瓶頸，例如IO等待，或者其他等待。
4. 采樣跟蹤
這個是用得最多的，先采樣，后分析報告。
NAME
perf-record - Run a command and record its profile into perf.data SYNOPSIS perf record [-e <EVENT> | --event=EVENT] [-l] [-a] <command> perf record [-e <EVENT> | --event=EVENT] [-l] [-a] — <command> [<options>] DESCRIPTION This command runs a command and gathers a performance counter profile from it, into perf.data - without displaying anything. This file can then be inspected later on, using perf report. -A, --append Append to the output file to do incremental profiling. -o, --output= Output file name. -e, --event= event來自perf list的輸出 Select the PMU event. Selection can be a symbolic event name (use perf list to list all events) or a raw PMU event (eventsel+umask) in the form of rNNN where NNN is a hexadecimal event descriptor. -a, --all-cpus System-wide collection from all CPUs. -g, --call-graph Do call-graph (stack chain/backtrace) recording. -v, --verbose Be more verbose (show counter open errors, etc). -s, --stat 相對的是默認的per cpu mode Per thread counts. -G name,..., --cgroup name,... 如果你只想跟蹤某一些進程的統計信息，可以將這些進程放到一個cgroup中，跟蹤這個cgroup的。 monitor only in the container (cgroup) called "name". This option is available only in per-cpu mode. The cgroup filesystem must be mounted. All threads belonging to container "name" are monitored when they run on the monitored CPUs. Multiple cgroups can be provided. Each cgroup is applied to the corresponding event, i.e., first cgroup to first event, second cgroup to second event and so on. It is possible to provide an empty cgroup (monitor all the time) using, e.g., -G foo,,bar. Cgroups must have corresponding events, i.e., they always refer to events defined earlier on the command line. 跑pgbench壓測，和前面的pgbench一樣，不斷並發插入。
然后開啟統計收集，收集10秒的統計信息，默認輸出到perf.data文件。
perf record -avg -- sleep 10 [ perf record: Woken up 142 times to write data ] [ perf record: Captured and wrote 37.111 MB perf.data (~1621415 samples) ] 5. 生成報告
前面使用perf record收集了統計信息到perf.data，接下來就對perf.data進行分析，輸出報告。
NAME
perf-report - Read perf.data (created by perf record) and display the profile SYNOPSIS perf report [-i <file> | --input=file] DESCRIPTION This command displays the performance counter profile information recorded via perf record. -i, --input= Input file name. (default: perf.data) -v, --verbose Be more verbose. (show symbol address, etc) -n, --show-nr-samples Show the number of samples for each symbol --showcpuutilization Show sample percentage for different cpu modes. -T, --threads Show per-thread event counters -U, --hide-unresolved Only display entries resolved to a symbol. -s, --sort= Sort by key(s): pid, comm, dso, symbol, parent. -g [type,min], --call-graph Display call chains using type and min percent threshold. type can be either: · flat: single column, linear exposure of call chains. · graph: use a graph tree, displaying absolute overhead rates. · fractal: like graph, but displays relative rates. Each branch of the tree is considered as a new profiled object. Default: fractal,0.5. --stdio Use the stdio interface. --tui Use the TUI interface, that is integrated with annotate and allows zooming into DSOs or threads, among other features. Use of --tui requires a tty, if one is not present, as when piping to other commands, the stdio interface is used. --tui模式可以查看概覽，支持交互式指令。
輸入E全展開，輸入C全收斂。 展開后可以使用鍵盤的上下鍵進行瀏覽。
[.] 表示userspace
[k] 表示kernel
1.39% 0.00% 0.01% 15 postgres /home/digoal/pgsql9.6/bin/postgres 0x524e3a d [.] AllocSetAlloc.lto_priv.1186 1.29% 0.00% 0.01% 22 postgres /lib64/libc-2.12.so 0x83127 B [.] __memset_sse2 1.25% 0.00% 0.00% 1 postgres /home/digoal/pgsql9.6/bin/postgres 0x57831d d [.] LWLockAcquire.constprop.931 1.24% 0.00% 0.05% 107 postgres /home/digoal/pgsql9.6/bin/postgres 0x574751 d [.] hash_search_with_hash_value.constprop.928 1.07% 0.00% 0.00% 2 postgres /home/digoal/pgsql9.6/bin/postgres 0x2c946f d [.] LWLockRelease 1.01% 0.00% 0.00% 1 postgres /home/digoal/pgsql9.6/bin/postgres 0x574035 d [.] hash_search_with_hash_value.constprop.930 0.98% 0.00% 0.03% 74 postgres /home/digoal/pgsql9.6/bin/postgres 0x334832 d [.] PostgresMain 0.94% 0.00% 0.02% 49 postgres /home/digoal/pgsql9.6/bin/postgres 0x2db87b d [.] GetSnapshotData 0.94% 0.00% 0.00% 1 postgres [kernel.kallsyms] 0xffffffff8150e8b1 k [k] _spin_lock 0.83% 0.00% 0.00% 1 postgres [kernel.kallsyms] 0xffffffff8150edb0 k [k] page_fault 0.81% 0.00% 0.00% 1 postgres /lib64/libc-2.12.so 0x88aa0 B [.] memcpy 0.77% 0.00% 0.22% 465 postgres /home/digoal/pgsql9.6/bin/postgres 0x533939 d [.] hash_seq_search 0.75% 0.00% 0.00% 1 postgres /lib64/libc-2.12.so 0x454ac B [.] __GI_vfprintf 0.75% 0.00% 0.03% 59 postgres /home/digoal/pgsql9.6/bin/postgres 0x579b1d d [.] LWLockAcquire.constprop.932 0.73% 0.00% 0.02% 42 postgres /home/digoal/pgsql9.6/bin/postgres 0x2df3ab d [.] LockAcquireExtended 0.67% 0.00% 0.00% 2 postgres /home/digoal/pgsql9.6/bin/postgres 0x1c66f9 d [.] hash_any 0.65% 0.00% 0.02% 49 postgres /home/digoal/pgsql9.6/bin/postgres 0x2ba33a d [.] _bt_compare 0.63% 0.00% 0.00% 3 postgres /home/digoal/pgsql9.6/bin/postgres 0xee632 d [.] XLogInsertRecord 0.62% 0.00% 0.00% 1 postgres /home/digoal/pgsql9.6/bin/postgres 0x53d5e1 d [.] hash_search_with_hash_value 0.59% 0.00% 0.59% 1318 pgbench /lib64/libc-2.12.so 0x47956 B [.] __GI_vfprintf 0.57% 0.00% 0.00% 1 postgres /lib64/libc-2.12.so 0x131aa7 B [.] __strlen_sse42 0.55% 0.00% 0.55% 1241 pgbench /home/digoal/pgsql9.6/bin/pgbench 0x85b3 d [.] doCustom.lto_priv.13 0.55% 0.00% 0.03% 55 postgres /home/digoal/pgsql9.6/bin/postgres 0x2c8327 d [.] PinBuffer.isra.3.lto_priv.2340 0.54% 0.00% 0.02% 35 postgres /home/digoal/pgsql9.6/bin/postgres 0x25059f d [.] pgstat_report_activity 0.53% 0.00% 0.02% 43 postgres /lib64/libc-2.12.so 0x78462 B [.] _int_malloc 0.52% 0.00% 0.01% 33 postgres /home/digoal/pgsql9.6/bin/postgres 0x426a36 d [.] SearchCatCache 0.47% 0.00% 0.00% 3 postgres [kernel.kallsyms] 0xffffffff81272a1c k [k] radix_tree_lookup_slot 0.45% 0.00% 0.01% 27 postgres /home/digoal/pgsql9.6/bin/postgres 0xfbe51 d [.] CommitTransaction.lto_priv.2946 0.44% 0.00% 0.00% 1 postgres /home/digoal/pgsql9.6/bin/postgres 0x5776f5 d [.] hash_search_with_hash_value.constprop.929 0.43% 0.00% 0.01% 30 postgres /home/digoal/pgsql9.6/bin/postgres 0x38a044 d [.] ExecModifyTable 0.41% 0.00% 0.00% 1 postgres [kernel.kallsyms] 0xffffffff8150bef4 k [k] schedule 0.40% 0.00% 0.01% 22 postgres /home/digoal/pgsql9.6/bin/postgres 0x2c86c2 d [.] LWLockWaitListLock.lto_priv.1265 0.40% 0.00% 0.01% 29 postgres /home/digoal/pgsql9.6/bin/postgres 0x2d2b2d d [.] LockReleaseAll 0.40% 0.00% 0.01% 12 postgres /home/digoal/pgsql9.6/bin/postgres 0x538a11 d [.] AllocSetFree.lto_priv.1187 0.39% 0.00% 0.00% 1 postgres [kernel.kallsyms] 0xffffffff8111e567 k [k] find_get_page 0.39% 0.01% 0.00% 24 postgres [kernel.kallsyms] 0xffffffff8148d1f8 k [k] tcp_sendmsg 0.39% 0.00% 0.01% 34 postgres /home/digoal/pgsql9.6/bin/postgres 0xef545 d [.] XLogInsert 0.39% 0.00% 0.01% 25 postgres /lib64/libc-