デバッグ方法

Last-modified: 2010-11-28 (日) 19:40:17

PostgreSQL に限ったことではないのですが、私流のデバッグ方法とかを。(使用OS:CentOS)

PostgreSQL の select を行うときの関数を追ってみましょう。
(今回は -g オプションなしでコンパイルしたもので。バイナリを追います。)

使うもの

  • gdb
  • objdump
  • cscope(ソースコード読むもの)
  • bvi(念のため)

まず PostgreSQL を起動させる。

$ pg_ctl start -l /var/log/postgres/postgres.log

セッション1


hogehoge Database にログイン

$ psql hogehoge
 hogehoge=#



セッション2


ps コマンドでログインしているセッションのPIDを確認する。

$ ps -ef | grep hogehoge | grep postgres | grep -v grep
postgres 30042 13996  0 02:01 pts/2    00:00:00 psql hogehoge
postgres 30043 29990  0 02:01 ?        00:00:00 postgres: postgres hogehoge [local] idle

セッション 30043 に対してデバッガを入れる。

$ gdb /usr/local/postgres/bin/postgres 30043
(gdb) bt
#0  0x00c45402 in __kernel_vsyscall ()
#1  0x009dfe21 in recv () from /lib/libc.so.6
#2  0x081b557f in secure_read ()
#3  0x081bcd88 in pq_recvbuf ()
#4  0x081bd198 in pq_getbyte ()
#5  0x08249fa2 in PostgresMain ()
#6  0x08216914 in ServerLoop ()
#7  0x08217712 in PostmasterMain ()
#8  0x081bf0a0 in main ()



セッション1


hogehoge=# select * from test;
 <--- ここで止まる。



セッション2


スタック見てみる。 以下の流れで動いてくる。

(gdb) bt
#0  0x00c45402 in __kernel_vsyscall ()
#1  0x009dfe21 in recv () from /lib/libc.so.6
#2  0x081b557f in secure_read ()
#3  0x081bcd88 in pq_recvbuf ()
#4  0x081bd198 in pq_getbyte ()
#5  0x08249fa2 in PostgresMain ()
#6  0x08216914 in ServerLoop ()
#7  0x08217712 in PostmasterMain ()
#8  0x081bf0a0 in main ()
  • いったん BreakPoint で PostgresMain 入れる
(gdb) b PostmasterMain
Breakpoint 1 at 0x8216e16
  • until 実行で Select が動くときを捕まえる。
(gdb) until ....
(gdb) until
0x0824a249 in PostgresMain ()
(gdb)
0x0824a24e in PostgresMain ()
 <---- ここで SELECT の結果が返ってきた。


ソースコードの該当箇所を見つける。

逆アセンブル

$ objdump -d /usr/local/postgres-bin/bin/postgres > objdump-postgres.txt
-----------------------------------------
824a235:       00
824a236:       c7 04 24 61 54 44 08    movl   $0x8445461,(%esp)
824a23d:       e8 6e c4 0c 00          call   83166b0 <set_ps_display>
824a242:       c7 04 24 44 92 42 08    movl   $0x8429244,(%esp)
824a249:       e8 92 65 fc ff          call   82107e0 <pgstat_report_activity>
824a24e:       e9 25 fd ff ff          jmp    8249f78 <PostgresMain+0x958>
^^^^^^^<--- 該当のアドレスはここ。
824a253:       89 74 24 04             mov    %esi,0x4(%esp)
824a257:       e9 07 ff ff ff          jmp    824a163 <PostgresMain+0xb43>
824a25c:       c7 44 24 10 00 00 00    movl   $0x0,0x10(%esp)
824a263:       00
-----------------------------------------
上記から PostgresMain+0x958 に jmp するアセンブラとなってます。
-----------------------------------------
08249620 <PostgresMain>:
 8249620:       55                      push   %ebp
 8249621:       89 e5                   mov    %esp,%ebp
 8249623:       57                      push   %edi
 8249624:       56                      push   %esi
-----------------------------------------
08249620 このアドレスが開始アドレスなので、
0x08249620 + 0x958 = 0x08249F78 に jmp します。


-----------------------------------------
8249f60:       c7 04 24 fc 91 42 08    movl   $0x84291fc,(%esp)
8249f67:       e8 44 c7 0c 00          call   83166b0 <set_ps_display>
8249f6c:       c7 04 24 18 9c 42 08    movl   $0x8429c18,(%esp)
8249f73:       e8 68 68 fc ff          call   82107e0 <pgstat_report_activity>
8249f78:       a1 74 df 45 08          mov    0x845df74,%eax     <------------ ここが jmp 先
8249f7d:       89 04 24                mov    %eax,(%esp)
8249f80:       e8 9b a7 ff ff          call   8244720 <ReadyForQuery>
                                                       ^^^^^^^^^^^^^ <---  call 先
8249f85:       83 3d 74 df 45 08 02    cmpl   $0x2,0x845df74
-----------------------------------------




流れ的に以下のようになる。
-----------------------------------------
824a249:       e8 92 65 fc ff          call   82107e0 <pgstat_report_activity>
824a24e:       e9 25 fd ff ff          jmp    8249f78 <PostgresMain+0x958>
↓
8249f78:       a1 74 df 45 08          mov    0x845df74,%eax
8249f7d:       89 04 24                mov    %eax,(%esp)
8249f80:       e8 9b a7 ff ff          call   8244720 <ReadyForQuery>
-----------------------------------------


処理関数的に、
pgstat_report_activity -> jmp -> ReadyForQuery なので、これに合う条件のソースコードは以下になる。
postgres.c
-----------------------------------------
  3797    if (send_ready_for_query)
  3798    {
  3799            if (IsAbortedTransactionBlockState())
  3800            {
  3801                    set_ps_display("idle in transaction (aborted)", false);
  3802                    pgstat_report_activity("<IDLE> in transaction (aborted)");
  3803            }
  3804            else if (IsTransactionOrTransactionBlock())
  3805            {
  3806                    set_ps_display("idle in transaction", false);
  3807                    pgstat_report_activity("<IDLE> in transaction");
  3808            }
  3809            else
  3810            {
  3811                    ProcessCompletedNotifies();
  3812                    pgstat_report_stat(false);
  3813
  3814                    set_ps_display("idle", false);
  3815                    pgstat_report_activity("<IDLE>");
  3816            }
  3817
  3818            ReadyForQuery(whereToSendOutput);
  3819            send_ready_for_query = false;
  3820    }
-----------------------------------------


どの if の条件を通っているかは、また cmp しているところを上に追っていく必要があるが、
こんな感じでバイナリからは追ってみると良いと思う。
商用のものでもこのように追っていけばソースコードがなくとも、わかることは多いはずだ。