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

From: <mccmx_at_hotmail.com>
Date: 24 Nov 2006 05:52:25 -0800
Message-ID: <1164376345.649599.113830@h54g2000cwb.googlegroups.com>

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 Received on Fri Nov 24 2006 - 07:52:25 CST