一套关键的系统,由于”_kghdsidx_count”这个参数设置为1,导致了严重的性能问题。从故障现象上看是大量的library cache latch的等待,以及shared pool latch的等待,但是前者的等待时间比后者长得多。在文章中,我提到,在当时我推断,由于”_kghdsidx_count”这个隐含参数设置为1,导致shared pool只有1个subpool,引起了shared pool latch的严重竞争,进而引起了library cache cache的更为严重的竞争,这个竞争的过程如下:
1 由于”_kghdsidx_count”=1,使得shared pool latch只有1个child latch。而library cache latch的child latch数量跟CPU数量有关,最大值为67,编号为child #1-#67。 2 会话1持有shared pool latch。 3 会话2解析SQL语句,首先持有了library cache latch的child latch,假设这里为child #1,然后去请求shared pool latch。很显然,这时候被会话1持有,那么会话2就会等待shared pool latch。 4 会话3解析SQL语句,首先需要请求library cache latch,如果请求的library cache child latch刚好是#1,那么由于会话2持有了这个child latch,就会等待library cache latch。 5 因此,实际上会话1和会话2的shared pool latch的竞争引起了会话3的library cache latch的等待。如果并发数不是太高,那么shared pool latch的竞争看上去就会比library cache latch的竞争多一些。但是如果有几百个活动会话,这个时候,就会有大量的会话首先等待library cache latch,因为在解析SQL时是首先需要获取library cache latch再获取shared pool latch。由于大量的软解析,甚至不需要获取shared pool latch,同时一个大型的OLTP系统中,某几条相同的SQL并发执行的概率很高,这样会使很多会话同时请求同一library cache child latch;另外,在解析过程中,可能会多次请求library cache latch和shared pool latch,而前者请求和释放的次数会比后者多得多;这样大量的会话在获取library cache latch时处于等待状态,从现象上看就比shared pool latch的等待多得多。
而本文主要表达的是,怎么来验证在解析时,Oracle进程在持有了library cache latch的情况下去请求shared pool latch,而不是在请求shared pool时不需要持有library cache latch。
由于这个验证过程过于internal,所以没有在《DBA手记III》中描述出来。这里写出来,供有兴趣的朋友参考。
验证上面的这一点,有2个方法。下面以测试过程来详细描述。
测试环境 :Oracle 10.2.0.5.1 for Linux X86.
方法一:使用oradebug。
1. 将数据库的”_kghdsidx_count”参数值设为1,并重启数据库,以保证只有一个shared pool child latch。
2. 使用sqlplus连接到数据库,假设这个会话是session-1,查询当前的SID:
1 SQL> select sid from v$mystat where rownum=1; 2 3 SID 4 ---------- 5 159
同时获得当前连接的spid为2415。
3. 新建一个连接到数据库,假设会话是session-2,查询shared pool latch的地址,并使用oradebug将这个地址对应的值置为1,以表示该latch已经被持有:
1 SQL> select addr,latch#,level#,child#,name,gets from v$latch_children where name='shared pool'; 2 3 ADDR LATCH# LEVEL# CHILD# NAME GETS 4 -------- ---------- ---------- ---------- -------------------------------------------------- ---------- 5 200999BC 216 7 1 shared pool 34949 6 20099A20 216 7 2 shared pool 6 7 20099A84 216 7 3 shared pool 6 8 20099AE8 216 7 4 shared pool 6 9 20099B4C 216 7 5 shared pool 6 10 20099BB0 216 7 6 shared pool 6 11 20099C14 216 7 7 shared pool 6 12 13 SQL> oradebug poke 0x200999BC 4 1 14 BEFORE: [200999BC, 200999C0) = 00000000 15 AFTER: [200999BC, 200999C0) = 00000001
4. 在session-1会话中执行下面的SQL:
1 SQL> select sysdate from dual;l
正如预料之中的反映,这个会话hang住。
5. 在session-2中,对session-1的进程作process dump。(注意这个时候不能查询v$session_wait、v$latchholder等视图)
1 SQL> oradebug setospid 2415 2 Oracle pid: 15, Unix process pid: 2415, image: oracle@xty (TNS V1-V3) 3 SQL> oradebug dump processstate 10 4 Statement processed. 5 SQL> oradebug tracefile_name 6 /oracle/app/oracle/admin/xty/udump/xty_ora_2415.trc
然后从/oracle/app/oracle/admin/xty/udump/xty_ora_2415.trc这个TRACE文件中可以找到下面的信息:
1 Process global information: 2 process: 0x51a2dce8, call: 0x51b465e4, xact: (nil), curses: 0x51b2a4b8, usrses: 0x51b2a4b8 3 ---------------------------------------- 4 SO: 0x51a2dce8, type: 2, owner: (nil), flag: INIT/-/-/0x00 5 (process) Oracle pid=15, calls cur/top: 0x51b465e4/0x51b465e4, flag: (0) - 6 int error: 0, call error: 0, sess error: 0, txn error 0 7 (post info) last post received: 110 0 4 8 last post received-location: kslpsr 9 last process to post me: 51a2a904 1 6 10 last post sent: 0 0 24 11 last post sent-location: ksasnd 12 last process posted by me: 51a2a904 1 6 13 (latch info) wait_event=0 bits=20 14 Location from where call was made: kghupr1: Chunk Header 15 Context saved from call: 1306572176 16 waiting for 200999bc Child shared pool level=7 child#=1 17 Location from where latch is held: kghupr1: Chunk Header 18 Context saved from call: 1299065692 19 state=busy, wlstate=free 20 waiters [orapid (seconds since: put on list, posted, alive check)]: 21 10 (54, 1304393092, 54) 22 11 (54, 1304393092, 54) 23 24 (15, 1304393092, 15) 24 15 (6, 1304393092, 6) 25 waiter count=4 26 gotten 35138 times wait, failed first 502 sleeps 5 27 gotten 0 times nowait, failed: 0 28 on wait list for 200999bc 29 holding (efd=3) 4f7c75f8 Child library cache level=5 child#=1 30 Location from where latch is held: kgllkdl: child: no lock handle: latch 31 Context saved from call: 2 32 state=busy, wlstate=free
从waiting for 200999bc Child shared pool level=7 child#=1和holding (efd=3) 4f7c75f8 Child library cache level=5 child#=1可以看到,进程的确是在持有了library cache latch的同时去请求 shared pool latch。
最后使用“oradebug poke 0×200999BC 4 0”命令将shared pool latch置为free状态。
方法二:使用gdb。
1. 还原”_kghdsidx_count”参数,重启数据库。
2. 使用sqlplus连接到数据库,获取对应的Oracle Process的spid为4868。
3. 使用gdb:
1 [oracle@xty ~]$ gdb -p 4868 2 GNU gdb (GDB) Red Hat Enterprise Linux (7.0.1-23.el5) 3 Copyright (C) 2009 Free Software Foundation, Inc. 4 ...省略部分输出... 5 Reading symbols from /lib/libnss_files.so.2...(no debugging symbols found)...done. 6 Loaded symbols for /lib/libnss_files.so.2 7 0x0059b402 in __kernel_vsyscall ()
4. 在gdb中,在latch的获取和释放的函数上设置断点:
注:最后几个函数只是猜测跟latch有关....latch的请求和释放所调用的函数主要为:kslgetl、kslgetsl和kslfre。
1 (gdb) b kslgpl 2 Breakpoint 1 at 0x8322f53 3 (gdb) b kslgetsl 4 Breakpoint 2 at 0x8317351 5 (gdb) b kslgetl 6 Breakpoint 3 at 0x83170ba 7 (gdb) b kslfre 8 Breakpoint 4 at 0x8318d49 9 (gdb) c 10 Continuing.
5. 在sqlplus中执行SQL:
SQL> select sysdate from dual;l
正如预期的那样,会话hang住。这是因为运行到了gdb设置的断点。
6.在gdb中可以看到:
Breakpoint 2, 0x08317351 in kslgetsl () (gdb) info f Stack level 0, frame at 0xbf8386b0: eip = 0x8317351 in kslgetsl; saved eip 0x83f5e10 called by frame at 0xbf8386ec Arglist at 0xbf8386a8, args: Locals at 0xbf8386a8, Previous frame's sp is 0xbf8386b0 Saved registers: ebp at 0xbf8386a8, eip at 0xbf8386ac (gdb) c Continuing. Breakpoint 4, 0x08318d49 in kslfre () (gdb) info f Stack level 0, frame at 0xbf8386c0: eip = 0x8318d49 in kslfre; saved eip 0x83f5e49 called by frame at 0xbf8386ec Arglist at 0xbf8386b8, args: Locals at 0xbf8386b8, Previous frame's sp is 0xbf8386c0 Saved registers: ebp at 0xbf8386b8, eip at 0xbf8386bc (gdb) x /10x 0xbf8386b8 0xbf8386b8: 0xbf8386e4 0x083f5e49 0x2fb2c108 0xbf8386e4 0xbf8386c8: 0x2fafb5a0 0x0cbd2dfc 0x0cbd2d00 0x00000002 0xbf8386d8: 0x00000000 0x2f7abf68 (gdb) c Continuing. ----下面很重要----- Breakpoint 3, 0x083170ba in kslgetl () (gdb) info f Stack level 0, frame at 0xbf837acc: eip = 0x83170ba in kslgetl; saved eip 0x8329508 called by frame at 0xbf837af4 Arglist at 0xbf837ac4, args: Locals at 0xbf837ac4, Previous frame's sp is 0xbf837acc Saved registers: ebp at 0xbf837ac4, eip at 0xbf837ac8 (gdb) x /10x 0xbf837ac4 0xbf837ac4: 0xbf837aec 0x08329508 0x2e3c3a74 0x00000001 0xbf837ad4: 0x00000000 0x000009f8 0x00000000 0x00000001 0xbf837ae4: 0x0cb84378 0x00dcf346 (gdb) c Continuing. Breakpoint 4, 0x08318d49 in kslfre () (gdb) info f Stack level 0, frame at 0xbf837b74: eip = 0x8318d49 in kslfre; saved eip 0x8329627 called by frame at 0xbf837b8c Arglist at 0xbf837b6c, args: Locals at 0xbf837b6c, Previous frame's sp is 0xbf837b74 Saved registers: ebp at 0xbf837b6c, eip at 0xbf837b70 (gdb) x /10x 0xbf837b6c 0xbf837b6c: 0xbf837b84 0x08329627 0x2e3c3a74 0x0cb84378 0xbf837b7c: 0x0001ffff 0x0832954c 0xbf837d1c 0x0ae96833 0xbf837b8c: 0x0cbd2d00 0x2e3c3a74 (gdb) c Continuing. Breakpoint 3, 0x083170ba in kslgetl () (gdb) info f Stack level 0, frame at 0xbf837acc: eip = 0x83170ba in kslgetl; saved eip 0x8329508 called by frame at 0xbf837af4 Arglist at 0xbf837ac4, args: Locals at 0xbf837ac4, Previous frame's sp is 0xbf837acc Saved registers: ebp at 0xbf837ac4, eip at 0xbf837ac8 (gdb) x /10x 0xbf837ac4 0xbf837ac4: 0xbf837aec 0x08329508 0x2e3c3a74 0x00000001 0xbf837ad4: 0x00000000 0x000009f8 0x00000000 0x00000001 0xbf837ae4: 0x0cb84378 0x00dcf346 (gdb) c Continuing. Breakpoint 3, 0x083170ba in kslgetl () (gdb) info f Stack level 0, frame at 0xbf837968: eip = 0x83170ba in kslgetl; saved eip 0x8329508 called by frame at 0xbf837990 Arglist at 0xbf837960, args: Locals at 0xbf837960, Previous frame's sp is 0xbf837968 Saved registers: ebp at 0xbf837960, eip at 0xbf837964 (gdb) x /10x 0xbf837960 0xbf837960: 0xbf837988 0x08329508 0x20095ad0 0x00000001 0xbf837970: 0x00000000 0x0000097f 0x0bfaf900 0x00000158 0xbf837980: 0x0cb84378 0xbf8379d4 (gdb) c Continuing. Breakpoint 4, 0x08318d49 in kslfre () (gdb) info f Stack level 0, frame at 0xbf837984: eip = 0x8318d49 in kslfre; saved eip 0x8329627 called by frame at 0xbf83799c Arglist at 0xbf83797c, args: Locals at 0xbf83797c, Previous frame's sp is 0xbf837984 Saved registers: ebp at 0xbf83797c, eip at 0xbf837980 (gdb) x /10x 0xbf83797c 0xbf83797c: 0xbf837994 0x08329627 0x20095ad0 0x0cb84378 0xbf83798c: 0x00000000 0x2001af7c 0xbf837a20 0x0abfc335 0xbf83799c: 0x0cbd2d00 0x20095ad0 (gdb) c Continuing. Breakpoint 4, 0x08318d49 in kslfre () (gdb) info f Stack level 0, frame at 0xbf837b74: eip = 0x8318d49 in kslfre; saved eip 0x8329627 called by frame at 0xbf837b8c Arglist at 0xbf837b6c, args: Locals at 0xbf837b6c, Previous frame's sp is 0xbf837b74 Saved registers: ebp at 0xbf837b6c, eip at 0xbf837b70 (gdb) x /10x 0xbf837b6c 0xbf837b6c: 0xbf837b84 0x08329627 0x2e3c3a74 0x0cb84378 0xbf837b7c: 0xbf837e5c 0x2bd8d494 0xbf837d1c 0x0ae96c1b 0xbf837b8c: 0x0cbd2d00 0x2e3c3a74 (gdb) c Continuing.
同时可以从数据库中查到:
SQL> select addr,latch#,child#,level#,name,gets from v$latch_children 2 where name in ('shared pool','library cache'); ADDR LATCH# CHILD# LEVEL# NAME GETS -------- ---------- ---------- ---------- ---------------------------------------- ---------- 20095AD0 213 1 7 shared pool 403174 20095B34 213 2 7 shared pool 18 20095B98 213 3 7 shared pool 18 20095BFC 213 4 7 shared pool 18 20095C60 213 5 7 shared pool 18 20095CC4 213 6 7 shared pool 18 20095D28 213 7 7 shared pool 18 2E3C3A74 214 1 5 library cache 507555
标记为”下面很重要“的输出,汇总起来就是:
kslgetl 0x2e3c3a74 library cache kslfre 0x2e3c3a74 library cache kslgetl 0x2e3c3a74 library cache kslgetl 0x20095ad0 shared pool kslfre 0x20095ad0 shared pool kslfre 0x2e3c3a74 library cache
这个过程可以理解为:Oracle进程首先获取library cache latch,在library cache中查找是否已经有要执行的SQL语句(这里显然没有找到),然后释放library cache。接下来是硬解析SQL的后半部分,首先获取library cache latch,然后获取shared pool latch,从shared pool中申请内存,然后释放shared pool latch,最后再获取library cache latch。
后面不再继续跟踪解析的过程,这个过程会有相当多的latch的获取和释放,但是从上面可以很清晰地看到,进程在持有了library cache latch的同时去请求shared pool latch。