High fsync() times to VRTSvxfs Files can be reduced using Solaris VMODSORT Feature

(Doc ID 842718.1)

Last updated on MARCH 08, 2017

Applies to:

Oracle Server - Enterprise Edition - Version: 8.1.7.0 to 11.1.0.7 - Release: 8.1.7 to 11.1
Oracle Solaris on x86 (32-bit)
Oracle Solaris on SPARC (64-bit)
Oracle Solaris on x86-64 (64-bit)
Oracle Solaris on SPARC (32-bit)
Sun Solaris x86 (32-bit)Sun Solaris SPARC (64-bit)Sun Solaris x86-64 (64-bit)Sun Solaris SPARC (32-bit)
Solaris 9 and 10
Veritas VXFS 4.1 and 5.0 not using VRTSodm
RDBMS 8.1.7 - 11.2.0
RDBMS utilities such as import, datapump (impdp)

Symptoms

When RDBMS processes perform cached writes to files (i.e. writes which are not issued by DBWR)
such as to a LOB object which is

then increased processing times can be experienced which are due to longer fsync() call times to flush the dirty pages to disk. 

Changes

Performing (datapump) imports or writes to LOB segments and

1. running "truss -faedDl -p " for the shadow or background process doing the writes
    shows long times spent in fsync() call.

Example:

create table lobtab(n number not null, c clob);

-- insert.sql
declare
mylob varchar2(4000);
begin
for i in 1..10 loop
mylob := RPAD('X', 3999, 'Z');
insert into lobtab values (i , rawtohex(mylob));
end loop;
end;
/

truss -faedDl sqlplus user/passwd @insert

shows 10 fsync() calls being executed possibly having high elapsed times:

25829/1: 1.3725 0.0121 fdsync(257, FSYNC) = 0
25829/1: 1.4062 0.0011 fdsync(257, FSYNC) = 0
25829/1: 1.4112 0.0008 fdsync(257, FSYNC) = 0
25829/1: 1.4164 0.0010 fdsync(257, FSYNC) = 0
25829/1: 1.4213 0.0008 fdsync(257, FSYNC) = 0
25829/1: 1.4508 0.0008 fdsync(257, FSYNC) = 0
25829/1: 1.4766 0.0207 fdsync(257, FSYNC) = 0
25829/1: 1.4821 0.0006 fdsync(257, FSYNC) = 0
25829/1: 1.4931 0.0063 fdsync(257, FSYNC) = 0
25829/1: 1.4985 0.0007 fdsync(257, FSYNC) = 0
25829/1: 1.5406 0.0002 fdsync(257, FSYNC) = 0



2. Solaris lockstat command showing frequent hold events for fsync internal functions:


Example:

Adaptive mutex hold: 432933 events in 7.742 seconds (55922 events/sec) 
------------------------------------------------------------------------
Count indv cuml rcnt nsec Lock Hottest Caller
15052 48% 48% 0.00 385437 vph_mutex[32784] pvn_vplist_dirty+0x368
nsec   ------ Time Distribution ------ count Stack
8192   |@@@                            1634 vx_putpage_dirty+0xf0
16384  |                               187 vx_do_putpage+0xac
32768  |                               10 vx_fsync+0x2a4
65536  |@@@@@@@@@@@@@@@@@@@@@@         12884 fop_fsync+0x14
131072 |                               255 fdsync+0x20
262144 |                               30 syscall_trap+0xac


  

3. AWR report would show increased CPU activity (SYS_TIME is unusual high in Operating System Statistics section).

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms