システムコールの先を追え

SQL*Plus でログインしてサーバープロセスの PID を確認して、

[oracle@localhost ~]$ sqlplus neo/zion
SQL> select s.sid, s.serial#, p.spid from v$session s, v$process p where p.addr = s.paddr and s.sid = sys_context('USERENV','SID');

       SID    SERIAL# SPID
---------- ---------- ------------------------
        29         57 4115

crash コマンドをつかって PID 4115 にバックトレースを仕掛け、

[root@localhost ~]# crash
crash> set scroll off
scroll: off (/usr/bin/less)
crash> repeat bt -l 4115

SQL を実行すると、

SQL> select count(1) from agent;

ダーっと流れるので、後でよく見るとシステムコールの先のカーネルのコールスタックが見えた。

PID: 4115   TASK: d11c7000  CPU: 0   COMMAND: "oracle"
 #0 [c7465d60] schedule at c061d348
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/kernel/sched.c: 2056
 #1 [c7465dd8] io_schedule at c061d9f9
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/kernel/sched.c: 4879
 #2 [c7465de4] sync_page at c0458c7f
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/filemap.c: 171
 #3 [c7465de8] __wait_on_bit_lock at c061db0e
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/kernel/wait.c: 195
 #4 [c7465dfc] __lock_page at c0458bc2
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/filemap.c: 594
 #5 [c7465e2c] do_generic_mapping_read at c04593ea
    include/linux/pagemap.h: 149
 #6 [c7465e94] __generic_file_aio_read at c0459de5
    include/linux/fs.h: 1951
 #7 [c7465ed8] generic_file_aio_read at c0459e59
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/filemap.c: 1282
 #8 [c7465ef4] do_sync_read at c0475c5c
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/read_write.c: 235
 #9 [c7465f8c] vfs_read at c0476536
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/read_write.c: 264
#10 [c7465fa4] sys_pread64 at c0476a4f
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/read_write.c: 393
#11 [c7465fb8] system_call at c0404f10
    include/asm/bitops.h: 246
    EAX: ffffffda  EBX: 00000101  ECX: 2bb30000  EDX: 00002000 
    DS:  007b      ESI: 33e3a000  ES:  007b      EDI: 00000000
    SS:  007b      ESP: bfc60684  EBP: bfc606a8
    CS:  0073      EIP: 00b5d402  ERR: 000000b4  EFLAGS: 00000246 

追記:

crash> mod -s ext3 /usr/lib/debug/lib/modules/2.6.18-194.17.1.0.1.el5/kernel/fs/ext3/ext3.ko.debug
crash> mod -s jbd /usr/lib/debug/lib/modules/2.6.18-194.17.1.0.1.el5/kernel/fs/jbd/jbd.ko.debug

すると、

PID: 30521  TASK: e404faa0  CPU: 0   COMMAND: "oracle"
 #0 [e2694a6c] schedule at c061d348
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/kernel/sched.c: 2056
 #1 [e2694ae4] io_schedule at c061d9f9
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/kernel/sched.c: 4879
 #2 [e2694af0] sync_buffer at c04788c6
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/buffer.c: 67
 #3 [e2694af4] __wait_on_bit at c061dbd2
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/kernel/wait.c: 169
 #4 [e2694b0c] out_of_line_wait_on_bit at c061dc57
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/kernel/wait.c: 182
 #5 [e2694b44] __wait_on_buffer at c0478843
    include/linux/wait.h: 434
 #6 [e2694b50] __bread at c04799d6
    include/linux/buffer_head.h: 318
 #7 [e2694b58] ext3_get_branch at f8882927
 #8 [e2694b78] ext3_get_blocks_handle at f8882ba4
 #9 [e2694c34] ext3_get_block at f888369b
#10 [e2694c6c] do_mpage_readpage at c0495a48
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/mpage.c: 241
#11 [e2694d34] mpage_readpages at c0495e80
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/mpage.c: 405
#12 [e2694d9c] __do_page_cache_readahead at c045e83e
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/readahead.c: 194
#13 [e2694dcc] blockable_page_cache_readahead at c045e8e7
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/readahead.c: 424
#14 [e2694de4] make_ahead_window at c045e9aa
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/readahead.c: 438
#15 [e2694e04] page_cache_readahead at c045eb1c
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/readahead.c: 562
#16 [e2694e24] do_generic_mapping_read at c04592ab
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/filemap.c: 933
#17 [e2694e94] __generic_file_aio_read at c0459de5
    include/linux/fs.h: 1951
#18 [e2694ed8] generic_file_aio_read at c0459e59
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/mm/filemap.c: 1282
#19 [e2694ef4] do_sync_read at c0475c5c
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/read_write.c: 235
#20 [e2694f8c] vfs_read at c0476536
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/read_write.c: 264
#21 [e2694fa4] sys_pread64 at c0476a4f
    /usr/src/debug/kernel-2.6.18/linux-2.6.18.i686/fs/read_write.c: 393
#22 [e2694fb8] system_call at c0404f10
    include/asm/bitops.h: 246
    EAX: ffffffda  EBX: 00000101  ECX: 01599000  EDX: 00040000 
    DS:  007b      ESI: 813c0000  ES:  007b      EDI: 00000000
    SS:  007b      ESP: bfa0e348  EBP: bfa0e36c
    CS:  0073      EIP: 00f26402  ERR: 000000b4  EFLAGS: 00000246