I observed user sessions intermittently waiting longer on log file sync<\/i>. Untypically, there weren’t any indications of slow redo log writes. In fact, according to the OS performance statistics, all redo log writes completed within 5 ms. But if the redo writes were fast, what was the log writer (LGWR) actually doing?<\/p>\n
If you’ve licensed the Diagnostic and Tuning Pack, Tanel Poder<\/a>‘s ash_wait_chains.sql<\/a> is the perfect tool for displaying such hidden dependencies – it proved invaluable for uncovering the root cause:<\/p>\n Basically, the user sessions were waiting on the LGWR, which, in turn, was mostly waiting on control file writes to complete. Also, the OS statistics confirmed sluggish control files writes. In this case, an OS bug have been causing slow writes on the ZFS data file pool during the peak load periods. It’s worth noting that the IO operations on the other pools were fast during that time. Understandably, the control file that was placed in the data file pool was affected by this problem too. After separating it from the data files, we predictably haven’t suffered any significant log file sync<\/i> wait events anymore, even when the data file writes were significantly slowing down.<\/p>\n But what information is the LGWR writing into the control files? And when does that happen? I mean, when a session issues a commit, the LGWR normally writes only into the redo logs, like described in [Hoogland 2018]<\/a>.<\/p>\n I captured the LGWR call stacks during control files writes to figure out what’s triggering them:<\/p>\n 256 is the control file descriptor which can be queried with pfiles:<\/p>\n The following simple loop was used to create activity on the database:<\/p>\n Here’s the captured stack:<\/p>\n kcrfwl<\/i> is the most interesting function. Its annotation “kernel cache recovery file write\/broadcast SCN sWitch logs” (according to Frits Hoogland<\/a>‘s Oracle C functions annotations<\/a>) tells us that it’s invoked during a log switch. This information is sufficient to reproduce the behavior observed on the production database.<\/p>\n First, I’ll attach with gdb to the LGWR and set a conditional breakpoint when the process writes to the control file:<\/p>\n Next, I’ll initiate a log switch:<\/p>\n Finally, in another session, I’ll insert and commit a row:<\/p>\n Expectedly, the commit<\/i> doesn’t come back, because it’s waiting on the LGWR to complete:<\/p>\n The LGWR, in turn, is waiting on the “slow” control file write to finish. Of course, that “slow” write is simulated with the breakpoint, and it won’t finish until I resume the execution.<\/p>\n Also, ash_wait_chains.sql<\/a> confirms the fingerprint of the production issue:<\/p>\n Frankly, it wasn’t my first thought that slower control file writes might impair commit<\/i> performance. In fact, control files placement isn’t even considered in the white paper Configuring Oracle Solaris ZFS for an Oracle Database<\/a>. This document recommends to separate data and redo file in separate pools for performance, but it doesn’t even mention control files. Of course, after having had understood the impact, we separated control files from data files.<\/p>\n Further, this case study reminded me that the underlying issue might not be obvious by observing only the affected session. Therefore, we shouldn’t rush into implementing “solutions” before having really understood the problem. Thanks to Tanel<\/a> we have ash_wait_chains.sql<\/a> – a superb tool for identifying the main blocker who is sometimes hidden in a remote link of the wait chain.<\/p>\n Last but not least, once we’ve understood the dependencies, we can even go a step further and reproduce the problem with debugger, which is surely a great way of studying the internals and understanding undocumented subtleties of a proprietary software.<\/p>\n [Hoogland 2018]<\/a> Frits Hoogland<\/a>. (February 27, 2018). A look into Oracle redo, part 5: the log writer writing<\/p>\n","protected":false},"excerpt":{"rendered":" Analyzing slow commits with ash_wait_chains.sql, gdb and DTrace Continue Reading @ash_wait_chains.sql<\/a> program2||event2 1=1 \"to_date('04.09.2019 07:05:09','dd.mm.yyyy hh24:mi:ss')\" \"to_date('04.09.2019 07:06:09','dd.mm.yyyy hh24:mi:ss')\" \n\n-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http:\/\/blog.tanelpoder.com )\n%This SECONDS AAS\n------ ---------- ----------\nWAIT_CHAIN\n--------------------------------------------------------------------------------\n 46% 146 2.4\n-> (App.exe) log file sync -> (LGWR) control file parallel write<\/span>\n\n 19% 60 1\n-> (LGWR) control file parallel write\n\n...<\/code><\/pre>\ncontrol file parallel write<\/i><\/h1>\n
ps -ef | grep DMUR1 | grep lgwr\noracle 8098 7951 0 12:07:45 ? 0:37 ora_lgwr_DMUR1\n\nsudo -u root \/usr\/sbin\/dtrace -n '\npid$target::pwrite:entry \/ arg0 == 256 \/ { ustack(); }\n' -p 8098<\/code><\/pre>\npfiles 8098\n256: S_IFREG mode:0640 dev:275,69139 ino:10 uid:1000 gid:1000 size:25706496 (25MB)\n O_RDWR|O_DSYNC|O_LARGEFILE FD_CLOEXEC\n advisory write lock set by process 3626\n \/u00\/oracle\/oradata01\/DMUR1\/ctl\/ctl1DMUR1.dbf\n offset:0 \n257: S_IFREG mode:0640 dev:275,69168 ino:10 uid:1000 gid:1000 size:25706496 (25MB)\n O_RDWR|O_DSYNC|O_LARGEFILE FD_CLOEXEC\n advisory write lock set by process 3626\n \/u00\/oracle\/oradata02\/DMUR1\/ctl\/ctl2DMUR1.dbf\n offset:0 \n258: S_IFREG mode:0640 dev:275,69198 ino:10 uid:1000 gid:1000 size:25706496 (25MB)\n O_RDWR|O_DSYNC|O_LARGEFILE FD_CLOEXEC\n advisory write lock set by process 3626\n \/u00\/oracle\/oradata03\/DMUR1\/ctl\/ctl3DMUR1.dbf\n offset:0<\/code><\/pre>\ncreate table t ( c varchar2(4000) ) ;\n\nbegin\n for i in 1..1e6\n loop\n insert into t values (lpad('A',4000)) ;\n\tcommit ;\n end loop ;\nend ;\n\/<\/code><\/pre>\nlibc.so.1`pwrite\noracle`skgfqio+0x5e5\noracle`ksfd_skgfqio+0x22c\noracle`ksfdgo+0x1a7\noracle`ksfd_sbio+0xe12\noracle`ksfdbio+0x109c\noracle`ksfdbio+0x12fa\noracle`kccwbp+0x466\noracle`kccrec_wdf+0x1ab\noracle`kccfhb+0x2b\noracle`kcccmt+0xdd\noracle`kcrfnl+0x3e6\noracle`kcrfwl+0x3b0\noracle`ksb_act_run_int+0x6a\noracle`ksb_act_run+0xad\noracle`ksbabs+0x3c9\noracle`ksbrdp+0xa77\noracle`opirip+0x2c4\noracle`opidrv+0x24b\noracle`sou2o+0x97<\/code><\/pre>\nlog file sync<\/i><\/h1>\n
attach 8098\nb *pwrite if $rdi==256\nc<\/code><\/pre>\nalter system switch logfile ;<\/code><\/pre>\ninsert into t values (1);\ncommit ;<\/code><\/pre>\ncolumn sid format 999\ncolumn program format a30\ncolumn event format a30\ncolumn state format a10\n\nset linesize 200\n\nselect sid,program,event,state,seconds_in_wait from v$session \n where sid in (37,97) ;\n\n SID PROGRAM EVENT STATE SECONDS_IN_WAIT\n---- ------------------------------ ------------------------------ ---------- ---------------\n 37 sqlplus@svdbp01i (TNS V1-V3) log file sync WAITING 138\n 97 oracle@svdbp01i (LGWR) control file parallel write WAITING 228<\/code><\/pre>\n@ash_wait_chains program2||event2 session_id=37 sysdate-400 sysdate\n\n\n-- Display ASH Wait Chain Signatures script v0.4 BETA by Tanel Poder ( http:\/\/blog.tanelpoder.com )\n\n%This SECONDS AAS\n------ ---------- ----------\nWAIT_CHAIN\n--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------\nFIRST_SEEN LAST_SEEN\n------------------- -------------------\n 60% 418 0\n-> (sqlplus) log file sync -> (LGWR) control file parallel write<\/span>\n2019-09-05 15:29:09 2019-09-05 15:36:06<\/code><\/pre>\nConclusion<\/h1>\n
References<\/h1>\n