Concatenating LOBs

If you have to handle LOBs, it’s worth checking for “unusual” activity. Here’s an example of unexpected behaviour that I came across a couple of years ago.

The client had a table with data that had to be written to a flat file so that a number of other databases could import it using SQL*Loader. The table definition and the query to dump the data are shown below – note, particularly, the CLOB sitting in the middle of the table:

Name                    Null?    Type
----------------------- -------- ----------------
ID                               NUMBER(10)
VIEW_NAME                        VARCHAR2(32)
USER_ID                          VARCHAR2(16)
XML_FILE                         CLOB
FILE_PATH                        VARCHAR2(127)
ACCOUNT_ID                       VARCHAR2(16)
AREA_ID                          VARCHAR2(16)
LABEL_ID                         VARCHAR2(16)
COMPLIANCY_FLAG                  VARCHAR2(1)

select
	id  		|| chr(27) ||
	view_name	|| chr(27) ||
	user_id		|| chr(27) ||
	xml_file	|| chr(27) ||
	file_path 	|| chr(27) ||
	account_id	|| chr(27) ||
	area_id		|| chr(27) ||
	label_id	|| chr(27) ||
	compliancy_flag
from
	t1
;

The dump code is fairly simple – it just concatenates the columns in order, inserting a separator between them using a value that’s not allowed to appear in the data. (The client’s code was a little more subtle, but essentially the same).

I’ve inserted 10,000 rows into this table, with 500 bytes of data for each LOB, and when I execute a simple; “select dbms_lob.getlength(xml_file) from t1;” it takes 20,653 logical I/Os – 653 for the tablescan and 2 to read each LOB value (since I’ve disabled storage in row).

So why, when I run the dump code, do I see the following stats – the number of buffer visits is obviously a little surprising but notice, in particular the number of “lob writes” and the number of “db block changes”:

session logical reads              1,840,063
db block gets                      1,540,034
consistent gets                      300,029
db block changes                     550,037
consistent changes                   550,015
free buffer requested                119,891
lob reads                             10,000
lob writes                           220,000

Despite all the block changes, by the way, the session generated less than 2KB of redo log – and that’s a bit of a clue to what’s going on.

Here are the results of the same job after I’ve optimised the code in two different ways:

session logical reads                240,006
db block gets                        140,000
consistent gets                      100,006
db block changes                      50,000
consistent changes                    50,000
free buffer requested                 19,910
lob reads                             10,000
lob writes                            20,000

session logical reads                400,006
db block gets                        280,000
consistent gets                      120,006
db block changes                     100,000
consistent changes                   100,000
free buffer requested                 29,907
lob reads                             10,000
lob writes                            40,000

Of course, you might be more interested in the timing rather than the simple counts – the original code used 13.95 CPU seconds, the best version 3.49 CPU seconds, and the third version 4.73 seconds – and it was the third option that we had to implement.

So where does the extra work come from? The answer is in the different versions of the code … the point at which you introduce the LOB into the list of concatenated columns makes a big difference:

rem
rem     Script:         lob_concat.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Mar 2008
rem

set long 320000
set longchunksize 32000

select
	id  		|| chr(27) ||
	view_name	|| chr(27) ||
	user_id		|| chr(27) ||
	file_path 	|| chr(27) ||
	account_id	|| chr(27) ||
	area_id		|| chr(27) ||
	label_id	|| chr(27) ||
	compliancy_flag	|| chr(27) ||
	xml_file
from
	t1
;

select
	start_piece || xml_file || end_piece
from
	(
	select
		id  		|| chr(27) ||
		view_name	|| chr(27) ||
		user_id		|| chr(27) 	start_piece,
/*								*/
		chr(27)		||
		file_path 	|| chr(27) ||
		account_id	|| chr(27) ||
		area_id		|| chr(27) ||
		label_id	|| chr(27) ||
		compliancy_flag			end_piece,
/*								*/
		xml_file
	from
		t1
	)
;

The minimum work appeared when the LOB was the last thing added to the concatenation; if the LOB wasn’t at the end of the list then every column (including all those chr(27)’s) resulted in the following extra work for every row selected:

	session logical reads                16
	db block gets                        14
	consistent gets                       2
	db block changes                      5
	consistent changes                    5
	free buffer requested                 1
	lob writes                            2

Essentially, every time you add a piece on the end of the LOB, Oracle creates and updates a new temporary LOB (hence two lob writes). Since they are temporary LOBs – associated therefore with the temporary tablespace – all those “db block changes” don’t cause any redo to be generated, but the overhead is significant.

In fact it’s quite easy to miss what may be the most significant figure – the “free buffer requested”. If you use code like this to dump a large amount of data you may find that everything else in the system starts doing more reads and writes because your session keeps demanding free buffers.

In the short term, we adopted the second, slightly more expense, option because the process was delivering data to lots of other systems that were going to parse it using SQL*Loader and the optimum code would forced us to supply a code release to all those remote systems to match the rearranged the column order. The slightly more expensive code kept the result looking the same while using the concatenation operator just once we had concatenated the LOB.

Conclsion:

Test carefully when you start using code that mixes concatenation and LOBs, and check for any unexpected increases in buffer activity.

Update (Aug 2018)

I’ve rerun the test on 11.2.0.4 and the behaviour relating to block accesses is basically the same, though the difference in timing has changed slightly. Moving on to 12.1.0.2, though, there seems to be no difference in the statistics whichever form of the SQL I run: something completely different is happening (and possibly something is happening that does not appear in the statistics). Among other changes, the “lob reads” and “lob writes” statistics disappear, and the number of “SQL*Net roundtrips to/from client” drops from 30,000 in 11g to 20,000 in 12c. I have some notes that the disappearing lob reads and writes may be due to the appearance of a special 256KB buffer in the PGA that is used for LOB manipulation – so these results may only be valid for “small” LOBs; if your LOB column is larger than about 128K the lob reads and writes may return.

The 12c tests run noticeably faster than the 11g tests – down to about fairly flat 5 seconds, compared to a time that varies from about 7 seconds (best) to 16 seconds (worst).  In all the tests the largest fraction of the time was SQL*Net transfer time, but the worst 11g test showed much more CPU utilisation than the 12c tests and the better 11g tests.

There is one interesting anomaly in 12.1.0.2 – the statistic “table scan rows gotten” jumps from the 11g value of 10,000 to a staggering 349,750 in all three tests, with no clues that I could find for why that happened.  (The same was true for 12.2.0.1).