{"id":2967,"date":"2019-10-20T16:43:19","date_gmt":"2019-10-20T16:43:19","guid":{"rendered":"https:\/\/nenadnoveljic.com\/blog\/?p=2967"},"modified":"2019-10-20T16:43:21","modified_gmt":"2019-10-20T16:43:21","slug":"log-write-elapsed-time","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/log-write-elapsed-time\/","title":{"rendered":"Warning: log write elapsed time"},"content":{"rendered":"

Maybe you’ve already seen the following warning in the log writer (lgwr) trace file correlating with slow commits:<\/p>\n

Warning: log write elapsed time 738ms, size 20KB<\/code><\/pre>\n
Many articles found on the Internet claim that this is an indication of an IO bottleneck and recommend fixing it straight away. But that might be misleading, because the code instrumented by this trace entry comprises much more than an OS write call. I’m going to show here what exactly gets measured and how to precisely identify the underlying problem.<\/p>\n
While the low-level analysis is Solaris specific, the conclusions are OS independent.<\/p>\n
Firstly, the measured time interval starts in the Oracle C procedure kcrfw_redo_write_driver<\/i><\/span> which, in turn, calls the OS kernel function gethrtime<\/i><\/a> to get the current timestamp. Unsurprisingly, kcrfw_redo_write_driver<\/i><\/span> is the function that performs redo write [1]<\/a>.<\/p>\n
Secondly, kcrfw_postprocess_write<\/i><\/span>, which is executed after the redo buffer was written, retrieves the end timestamp and calculates the elapsed time.<\/p>\n
Finally, the same function writes the warning into the lgwr trace file if the operation lasted longer than 500 ms:<\/p>\n
#0  0x00007ffafd13d0c4 in write () from \/lib\/64\/libc.so.1\n#1  0x000000000b1910a2 in sdbgrfuwf_write_file ()\n#2  0x000000000b19100a in sdbgrfwf_write_file ()\n#3  0x000000000b174de0 in dbgtfdFileWrite ()\n#4  0x000000000b0e07e7 in dbgtfdFileAccessCbk ()\n#5  0x000000000b172665 in dbgtfWriteRec ()\n#6  0x000000001d6df55a in dbgtRecVAWriteDisk ()\n#7  0x000000000b170cd6 in dbgtTrcVaList_int ()\n#8  0x000000000b170226 in dbgtTrc_int ()\n#9  0x0000000015adb8f3 in dbktWriteTimestampWCdbInfo ()\n#10 0x000000000ac2d62c in kcrfw_postprocess_write<\/span> ()\n#11 0x000000000ac1bf1c in kcrfw_redo_write<\/span> ()\n#12 0x000000000af0462c in kcrfw_redo_write_driver ()\n#13 0x00000000194f3fea in ksb_act_run_int ()\n#14 0x00000000194f9ebd in ksb_act_run ()\n#15 0x000000000af0e263 in ksbcti ()\n#16 0x000000000af0263f in ksbabs ()\n#17 0x000000000af00bc7 in ksbrdp ()\n#18 0x000000000aaccf54 in opirip ()\n#19 0x0000000009d10a2b in opidrv ()\n#20 0x0000000009d10747 in sou2o ()\n#21 0x0000000009d1050f in opimai_real ()\n#22 0x0000000009d100a6 in ssthrdmain ()\n#23 0x0000000009d0fe17 in main ()<\/code><\/pre>\n
I wrote the following DTrace script to gain an insight into what’s instrumented by the trace file entry:<\/p>\n
\/*\n(c) 2019 Nenad Noveljic All Rights Reserved\n\nusage: dtrace -s log_write_elapsed.d -p PID\n*\/\n\n#pragma D option quiet\n\npid$target::kcrfw_redo_write_driver:entry\n{\n  self->entered_kcrfw_redo_write_driver = 1 ;\n}\n\npid$target::gethrtime*:return\n\/ self->entered_kcrfw_redo_write_driver \/\n{\n  self->log_write_started = arg1 ;\n  self->entered_kcrfw_redo_write_driver = 0 ;\n}\n\npid$target::kcrfw_postprocess_write:entry\n{\n  self->entered_kcrfw_postprocess_write = 1 ;\n}\n\npid$target::gethrtime*:return\n\/ self->entered_kcrfw_postprocess_write \/\n{\n  printf(\"log write elapsed [ms]: %d\\n\\n\", \\\n    ( arg1 - self->log_write_started ) \/ 1000000 ) ;\n  self->entered_kcrfw_postprocess_write = 0 ;\n  self->log_write_started = 0 ;\n}\n\npid$target::pwrite:entry\n\/ strstr(fds[arg0].fi_pathname,\"redo\") != 0 && self->log_write_started \/\n{\n  self->pwrite_start = timestamp ;\n}\n\npid$target::pwrite:return\n\/ self->pwrite_start \/\n{\n  printf(\"OS write elapsed [ms]: %d\\n\", \\\n    ( timestamp - self->pwrite_start ) \/ 1000000  ) ;\n  self->pwrite_start = 0 ;\n}\n\npid$target::kslgetl:entry\n\/ self->log_write_started \/\n{\n  printf(\"get latch: 0x%X %d 0x%X %d\\n\", arg0, arg1, arg2, arg3);\n}<\/code><\/pre>\n
This script independently measures the instrumented time by capturing the gethrtime<\/i> return values and calculating the difference. On top of that, it traces the latch allocations within the observed time period. It is tested on Oracle 18.7 \/ Solaris x64 11.4 and assumes synchronous IO (disk_asynch_io=FALSE<\/i>).<\/p>\n
Here’s a sample output:<\/p>\n
get latch: 0x6000B2B0 1 0x0 322\nget latch: 0x6000B2B0 1 0x0 322\nget latch: 0x6001EC40 1 0x0 2749\nget latch: 0x6001EC40 1 0x0 2749\nget latch: 0x969B61B0 1 0x0 3737\nget latch: 0x969B61B0 1 0x0 3737\nget latch: 0x969B6250 1 0x1 3737\nget latch: 0x969B6250 1 0x1 3737\nget latch: 0x969B62F0 1 0x2 3737\nget latch: 0x969B62F0 1 0x2 3737\nget latch: 0x969B6390 1 0x3 3737\nget latch: 0x969B6390 1 0x3 3737\nget latch: 0x969B6430 1 0x4 3737\nget latch: 0x969B6430 1 0x4 3737\nget latch: 0x969B64D0 1 0x5 3737\nget latch: 0x969B64D0 1 0x5 3737\nget latch: 0x969B6570 1 0x6 3737\nget latch: 0x969B6570 1 0x6 3737\nget latch: 0x6000B2B0 1 0xBE913438 321\nget latch: 0x6000B2B0 1 0xBE913438 321\nget latch: 0x6000B2B0 1 0x0 322\nget latch: 0x6000B2B0 1 0x0 322\nget latch: 0x6001EC40 1 0x0 2749\nget latch: 0x6001EC40 1 0x0 2749\nget latch: 0x969B61B0 1 0x0 3737\nget latch: 0x969B61B0 1 0x0 3737\nget latch: 0x969B6250 1 0x1 3737\nget latch: 0x969B6250 1 0x1 3737\nget latch: 0x969B62F0 1 0x2 3737\nget latch: 0x969B62F0 1 0x2 3737\nget latch: 0x969B6390 1 0x3 3737\nget latch: 0x969B6390 1 0x3 3737\nget latch: 0x969B6430 1 0x4 3737\nget latch: 0x969B6430 1 0x4 3737\nget latch: 0x969B64D0 1 0x5 3737\nget latch: 0x969B64D0 1 0x5 3737\nget latch: 0x969B6570 1 0x6 3737\nget latch: 0x969B6570 1 0x6 3737\nget latch: 0x60025EF8 1 0x0 3752 \nget latch: 0x60025EF8<\/span> 1 0x0 3752\nOS write elapsed [ms]: 3\nlog write elapsed [ms]: 3<\/span><\/code><\/pre>\n
We can observe two things. One is that, normally, the OS write is the largest contributor to the instrumented elapsed time. The other is, there are lots of latch allocations within the instrumented time period.<\/p>\n
In particular, one of the allocated latches is redo writing<\/i><\/span>:<\/p>\n
column name format a12\nselect name from v$latch where addr like '%60025EF8<\/span>%' ;\n\nNAME\n------------\nredo writing<\/span><\/code><\/pre>\n
Now it’s time for a little experiment (but not in production!) – I’ll allocate the redo writing<\/i><\/span> latch by directly calling the Oracle C function kslgetl<\/i> [2]<\/a> from another session before committing some changed data:<\/p>\n
oradebug setmypid\noradebug call kslgetl 0x60025EF8<\/span> 1 0x0 3752<\/code><\/pre>\n
Expectedly, the commit was hanging, because it was waiting on the redo writing latch, and it completed immediately after terminating the latch holder session.<\/p>\n
The DTrace script produced the following output:<\/p>\n
$dtrace -s log_write_elapsed.d -p 4198\n\nOS write elapsed [ms]: 13\nOS write elapsed [ms]: 5\nOS write elapsed [ms]: 2\nlog write elapsed [ms]: 12872<\/span><\/code><\/pre>\n
As you can see, the measured time is now significantly longer than the time it took for the IO operation to complete.<\/p>\n
The trace file entry matches the time measured by the DTrace script:<\/p>\n
*** 2019-10-07T08:15:33.531014+02:00\nWarning: log write elapsed time 12872ms<\/span>, size 20KB<\/code><\/pre>\n
That was the proof that a slow IO isn’t the only possible cause for this warning.<\/p>\n
Anyway, if you notice this message, you can use Tanel Poder’s ash_wait_chains.sql<\/a> to see if the log writer was waiting on something – before compulsively addressing an “IO issue”:<\/p>\n
@ash_wait_chains.sql<\/a> program2||event2 session_id=148 \"to_date('07.10.2019 08:15:21','dd.mm.yyyy hh24:mi:ss')\" \"to_date('07.10.2019 08:15:34','dd.mm.yyyy hh24:mi:ss')\"\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 100%          12         .9\n-> (sqlplus) log file sync  -> (LGWR) latch: redo writing  -> [idle blocker<\/span>\n1,253<\/span>,8655]\n2019-10-07 08:15:21 2019-10-07 08:15:32<\/code><\/pre>\n
The output above shows us that the log writer was waiting on the redo writing latch which was held by the session 253<\/span> – the session that issued the kslgetl<\/i> call. Notice that this session is correctly annotated as an “idle blocker<\/span>“, as it didn’t do anything after allocating the latch, and, consequently, didn’t produce any samples in v$active_session_history<\/i>.<\/p>\n
In conclusion, the code instrumented by the log writer trace file entry entails not only the the OS write call, but also the latch handling. Therefore, triage is the first thing to do after spotting longer redo writes in the lgwr trace: was it an IO bottleneck or, perhaps, some wait chain? You can crosscheck the former with OS utilities and\/or log file parallel write<\/i> waits. The latter you can investigate with ash_wait_chains.sql<\/a>. In any case, there isn’t any room left for guesswork and speculation.<\/p>\n
References:<\/p>\n