lgwr/dbw0 did not issue pwrite64 sys call
- From: Sidney Chen <huanshengchen@xxxxxxxxx>
- To: oracle-l@xxxxxxxxxxxxx
- Date: Sat, 26 Nov 2011 19:14:06 +0800
it's two nodes rac, 10.2.0.3, Linux server x86_64, with asm running.
Here is some obervation
It's strange to me at first that lgwr and dbw0 did not issue pwrite64
system call, I enable the 10046 trace on lgwr and see there is 'log file
parallel write' event, for dbw0, i do a 'alter system checkpoint' to make
sure dbw0 have some work to do. but still, there is no pwrite64 system call
in the stracefile.
I guess it's because the ASM instance come into play, the lgwr/dbw0 just
post the asm process via semophore to do the physical io work for them.
There is consitent semophore operation during the trace.
for physical read, I start a session to do a full table scan, and the
pread64 does not show up.
It makes sense that the ASM will take case such physical IO request, i'm
not sure if i can jump to the conclusion just from such trace. So any idea
on this is appreciated.
strace segment for lgwr:(16364 is the pid of lms0 backend processes)
16:37:00 times(NULL) = 835848393 <0.000004>
16:37:00 read(17,
"MSA\0\2\0\10\0P\0\0\0\222\377\377\377\320\243j\6\0\0\0"..., 80) = 80
<0.000030>
16:37:00 kill(16364, SIGWINCH) = 0 <0.000096>
16:37:00 read(17,
"MSA\0\2\0\10\0P\0\0\0\0\0\0\0\320\243j\6\0\0\0\0\0\0\0"..., 80) = 80
<0.011571>
16:37:00 times(NULL) = 835848394 <0.000004>
16:37:00 semctl(6455324, 176, SETVAL, 0x7f00000001) = 0 <0.000048>
16:37:00 times(NULL) = 835848394 <0.000003>
16:37:00 times(NULL) = 835848394 <0.000004>
16:37:00 read(17,
"MSA\0\2\0\10\0P\0\0\0\222\377\377\377\320\243j\6\0\0\0"..., 80) = 80
<0.000015>
16:37:00 kill(16364, SIGWINCH) = 0 <0.000033>
16:37:00 read(17,
"MSA\0\2\0\10\0P\0\0\0\0\0\0\0\320\243j\6\0\0\0\0\0\0\0"..., 80) = 80
<0.000558>
16:37:00 times(NULL) = 835848394 <0.000004>
16:37:00 semctl(6455324, 132, SETVAL, 0x7f00000001) = 0 <0.000006>
16:37:00 times(NULL) = 835848394 <0.000003>
16:37:00 times(NULL) = 835848394 <0.000003>
16:37:00 semtimedop(6455324, 0x7fbfffdde0, 1, {0, 190000000}) = 0 <0.001599>
16:37:00 times(NULL) = 835848394 <0.000007>
16:37:00 times(NULL) = 835848394 <0.000003>
16:37:00 read(17,
"MSA\0\2\0\10\0P\0\0\0\222\377\377\377\320\243j\6\0\0\0"..., 80) = 80
<0.000021>
16:37:00 kill(16364, SIGWINCH) = 0 <0.000029>
strace segment for dbwr:
16:56:11 getrusage(RUSAGE_SELF, {ru_utime={178, 93925}, ru_stime={90,
621223}, ...}) = 0 <0.000003>
16:56:11 getrusage(RUSAGE_SELF, {ru_utime={178, 93925}, ru_stime={90,
621223}, ...}) = 0 <0.000003>
16:56:11 getrusage(RUSAGE_SELF, {ru_utime={178, 93925}, ru_stime={90,
621223}, ...}) = 0 <0.000004>
16:56:11 read(16,
"MSA\0\2\0\10\0P\0\0\0\222\377\377\377\0Ek\6\0\0\0\0\0\220"..., 80) = 80
<0.000058>
16:56:11 read(16,
"MSA\0\2\0\10\0P\0\0\0\0\0\0\0\0Ek\6\0\0\0\0\0\0\0\0\0\0"..., 80) = 80
<0.000672>
16:56:11 times(NULL) = 835963408 <0.000003>
16:56:11 read(16,
"MSA\0\2\0\10\0P\0\0\0\222\377\377\377\0Ek\6\0\0\0\0\0\0"..., 80) = 80
<0.000014>
16:56:11 getrusage(RUSAGE_SELF, {ru_utime={178, 93925}, ru_stime={90,
621223}, ...}) = 0 <0.000003>
16:56:11 getrusage(RUSAGE_SELF, {ru_utime={178, 93925}, ru_stime={90,
621223}, ...}) = 0 <0.000004>
16:56:11 times(NULL) = 835963408 <0.000003>
16:56:11 read(16,
"MSA\0\2\0\10\0P\0\0\0\0\0\0\0\0Ek\6\0\0\0\0\0\0\0\0\0\0"..., 80) = 80
<0.000005>
16:56:11 read(16,
"MSA\0\2\0\10\0P\0\0\0\222\377\377\377\0Ek\6\0\0\0\0\0\0"..., 80) = 80
<0.000005>
16:56:11 getrusage(RUSAGE_SELF, {ru_utime={178, 93925}, ru_stime={90,
621223}, ...}) = 0 <0.000004>
strace segment for a server process which do a full table scan:
17:14:25 recvmsg(7, {msg_name(16)={sa_family=AF_INET,
sin_port=htons(23375), sin_addr=inet_addr("192.168.8.42")},
msg_iov(2)=[{"\344\267z<MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48}, {"\v\0\0\0&yP$z:\225y\377\177\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 136}],
msg_controllen=0, msg_flags=0}, 0) = 184 <0.000007>
17:14:25 recvmsg(7, 0x7fbffe7360, 0) = -1 EAGAIN (Resource temporarily
unavailable) <0.000006>
17:14:25 times({tms_utime=2, tms_stime=1, tms_cutime=0, tms_cstime=0}) =
836072791 <0.000010>
17:14:25 times({tms_utime=2, tms_stime=1, tms_cutime=0, tms_cstime=0}) =
836072791 <0.000004>
17:14:25 poll([{fd=7, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}, {fd=12,
events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND, revents=POLLIN|POLLRDNORM}],
2, 1250) = 1 <0.000005>
17:14:25 recvmsg(12, {msg_name(16)={sa_family=AF_INET,
sin_port=htons(23375), sin_addr=inet_addr("192.168.8.42")},
msg_iov(1)=[{"\1\270z<DPUM\1\0\4\0000 \0\0\271\221\302\v\0\0\0\0\0\0"...,
48}], msg_controllen=0, msg_flags=MSG_TRUNC}, MSG_PEEK) = 48 <0.000009>
17:14:25 recvmsg(12, {msg_name(16)={sa_family=AF_INET,
sin_port=htons(23375), sin_addr=inet_addr("192.168.8.42")},
msg_iov(2)=[{"\1\270z<DPUM\1\0\4\0000 \0\0\271\221\302\v\0\0\0\0\0\0"...,
48}, {"\6\5\210\0;@Y\230X\253\177\f,\0\0026\241\212,\0\2\0\0\0"..., 8192}],
msg_controllen=0, msg_flags=0}, 0) = 8240 <0.000013>
17:14:25 times({tms_utime=2, tms_stime=1, tms_cutime=0, tms_cstime=0}) =
836072791 <0.000003>
--
Regards
Sidney Chen
--
//www.freelists.org/webpage/oracle-l
Other related posts:
