Skip to Content

Introduction

A long time has gone since my last blog post on SCN in March 2014, but i was quite busy with Oracle RAC implementations and troubleshooting performance issues in the last month. It was a quite interesting time for me and i have learned a lot of new stuff about Oracle 12c and so in consequence this is just a tiny blog post about a new diagnostic event called “wait_event[]”, which was introduced with Oracle 12c R1 (12.1.0.1). Oracle has re-engineered its kernel diagnostics & tracing infrastructure with Oracle 11g, which allows you to be much more detailed and extensive by tracing and dumping diagnostic / low level (internals) information. Please check the reference section for more detailed information about that “new” kernel diagnostics & tracing infrastructure, if you have never heard of it until yet.

Luckily Oracle has extended this infrastructure with several new events in Oracle 12c, which helped me to troubleshoot a “log file sync” issue a few weeks ago on Oracle 12c R1 (12.1.0.1). Basically said an user session sporadically waited on “log file sync” for a “long” time, even if the “log file parallel write” time was fast as always and no obvious contention, handling or load on “log buffer” (described very simplistic).

I tried to get a call stack trace only for this wait event in a separate (load simulation and testing) session as the issue occurs very sporadic and it should not harm the standard application. You usually use OS tools like DTrace on Solaris or oradebug on Oracle level, but it is very hard to capture this kind of issue (especially as the platform was Linux and not Solaris) as it only happens very rare and it is specific to one wait condition. The idea behind the whole effort was to get an idea and figure out, if Oracle runs a different code path when this issue occurs.

New diagnostic events in Oracle 12c

Let’s cross-check the new diagnostic event capabilities with Oracle 12c first.

Oracle 11g (11.2.0.3.6)

Oracle_11g.png

Oracle 12c (12.1.0.1)

Oracle_12c.png

In sum Oracle has extended the infrastructure with 18 new events and you will notice a new event called “wait_event[]” in the RDBMS library with a description “event to control wait event post-wakeup actions”. This sounds exactly like something that i was looking for.

However the syntax was a bit tricky (or i was just too impatient) and so i got the details from a good Oracle colleague.


SQL> alter session set events 'wait_event["<wait event name>"]  trace("%s\n", shortstack())';














So here is just a short example of this tracing capability and its output with Oracle 12.1.0.1 on OEL 6.4 (2.6.39-400.109.1) and Virtualbox 4.2.12.


SQL> alter session set events 'wait_event["log file sync"]  trace("%s\n", shortstack())';
SQL> insert into t values (11);
SQL> commit;
SQL> insert into t values (12);
SQL> commit;
SQL> insert into t values (13);
SQL> commit;














… and the trace file (in diagnostic_dest) looks like this for example:


2014-10-26 10:50:38.773
kslwtectx<-kcrf_commit_force_int<-kcbdsy<-ksupop<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_mains
*** 2014-10-26 10:50:44.905
kslwtectx<-kcrf_commit_force_int<-kcbdsy<-ksupop<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_mains
*** 2014-10-26 10:51:47.633
kslwtectx<-kcrf_commit_force_int<-kcbdsy<-ksupop<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_mains














You also can enable SQL trace (e.g. with waits only) to get the connection between each “log file sync” wait time and the call stack trace as the short stack dump is a post-wakeup action and called after the wait has finished.

It looks like this, if you combine both capabilities.


SQL> alter session set events 'wait_event["log file sync"]  trace("%s\n", shortstack())';
SQL> exec DBMS_MONITOR.SESSION_TRACE_ENABLE(waits => true, binds => false, plan_stat => 'NEVER');
SQL> insert into t values (14);
SQL> commit;
SQL> insert into t values (15);
SQL> commit;














… and the trace file (in diagnostic_dest) looks like this for example:


…
WAIT #139662026595296: nam='log file sync' ela= 1574 buffer#=3316 sync scn=1023722 p3=0 obj#=-1 tim=3813212804
kslwtectx<-kcrf_commit_force_int<-kcbdsy<-ksupop<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_mains
…
*** 2014-10-26 10:56:50.841
…
WAIT #139662026595296: nam='log file sync' ela= 732 buffer#=3318 sync scn=1023724 p3=0 obj#=-1 tim=3816960681
kslwtectx<-kcrf_commit_force_int<-kcbdsy<-ksupop<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_mains
…














I hope you get the main idea behind this new capability and its range of application, even if you will not need it regularly by troubleshooting Oracle database issues.

If you have any further questions – please feel free to ask or get in contact directly, if you need assistance by troubleshooting Oracle database (performance) issues.

References

To report this post you need to login first.

Be the first to leave a comment

You must be Logged on to comment or reply to a post.

Leave a Reply