lgwr/dbw0 did not issue pwrite64 sys call

From: Sidney Chen <huanshengchen_at_gmail.com>
Date: Sat, 26 Nov 2011 19:14:06 +0800
Message-ID: <CAM_ddu_+ZOnb5rHV66yqsgdAGLxCN9juwXh593UkprNr0Xd5Ww_at_mail.gmail.com>

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;_at_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


--
http://www.freelists.org/webpage/oracle-l

Received on Sat Nov 26 2011 - 05:14:06 CST