RE: lgwr/dbw0 did not issue pwrite64 sys call

From: D'Hooge Freek <Freek.DHooge_at_uptime.be>
Date: Sat, 26 Nov 2011 17:52:37 +0100
Message-ID: <4814386347E41145AAE79139EAA398981939EB82ED_at_ws03-exch07.iconos.be>

Chen,

You can use the -c flag with strace to get a list of the different system calls done, together with how many times and how much time was spend in total for each system call.

ASM is not responsible for reading or writing database or redo blocks. This is still done by the database processes themselves (ASM provides them with a kind of map of where each block is located).

My guess is that you have enabled async io and that the io_submit system call is used to pass the io requests to the async io servers (and io_getevents to get the status of the request). This can be confirmed by using "strace -cfp <process id>".

Regards,  

Freek D'Hooge
Uptime
Oracle Database Administrator
email: freek.dhooge_at_uptime.be
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer

-----Original Message-----
From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Sidney Chen Sent: zaterdag 26 november 2011 12:14
To: oracle-l_at_freelists.org
Subject: lgwr/dbw0 did not issue pwrite64 sys call

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


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

Received on Sat Nov 26 2011 - 10:52:37 CST