A while ago I wrote about rediculous log writer waits I have encountered. It turned out to have to do something with caching issues in our storage virtualization implementation. Unfortunately I don’t know the exact details. Storage has still secrets to me. However, our storage guys have been working hard to come up with a solution. Meanwhile I want to keep monitoring the log writer trace (you’ll find that in $ORACLE_BASE/diag/rdbms/$gdbname/$ORACLE_SID/trace. You’ll have to come up with the values of the global dbname and the instance name of course).
I want to go from this:
*** 2013-11-20 22:00:16.995 Warning: log write elapsed time 1382ms, size 3KB *** 2013-11-20 22:02:12.372 Warning: log write elapsed time 795ms, size 0KB *** 2013-11-20 22:03:03.507 Warning: log write elapsed time 997ms, size 8KB
So I’ve been hacking in shell and I think I’ve almost got it. Here is a statement that managed to translate a log writer trace file to a CSV file:
grep "Warning: log write elapsed time" /u01/app/oracle/diag/rdbms/$gdbname/$ORACLE_SID/trace/ORCL11_lgwr_12345.trc -B1| sed 's/\r$//' |grep -v "\-\-" | sed 's/\*\*\* //' | xargs -L 2 | sed 's/ Warning: log write elapsed time/,/' | sed 's/ms//' | sed 's/size//' | sed 's/KB//' |cut -c -19,24-
And voila, I have something I can put in Excel:
2013-11-18 01:00:07, 694, 2562 2013-11-18 16:08:29, 539, 5 2013-11-18 17:08:40, 676, 1 2013-11-19 14:12:31, 811, 61 2013-11-19 14:12:43, 511, 334 2013-11-19 22:06:48, 2129, 0 2013-11-20 12:08:23, 627, 19 2013-11-20 13:08:42, 571, 6 2013-11-21 07:22:39, 4262, 0 2013-11-21 07:27:43, 1006, 3 2013-11-21 07:27:45, 528, 0
I’ll admit the shell code ugly and it still has one bug. Oracle breaks the log writer trace just somewhere in the middle to start a new one. So more often than you’d think the trace starts with the warning without the preceding timestamp. For now, I solve that with a different statement:
grep "Warning: log write elapsed time" /u01/app/oracle/diag/rdbms/$gdbname/$ORACLE_SID/trace/ORCL12_lgwr_5432.trc -B1| sed 's/\r$//' |grep -v "\-\-" | sed 's/\*\*\* //'| tail -n +3| sed 's/Warning: log write elapsed time/,/' | sed 's/ms//' | sed 's/size//' | sed 's/KB//' | xargs -L 2|cut -c -19,24-
Now I can cough up the data I need for log writer performance investigations in a minute. It’s a great deal faster than my previous method: editing a grepped version of the log writer trace in UltraEdit. I’m pretty happy about this.