2

I've and Oracle (11 Enterprise) schema with a table

 CREATE TABLE USER.WSP_BUNDLE ( 
    NODE_ID     RAW(16) NOT NULL,
    BUNDLE_DATA BLOB NOT NULL 
    );
CREATE UNIQUE INDEX USER.WSP_BUNDLE_IDX ON USER.WSP_BUNDLE(NODE_ID);

and 3'rd party library (Java 6, JDBC - latest jdbc driver) that manipulate it.

Oracle profiler (tkprof) shows that about 50% of overall time the lib execute such statement:

update WSP_BUNDLE set BUNDLE_DATA = :1 where NODE_ID = :2

TKProf data

Plan Hash: 4085453680
update WSP_BUNDLE set BUNDLE_DATA = :1  where NODE_ID = :2 


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      264      0.00       0.00          0          0          0           0
Execute    400     30.59     382.88     141451    1623163    3233827         400
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      664     30.59     382.88     141451    1623163    3233827         400

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 87  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  WSP_BUNDLE (cr=8753 pr=707 pw=706 time=0 us)
      1   INDEX UNIQUE SCAN WSP_BUNDLE_IDX (cr=3 pr=0 pw=0 time=0 us cost=2 size=104 card=1)(object id 75730)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                    141251        5.53        328.04
  direct path write                             402        0.09          0.43
  SQL*Net more data from client              142158        1.04         11.89
  direct path read                              200        0.03          0.07
  Disk file operations I/O                        1        0.00          0.00
  SQL*Net message to client                     400        0.00          0.00
  SQL*Net message from client                   400        0.29          0.50
  log file switch (private strand flush incomplete)
                                                  5        0.05          0.23
  asynch descriptor resize                   139723        7.46          8.57
  buffer busy waits                               2        0.00          0.00
  log file switch (checkpoint incomplete)         3        0.18          0.27
  log file sync                                   2        0.00          0.00

Could anybody explain/hint me what's going on? Why the update is so slow?

The table WSP_BUNDLE contains about 200+k rows. At the same time I've other tables in the same schema with blobs (CLOB to be more concrete) that contains 600+k rows where similar updates work correctly.

FoxyBOA
  • 417
  • 1
  • 6
  • 12
  • Depends what you find to be appropriate, I suppose. – Tom O'Connor Dec 30 '11 at 08:41
  • I don't understand why the request is so slow. It consumes about 50% of overall job time. And at the same time I can't find what's goes wrong. Similar updates on other table works very quickly. – FoxyBOA Dec 30 '11 at 10:17
  • What's the underlying server hardware like? What's the iowait like? How is the database laid out on the disks? – Tom O'Connor Dec 30 '11 at 11:01
  • Hardware/OS: dedicated server 16GB RAM, i7 3.4Ghz, SATA3 HDD, Windows 2008R2. How could I check iowait? What do you mean by "How is the database laid out on the disks"? I'm not an Oracle DBA, I'm from Java world :) – FoxyBOA Dec 30 '11 at 12:05
  • IOWait refers to the amount of time when the CPU is "locked", waiting for the IO subsystem to return data. http://www.computerperformance.co.uk/HealthCheck/Disk_Health.htm#Disk%20Bottleneck%202 for more info on that – Tom O'Connor Dec 30 '11 at 12:27
  • As far as "how is the database layed out on the disk". If you have one disk, then you could expect IO bottlenecks when the disk is both reading sequentially / writing sequentially, and writing randomly. This is because the disk could have to seek a long distance to get back to where it was. So, how many disks do you have, and what type/speed are they? – Tom O'Connor Dec 30 '11 at 12:28
  • We have one Western Digital Caviar Black 1TB 7200rpm 64MB WD1002FAEX 7200 RPM SATA 3. – FoxyBOA Dec 30 '11 at 13:08

1 Answers1

3

In Oracle, LOB (including BLOB) is stored as:

  • in-the-table LOB - if the LOB is smaller than 3900 bytes it can be stored inside the table row; by default this is enabled, unless you specify DISABLE STORAGE IN ROW
  • normal LOB - stored in a separate segment, outside of table, you may even put it in another tablespace; for these:
    • a minimum of CHUNK bytes are allocated and entirely redo-logged (even if LOB has only 1 byte)
    • there is an internal intermediate index behind a LOB column, which gets contentious on updates and may practically serialize them
    • access is multi-level and thus relatively slower
    • with NOCACHE option, the waiters are "direct path read" - the default
    • with CACHE option, the waiters are "db file sequential read"
      • where CACHE_SIZE_THRESHOLD is not taken into account, so a large LOB can waste your cache

Therefore, if your LOBs are larger than 4 kB they will get relatively slow, and this may simply be your case. I would examine the sizes.

I would examine USER_LOBS (or DBA_LOBS) to see how the "good" and "slow" LOB columns differ in their definitions.

The Metalink note ID 66431.1 describes this and may be of interest to you, if you have access there.

UPDATE: Fascinated by the seemingly unexplainable wild amount of "db file sequential read", I did a little bit of searching, and found out that strange things can happen with the lob index after mass DELETEs. Just a guess, but looks very similar to your case. If this is it, I would rebuild the lob column entirely. (Moving a lob column might also rebuild the lob index - I'm not sure).

kubanczyk
  • 13,502
  • 5
  • 40
  • 55