Why my job is safe

I spent the last couple of days with coding a new registration module for a private website that I administrate. The requirements were the very basic ones:

  • Make an HTML form
  • Validate the inputs
  • Send a confirmation email with a link
  • On link activation: Retrieve the data and write it into a table in the database

As those requirements are common in so many registration forms all over the web, I thought: Before coding something again, just have a look at Google and see if  you can find something useful to embed. And I found stuff, lots of stuff but surprisingly every example I found did the following:

  • HTML form
  • Write data into the table with an “active” column set to false
  • Send a confirmation email with an link with an unique identifier for the inserted row (most times a md5 hash value)
  • On link activation: Retrieve the unique identifier
  • Update the row in the database with active flag set to true

And, at least some examples, took also care about the house keeping and cleaned the inactive rows from time to time.

Well, this does the job of course but the way how it does it is simply dirty – very dirty!

From the functional aspect there are following issues:

  • Every SQL statement for retrieving the active data has to make sure to include ” AND active = TRUE” in the WHERE clause
  • If an user is unlucky, the cleanup process removes his data before he can click the activation link if the process doesn’t implement a time range

From the performance side however:

All I want to do is:

  • Validate the data from the form
  • Save it temporarily until the link is clicked or the data gets expired
  • Write it into the database

With those solutions found on the internet however I would have done following:

  • Validate the data
  • Write it into the database (with an column extension for an active flag)
  • Retrieve the data again and update it to set it active
  • Create a cleanup job to purge inactive data
  • Extend all my SQLs against that table with a “AND active = TRUE” WHERE clause

So I have more steps, more unnecessary hops to the database, probably maintain another index over time for the cleanup job. Sometimes I wonder why programmers don’t think first before the code. Of course many roads lead to Rome but that doesn’t mean that you should just take a random one. But as long as there are programmers out there who don’t think or don’t think hard enough there will be always performance problems and people like me needed to solve them. So I guess I shouldn’t complain but my dream of the perfect IT world is still alive…

Well, the webpage in my case is made in PHP which has one nice feature called: Sessions
That does the job perfectly fine and most important: Clean! It is enabled by default, allows you to store data within a session and includes also an expire functionality which is also enabled by default. It supports two ways of storing the session id: Either within a cookie in the browser (enabled by default) or you can also pass the session id over POST and GET requests. As I use a confirmation email to activate the registration I just had to make sure to deactivate the cookie storage feature first as I pass the session id over a link/GET request. I wouldn’t have to deactivate the cookie storage from a functional point of view as the cookie would be just never read again and would expire some time but from security and the “do it right” aspect this has to be deactivated. So all I did was following:

// Disable cookie storage
ini_set("session.use_cookies",0);
// Start the session
session_start();

// Save the data within the session
$_SESSION["Title"] = $Title;
$_SESSION["FirstName"] = $FistName;
$_SESSION["LastName"] = $LastName;

//Send the email with the activation link
if (mail($Email, "Please activate your registration", "http://www.mywebsite.com/activate.php?sid=".htmlspecialchars (session_id()))
{
 // If sending the mail was successful, store all session data and close the session
 session_write_close();
}
else
{
 // If sending the mail failed, report an error, delete the session data and destroy the session!
 // Error reporting....
 session_unset();
 session_destroy();
}

And all the activation.php file does, is:


// Disable cookie storage
ini_set("session.use_cookies",0);
// Set the session id from GET request
session_id($_GET["sid"]);
// Start session
session_start();
// Get variables
$Title = $_SESSION["Title"];
$FistName = $_SESSION["FirstName"];
$LastName = $_SESSION["LastName"];

// Connect to database
$hDB = @mysql_connect("localhost", "user","password");
mysql_select_db("myDB", $hDB);

// Insert data into database
if (mysql_query("INSERT INTO table (Title, FirstName, LastName) VALUES ('".mysql_real_escape_string($Title)."','".mysql_real_escape_string($FirstName)."','".mysql_real_escape_string($LastName)."'")
{
 // Destroy session
 session_unset();
 session_destroy();
}

The big picture

A couple of weeks ago a customer had some troubles with the overall performance. He complained that everything is slow and (of course) nothing changed since the last few weeks. They also immediately blamed the database on their side to be the issue. The usual stuff also, I’m sure that sounds just too familiar to you.

So as they “identified” the database already as being the issue my team requested some AWR reports and as we got them I noticed a strange but all to common behavior. My team mates got the AWR reports, went to the SQL Statistics, sections “SQL ordered by Elapsed Time” and “SQL ordered by CPU Time” and identified immediately a materialized view rebuild as cause for the problem. That looked like this:

SQL ordered by Elapsed Time

  • Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
  • % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
1,343 679 1 1342.85 33.00 f20ccnxhvbk65 DECLARE job BINARY_INTEGER := …
770 323 1 770.24 18.93 1usnr4gmcq60d /* MV_REFRESH (DEL) */ delete …
571 355 1 571.23 14.04 gz04689vd55db /* MV_REFRESH (INS) */INSERT /…
311 311 1 310.91 7.64 0vhmfumrjchnh SQL*Plus BEGIN dm_incr_symbols_post_pro…
288 9 0 7.09 bb3f2gjndvjss oracle@crptd1 (TNS V1-V3) SELECT /*+ OPAQUE_TRANSFORM */…
258 258 1 257.76 6.34 75vtwb7j4jzdm SQL*Plus INSERT INTO SYMB_EXTRACTT SELE…
149 121 1 148.80 3.66 90wtn50vy6af6 DECLARE job BINARY_INTEGER := …
114 103 1 113.75 2.80 9993mp6h7kqkp INSERT /*+ BYPASS_RECURSIVE_CH…
48 38 2 24.00 1.18 3nkcg1h5ysqss DECLARE job BINARY_INTEGER := …
48 38 2 23.98 1.18 fvb5prrr7b0c3 MERGE INTO FT_E_UPS1 UPS1 USIN…

Back to SQL Statistics
Back to Top

SQL ordered by CPU Time

  • Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
  • % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
CPU Time (s) Elapsed Time (s) Executions CPU per Exec (s) % Total DB Time SQL Id SQL Module SQL Text
679 1,343 1 679.06 33.00 f20ccnxhvbk65 DECLARE job BINARY_INTEGER := …
355 571 1 355.50 14.04 gz04689vd55db /* MV_REFRESH (INS) */INSERT /…
323 770 1 323.18 18.93 1usnr4gmcq60d /* MV_REFRESH (DEL) */ delete …
311 311 1 310.89 7.64 0vhmfumrjchnh SQL*Plus BEGIN dm_incr_symbols_post_pro…
258 258 1 257.74 6.34 75vtwb7j4jzdm SQL*Plus INSERT INTO SYMB_EXTRACTT SELE…
121 149 1 121.05 3.66 90wtn50vy6af6 DECLARE job BINARY_INTEGER := …
103 114 1 102.58 2.80 9993mp6h7kqkp INSERT /*+ BYPASS_RECURSIVE_CH…
38 48 2 19.20 1.18 3nkcg1h5ysqss DECLARE job BINARY_INTEGER := …
38 48 2 19.20 1.18 fvb5prrr7b0c3 MERGE INTO FT_E_UPS1 UPS1 USIN…
29 29 12 2.38 0.70 68930z34bm3db SQL*Plus select ‘file[‘ || substr(trim(…
9 288 0 7.09 bb3f2gjndvjss oracle@dftg1 (TNS V1-V3) SELECT /*+ OPAQUE_TRANSFORM */…

So here we have a PL/SQL job which does the materialized view refresh (first line) and the statements for the refresh itself as second and third line. For completeness here the first statement:


DECLARE
 job BINARY_INTEGER := :job;
 next_date DATE := :mydate;
 broken BOOLEAN := FALSE;
BEGIN
 dbms_refresh.refresh('"ABTGHS"."DB_CREAT_STST_PWOR"');
 :mydate := next_date;
 IF broken THEN
 :b := 1;
 ELSE
 :b := 0;
 END IF;
END;

So all what they did was to go there, look the first SQL with high elapsed and cpu time and nearly reported back to them that this is the problem and they have to solve this. I call this the “lucky shot method”. Sometimes when you are lucky than the reason for the issue on the DB is a bad SQL or a bunch of bad SQLs which max out the DB on CPU power, or I/O or whatever. In such a case you just go to those sections, identify the SQLs, fix them and everything is good again – you were lucky. This works sometimes and you are a hero because it took you just 5 minutes for fixing the issue but sometimes it doesn’t and you blame it on some weird constellation of OS, network and something else so that nobody recognizes that you are just a fool and didn’t look at the big picture. Thinking of that I noticed that this is just far too common in IT. Tech admins, DBA, developers – in every section you have people like this. Looking 5 minutes into the issue and telling you then that this and that is the issue. You go ahead and fix them but still no change. So next round trip, and next, and next, and next. All could have been prevented if the person had just once a look into the big picture…

So what is the big picture, what do I mean by that?

I’m a fan of knowing what happens and why. Always analyze all the information you got, even request some more if you think that some vital information is missing and make your conclusions out of that. Stop the try and error method, the lucky shot method. The AWR report I got from the customer is an all too good example. There were 2 simple lines which made me curious:

Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 17934 05-May-10 09:00:59 129 144.1
End Snap: 17935 05-May-10 10:00:12 130 143.0
Elapsed: 59.21 (mins)
DB Time: 67.81 (mins)

I’m talking about the last two. The first tells me that the snapshot which got compared are in a time range of 59.21 minutes. The DB time, so the time when the DB was actually working was 67.81 minutes. So something looks strange here. If I would be in a single core environment I wouldn’t be over my 59.21. If I would be in a dual-core environment then the database was just working 57% of the time (59.21 x 2 cores = 118.42 – DB time multiplies by the amount of cores where work was performed parallel). Next I had a look into the locks going on. If you have high locking then the DB time is also idle but the throughput is low. But it turned that this was also no issue. The next information confirmed then that the DB wasn’t the problem at all:

Operating System Statistics

Statistic Total
AVG_BUSY_TIME 33,088
AVG_IDLE_TIME 321,941

The average idle time statistic is much higher than the busy time. So I requested the amount of cores on that system and it turned out that there are 14 available. A busy database would have a DB time of max. 828.94 minutes. No locking going on. I followed up with them and it turned out as I thought: The database wasn’t the problem at all. In fact it was pretty much idle over the whole time. The issue was on the application side. A java application which memory got filled up so that it had to do full garbage collection all the time to continue processing.

Instead of doing the lucky shot we prevented us and them from a lot of headache by looking into the big picture.

Oracle 10g enqueue waits

Just found a useful list of Oracle 10g enqueue waits in the web which I don’t want to deprive from you:

Enqueue Type Description
enq: AD – allocate AU Synchronizes accesses to a specific OSM (Oracle Software Manager) disk AU
enq: AD – deallocate AU Synchronizes accesses to a specific OSM disk AU
enq: AF – task serialization Serializes access to an advisor task
enq: AG – contention Synchronizes generation use of a particular workspace
enq: AO – contention Synchronizes access to objects and scalar variables
enq: AS – contention Synchronizes new service activation
enq: AT – contention Serializes alter tablespace operations
enq: AW – AW$ table lock Allows global access synchronization to the AW$ table (analytical workplace tables used in OLAP option)
enq: AW – AW generation lock Gives in-use generation state for a particular workspace
enq: AW – user access for AW Synchronizes user accesses to a particular workspace
enq: AW – AW state lock Row lock synchronization for the AW$ table
enq: BR – file shrink Lock held to prevent file from decreasing in physical size during RMAN backup
enq: BR – proxy-copy Lock held to allow cleanup from backup mode during an RMAN proxy-copy backup
enq: CF – contention Synchronizes accesses to the controlfile
enq: CI – contention Coordinates cross-instance function invocations
enq: CL – drop label Synchronizes accesses to label cache when dropping a label
enq: CL – compare labels Synchronizes accesses to label cache for label comparison
enq: CM – gate Serializes access to instance enqueue
enq: CM – instance Indicates OSM disk group is mounted
enq: CT – global space management Lock held during change tracking space management operations that affect the entire change tracking file
enq: CT – state Lock held while enabling or disabling change tracking to ensure that it is enabled or disabled by only one user at a time
enq: CT – state change gate 2 Lock held while enabling or disabling change tracking in RAC
enq: CT – reading Lock held to ensure that change tracking data remains in existence until a reader is done with it
enq: CT – CTWR process start/stop Lock held to ensure that only one CTWR (Change Tracking Writer, which tracks block changes and is initiated by the alter database enable block change tracking command) process is started in a single instance
enq: CT – state change gate 1 Lock held while enabling or disabling change tracking in RAC
enq: CT – change stream ownership Lock held by one instance while change tracking is enabled to guarantee access to thread-specific resources
enq: CT – local space management Lock held during change tracking space management operations that affect just the data for one thread
enq: CU – contention Recovers cursors in case of death while compiling
enq: DB – contention Synchronizes modification of database wide supplemental logging attributes
enq: DD – contention Synchronizes local accesses to ASM (Automatic Storage Management) disk groups
enq: DF – contention Enqueue held by foreground or DBWR when a datafile is brought online in RAC
enq: DG – contention Synchronizes accesses to ASM disk groups
enq: DL – contention Lock to prevent index DDL during direct load
enq: DM – contention Enqueue held by foreground or DBWR to synchronize database mount/open with other operations
enq: DN – contention Serializes group number generations
enq: DP – contention Synchronizes access to LDAP parameters
enq: DR – contention Serializes the active distributed recovery operation
enq: DS – contention Prevents a database suspend during LMON reconfiguration
enq: DT – contention Serializes changing the default temporary table space and user creation
enq: DV – contention Synchronizes access to lower-version Diana (PL/SQL intermediate representation)
enq: DX – contention Serializes tightly coupled distributed transaction branches
enq: FA – access file Synchronizes accesses to open ASM files
enq: FB – contention Ensures that only one process can format data blocks in auto segment space managed tablespaces
enq: FC – open an ACD thread LGWR opens an ACD thread
enq: FC – recover an ACD thread SMON recovers an ACD thread
enq: FD – Marker generation Synchronization
enq: FD – Flashback coordinator Synchronization
enq: FD – Tablespace flashback on/off Synchronization
enq: FD – Flashback on/off Synchronization
enq: FG – serialize ACD relocate Only 1 process in the cluster may do ACD relocation in a disk group
enq: FG – LGWR redo generation enq race Resolves race condition to acquire Disk Group Redo Generation Enqueue
enq: FG – FG redo generation enq race Resolves race condition to acquire Disk Group Redo Generation Enqueue
enq: FL – Flashback database log Synchronizes access to Flashback database log
enq: FL – Flashback db command Synchronizes Flashback Database and deletion of flashback logs
enq: FM – contention Synchronizes access to global file mapping state
enq: FR – contention Begins recovery of disk group
enq: FS – contention Synchronizes recovery and file operations or synchronizes dictionary check
enq: FT – allow LGWR writes Allows LGWR to generate redo in this thread
enq: FT – disable LGWR writes Prevents LGWR from generating redo in this thread
enq: FU – contention Serializes the capture of the DB feature, usage, and high watermark statistics
enq: HD – contention Serializes accesses to ASM SGA data structures
enq: HP – contention Synchronizes accesses to queue pages
enq: HQ – contention Synchronizes the creation of new queue IDs
enq: HV – contention Lock used to broker the high watermark during parallel inserts
enq: HW – contention Lock used to broker the high watermark during parallel inserts
enq: IA – contention Information not available
enq: ID – contention Lock held to prevent other processes from performing controlfile transaction while NID is running
enq: IL – contention Synchronizes accesses to internal label data structures
enq: IM – contention for blr Serializes block recovery for IMU txn
enq: IR – contention Synchronizes instance recovery
enq: IR – contention2 Synchronizes parallel instance recovery and shutdown immediate
enq: IS – contention Synchronizes instance state changes
enq: IT – contention Synchronizes accesses to a temp object’s metadata
enq: JD – contention Synchronizes dates between job queue coordinator and slave processes
enq: JI – contention Lock held during materialized view operations (such as refresh, alter) to prevent concurrent operations on the same materialized view
enq: JQ – contention Lock to prevent multiple instances from running a single job
enq: JS – contention Synchronizes accesses to the job cache
enq: JS – coord post lock Lock for coordinator posting
enq: JS – global wdw lock Lock acquired when doing wdw ddl
enq: JS – job chain evaluate lock Lock when job chain evaluated for steps to create
enq: JS – q mem clnup lck Lock obtained when cleaning up q memory
enq: JS – slave enq get lock2 Gets run info locks before slv objget
enq: JS – slave enq get lock1 Slave locks exec pre to sess strt
enq: JS – running job cnt lock3 Lock to set running job count epost
enq: JS – running job cnt lock2 Lock to set running job count epre
enq: JS – running job cnt lock Lock to get running job count
enq: JS – coord rcv lock Lock when coord receives msg
enq: JS – queue lock Lock on internal scheduler queue
enq: JS – job run lock – synchronize Lock to prevent job from running elsewhere
enq: JS – job recov lock Lock to recover jobs running on crashed RAC inst
enq: KK – context Lock held by open redo thread, used by other instances to force a log switch
enq: KM – contention Synchronizes various Resource Manager operations
enq: KP – contention Synchronizes kupp process startup
enq: KT – contention Synchronizes accesses to the current Resource Manager plan
enq: MD – contention Lock held during materialized view log DDL statements
enq: MH – contention Lock used for recovery when setting Mail Host for AQ e-mail notifications
enq: ML – contention Lock used for recovery when setting Mail Port for AQ e-mail notifications
enq: MN – contention Synchronizes updates to the LogMiner dictionary and prevents multiple instances from preparing the same LogMiner session
enq: MR – contention Lock used to coordinate media recovery with other uses of datafiles
enq: MS – contention Lock held during materialized view refresh to set up MV log
enq: MW – contention Serializes the calibration of the manageability schedules with the Maintenance Window
enq: OC – contention Synchronizes write accesses to the outline cache
enq: OL – contention Synchronizes accesses to a particular outline name
enq: OQ – xsoqhiAlloc Synchronizes access to olapi history allocation
enq: OQ – xsoqhiClose Synchronizes access to olapi history closing
enq: OQ – xsoqhistrecb Synchronizes access to olapi history globals
enq: OQ – xsoqhiFlush Synchronizes access to olapi history flushing
enq: OQ – xsoq*histrecb Synchronizes access to olapi history parameter CB
enq: PD – contention Prevents others from updating the same property
enq: PE – contention Synchronizes system parameter updates
enq: PF – contention Synchronizes accesses to the password file
enq: PG – contention Synchronizes global system parameter updates
enq: PH – contention Lock used for recovery when setting proxy for AQ HTTP notifications
enq: PI – contention Communicates remote Parallel Execution Server Process creation status
enq: PL – contention Coordinates plug-in operation of transportable tablespaces
enq: PR – contention Synchronizes process startup
enq: PS – contention Parallel Execution Server Process reservation and synchronization
enq: PT – contention Synchronizes access to ASM PST metadata
enq: PV – syncstart Synchronizes slave start_shutdown
enq: PV – syncshut Synchronizes instance shutdown_slvstart
enq: PW – prewarm status in dbw0 DBWR0 holds this enqueue indicating pre-warmed buffers present in cache
enq: PW – flush prewarm buffers Direct Load needs to flush prewarmed buffers if DBWR0 holds this enqueue
enq: RB – contention Serializes OSM rollback recovery operations
enq: RF – synch: per-SGA Broker metadata Ensures r/w atomicity of DG configuration metadata per unique SGA
enq: RF – synchronization: critical ai Synchronizes critical apply instance among primary instances
enq: RF – new AI Synchronizes selection of the new apply instance
enq: RF – synchronization: chief Anoints 1 instance’s DMON (Data Guard Broker Monitor) as chief to other instance’s DMONs
enq: RF – synchronization: HC master Anoints 1 instance’s DMON as health check master
enq: RF – synchronization: aifo master Synchronizes critical apply instance failure detection and failover operation
enq: RF – atomicity Ensures atomicity of log transport setup
enq: RN – contention Coordinates nab computations of online logs during recovery
enq: RO – contention Coordinates flushing of multiple objects
enq: RO – fast object reuse Coordinates fast object reuse
enq: RP – contention Enqueue held when resilvering is needed or when data block is repaired from mirror
enq: RS – file delete Lock held to prevent file from accessing during space reclamation
enq: RS – persist alert level Lock held to make alert level persistent
enq: RS – write alert level Lock held to write alert level
enq: RS – read alert level Lock held to read alert level
enq: RS – prevent aging list update Lock held to prevent aging list update
enq: RS – record reuse Lock held to prevent file from accessing while reusing circular record
enq: RS – prevent file delete Lock held to prevent deleting file to reclaim space
enq: RT – contention Thread locks held by LGWR, DBW0, and RVWR (Recovery Writer, used in Flashback Database operations) to indicate mounted or open status
enq: SB – contention Synchronizes logical standby metadata operations
enq: SF – contention Lock held for recovery when setting sender for AQ e-mail notifications
enq: SH – contention Enqueue always acquired in no-wait mode – should seldom see this contention
enq: SI – contention Prevents multiple streams table instantiations
enq: SK – contention Serialize shrink of a segment
enq: SQ – contention Lock to ensure that only one process can replenish the sequence cache
enq: SR – contention Coordinates replication / streams operations
enq: SS – contention Ensures that sort segments created during parallel DML operations aren’t prematurely cleaned up
enq: ST – contention Synchronizes space management activities in dictionary-managed tablespaces
enq: SU – contention Serializes access to SaveUndo Segment
enq: SW – contention Coordinates the ‘alter system suspend’ operation
enq: TA – contention Serializes operations on undo segments and undo tablespaces
enq: TB – SQL Tuning Base Cache Update Synchronizes writes to the SQL Tuning Base Existence Cache
enq: TB – SQL Tuning Base Cache Load Synchronizes writes to the SQL Tuning Base Existence Cache
enq: TC – contention Lock held to guarantee uniqueness of a tablespace checkpoint
enq: TC – contention2 Lock during setup of a unique tablespace checkpoint in null mode
enq: TD – KTF dump entries KTF dumping time/scn mappings in SMON_SCN_TIME table
enq: TE – KTF broadcast KTF broadcasting
enq: TF – contention Serializes dropping of a temporary file
enq: TL – contention Serializes threshold log table read and update
enq: TM – contention Synchronizes accesses to an object
enq: TO – contention Synchronizes DDL and DML operations on a temp object
enq: TQ – TM contention TM access to the queue table
enq: TQ – DDL contention DDL access to the queue table
enq: TQ – INI contention TM access to the queue table
enq: TS – contention Serializes accesses to temp segments
enq: TT – contention Serializes DDL operations on tablespaces
enq: TW – contention Lock held by one instance to wait for transactions on all instances to finish
enq: TX – contention Lock held by a transaction to allow other transactions to wait for it
enq: TX – row lock contention Lock held on a particular row by a transaction to prevent other transactions from modifying it
enq: TX – allocate ITL entry Allocating an ITL entry in order to begin a transaction
enq: TX – index contention Lock held on an index during a split to prevent other operations on it
enq: UL – contention Lock held used by user applications
enq: US – contention Lock held to perform DDL on the undo segment
enq: WA – contention Lock used for recovery when setting watermark for memory usage in AQ notifications
enq: WF – contention Enqueue used to serialize the flushing of snapshots
enq: WL – contention Coordinates access to redo log files and archive logs
enq: WP – contention Enqueue to handle concurrency between purging and baselines
enq: XH – contention Lock used for recovery when setting No Proxy Domains for AQ HTTP notifications
enq: XR – quiesce database Lock held during database quiesce
enq: XR – database force logging Lock held during database force logging mode
enq: XY – contention Lock used by Oracle Corporation for internal testing

Of course I don’t want to steal anyones content here:

Found at: http://oracle-dox.net/

Direct link: http://oracle-dox.net/McGraw.Hill-Oracle.Wait.Interf/8174final/LiB0063.html

Many thanks to Oracle-Dox for providing this table!

11g and the new SecureFILE LOB data type (simple quick test)

As I had to run some comparison test Oracle 10g and 11g I also did a little test with the new and fast (as Oracle promises) SecureFILE LOB data type. The test is really little as there wasn’t any time to test the feature totally out, but also this result is impressive. Of course all test occurred on the same box and the same settings:

First the 10g test:

The first step is to create a table with a CLOB data type:

SQL> create table test1 (created_tms date, data clob) tablespace data1 lob (data) store as (cache);
Table created.
SQL>

I used cache to get as much bytes as possible into the buffer cache. If you need performance on LOB anyone would activate this as first step. As next step I wrote a little PL/SQL program  which inserts 100.000 rows with a 4402 bytes (that’s 4.4GB all together!):

SQL> set serveroutput on;
SQL> declare
2    thedata CLOB := TO_CLOB (
3  ‘somedata somedata somedata somedata somedata somedata somedata somedata somedata somedata
4  somedata somedata somedata somedata somedata somedata somedata somedata somedata somedata
……
49  somedata somedata somedata somedata somedata somedata somedata somedata somedata somedata
50  somedata somedata somedata somedata somedata somedata somedata somedata somedata somedata ‘);
51  begin
52    dbms_output.put_line(‘Begin: ‘ || systimestamp);
53    for n in 1..100000 loop
54      insert into test1 values (sysdate,thedata);
55    end loop;
56    dbms_output.put_line(‘End: ‘ || systimestamp);
57  end;
58  /
Begin: 11-JAN-08 04.30.50.203325000 PM +01:00
End: 11-JAN-08 04.32.50.422759000 PM +01:00

PL/SQL procedure successfully completed.

Checking the time stamp you can see that with 10g the inserts took nearly exactly 2 minutes (the last time, I executed it several times). Also you can see that I inserted the actual sysdate in a column too. So now we can compute a average of inserts per second:

SQL> select count(*)/((max(created_tms)-min(created_tms))*24*60*60) from test1;

COUNT(*)/((MAX(CREATED_TMS)-MIN(CREATED_TMS))*24*60*60)
——————————————————-
833.333333

The last 4 runs made (average inserts/second):

840.336134
826.446281
800
833.333333

So, now we going to 11g. First step: We need a table with the new SecureFILE LOB type:

SQL>
SQL> create table test1 (created_tms date, data clob) tablespace data1 lob (data) store as securefile cache;

Table created.

Next, I executed exactly the same procedure:

SQL> set serveroutput on;
SQL> declare
2    thedata CLOB := TO_CLOB (
3  ‘somedata somedata somedata somedata somedata somedata somedata somedata somedata somedata
……
49  somedata somedata somedata somedata somedata somedata somedata somedata somedata somedata
50  somedata somedata somedata somedata somedata somedata somedata somedata somedata somedata ‘);
51  begin
52    dbms_output.put_line(‘Begin: ‘ || systimestamp);
53    for n in 1..100000 loop
54      insert into test1 values (sysdate,thedata);
55    end loop;
56    dbms_output.put_line(‘End: ‘ || systimestamp);
57  end;
58  /
Begin: 11-JAN-08 04.19.06.534822000 PM +01:00
End: 11-JAN-08 04.20.01.703784000 PM +01:00

PL/SQL procedure successfully completed.

Looking at the time stamps the run took less than a minute! Remember, 10g needed around 2 minutes. So lets look to the average inserts per second:

SQL> select count(*)/((max(created_tms)-min(created_tms))*24*60*60) from test1;

COUNT(*)/((MAX(CREATED_TMS)-MIN(CREATED_TMS))*24*60*60)
——————————————————-
1818.18182

We can see that the program made average 1818 inserts per second. Compared to 833 from 10g it’s more than 100% faster! And that’s not bad without any fine tuning I would say!

The last 4 runs made:

1960.78431
1818.18182
1754.38596
1818.18182

I hope I’ve some time left to provide a good test case, but also this quick one showed that the SecureFILE  data type really speeded-up compared to convention LOB, and that’s what Oracle promised! 😉

Prepared statement in batch mode vs. FORALL in PL/SQL

A few days ago I had a nice discussion with one of our developers here in the office. The subject: What’s faster? Prepared statements with batch mode or calling a PL/SQL function which is using FORALL.

So I made a simple test: Insert 1 million rows with two columns (a number and a string column) into a table. The first part builds the values in java give it to the batch array and executes the insert in batch mode (This feature of JDBC stores the values in the memory until you execute the batch. Then JDBC executes the DML and loads the array at ones, very similar to FORALL.) The second part builds the values also in java creates two collections and call a procedure with the collections. The procedure itself just performs a FORALL over the insert.

So the first part of the java code looks like this:

long l = System.currentTimeMillis();
PreparedStatement pstmt = conn1.prepareStatement(“INSERT INTO TEST VALUES(?,?)”);
System.out.println(“PrepareStatement took: “+(System.currentTimeMillis() – l));
long l1 = System.currentTimeMillis();
for (int i=0;i<1000000;++i)
{
pstmt.setInt(1, i);
pstmt.setString(2, “testvalue”+i);
pstmt.addBatch();
if(i%16961 == 0)
pstmt.executeBatch();
}

pstmt.executeBatch();
System.out.println(“ExecuteBatch took: “+ (System.currentTimeMillis() – l1));

Don’t worry about the if with the modulo function. It turned out that JDBC has a bug with addBatch. It can just execute around 16000 rows at ones. If you add more rows it just ignores them! So I had to call the executeBatch more often. But we will see, if this slows down the test.

The second part of the java code looks like this:

l = System.currentTimeMillis();

ArrayDescriptor integer = ArrayDescriptor.createDescriptor(“INTARRAY”, conn1);
ArrayDescriptor varchar = ArrayDescriptor.createDescriptor(“VARARRAY”, conn1);

ARRAY pliArray = new ARRAY(integer,conn1, iArray);
ARRAY plsArray = new ARRAY(varchar,conn1, sString);
System.out.println(“Creating the Array took: “+(System.currentTimeMillis() – l));

l = System.currentTimeMillis();
CallableStatement callStatement = (CallableStatement)conn1.prepareCall(“{call insertvalues(?,?)}”);
System.out.println(“Preparing Call took: “+(System.currentTimeMillis() – l));

callStatement.setArray(1, pliArray);
callStatement.setArray(2, plsArray);

l1 = System.currentTimeMillis();
callStatement.execute();
System.out.println(“Executing PL/SQL took: “+(System.currentTimeMillis() – l1));

The PL/SQL code:

CREATE OR REPLACE TYPE TEST.intArray IS VARRAY(1000000) OF NUMBER;
show errors;
CREATE OR REPLACE TYPE TEST.varArray IS VARRAY(1000000) OF VARCHAR2(18);
show errors;

create or replace procedure insertvalues (nValue1 IN intArray, sValue2 IN varArray) is
begin
forall nvalue in nValue1.first..nValue1.last
insert into test values (nValue1(nvalue), sValue2(nvalue));
end;
show errors;

Well the result surprised me a little bit. Java was much faster. Look at the trace alone (trimmed!):

INSERT INTO TEST
VALUES
(:1,:2)

call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 1 0.00 0.00 0 0 0 0
Execute 60 1.38 2.08 0 7646 34579 1000000
Fetch 0 0.00 0.00 0 0 0 0
——- —— ——– ———- ———- ———- ———- ———-
total 61 1.38 2.08 0 7646 34579 1000000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 1159

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
—————————————- Waited ———- ————
SQL*Net message to client 60 0.00 0.00
SQL*Net message from client 60 0.09 1.64
SQL*Net more data from client 10726 0.00 0.72
********************************************************************************

BEGIN insertvalues(:1,:2); END;

call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 1 0.01 0.00 0 0 0 0
Execute 1 7.77 9.01 0 9277 34886 1
Fetch 0 0.00 0.00 0 0 0 0
——- —— ——– ———- ———- ———- ———- ———-
total 2 7.78 9.01 0 9277 34886 1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 1159

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
—————————————- Waited ———- ————
SQL*Net more data from client 10399 0.00 1.17
SQL*Net message to client 1 0.00 0.00
log file sync 1 0.21 0.21
SQL*Net message from client 1 0.00 0.00
********************************************************************************
As you can see, the count of the procedure execution is just 1, from JDBC it is 60 (because of the bug with the 16000 rows). The elapsed time with prepared statement just took 2.08 seconds but with FORALL it took 9.01 seconds. And the CPU time is also of course lower than in PL/SQL. To be fair: That 9.01 seconds also include the call of the procedure plus the load of the collections. As it showed, just creating the collection in java took around 2 seconds!

In summary: You can see that prepared statement is much faster than FORALL. But to be fair: FORALL was developed to have some kind of bulking in PL/SQL within cursors to decrease the calls between SQL and PL/SQL engine. But if you using Java and JDBC anyway, work with prepared statements and with batch mode if possible. Don’t mind about the SQL*Net waiting events, these are idle events what means that your application isn’t waiting for it!

BTW: That JDBC bug is fixed in 11g and 10.2.0.3!