Examine what DBW process does during a buffer cache flush

To observe the sequence of events, I did the below steps to simulate some IO.

1) Enabled strace with -ttT for dbw process at os level (redirected the output to a file)

2) Enable sql trace for the dbw process in the DB

3) I load a table in memory and modify it by an update statement

4) Do a buffer_cache flush

5) terminate strace & disable 10046 trace

6) Review

Note under an ideal 'rdbms ipc message' situation the dbw wont write any information in the trace file, this is examined before 10046 trace was enabled.

rdbms ipc message - rdbms inter process communication message, an ideal event for the db background process (I hope).

1) strace -ttT -p 2090 -o .../rmn01tst_dbw.2090

2) Enabled sql trace @ db level

SQL> select a.sid,a.serial#,a.program,b.spid,b.pid,b.program from v$session a,v$process b where a.paddr=b.addr and a.sid=242;

       SID    SERIAL# PROGRAM                                          SPID                            PID PROGRAM
---------- ---------- ------------------------------------------------ ------------------------ ---------- ------------------------------------------------
       242          1 oracle@db12c.oracle.com (DBW0)                   2090                             11 oracle@db12c.oracle.com (DBW0)

SQL> exec dbms_system.set_ev(242,1,10046,12,'');

PL/SQL procedure successfully completed.

====================================================================================

Note: how does it look under an ideal situation, when dbw process is ideal...

This is sql trace: /u01/app/oracle/diag/rdbms/rmn01tst/rmn01tst/trace/rmn01tst_dbw0_2090.trc

*** 2018-08-31 15:50:49.336                                        <<< Look at the timestamp

WAIT #0: nam='rdbms ipc message' ela= 1861215 timeout=186 p2=0 p3=0 obj#=-1 tim=2464924796       

*** 2018-08-31 15:50:52.339

WAIT #0: nam='rdbms ipc message' ela= 3001242 timeout=300 p2=0 p3=0 obj#=-1 tim=2467927765

strace: .../rmn01tst_dbw.2090

15:50:49.335903 times(NULL)             = 429647905 <0.000022>

15:50:49.336067 write(12, "\n*** 2018-08-31 15:50:49.336\n", 29) = 29 <0.000029>

15:50:49.336204 lseek(12, 0, SEEK_CUR)  = 40413 <0.000016>

15:50:49.336264 write(12, "WAIT #0: nam='rdbms ipc message'"..., 90) = 90 <0.000026>

15:50:49.336357 write(13, "J?lc67~UQ1\n", 11) = 11 <0.000047>

15:50:49.336470 write(12, "\n", 1)      = 1 <0.000021>

15:50:49.336565 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 660899}, ru_stime={0, 543917}, ...}) = 0 <0.000017>

15:50:49.336758 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 660899}, ru_stime={0, 543917}, ...}) = 0 <0.000026>

15:50:49.336901 times(NULL)             = 429647905 <0.000016>

15:50:49.336999 open("/proc/2070/stat", O_RDONLY) = 17 <0.000059>

15:50:49.337162 read(17, "2070 (ora_pmon_rmn01t) S 1 2070 "..., 999) = 250 <0.000034>            <<<< 2070 is rmn01tst - pmon's process id @ OS

15:50:49.337245 close(17)               = 0 <0.000019>

15:50:49.337380 times(NULL)             = 429647905 <0.000017>

15:50:49.337516 times(NULL)             = 429647905 <0.000016>

15:50:49.337589 semtimedop(196610, {{15, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001079>     <<< On this event it sleeps for 3 seconds and the iteration continues.

15:50:52.339008 times(NULL)             = 429648205 <0.000032>                        <<<< Start of next idle event

>>pgrep -fl ora_pmon_rmn

2070 ora_pmon_rmn01tst

====================================================================================

3) update the table to populate some data in buffer cache

SQL> update scott_HIST_OSSTAT set value=100;

50 rows updated.


Statistics
----------------------------------------------------------
         58  recursive calls
         45  db block gets
         70  consistent gets
          1  physical reads
          0  redo size
        860  bytes sent via SQL*Net to client
        839  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          7  sorts (memory)
          0  sorts (disk)
         50  rows processed

4) flush buffer cache

15:52:19 SQL> alter system flush buffer_cache;

System altered.

15:52:25 SQL> exit <<< is the time buffer cache was actually flushed.

5) close the strace and sqltrace

SQL> exec dbms_system.set_ev(242,1,10046,0,'');

PL/SQL procedure successfully completed.

^CProcess 2090 detached

6) Review.

Noticeable messages in dbw process trace file.

*** 2018-08-31 15:51:25.424
WAIT #0: nam='rdbms ipc message' ela= 3000826 timeout=300 p2=0 p3=0 obj#=-1 tim=2501013342
WAIT #0: nam='db file async I/O submit' ela= 102982 requests=1 interrupt=0 timeout=0 obj#=-1 tim=2501121190
WAIT #0: nam='db file async I/O submit' ela= 22061 requests=1 interrupt=0 timeout=0 obj#=-1 tim=2501147503

...
*** 2018-08-31 15:51:40.574
WAIT #0: nam='rdbms ipc message' ela= 3001774 timeout=300 p2=0 p3=0 obj#=-1 tim=2516162844
WAIT #0: nam='db file async I/O submit' ela= 64605 requests=1 interrupt=0 timeout=0 obj#=-1 tim=2516233393
WAIT #0: nam='db file async I/O submit' ela= 33987 requests=1 interrupt=0 timeout=0 obj#=-1 tim=2516271105
WAIT #0: nam='db file async I/O submit' ela= 2425 requests=1 interrupt=0 timeout=0 obj#=-1 tim=2516276205
WAIT #0: nam='db file async I/O submit' ela= 2828 requests=1 interrupt=0 timeout=0 obj#=-1 tim=2516282707

...
*** 2018-08-31 15:52:25.473   
WAIT #0: nam='rdbms ipc message' ela= 2728946 timeout=300 p2=0 p3=0 obj#=-1 tim=2561062246            <<< timestamp of our interest [but see above 2 timestamps it looks like oracle already stared writing the dirty blocks out]
WAIT #0: nam='db file async I/O submit' ela= 93225 requests=30 interrupt=0 timeout=0 obj#=-1 tim=2561158997
WAIT #0: nam='rdbms ipc message' ela= 172443 timeout=17 p2=0 p3=0 obj#=-1 tim=2561334413
..


strace messages:
15:51:25.424487 times(NULL)             = 429651513 <0.000054>
15:51:25.424804 write(12, "\n*** 2018-08-31 15:51:25.424\n", 29) = 29 <0.000255>
15:51:25.425376 lseek(12, 0, SEEK_CUR)  = 41853 <0.000056>
15:51:25.425568 write(12, "WAIT #0: nam='rdbms ipc message'"..., 90) = 90 <0.000130>
15:51:25.426252 write(13, "J?VOTB~TQ1\n", 11) = 11 <0.000206>
15:51:25.426619 lseek(12, 0, SEEK_CUR)  = 41943 <0.000059>
15:51:25.426976 write(12, "\n", 1)      = 1 <0.000195>
15:51:25.427316 write(13, "3?Ja~01\n", 8) = 8 <0.000097>
15:51:25.427938 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 667898}, ru_stime={0, 559914}, ...}) = 0 <0.000054>
15:51:25.428222 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 668898}, ru_stime={0, 559914}, ...}) = 0 <0.000054>
15:51:25.428484 times(NULL)             = 429651514 <0.000052>
15:51:25.428789 times(NULL)             = 429651514 <0.000060>
15:51:25.429315 pwrite(261, "\2\242\0\0k8\0\1\220\331!\0\0\0\1\4\337\33\0\0\3\0\30\0\266\6\0\0\253\1!!"..., 8192, 118317056) = 8192 <0.102389>
15:51:25.531936 times(NULL)             = 429651524 <0.000157>
15:51:25.532320 lseek(12, 0, SEEK_CUR)  = 41944 <0.000167>
15:51:25.532633 write(12, "WAIT #0: nam='db file async I/O "..., 107) = 107 <0.000654>
15:51:25.533443 write(13, "J?ggP~0h1\n", 10) = 10 <0.000180>
15:51:25.533785 lseek(12, 0, SEEK_CUR)  = 42051 <0.000095>
15:51:25.534020 write(12, "\n", 1)      = 1 <0.000363>
15:51:25.534665 write(13, "3?9K~01\n", 8) = 8 <0.000145>
15:51:25.535944 times(NULL)             = 429651525 <0.000044>
15:51:25.536214 times(NULL)             = 429651525 <0.000043>
15:51:25.536663 pwrite(261, "&\242\0\0\240\0\0\1\221\331!\0\0\0\1\4\355\316\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 1310720) = 8192 <0.021443>
15:51:25.558320 times(NULL)             = 429651527 <0.000045>
15:51:25.558630 lseek(12, 0, SEEK_CUR)  = 42052 <0.000044>
15:51:25.558993 write(12, "WAIT #0: nam='db file async I/O "..., 106) = 106 <0.000481>
15:51:25.559766 write(13, "J?u36~0g1\n", 10) = 10 <0.000067>
15:51:25.560290 lseek(12, 0, SEEK_CUR)  = 42158 <0.000049>
15:51:25.560531 write(12, "\n", 1)      = 1 <0.000334>
15:51:25.561037 write(13, "3?cL~01\n", 8) = 8 <0.000044>
15:51:25.562385 times(NULL)             = 429651527 <0.000042>
15:51:25.562622 times(NULL)             = 429651527 <0.000040>
15:51:25.562852 semtimedop(196610, {{15, -1, 0}}, 1, {2, 980000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.980897>
15:51:28.544029 times(NULL)             = 429651825 <0.000057>


15:51:40.574191 times(NULL)             = 429653028 <0.000058>
15:51:40.574464 lseek(12, 0, SEEK_CUR)  = 42639 <0.000057>
15:51:40.574707 write(12, "\n*** 2018-08-31 15:51:40.574\n", 29) = 29 <0.000845>
15:51:40.575901 write(13, "3?eLTB~0T\n", 10) = 10 <0.000166>
15:51:40.576278 lseek(12, 0, SEEK_CUR)  = 42668 <0.000060>
15:51:40.576470 write(12, "WAIT #0: nam='rdbms ipc message'"..., 90) = 90 <0.000567>
15:51:40.577328 write(13, "I?pZz2xKx52~0Q1\n", 16) = 16 <0.000068>
15:51:40.577545 lseek(12, 0, SEEK_CUR)  = 42758 <0.000161>
15:51:40.577835 write(12, "\n", 1)      = 1 <0.000494>
15:51:40.578474 write(13, "3?Xz~01\n", 8) = 8 <0.000068>
15:51:40.578716 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 671897}, ru_stime={0, 566913}, ...}) = 0 <0.000059>
15:51:40.579149 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 671897}, ru_stime={0, 566913}, ...}) = 0 <0.000094>
15:51:40.579470 times(NULL)             = 429653029 <0.000060>
15:51:40.579697 times(NULL)             = 429653029 <0.000052>
15:51:40.580023 pwrite(260, "!\242\0\0\361\1\300\0\226\331!\0\0\0\1\4<\343\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 4071424) = 8192 <0.063195>
15:51:40.643942 times(NULL)             = 429653035 <0.000049>
15:51:40.644529 lseek(12, 0, SEEK_CUR)  = 42759 <0.000140>
15:51:40.644807 write(12, "WAIT #0: nam='db file async I/O "..., 106) = 106 <0.000420>
15:51:40.646231 write(13, "J?kUG~0g1\n", 10) = 10 <0.000058>
15:51:40.646430 lseek(12, 0, SEEK_CUR)  = 42865 <0.000041>
15:51:40.646581 write(12, "\n", 1)      = 1 <0.000342>
15:51:40.647304 write(13, "3?QS~01\n", 8) = 8 <0.000061>
15:51:40.647588 times(NULL)             = 429653036 <0.000041>
15:51:40.647918 times(NULL)             = 429653036 <0.000042>
15:51:40.648225 pwrite(260, " \242\0\0\230d\303\0\226\331!\0\0\0\1\4~\321\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384, 1821573120) = 16384 <0.033497>
15:51:40.681892 times(NULL)             = 429653039 <0.000043>
15:51:40.682272 lseek(12, 0, SEEK_CUR)  = 42866 <0.000044>
15:51:40.682448 write(12, "WAIT #0: nam='db file async I/O "..., 106) = 106 <0.000423>
15:51:40.683057 write(13, "J?Ok8~0g1\n", 10) = 10 <0.000063>
15:51:40.683319 lseek(12, 0, SEEK_CUR)  = 42972 <0.000041>
15:51:40.683471 write(12, "\n", 1)      = 1 <0.000522>
15:51:40.684204 write(13, "3?BK~01\n", 8) = 8 <0.000101>
15:51:40.684560 times(NULL)             = 429653039 <0.000041>
15:51:40.684881 pwrite(261, "&\242\0\0\220\0\0\1\27\332!\0\0\0\1\4\6|\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 1179648) = 8192 <0.001932>
15:51:40.687027 times(NULL)             = 429653039 <0.000042>
15:51:40.687331 lseek(12, 0, SEEK_CUR)  = 42973 <0.000091>
15:51:40.687553 write(12, "WAIT #0: nam='db file async I/O "..., 105) = 105 <0.001097>
15:51:40.688879 write(13, "J?zw~0f1\n", 9) = 9 <0.000129>
15:51:40.689235 lseek(12, 0, SEEK_CUR)  = 43078 <0.000042>
15:51:40.689396 write(12, "\n", 1)      = 1 <0.000454>
15:51:40.690179 write(13, "3?ZU~01\n", 8) = 8 <0.000085>
15:51:40.690568 times(NULL)             = 429653040 <0.000041>
15:51:40.691026 pwrite(261, "\2\242\0\0\227\3\0\1\26\332!\0\0\0\3\4\274e\0\0\2\0\2\0\326\6\0\0\f\1\21\21"..., 8192, 7528448) = 8192 <0.002290>
15:51:40.693568 times(NULL)             = 429653040 <0.000042>
15:51:40.693833 lseek(12, 0, SEEK_CUR)  = 43079 <0.000045>
15:51:40.694001 write(12, "WAIT #0: nam='db file async I/O "..., 105) = 105 <0.000597>
15:51:40.694751 write(13, "J?Ww~0f1\n", 9) = 9 <0.000054>
15:51:40.694917 lseek(12, 0, SEEK_CUR)  = 43184 <0.000046>
15:51:40.695211 write(12, "\n", 1)      = 1 <0.000566>
15:51:40.695929 write(13, "3?BJ~01\n", 8) = 8 <0.000053>
15:51:40.696364 times(NULL)             = 429653040 <0.000045>
15:51:40.696602 times(NULL)             = 429653040 <0.000040>
15:51:40.696927 semtimedop(196610, {{15, -1, 0}}, 1, {2, 960000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.961220>
15:51:43.658446 times(NULL)             = 429653336 <0.000054>


15:52:25.473382 times(NULL)             = 429657517 <0.000050>  <<< the time of interst. Looking alone this event there were many occurence of the pwrite vs above only 1 occurence with each async io event. This makes a buffer cache flush look different from other normal async io events.
15:52:25.473613 write(12, "\n*** 2018-08-31 15:52:25.473\n", 29) = 29 <0.000099>

 15:52:25.473852 lseek(12, 0, SEEK_CUR)  = 44894 <0.000047>
15:52:25.474189 write(12, "WAIT #0: nam='rdbms ipc message'"..., 90) = 90 <0.000314>
15:52:25.474659 write(13, "J?i8RA~TQ1\n", 11) = 11 <0.000065>
15:52:25.474856 lseek(12, 0, SEEK_CUR)  = 44984 <0.000051>
15:52:25.475032 write(12, "\n", 1)      = 1 <0.000338>
15:52:25.475703 write(13, "3?aD~01\n", 8) = 8 <0.000054>
15:52:25.475963 times(NULL)             = 429657518 <0.000148>
15:52:25.476864 pwrite(258, "\6\242\0\0\326\0@\0\22\332!\0\0\0\1\6\336\20\0\0\1\0\0\0\n\0\0\0\21\332!\0"..., 8192, 1753088) = 8192 <0.035898>
15:52:25.512914 pwrite(258, "\6\242\0\0\321#@\0\r\332!\0\0\0\1\6\253\241\0\0\1\0\0\0k\5\0\0\f\332!\0"..., 8192, 75112448) = 8192 <0.003003>
15:52:25.516117 pwrite(258, "\6\242\0\0\v<@\0\354\331!\0\0\0\1\6\356\37\0\0\1\0\0\0\213\33\0\0\353\331!\0"..., 8192, 125919232) = 8192 <0.002175>
15:52:25.518370 pwrite(258, "\6\242\0\0001<@\0\354\331!\0\0\0\1\0063-\0\0\2\0\33\0\220\33\0\0\353\331!\0"..., 8192, 126230528) = 8192 <0.000951>
15:52:25.519454 pwrite(258, "\6\242\0\0009<@\0\354\331!\0\0\0\1\6\271i\0\0\2\0\v\0\222\33\0\0\353\331!\0"..., 8192, 126296064) = 8192 <0.001992>
15:52:25.521578 pwrite(258, "\6\242\0\0\21|@\0\353\331!\0\0\0\3\6{=\0\0\1\0\30\0:>\0\0\352\331!\0"..., 8192, 260186112) = 8192 <0.001118>
15:52:25.522821 pwrite(258, "\6\242\0\0)|@\0\353\331!\0\0\0\3\6\v\357\0\0\2\0\0\0=>\0\0\352\331!\0"..., 8192, 260382720) = 8192 <0.001268>
15:52:25.524253 pwrite(258, "\6\242\0\0U>A\0\354\331!\0\0\0\1\6\220\362\0\0\1\0\36\0\22\0\0\0\353\331!\0"..., 8192, 667590656) = 8192 <0.001627>
15:52:25.526013 pwrite(260, "\6\242\0\0\373\1\300\0\27\332!\0\0\0\1\6\307c\0\0\2\0\0\0U\1\0\0\26\332!\0"..., 8192, 4153344) = 8192 <0.002081>
15:52:25.528274 pwrite(260, "\6\242\0\0\3\2\300\0\27\332!\0\0\0\1\6TS\0\0\2\0\0\0V\1\0\0\26\332!\0"..., 8192, 4218880) = 8192 <0.001008>
15:52:25.529414 pwrite(260, "\6\242\0\0D\22\300\0\354\331!\0\0\0\1\6\207x\0\0\1\0\37\0\257\33\0\0\353\331!\0"..., 8192, 38305792) = 8192 <0.002232>
15:52:25.531803 pwrite(260, "\6\242\0\0c\22\300\0\354\331!\0\0\0\1\6F\360\0\0\2\0\f\0\262\33\0\0M\327!\0"..., 8192, 38559744) = 8192 <0.001065>
15:52:25.532996 pwrite(260, "\6\242\0\0l\22\300\0\354\331!\0\0\0\1\6\353\307\0\0\1\0\35\0\263\33\0\0o\331!\0"..., 8192, 38633472) = 8192 <0.003181>
15:52:25.536301 pwrite(260, "\6\242\0\0s\22\300\0\354\331!\0\0\0\1\6\2725\0\0\2\0\n\0\264\33\0\0\353\331!\0"..., 8192, 38690816) = 8192 <0.001406>
15:52:25.537830 pwrite(260, "\6\242\0\0Td\301\0\24\332!\0\0\0\1\6\2411\0\0\1\0\5\0\272f\1\0\23\332!\0"..., 8192, 747274240) = 8192 <0.001649>
15:52:25.539569 pwrite(260, "\6\242\0\0sd\301\0\24\332!\0\0\0\1\6\364\215\0\0\2\0\6\0\300f\1\0\23\332!\0"..., 8192, 747528192) = 8192 <0.001308>
15:52:25.540998 pwrite(260, "\6\242\0\0{d\301\0\24\332!\0\0\0\1\6~/\0\0\2\0\6\0\302f\1\0\23\332!\0"..., 8192, 747593728) = 8192 <0.001952>
15:52:25.543125 pwrite(260, "\6\242\0\0\3e\301\0\24\332!\0\0\0\1\6\363\n\0\0\2\0\6\0\304f\1\0\23\332!\0"..., 8192, 748707840) = 8192 <0.001206>
15:52:25.544453 pwrite(261, "&\242\0\0\200\0\0\1\354\331!\0\0\0\1\4\247(\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 1048576) = 8192 <0.001786>
15:52:25.546360 pwrite(261, "&\242\0\0\260\0\0\1\r\332!\0\0\0\1\4v\272\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 1441792) = 8192 <0.001876>
15:52:25.548364 pwrite(261, "&\242\0\0\300\0\0\1\22\332!\0\0\0\1\4}M\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 1572864) = 8192 <0.001182>
15:52:25.549667 pwrite(261, "&\242\0\0\340\0\0\1\353\331!\0\0\0\2\4\23\26\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 1835008) = 8192 <0.001981>
15:52:25.551801 pwrite(261, "&\242\0\0\360\0\0\1\24\332!\0\0\0\1\4\366\31\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 1966080) = 8192 <0.000871>
15:52:25.552791 pwrite(261, "&\242\0\0\20\1\0\1\351\331!\0\0\0\1\4\335o\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 2228224) = 8192 <0.001311>
15:52:25.554222 pwrite(261, "\2\242\0\0V\2\0\1\353\331!\0\0\0\n\4\311\200\0\0\1\0\10\0\\\5\0\0\327\00088"..., 8192, 4898816) = 8192 <0.003142>
15:52:25.557490 pwrite(261, "\2\242\0\0@\3\0\1\f\332!\0\0\0\1\4\t1\0\0\4\0\1\0y\6\0\0\316\0,,"..., 8192, 6815744) = 8192 <0.001824>
15:52:25.559430 pwrite(261, "\2\242\0\0\232\r\0\1\21\332!\0\0\0\1\4r\342\0\0\5\0\26\0i\6\0\0\6\1\37\37"..., 8192, 28524544) = 8192 <0.000853>
15:52:25.560474 pwrite(261, "\2\242\0\0\251\r\0\1\353\331!\0\0\0\4\4V\364\0\0\7\0\24\0O\5\0\0\346\00000"..., 8192, 28647424) = 8192 <0.001340>
15:52:25.561934 pwrite(261, "\2\242\0\0-<\0\1\23\332!\0\0\0\5\4^\376\0\0\10\0\31\0\326\6\0\0\1\00144"..., 8192, 126197760) = 8192 <0.002343>
15:52:25.564396 pwrite(261, "\2\242\0\0\272=\0\1\350\331!\0\0\0\3\4M\221\0\0\n\0\21\0'\5\0\0\353\0++"..., 8192, 129449984) = 8192 <0.001724>
15:52:25.566249 times(NULL)             = 429657527 <0.000033>
15:52:25.566368 times(NULL)             = 429657527 <0.000032>
15:52:25.566473 times(NULL)             = 429657527 <0.000031>
15:52:25.566575 times(NULL)             = 429657527 <0.000031>
15:52:25.566676 times(NULL)             = 429657527 <0.000032>
15:52:25.566777 times(NULL)             = 429657527 <0.000031>
15:52:25.566941 times(NULL)             = 429657527 <0.000036>
15:52:25.567235 times(NULL)             = 429657527 <0.000035>
15:52:25.567353 times(NULL)             = 429657527 <0.000031>
15:52:25.567454 times(NULL)             = 429657527 <0.000031>
15:52:25.567554 times(NULL)             = 429657527 <0.000031>
15:52:25.567655 times(NULL)             = 429657527 <0.000031>
15:52:25.567755 times(NULL)             = 429657527 <0.000035>
15:52:25.567923 times(NULL)             = 429657527 <0.000032>
15:52:25.568028 times(NULL)             = 429657527 <0.000037>
15:52:25.568201 times(NULL)             = 429657527 <0.000034>
15:52:25.568387 times(NULL)             = 429657527 <0.000031>
15:52:25.568488 times(NULL)             = 429657527 <0.000031>
15:52:25.568588 times(NULL)             = 429657527 <0.000032>
15:52:25.568689 times(NULL)             = 429657527 <0.000037>
15:52:25.568796 times(NULL)             = 429657527 <0.000032>
15:52:25.568898 times(NULL)             = 429657527 <0.000032>
15:52:25.568998 times(NULL)             = 429657527 <0.000088>
15:52:25.569179 times(NULL)             = 429657527 <0.000199>
15:52:25.569441 times(NULL)             = 429657527 <0.000032>
15:52:25.569548 times(NULL)             = 429657527 <0.000031>
15:52:25.569649 times(NULL)             = 429657527 <0.000031>
15:52:25.569755 times(NULL)             = 429657527 <0.000032>
15:52:25.569858 times(NULL)             = 429657527 <0.000031>
15:52:25.569959 times(NULL)             = 429657527 <0.000031>
15:52:25.570140 lseek(12, 0, SEEK_CUR)  = 44985 <0.000035>
15:52:25.570258 write(12, "WAIT #0: nam='db file async I/O "..., 107) = 107 <0.000198>
15:52:25.570550 write(13, "J?xFN~0h1\n", 10) = 10 <0.000042>
15:52:25.570993 lseek(12, 0, SEEK_CUR)  = 45092 <0.000109>
15:52:25.571206 write(12, "\n", 1)      = 1 <0.000074>
15:52:25.571365 write(13, "3?kH~01\n", 8) = 8 <0.000040>
15:52:25.571869 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 680896}, ru_stime={0, 595909}, ...}) = 0 <0.000036>
15:52:25.572017 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 680896}, ru_stime={0, 595909}, ...}) = 0 <0.000091>
15:52:25.572457 times(NULL)             = 429657527 <0.000033>
15:52:25.572594 semctl(196610, 17, SETVAL, 0x1) = 0 <0.000214>
15:52:25.572920 times(NULL)             = 429657527 <0.000034>
15:52:25.573051 semtimedop(196610, {{15, -1, 0}}, 1, {0, 170000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.172182>
15:52:25.745557 lseek(12, 0, SEEK_CUR)  = 45093 <0.000057>
15:52:25.745850 write(12, "WAIT #0: nam='rdbms ipc message'"..., 88) = 88 <0.000334>
15:52:25.746352 write(13, "J?kag~0O1\n", 10) = 10 <0.000068>
15:52:25.747023 lseek(12, 0, SEEK_CUR)  = 45181 <0.000056>
15:52:25.747463 write(12, "\n", 1)      = 1 <0.000135>
15:52:25.747753 write(13, "3?RM~01\n", 8) = 8 <0.000067>
15:52:25.748014 times(NULL)             = 429657545 <0.000156>
15:52:25.748345 times(NULL)             = 429657545 <0.000181>
15:52:25.748692 times(NULL)             = 429657545 <0.000074>
15:52:25.748915 semtimedop(196610, {{15, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000229>
15:52:28.749328 times(NULL)             = 429657845 <0.000024>

This is all I noticed when a buffer cache flush is invoked in DB. Will write more details about this pwrite and write calls in the upcoming blogs.

Thanks for paying a visit.