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:

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 the system starts doing more reads and writes because you keep 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 to be loaded by SQL*Loader and the optimum code would have rearranged the column order and forced us to supply a code release to all those remote systems. The slightly more expensive code kept the result looking the same while concatenaring just one extra column afte the LOB.

Conclsion:

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