问题描述：
数据库出现异常等待事件LOG FILE SYNC，BLOCKING SESSION是LGWR，LGWR等待enq:CF-contention,blocking session是ARC6进程，ARC6等待control file sequential read，当时伴有连接数满，影响应用短暂不可用。
问题分析：
在一般的情况下，control file sequential read发生在：
Control file sequential read
Reading from the control file. This happens in many cases. For example, while:
? Making a backup of the control files
? Sharing information (between instances) from the control file
? Reading other blocks from the control files
? Reading the header block
ARCHIVE 6是Dataguard的Heartbeat进程，用来在远程灾备重新连接时进行gap resolution。Heartbeat进程从control file中获取归档信息，判断哪些归档已经传送到远程灾备。由于该库的归档日志信息有15万个条目，读取操作持续了5秒。
arc6归档进程的trace文件如下，最终调用的oracle函数是kcc_scan。
pread()+100 FRM_LESS _pread() 000100000 ? 3003B024230 ?
000100000 ? 0024F4000 ?
000100000 ? 000004000 ?
skgfqio()+516 CALL 000000010635DD20 000000100 ?
FFFFFFFF785CFE00 ?
000100000 ? 0024F4000 ?
000000000 ?
FFFFFFFF7FFF6C50 ?
ksfdread1()+852 CALL skgfqio() 106521CD0 ? 000100000 ?
000000000 ? 000000000 ?
FFFFFFFFFFFFFFFF ?
0024F4000 ?
ksfdread()+32 CALL ksfdread1() AEC255BD8 ? 000000001 ?
106363580 ? 000100000 ?
000000000 ? 000106369 ?
kccgft_prefetch()+2 CALL ksfdread() AEC255BD8 ? 00000093D ?
56 FFFFFFFF785CFE00 ?
000100000 ? 000000000 ?
000000703 ?
kccrec_rbl()+588 CALL kccgft_prefetch() FFFFFFFF7FFF8FB0 ?
FFFFFFFFFFFFFFFF ?
38000F000 ? 000000000 ?
AEC255BD8 ? 000000040 ?
kccext_ugg()+316 CALL kccrec_rbl() FFFFFFFF7FFF8FB0 ?
0000004BD ?
FFFFFFFF7FFF8518 ?
000000001 ? 000000001 ?
00000097B ?
kccrec_read_write() CALL kccext_ugg() FFFFFFFF7FFF8FB0 ?
+132 FFFFFFFF7FFF8518 ?
000003FE7 ? 000003EA0 ?
0002EED18 ?
FFFFFFFF7FFF8CC8 ?
kccgftcs()+696 CALL kccrec_read_write() FFFFFFFF7FFF8FB0 ?
FFFFFFFF797CC0E0 ?
000005DAB ?
FFFFFFFF7FFF8CC8 ?
00000000B ? 000000001 ?
kcc_scan()+116 CALL kccgftcs() 38000F000 ? 00000000B ?
Bug 5399901 : ARCHIVED LOG ENTRIES CAN TAKE A LONG TIME TO SEARCH
PROBLEM:
--------
When the number of archived log entries grow to a large value, and dataguard
scans these for gap determination, etc, it is possible in some cases for
dataguard processes to scan the entire set of archived log entries. The
current code that handles the c/f i.o when looking up archived log entries
given the record id of the archived log entries is not very efficient, and
does not perform read-aheads. This can result in the reader of the archived
log entries holding the c/f enqueue in some cases for 2-3 minutes, and this
in turn can lead other processes to starve for the c/f enqueue.
DIAGNOSTIC ANALYSIS:
--------------------
Look for c/f enqueue issues in the alert log with dataguard - each situation
needs to be analyzed for c/f enqueue issues separately, as each situation is
unique. But in the case of this customer (see tar above), it was obvious that
the PING arch was spending several minutes trying to scan thru over 60,000
archived log entries. Another reason for the delay could be because the
control file was in ASM, and the call stack of the PING arch showed ASM on
top of the stack, with c/f read wait events for some of the 2k blocks read
almost one second. This will lead to several minutes of wait since a 2k block
can contain atmost 4 arhcived log entries, and you will end up reading
atleast 15000 2k blocks to read 60,000 archived log entries.
WORKAROUND:
-----------
There is one workaround, but it means taking an outage at the primary - the
primary controlfile can be created from a backup of the orignal primary
controlfile (which has 60,0000 entries for arhcived log) to trace. The new
controlfile can be modified to hold a maximum of X arhicved log entries,
where X is dependent on a variety of factors such as frequency of backups,
how behind is the stanbdy usually, but X should be much much less than 60,000
normally - X is dictated by MAXLOGHISTORY option when creating the new
controlfile. The controlfile to trace should be created with the NORESETLOGS
option as well. Then, a remout of the primary with the new controlfile should
put a cap on the number of archived log entries that will get created.
解决方案：
重建控制文件清空归档日志条目
结论：
控制文件过大可能会导致读取控制文件的时间超长。并引发control的enqueue。
附录：
dtrace脚本-syscall.d - 查看调用了哪些函数。
BEGIN
{ cnt = 0; }
syscall::pread:entry
/ pid == 8333 && arg0 == 256 /
{
ustack(50,10);
cnt++;
}
END
{ printf("%3d", cnt); }
dtrace脚本-time_func1.d，打印步骤执行的时间。
cat time_func1.d
#pragma D option flowindent
pid$1::$2:entry
{
self->in = 1;
self->t = timestamp;
ustack(50,10);
}
pid$1::kc*:entry,pid$1::ks*:entry
/ self->in /
{
self->tm[probefunc] = timestamp;
}
pid$1::kc*:return,pid$1::ks*:return
/ self->in /
{
printf("%d nsec on %s\n", timestamp - self->tm[probefunc], probefunc);
self->tm[probefunc] = 0;
}
pid$1::$2:return
/ self->in /
{
self->in = 0;
printf("%d nsec on this function\n", timestamp - self->t);
exit(0);
}
dtrace脚本-quantize_time_func.d，打印汇总的时间。
pid$1::$2:entry
{
self->in = 1;
self->t = timestamp;
}
pid$1::$2:return
/ self->in /
{
self->in = 0;
@["ns"] = quantize(timestamp - self->t);
}
dtrace脚本-func_stack.d，打印堆栈。
#pragma D option flowindent
pid$1::$2:entry
{
self->in = 1;
}
pid$1::kcc*:entry,pid$1::ks*:entry
/ self->in /
{
}
pid$1::kcc*:return,pid$1::ks*:return
/ self->in /
{
}
pid$1::$2:return
/ self->in /
{
self->in = 0;
exit(0);
}
1. Syscall.d脚本运行，有结果返回即可中断。
root@machine1 # dtrace -s /tmp/syscall.d
2. Time_func.d运行，有结果返回即可中断。
root@machine1 # dtrace -s /tmp/time_func1.d 8333 kccrec_read_write
root@machine1 # dtrace -s /tmp/time_func1.d 8333 kccgft
3. quantize_time_func.d运行结果如下：
root@machine1 # dtrace -s /tmp/quantize_time_func.d 8333 kccrec_read_write
运行5分钟后中断
root@machine1 # dtrace -s /tmp/quantize_time_func.d 8333 kccgft
运行5分钟后中断
root@machine1 # cd /tmp
root@machine1 # ls -l *1.d
-rw-r--r-- 1 opnetsli dba 537 Nov 26 18:34 time_func1.d
-rw-r--r-- 1 opnetsli dba 740 Dec 11 14:53 time_func_stack1.d
root@machine1 # dtrace -s /tmp/time_func1.d 27356 kcc_scan
dtrace: script '/tmp/time_func1.d' matched 12087 probes
CPU FUNCTION
128 -> kcc_scan
oracle`kcc_scan
oracle`kcrrsal+0x26c
oracle`krsfqgap+0xeb0
oracle`kcrrpng+0x35a4
oracle`kcrrwkx+0xe64
oracle`kcrrwk+0x3b0
oracle`ksbcti+0x3e4
oracle`ksbabs+0x3a8
oracle`ksbrdp+0x3f8
oracle`opirip+0x344
oracle`opidrv+0x4b0
oracle`sou2o+0x50
oracle`opimai_real+0x10c
oracle`main+0x98
oracle`_start+0x17c
128 <- ksdpec 8040 nsec on ksdpec
128 <- kccrof 28440 nsec on kccrof
128 <- ksdpec 4410 nsec on ksdpec
128 <- ksmrf_ext_min 7860 nsec on ksmrf_ext_min
128 <- ksmrf_ext_min 4770 nsec on ksmrf_ext_min
128 <- ksmrf_init_alloc 12990 nsec on ksmrf_init_alloc
128 <- ksmpga_update_size 9710 nsec on ksmpga_update_size
128 <- ksmapg 81400 nsec on ksmapg
128 <- ksdpec 4840 nsec on ksdpec
128 <- ksdpec 4990 nsec on ksdpec
128 <- ksmpga_allo_cb 24540 nsec on ksmpga_allo_cb
128 <- kccbc_init 5040 nsec on kccbc_init
128 <- kccbc_empty 6310 nsec on kccbc_empty
128 <- kccbc_empty 5050 nsec on kccbc_empty
128 <- ksdpec 4510 nsec on ksdpec
128 <- kskthbwt 5700 nsec on kskthbwt
128 <- kslwtb_resmgr 17390 nsec on kslwtb_resmgr
128 <- kslwtb_tm 5850 nsec on kslwtb_tm
128 <- ksdpec 4680 nsec on ksdpec
128 <- ksmals 4650 nsec on ksmals
128 <- ksdpec 4670 nsec on ksdpec
128 <- ksfd_osdrqfil 15360 nsec on ksfd_osdrqfil
128 <- ksmfrs 4540 nsec on ksmfrs
128 <- ksfdread1 81360 nsec on ksfdread1
128 <- ksfdread 92800 nsec on ksfdread
128 <- ksdpec 5160 nsec on ksdpec
128 <- ksl_which_bucket 5680 nsec on ksl_which_bucket
128 <- kslwte_tm 27150 nsec on kslwte_tm
128 <- kslwte_resmgr 38740 nsec on kslwte_resmgr
128 <- kskthewt 5950 nsec on kskthewt
128 <- ksdpec 4790 nsec on ksdpec
128 <- kcbhxoro 8630 nsec on kcbhxoro
128 <- kcbhvbo 20430 nsec on kcbhvbo
128 <- kcbzvb 31320 nsec on kcbzvb
128 <- kccrhd 247600 nsec on kccrhd
128 <- kccbmp_wdl 5870 nsec on kccbmp_wdl
128 <- kcbwdbr 4530 nsec on kcbwdbr
128 <- ksdpec 5390 nsec on ksdpec
128 <- kskthbwt 5170 nsec on kskthbwt
128 <- kslwtb_resmgr 15320 nsec on kslwtb_resmgr
128 <- kslwtb_tm 5190 nsec on kslwtb_tm
128 <- ksdpec 4570 nsec on ksdpec
128 <- ksmals 3850 nsec on ksmals
128 <- ksdpec 4670 nsec on ksdpec
128 <- ksfd_osdrqfil 14310 nsec on ksfd_osdrqfil
128 <- ksmfrs 4460 nsec on ksmfrs
128 <- ksfdread1 73830 nsec on ksfdread1
128 <- ksfdread 83790 nsec on ksfdread
128 <- ksdpec 5010 nsec on ksdpec
128 <- ksl_which_bucket 5960 nsec on ksl_which_bucket
128 <- kslwte_tm 26370 nsec on kslwte_tm
128 <- kslwte_resmgr 36470 nsec on kslwte_resmgr
128 <- kskthewt 5160 nsec on kskthewt
128 <- kcbhxoro 7970 nsec on kcbhxoro
128 <- kcbhvbo 18360 nsec on kcbhvbo
128 <- kcbzvb 28050 nsec on kcbzvb
128 <- kccrbp 227560 nsec on kccrbp
128 <- ksdpec 5090 nsec on ksdpec
128 <- kccpb_sanity_check 15810 nsec on kccpb_sanity_check
128 <- kccbmp_get 273350 nsec on kccbmp_get
128 <- kcbwdbr 3830 nsec on kcbwdbr
128 <- ksdpec 5050 nsec on ksdpec
128 <- kskthbwt 5210 nsec on kskthbwt
128 <- kslwtb_resmgr 15430 nsec on kslwtb_resmgr
128 <- kslwtb_tm 5100 nsec on kslwtb_tm
128 <- ksdpec 4930 nsec on ksdpec
128 <- ksmals 4220 nsec on ksmals
128 <- ksdpec 5110 nsec on ksdpec
128 <- ksfd_osdrqfil 15060 nsec on ksfd_osdrqfil
128 <- ksmfrs 4850 nsec on ksmfrs
128 <- ksfdread1 74810 nsec on ksfdread1
128 <- ksfdread 84930 nsec on ksfdread
128 <- ksdpec 5170 nsec on ksdpec
128 <- ksl_which_bucket 6180 nsec on ksl_which_bucket
128 <- kslwte_tm 26660 nsec on kslwte_tm
128 <- kslwte_resmgr 37170 nsec on kslwte_resmgr
128 <- kskthewt 5210 nsec on kskthewt
128 <- kcbhxoro 8160 nsec on kcbhxoro
128 <- kcbhvbo 18440 nsec on kcbhvbo
128 <- kcbzvb 28150 nsec on kcbzvb
128 <- kccrbp 227120 nsec on kccrbp
128 <- kccsed_rbl 517080 nsec on kccsed_rbl
128 <- ksdpec 5240 nsec on ksdpec
128 <- kccpb_sanity_check 15610 nsec on kccpb_sanity_check
128 <- kccgft_refresh_hdr 815280 nsec on kccgft_refresh_hdr
128 <- kccgde 6320 nsec on kccgde
128 <- kccgrsd 17000 nsec on kccgrsd
128 <- ksdpec 5030 nsec on ksdpec
128 <- ksmrf_ext_min 5810 nsec on ksmrf_ext_min
128 <- ksmrf_ext_min 5510 nsec on ksmrf_ext_min
128 <- ksmrf_init_alloc 7170 nsec on ksmrf_init_alloc
128 <- ksmpga_update_size 5900 nsec on ksmpga_update_size
128 <- ksmapg 59520 nsec on ksmapg
128 <- ksdpec 5990 nsec on ksdpec
128 <- ksdpec 5080 nsec on ksdpec
128 <- ksmpga_allo_cb 26930 nsec on ksmpga_allo_cb
128 <- kccbmp_get 6290 nsec on kccbmp_get
128 <- kcbwdbr 4940 nsec on kcbwdbr
128 <- ksdpec 5340 nsec on ksdpec
128 <- kskthbwt 5640 nsec on kskthbwt
128 <- kslwtb_resmgr 16450 nsec on kslwtb_resmgr
128 <- kslwtb_tm 5910 nsec on kslwtb_tm
128 <- ksdpec 5550 nsec on ksdpec
128 <- ksmals 4490 nsec on ksmals
128 <- ksdpec 5470 nsec on ksdpec
128 <- ksfd_osdrqfil 15900 nsec on ksfd_osdrqfil
128 <- ksmfrs 5160 nsec on ksmfrs
128 <- ksfdread1 99710 nsec on ksfdread1
128 <- ksfdread 111050 nsec on ksfdread
128 <- ksdpec 6060 nsec on ksdpec
128 <- ksl_which_bucket 7210 nsec on ksl_which_bucket
128 <- kslwte_tm 29370 nsec on kslwte_tm
128 <- kslwte_resmgr 40680 nsec on kslwte_resmgr
128 <- kskthewt 6050 nsec on kskthewt
128 <- kcbhxoro 10820 nsec on kcbhxoro
128 <- kcbhvbo 21930 nsec on kcbhvbo
128 <- kcbzvb 32660 nsec on kcbzvb
128 <- kccrbp 268870 nsec on kccrbp
128 <- ksdpec 5730 nsec on ksdpec
128 <- kccpb_sanity_check 17030 nsec on kccpb_sanity_check
128 <- kccrec_rbl 315990 nsec on kccrec_rbl
128 <- kccext_info 330770 nsec on kccext_info
128 <- kccbmp_get 5880 nsec on kccbmp_get
128 <- kskthbwt 5880 nsec on kskthbwt
128 <- kslwtb_resmgr 16270 nsec on kslwtb_resmgr
128 <- kslwtb_tm 6030 nsec on kslwtb_tm
128 <- ksdpec 5620 nsec on ksdpec
128 <- ksmals 4710 nsec on ksmals
128 <- ksdpec 5560 nsec on ksdpec
128 <- ksfd_osdrqfil 16150 nsec on ksfd_osdrqfil
128 <- ksmfrs 10730 nsec on ksmfrs
128 <- ksfdread1 38366530 nsec on ksfdread1
128 <- ksfdread 38381580 nsec on ksfdread
128 <- ksdpec 5300 nsec on ksdpec
128 <- ksl_which_bucket 6260 nsec on ksl_which_bucket
128 <- kslwte_tm 30090 nsec on kslwte_tm
128 <- kslwte_resmgr 42170 nsec on kslwte_resmgr
128 <- kskthewt 5030 nsec on kskthewt
128 <- kccgft_prefetch 38488440 nsec on kccgft_prefetch
128 <- ksdpec 4060 nsec on ksdpec
128 <- kccpb_sanity_check 14510 nsec on kccpb_sanity_check
128 <- kccrec_rbl 38546600 nsec on kccrec_rbl
128 <- kccext_ugg 38560720 nsec on kccext_ugg
128 <- kccrec_read_write 38914550 nsec on kccrec_read_write
128 <- kcc_rno_to_rid 7430 nsec on kcc_rno_to_rid
128 <- kccgftcs 40210220 nsec on kccgftcs
128 <- kccdebug_pointer_cr 7760 nsec on kccdebug_pointer_cr
128 <- kccdebug_set 5220 nsec on kccdebug_set
128 | kcc_scan:return 40258180 nsec on kcc_scan
128 <- kcc_scan 40277450 nsec on this function
root@machine1 #
root@machine1 #
root@machine1 # dtrace -s /tmp/time_func_stack1.d 27356 kcc_scan > func_stack.log
dtrace: script '/tmp/time_func_stack1.d' matched 12090 probes
root@machine1 # more func_stack.log
CPU FUNCTION
183 -> kcc_scan
oracle`kcc_scan
oracle`kcrrsal+0x26c
oracle`krsfqgap+0xeb0
oracle`kcrrpng+0x35a4
oracle`kcrrwkx+0xe64
oracle`kcrrwk+0x3b0
oracle`ksbcti+0x3e4
oracle`ksbabs+0x3a8
oracle`ksbrdp+0x3f8
oracle`opirip+0x344
oracle`opidrv+0x4b0
oracle`sou2o+0x50
oracle`opimai_real+0x10c
oracle`main+0x98
oracle`_start+0x17c
183 | kcc_scan:entry -> entry of kcc_scan
183 -> kccgftcs -> entry of kccgftcs
183 -> kccrof -> entry of kccrof
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 9840 nsec on ksdpec
183 <- kccrof 30780 nsec on kccrof
183 -> ksmapg -> entry of ksmapg
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5930 nsec on ksdpec
183 -> ksmrf_ext_min -> entry of ksmrf_ext_min
183 <- ksmrf_ext_min 8910 nsec on ksmrf_ext_min
183 -> ksmrf_ext_min -> entry of ksmrf_ext_min
183 <- ksmrf_ext_min 5720 nsec on ksmrf_ext_min
183 -> ksmrf_init_alloc -> entry of ksmrf_init_alloc
183 <- ksmrf_init_alloc 11080 nsec on ksmrf_init_alloc
183 -> ksmpga_update_size -> entry of ksmpga_update_size
183 <- ksmpga_update_size 11340 nsec on ksmpga_update_size
183 <- ksmapg 85950 nsec on ksmapg
183 -> ksmpga_allo_cb -> entry of ksmpga_allo_cb
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5580 nsec on ksdpec
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5340 nsec on ksdpec
183 <- ksmpga_allo_cb 26620 nsec on ksmpga_allo_cb
183 -> kccbc_init -> entry of kccbc_init
183 <- kccbc_init 5620 nsec on kccbc_init
183 -> kccbc_empty -> entry of kccbc_empty
183 <- kccbc_empty 6850 nsec on kccbc_empty
183 -> kccgft_refresh_hdr -> entry of kccgft_refresh_hdr
183 -> kccbc_empty -> entry of kccbc_empty
183 <- kccbc_empty 5850 nsec on kccbc_empty
183 -> kccrhd -> entry of kccrhd
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5370 nsec on ksdpec
183 -> kslwtb_resmgr -> entry of kslwtb_resmgr
183 -> kskthbwt -> entry of kskthbwt
183 <- kskthbwt 6540 nsec on kskthbwt
183 <- kslwtb_resmgr 19220 nsec on kslwtb_resmgr
183 -> kslwtb_tm -> entry of kslwtb_tm
183 <- kslwtb_tm 6540 nsec on kslwtb_tm
183 -> ksfdread -> entry of ksfdread
[1;7m--More--(13%)[m
183 -> ksfdread1 -> entry of ksfdread1
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5470 nsec on ksdpec
183 -> ksmals -> entry of ksmals
183 <- ksmals 5070 nsec on ksmals
183 -> ksfd_osdrqfil -> entry of ksfd_osdrqfil
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5510 nsec on ksdpec
183 <- ksfd_osdrqfil 16790 nsec on ksfd_osdrqfil
183 -> pread -> entry of pread
183 | pread:entry read 16384 bytes from 16384 pos on the file 256
183 <- pread 36210 nsec on pread
183 -> ksmfrs -> entry of ksmfrs
183 <- ksmfrs 5330 nsec on ksmfrs
183 <- ksfdread1 106090 nsec on ksfdread1
183 <- ksfdread 118490 nsec on ksfdread
183 -> kslwte_resmgr -> entry of kslwte_resmgr
183 -> kslwte_tm -> entry of kslwte_tm
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5740 nsec on ksdpec
183 -> ksl_which_bucket -> entry of ksl_which_bucket
183 <- ksl_which_bucket 6670 nsec on ksl_which_bucket
183 <- kslwte_tm 29690 nsec on kslwte_tm
183 <- kslwte_resmgr 42520 nsec on kslwte_resmgr
183 -> kskthewt -> entry of kskthewt
183 <- kskthewt 6610 nsec on kskthewt
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5510 nsec on ksdpec
183 -> kcbzvb -> entry of kcbzvb
183 -> kcbhvbo -> entry of kcbhvbo
183 -> kcbhxoro -> entry of kcbhxoro
183 <- kcbhxoro 8970 nsec on kcbhxoro
183 <- kcbhvbo 21790 nsec on kcbhvbo
183 <- kcbzvb 33800 nsec on kcbzvb
183 <- kccrhd 284680 nsec on kccrhd
183 -> kccsed_rbl -> entry of kccsed_rbl
183 -> kccbmp_get -> entry of kccbmp_get
183 -> kccbmp_wdl -> entry of kccbmp_wdl
183 <- kccbmp_wdl 6540 nsec on kccbmp_wdl
183 -> kccrbp -> entry of kccrbp
183 -> kcbwdbr -> entry of kcbwdbr
183 <- kcbwdbr 5300 nsec on kcbwdbr
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5850 nsec on ksdpec
183 -> kslwtb_resmgr -> entry of kslwtb_resmgr
183 -> kskthbwt -> entry of kskthbwt
183 <- kskthbwt 5880 nsec on kskthbwt
183 <- kslwtb_resmgr 16830 nsec on kslwtb_resmgr
183 -> kslwtb_tm -> entry of kslwtb_tm
183 <- kslwtb_tm 5990 nsec on kslwtb_tm
183 -> ksfdread -> entry of ksfdread
183 -> ksfdread1 -> entry of ksfdread1
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5860 nsec on ksdpec
183 -> ksmals -> entry of ksmals
183 <- ksmals 4750 nsec on ksmals
183 -> ksfd_osdrqfil -> entry of ksfd_osdrqfil
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5760 nsec on ksdpec
[1;7m--More--(29%)[m
183 <- ksfd_osdrqfil 16320 nsec on ksfd_osdrqfil
183 -> pread -> entry of pread
183 | pread:entry read 16384 bytes from 262144 pos on the file 256
183 <- pread 28330 nsec on pread
183 -> ksmfrs -> entry of ksmfrs
183 <- ksmfrs 5010 nsec on ksmfrs
183 <- ksfdread1 91540 nsec on ksfdread1
183 <- ksfdread 102680 nsec on ksfdread
183 -> kslwte_resmgr -> entry of kslwte_resmgr
183 -> kslwte_tm -> entry of kslwte_tm
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6110 nsec on ksdpec
183 -> ksl_which_bucket -> entry of ksl_which_bucket
183 <- ksl_which_bucket 6700 nsec on ksl_which_bucket
183 <- kslwte_tm 28720 nsec on kslwte_tm
183 <- kslwte_resmgr 39740 nsec on kslwte_resmgr
183 -> kskthewt -> entry of kskthewt
183 <- kskthewt 6060 nsec on kskthewt
183 -> kcbzvb -> entry of kcbzvb
183 -> kcbhvbo -> entry of kcbhvbo
183 -> kcbhxoro -> entry of kcbhxoro
183 <- kcbhxoro 8620 nsec on kcbhxoro
183 <- kcbhvbo 19480 nsec on kcbhvbo
183 <- kcbzvb 30060 nsec on kcbzvb
183 <- kccrbp 257230 nsec on kccrbp
183 -> kccpb_sanity_check -> entry of kccpb_sanity_check
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6000 nsec on ksdpec
183 <- kccpb_sanity_check 18130 nsec on kccpb_sanity_check
183 <- kccbmp_get 306360 nsec on kccbmp_get
183 -> kccrbp -> entry of kccrbp
183 -> kcbwdbr -> entry of kcbwdbr
183 <- kcbwdbr 4830 nsec on kcbwdbr
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5950 nsec on ksdpec
183 -> kslwtb_resmgr -> entry of kslwtb_resmgr
183 -> kskthbwt -> entry of kskthbwt
183 <- kskthbwt 6090 nsec on kskthbwt
183 <- kslwtb_resmgr 17160 nsec on kslwtb_resmgr
183 -> kslwtb_tm -> entry of kslwtb_tm
183 <- kslwtb_tm 6480 nsec on kslwtb_tm
183 -> ksfdread -> entry of ksfdread
183 -> ksfdread1 -> entry of ksfdread1
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5930 nsec on ksdpec
183 -> ksmals -> entry of ksmals
183 <- ksmals 4920 nsec on ksmals
183 -> ksfd_osdrqfil -> entry of ksfd_osdrqfil
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5800 nsec on ksdpec
183 <- ksfd_osdrqfil 16820 nsec on ksfd_osdrqfil
183 -> pread -> entry of pread
183 | pread:entry read 16384 bytes from 294912 pos on the file 256
183 <- pread 28070 nsec on pread
183 -> ksmfrs -> entry of ksmfrs
183 <- ksmfrs 5210 nsec on ksmfrs
183 <- ksfdread1 91520 nsec on ksfdread1
183 <- ksfdread 102310 nsec on ksfdread
183 -> kslwte_resmgr -> entry of kslwte_resmgr
[1;7m--More--(45%)[m
183 -> kslwte_tm -> entry of kslwte_tm
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6260 nsec on ksdpec
183 -> ksl_which_bucket -> entry of ksl_which_bucket
183 <- ksl_which_bucket 8480 nsec on ksl_which_bucket
183 <- kslwte_tm 31250 nsec on kslwte_tm
183 <- kslwte_resmgr 42630 nsec on kslwte_resmgr
183 -> kskthewt -> entry of kskthewt
183 <- kskthewt 6340 nsec on kskthewt
183 -> kcbzvb -> entry of kcbzvb
183 -> kcbhvbo -> entry of kcbhvbo
183 -> kcbhxoro -> entry of kcbhxoro
183 <- kcbhxoro 8910 nsec on kcbhxoro
183 <- kcbhvbo 20060 nsec on kcbhvbo
183 <- kcbzvb 30860 nsec on kcbzvb
183 <- kccrbp 260410 nsec on kccrbp
183 <- kccsed_rbl 584230 nsec on kccsed_rbl
183 -> kccpb_sanity_check -> entry of kccpb_sanity_check
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6300 nsec on ksdpec
183 <- kccpb_sanity_check 18560 nsec on kccpb_sanity_check
183 <- kccgft_refresh_hdr 924110 nsec on kccgft_refresh_hdr
183 -> kccgrsd -> entry of kccgrsd
183 -> kccgde -> entry of kccgde
183 <- kccgde 7030 nsec on kccgde
183 <- kccgrsd 19050 nsec on kccgrsd
183 -> ksmapg -> entry of ksmapg
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6300 nsec on ksdpec
183 -> ksmrf_ext_min -> entry of ksmrf_ext_min
183 <- ksmrf_ext_min 6530 nsec on ksmrf_ext_min
183 -> ksmrf_ext_min -> entry of ksmrf_ext_min
183 <- ksmrf_ext_min 6360 nsec on ksmrf_ext_min
183 -> ksmrf_init_alloc -> entry of ksmrf_init_alloc
183 <- ksmrf_init_alloc 8190 nsec on ksmrf_init_alloc
183 -> ksmpga_update_size -> entry of ksmpga_update_size
183 <- ksmpga_update_size 9160 nsec on ksmpga_update_size
183 <- ksmapg 67950 nsec on ksmapg
183 -> ksmpga_allo_cb -> entry of ksmpga_allo_cb
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 7030 nsec on ksdpec
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6080 nsec on ksdpec
183 <- ksmpga_allo_cb 29470 nsec on ksmpga_allo_cb
183 -> kccrec_read_write -> entry of kccrec_read_write
183 -> kccext_info -> entry of kccext_info
183 -> kccrec_rbl -> entry of kccrec_rbl
183 -> kccbmp_get -> entry of kccbmp_get
183 <- kccbmp_get 6860 nsec on kccbmp_get
183 -> kccrbp -> entry of kccrbp
183 -> kcbwdbr -> entry of kcbwdbr
183 <- kcbwdbr 5720 nsec on kcbwdbr
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6390 nsec on ksdpec
183 -> kslwtb_resmgr -> entry of kslwtb_resmgr
183 -> kskthbwt -> entry of kskthbwt
183 <- kskthbwt 6820 nsec on kskthbwt
183 <- kslwtb_resmgr 19110 nsec on kslwtb_resmgr
183 -> kslwtb_tm -> entry of kslwtb_tm
[1;7m--More--(61%)[m
183 <- kslwtb_tm 6850 nsec on kslwtb_tm
183 -> ksfdread -> entry of ksfdread
183 -> ksfdread1 -> entry of ksfdread1
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6090 nsec on ksdpec
183 -> ksmals -> entry of ksmals
183 <- ksmals 5890 nsec on ksmals
183 -> ksfd_osdrqfil -> entry of ksfd_osdrqfil
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6380 nsec on ksdpec
183 <- ksfd_osdrqfil 17820 nsec on ksfd_osdrqfil
183 -> pread -> entry of pread
183 | pread:entry read 16384 bytes from 17235968 pos on the file 256
183 <- pread 48710 nsec on pread
183 -> ksmfrs -> entry of ksmfrs
183 <- ksmfrs 6080 nsec on ksmfrs
183 <- ksfdread1 117280 nsec on ksfdread1
183 <- ksfdread 128470 nsec on ksfdread
183 -> kslwte_resmgr -> entry of kslwte_resmgr
183 -> kslwte_tm -> entry of kslwte_tm
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6590 nsec on ksdpec
183 -> ksl_which_bucket -> entry of ksl_which_bucket
183 <- ksl_which_bucket 8990 nsec on ksl_which_bucket
183 <- kslwte_tm 32740 nsec on kslwte_tm
183 <- kslwte_resmgr 44590 nsec on kslwte_resmgr
183 -> kskthewt -> entry of kskthewt
183 <- kskthewt 6550 nsec on kskthewt
183 -> kcbzvb -> entry of kcbzvb
183 -> kcbhvbo -> entry of kcbhvbo
183 -> kcbhxoro -> entry of kcbhxoro
183 <- kcbhxoro 10150 nsec on kcbhxoro
183 <- kcbhvbo 21980 nsec on kcbhvbo
183 <- kcbzvb 33600 nsec on kcbzvb
183 <- kccrbp 296380 nsec on kccrbp
183 -> kccpb_sanity_check -> entry of kccpb_sanity_check
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6420 nsec on ksdpec
183 <- kccpb_sanity_check 17990 nsec on kccpb_sanity_check
183 <- kccrec_rbl 344890 nsec on kccrec_rbl
183 <- kccext_info 358340 nsec on kccext_info
183 -> kccext_ugg -> entry of kccext_ugg
183 -> kccrec_rbl -> entry of kccrec_rbl
183 -> kccbmp_get -> entry of kccbmp_get
183 <- kccbmp_get 6930 nsec on kccbmp_get
183 -> kccgft_prefetch -> entry of kccgft_prefetch
183 -> kslwtb_resmgr -> entry of kslwtb_resmgr
183 -> kskthbwt -> entry of kskthbwt
183 <- kskthbwt 6720 nsec on kskthbwt
183 <- kslwtb_resmgr 18260 nsec on kslwtb_resmgr
183 -> kslwtb_tm -> entry of kslwtb_tm
183 <- kslwtb_tm 6780 nsec on kslwtb_tm
183 -> ksfdread -> entry of ksfdread
183 -> ksfdread1 -> entry of ksfdread1
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6500 nsec on ksdpec
183 -> ksmals -> entry of ksmals
183 <- ksmals 5680 nsec on ksmals
183 -> ksfd_osdrqfil -> entry of ksfd_osdrqfil
[1;7m--More--(77%)[m
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 6360 nsec on ksdpec
183 <- ksfd_osdrqfil 17580 nsec on ksfd_osdrqfil
183 -> pread -> entry of pread
183 | pread:entry read 622592 bytes from 22691840 pos on the file 256
183 <- pread 25012860 nsec on pread
183 -> ksmfrs -> entry of ksmfrs
183 <- ksmfrs 12600 nsec on ksmfrs
183 <- ksfdread1 25115600 nsec on ksfdread1
183 <- ksfdread 25131470 nsec on ksfdread
183 -> kslwte_resmgr -> entry of kslwte_resmgr
183 -> kslwte_tm -> entry of kslwte_tm
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 8900 nsec on ksdpec
183 -> ksl_which_bucket -> entry of ksl_which_bucket
183 <- ksl_which_bucket 12440 nsec on ksl_which_bucket
183 <- kslwte_tm 48080 nsec on kslwte_tm
183 <- kslwte_resmgr 66970 nsec on kslwte_resmgr
183 -> kskthewt -> entry of kskthewt
183 <- kskthewt 8510 nsec on kskthewt
183 <- kccgft_prefetch 25278660 nsec on kccgft_prefetch
183 -> kccpb_sanity_check -> entry of kccpb_sanity_check
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5300 nsec on ksdpec
183 <- kccpb_sanity_check 20980 nsec on kccpb_sanity_check
183 <- kccrec_rbl 25352510 nsec on kccrec_rbl
183 -> kccrec_rbl -> entry of kccrec_rbl
183 -> kccbmp_get -> entry of kccbmp_get
183 <- kccbmp_get 9470 nsec on kccbmp_get
183 -> kccgft_prefetch -> entry of kccgft_prefetch
183 -> kslwtb_resmgr -> entry of kslwtb_resmgr
183 -> kskthbwt -> entry of kskthbwt
183 <- kskthbwt 7430 nsec on kskthbwt
183 <- kslwtb_resmgr 22720 nsec on kslwtb_resmgr
183 -> kslwtb_tm -> entry of kslwtb_tm
183 <- kslwtb_tm 7850 nsec on kslwtb_tm
183 -> ksfdread -> entry of ksfdread
183 -> ksfdread1 -> entry of ksfdread1
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5820 nsec on ksdpec
183 -> ksmals -> entry of ksmals
183 <- ksmals 6700 nsec on ksmals
183 -> ksfd_osdrqfil -> entry of ksfd_osdrqfil
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5180 nsec on ksdpec
183 <- ksfd_osdrqfil 18600 nsec on ksfd_osdrqfil
183 -> pread -> entry of pread
183 | pread:entry read 655360 bytes from 22691840 pos on the file 256
183 <- pread 2171790 nsec on pread
183 -> ksmfrs -> entry of ksmfrs
183 <- ksmfrs 4810 nsec on ksmfrs
183 <- ksfdread1 2257330 nsec on ksfdread1
183 <- ksfdread 2270250 nsec on ksfdread
183 -> kslwte_resmgr -> entry of kslwte_resmgr
183 -> kslwte_tm -> entry of kslwte_tm
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5340 nsec on ksdpec
183 -> ksl_which_bucket -> entry of ksl_which_bucket
183 <- ksl_which_bucket 7370 nsec on ksl_which_bucket
[1;7m--More--(93%)[m
183 <- kslwte_tm 28630 nsec on kslwte_tm
183 <- kslwte_resmgr 39310 nsec on kslwte_resmgr
183 -> kskthewt -> entry of kskthewt
183 <- kskthewt 5240 nsec on kskthewt
183 <- kccgft_prefetch 2384290 nsec on kccgft_prefetch
183 -> kccpb_sanity_check -> entry of kccpb_sanity_check
183 -> ksdpec -> entry of ksdpec
183 <- ksdpec 5190 nsec on ksdpec
183 <- kccpb_sanity_check 15720 nsec on kccpb_sanity_check
183 <- kccrec_rbl 2448100 nsec on kccrec_rbl
183 <- kccext_ugg 27824950 nsec on kccext_ugg
183 <- kccrec_read_write 28206320 nsec on kccrec_read_write
183 -> kcc_rno_to_rid -> entry of kcc_rno_to_rid
183 <- kcc_rno_to_rid 8900 nsec on kcc_rno_to_rid
183 <- kccgftcs 29635100 nsec on kccgftcs
183 -> kccdebug_pointer_cr -> entry of kccdebug_pointer_cr
183 <- kccdebug_pointer_cr 9660 nsec on kccdebug_pointer_cr
183 -> kccdebug_set -> entry of kccdebug_set
183 <- kccdebug_set 6450 nsec on kccdebug_set
183 | kcc_scan:return 29690700 nsec on kcc_scan
183 <- kcc_scan 29710330 nsec on this function
来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/25105315/viewspace-2132219/，如需转载，请注明出处，否则将追究法律责任。
转载于:http://blog.itpub.net/25105315/viewspace-2132219/
扫一扫
122
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
