Re: Very high 'log file sync' wait time with no 'log file parallel write' wait time

mccmx_at_hotmail.com wrote:
> Oracle 10.2.0.2 SE on Windows 2003 SP1
>
> The following trace file section is from a very slow import session
> which is importing 9 Million rows into the database.
>
> COMMIT
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 0 0.00 0.00 0 0 0
> 0
> Execute 179802 4.90 474.73 0 0 0
> 0
> Fetch 0 0.00 0.00 0 0 0
> 0
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 179802 4.90 474.73 0 0 0
> 0
>
> Misses in library cache during parse: 0
> Parsing user id: 21 (recursive depth: 1)
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> log file sync 179077 0.53
> 468.19
>
> ********************************************************************************
> ***Snipped***
> ********************************************************************************
>
> OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 0 0.00 0.00 0 0 0
> 0
> Execute 17 14.64 81.21 1 6176 210055
> 184773
> Fetch 0 0.00 0.00 0 0 0
> 0
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 17 14.64 81.21 1 6176 210055
> 184773
>
> Misses in library cache during parse: 0
> Misses in library cache during execute: 1
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> log file sync 18 0.00
> 0.02
> SQL*Net more data from client 20641 0.00
> 0.34
> SQL*Net message to client 32 0.00
> 0.00
> SQL*Net message from client 32 3.75
> 17.60
> log file switch completion 1 0.10
> 0.10
>
>
> OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 15 0.01 0.00 0 0 1
> 0
> Execute 179817 4.90 474.74 0 40 10
> 10
> Fetch 15 0.00 0.00 0 25 0
> 10
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 179847 4.92 474.74 0 65 11
> 20
>
> Misses in library cache during parse: 3
> Misses in library cache during execute: 3
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> log file sync 179075 0.53
> 468.19
>
> I am using the following options for import:
>
> imp sysadm/<pwd> file=D:\temp\SAND_RPTD.DMP
> log=D:\temp\IMP_SAND_RPTD.log tables=(PS_TL_RPTD_TIME) buffer=20000000
> ignore=y statistics=none commit=y indexes=y
>
> the import session is committing approximately every 10,000 rows (I can
> confirm this by doing a count(*) from the table)
>
> I am seeing approximately one 'log file sync' wait for every row
> inserted into the table:
>
> SQL> select total_waits from v$session_event where event = 'log file
> sync'
> 2 and sid=94
> 3 union select count(*) from ps_tl_rptd_time
> 4 ;
>
> TOTAL_WAITS
> -----------
> 4891689
> 4901919
>
> but we have had no significant waits for 'log file parallel write'
> since instance startup.
>
> What is causing this huge amount of 'log file sync' activity..? The
> 10046 trace file seems to suggest that we are committing for every row
> in the table but the count(*) is increasing in line with the 'buffer'
> parameter from the import command.
>
> Is this a bug..?
>
>
> Matt

Are your logs on different mounts? Are you on RAID-5. Is it Direct Path, looks like not.
I hope you don't have your windows page file on the same volume as the redo. Received on Tue Nov 28 2006 - 08:21:38 CST