Analytic Agony

When I wrote Practical Oracle 8i, version 8.1.5 was the most recent version of Oracle but version 8.1.6  came out just before I finished writing – and the only thing in 8.1.6 I thought important enough to add to the book was a section on Analytic Functions because they were the best new coding feature in the product.

Since then I’ve always warned people to be a little careful about how they use analytic functions because of the amount of sorting they can introduce. My suggestion has always been to crunch “large” volumes of data down to “small” volumes of data before applying any analytic functions to add “intelligence” to the intermediate result.

This advice was based on my awareness of how much sorting analytic functions can introduce  – but I’ve only just discovered how badly Oracle handles the sort operation if the data spills to disc.

Here’s a simple example to demonstrate the problem. This is a test case I’ve run on 10g (10.2.0.3) and 11g (11.1.0.6) with workarea_size_policy set to auto and the pga_aggregate_target set to 128MB (which means an individual workarea operation can acquire 25.6MB of memory).

First we set the environment – I’ve disabled system statistics (a.k.a. CPU costing) for the purposes of the demonstration just to get a stable environment:

rem
rem     Script:         analytic_problem.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Sept 2009
rem

begin
	begin		execute immediate 'begin dbms_stats.delete_system_stats; end;';
	exception	when others then null;
	end;

	begin		execute immediate 'alter session set "_optimizer_cost_model"=io';
	exception	when others then null;
	end;
end;
/

Then I create a simple data set with a little help from the random number generator – which I’ve seeded so that every run on every version of Oracle gets the same random data set. I create 1,000,000 rows and collect basic statistics on the table.

execute dbms_random.seed(0)

create table t1
nologging
as
with generator as (
	select	--+ materialize
		rownum id
	from dual
	connect by
		rownum <= 1000
)
select
	rownum					id,
	trunc(dbms_random.value(1,1000))	n1,
	trunc(dbms_random.value(1,1000))	n2,
	lpad(rownum,30,'0')			small_vc
from
	generator	v1,
	generator	v2
where
	rownum <= 1000000
;

begin
	dbms_stats.gather_table_stats(
		ownname		 => user,
		tabname		 =>'T1',
		method_opt 	 => 'for all columns size 1'
	);
end;
/

Then I’ve turned on some tracing and enabled autotrace. Apart from the extended sql_trace (event 10046 at level 8 ) I’ve also enabled a trace on sort statistics (event 10032) and sort I/O operations (event 10033).

The call to autotrace is there so that I can run the query, pulling the data into the SQL*Plus session and throwing it away as cheaply as possible. I’ve also set the arraysize to 1,000 to make sure that each SQL*Net roundtrip pulls a lot of data from the database in case the data fetch size affects the I/O pattern.

alter session set events '10032 trace name context forever';
alter session set events '10033 trace name context forever';
alter session set events '10046 trace name context forever, level 8';

set arraysize 1000
set autotrace traceonly statistics

Finally, here’s the query. It’s a very simple example of using an analytic function.

The inline view partitions the data by n1, sorting each partition by n2, picking up the id value in the last row of the partition. By wrapping this query inside a view we can add a predicate to identify just those rows where the value of the id is the same as the last id of the partition – and then report the n1, n2, and small_vc values from those rows.

To execute this query Oracle has to sort the data into (n1, n2) order then walk through it to find the value for id for the last row in each n1 partition in turn. So we are going to need quite a lot of memory – and we’re not going to have enough because of my settings for the pga_aggregate_target.

select
	n1,
	n2,
	small_vc
from
	(
	select
		n1,
		n2,
		id,
		small_vc,
		last_value(id) over (
			partition by n1
			order by n2
		)	last_id
	from
		t1
	)
where
	id = last_id
;

Here’s the history of how Oracle handles this query – as reported by the 10032 and 10033 traces.
The first step is to sort 1 million rows of (n1, n2, id, small_vc) which – with sort-related overheads – totals about 50MB of data. Since the session is limited to 25.6MB for a single, serial, sort operation the sort spills to disc and the 10033 trace file shows the following runs of data being written (for more information about sorting and Oracle’s sort traces, see Cost Based Oracle – Fundamentals, chapter 13):

Recording run at 400a89 for 2264 blocks
Recording run at 401ce2 for 419 blocks
Recording run at 401b85 for 531 blocks
Recording run at 401898 for 701 blocks
Recording run at 401655 for 839 blocks
Recording run at 40129c for 1023 blocks
Recording run at 400e9b for 637 blocks

The first run is written as the workarea hits the limit, at which point Oracle falls back from attempting an “optimal” operation to a “one-pass” operation – which is why the session releases some PGA memory and the sizes of the subsequent runs are smaller (the final 637 block run corresponded to a workarea size of about 8MB).

At this point a small disaster happens. Having completed the first phase of the sort Oracle releases more memory before starting the merge phase, and at this point we see the following report from the 10032 trace:

---- Sort Parameters ------------------------------
sort_area_size                    3555328
sort_area_retained_size           3555328
sort_multiblock_read_count        31
max intermediate merge width      5

Oracle has reduced the workarea to 3.5MB – which it believes is enough to merge five runs simultaneously using multiblock reads (of the temporary tablespace) of 31 blocks.  Given that the 10033 trace has just reported that it has written seven runs it is a pity that Oracle hasn’t decided to use smaller reads to be able to read all seven runs simultaneously – our sort is (apparently) going to turn into a multipass (specifically two-pass) workarea operation.

But the actual behaviour is worse than the promise – look what the 10033 trace reports over the next couple of minutes:

Merging run at 401ce2 for 419 blocks
Merging run at 401b85 for 531 blocks
Merging run at 400e9b for 637 blocks
Merging run at 401898 for 701 blocks
Total number of blocks to read: 2288 blocks

Recording run at 400c18 for 2286 blocks

Merging run at 401655 for 839 blocks
Merging run at 40129c for 1023 blocks
Total number of blocks to read: 1862 blocks

Recording run at 400cc6 for 1861 blocks

Merging run at 400cc6 for 1861 blocks
Merging run at 400a89 for 2264 blocks
Total number of blocks to read: 4125 blocks

Recording run at 400f0b for 4125 blocks

Merging run at 400c18 for 2286 blocks
Merging run at 400f0b for 4125 blocks
Total number of blocks to read: 6411 blocks

Recording run at 401cc8 for 6411 blocks

Merging run at 401cc8 for 6411 blocks
Total number of blocks to read: 6411 blocks

On its first pass Oracle didn’t even manage to handle the predicted five runs, it only managed to merge four of them and then write out a single run of 2288 blocks. Then it merged two more runs and wrote out a single run of 1,862 blocks. Then it merged another two runs and wrote out 4,125 blocks. Then it got to the point where it merged the last two remaining runs to get the entire result set of 6,411 blocks sorted – and wrote out the whole sorted set. Finally it started to read back the 6,411 blocks to generate the last_value() results.

So it’s done a four-pass workarea operation – when it should have been possible to do a one-pass operation; and it seems to have written the entire result set to disk after the final merge when it really shouldn’t have needed to. (In earlier versions of Oracle an extra write of the whole sorted data set used to take place when Oracle spilled to disc during an index build – I don’t remember when the redundant write was eliminated, but it seems to be back for analytic functions).

So the analytic sort is pretty unhealthy so far – but there’s still scope for things to get worse. Here are some results from the 10046 trace showing what’s going on with the “direct path reads” as Oracle reads back data from the temporary segment in the merge passes. Remember how the 10032 trace said that the sort_multiblock_read was going to be 31 blocks – look what really happened – this sample appears about halfway through the merging phase:

WAIT #33: nam='direct path read temp' ela= 250 file number=201 first dba=4842 block cnt=1 obj#=101556 tim=761555607096
WAIT #33: nam='direct path read temp' ela= 473 file number=201 first dba=4843 block cnt=7 obj#=101556 tim=761555607915
WAIT #33: nam='direct path read temp' ela= 217 file number=201 first dba=5529 block cnt=1 obj#=101556 tim=761555608880
WAIT #33: nam='direct path read temp' ela= 452 file number=201 first dba=5530 block cnt=7 obj#=101556 tim=761555609602
WAIT #33: nam='direct path read temp' ela= 239 file number=201 first dba=4850 block cnt=1 obj#=101556 tim=761555610227
WAIT #33: nam='direct path read temp' ela= 480 file number=201 first dba=4851 block cnt=7 obj#=101556 tim=761555610954
WAIT #33: nam='direct path read temp' ela= 1122 file number=201 first dba=5537 block cnt=1 obj#=101556 tim=761555613237
WAIT #33: nam='direct path read temp' ela= 1500 file number=201 first dba=4858 block cnt=1 obj#=101556 tim=761555614889
WAIT #33: nam='direct path read temp' ela= 426 file number=201 first dba=5538 block cnt=7 obj#=101556 tim=761555615530
WAIT #33: nam='direct path read temp' ela= 557 file number=201 first dba=4859 block cnt=7 obj#=101556 tim=761555616151
WAIT #33: nam='direct path read temp' ela= 228 file number=201 first dba=4866 block cnt=1 obj#=101556 tim=761555617379
WAIT #33: nam='direct path read temp' ela= 29213 file number=201 first dba=5545 block cnt=1 obj#=101556 tim=761555646867
WAIT #33: nam='direct path read temp' ela= 422 file number=201 first dba=5546 block cnt=7 obj#=101556 tim=761555647595

Notice how we are probably merging two runs at this pont. By stepping through the list of “first dba” values and adding the “block cnt”, you can see (picking out just one of the two runs) the following pattern:

• 4842 + 1 = 4843

• 4843 + 7 = 4850  (then skip 2 lines)

• 4850 + 1 = 4851

• 4851 + 7 = 4858  (then skip 1 line)

• 4858 + 1 = 4859  (then skip 1 line)

• 4859 + 7 = 4866

4855 + 1 = 4867

We’re reading great long ranges of adjacent blocks – in little pieces.

And it gets still worse. By the time we get to the end of the merge operation and start reading back the final (and redundantly written) stream, look what the read pattern shows – the examples come from two separate parts of the final read back, one near the start and one near the end:

WAIT #33: nam='direct path read temp' ela= 325 file number=201 first dba=7368 block cnt=1 obj#=101556 tim=761573681919
WAIT #33: nam='direct path read temp' ela= 327 file number=201 first dba=4937 block cnt=1 obj#=101556 tim=761573685178
WAIT #33: nam='direct path read temp' ela= 494 file number=201 first dba=7368 block cnt=1 obj#=101556 tim=761573685888
WAIT #33: nam='direct path read temp' ela= 264 file number=201 first dba=4938 block cnt=1 obj#=101556 tim=761573687691
WAIT #33: nam='direct path read temp' ela= 272 file number=201 first dba=7368 block cnt=1 obj#=101556 tim=761573688149
WAIT #33: nam='direct path read temp' ela= 260 file number=201 first dba=4939 block cnt=1 obj#=101556 tim=761573689642
WAIT #33: nam='direct path read temp' ela= 245 file number=201 first dba=7368 block cnt=1 obj#=101556 tim=761573690062
WAIT #33: nam='direct path read temp' ela= 245 file number=201 first dba=4940 block cnt=1 obj#=101556 tim=761573691804
WAIT #33: nam='direct path read temp' ela= 254 file number=201 first dba=7368 block cnt=1 obj#=101556 tim=761573692211
WAIT #33: nam='direct path read temp' ela= 270 file number=201 first dba=4941 block cnt=1 obj#=101556 tim=761573693620
WAIT #33: nam='direct path read temp' ela= 273 file number=201 first dba=7368 block cnt=1 obj#=101556 tim=761573694030
WAIT #33: nam='direct path read temp' ela= 312 file number=201 first dba=4942 block cnt=1 obj#=101556 tim=761573695493
WAIT #33: nam='direct path read temp' ela= 295 file number=201 first dba=7368 block cnt=1 obj#=101556 tim=761573696101
WAIT #33: nam='direct path read temp' ela= 671 file number=201 first dba=4943 block cnt=1 obj#=101556 tim=761573697864
WAIT #33: nam='direct path read temp' ela= 288 file number=201 first dba=4944 block cnt=1 obj#=101556 tim=761573699601
WAIT #33: nam='direct path read temp' ela= 395 file number=201 first dba=4945 block cnt=1 obj#=101556 tim=761573702930
WAIT #33: nam='direct path read temp' ela= 289 file number=201 first dba=4946 block cnt=1 obj#=101556 tim=761573711065
WAIT #33: nam='direct path read temp' ela= 270 file number=201 first dba=4942 block cnt=1 obj#=101556 tim=761573711462
WAIT #33: nam='direct path read temp' ela= 271 file number=201 first dba=4947 block cnt=1 obj#=101556 tim=761573712867
WAIT #33: nam='direct path read temp' ela= 274 file number=201 first dba=4942 block cnt=1 obj#=101556 tim=761573713269
WAIT #33: nam='direct path read temp' ela= 287 file number=201 first dba=4948 block cnt=1 obj#=101556 tim=761573714687
WAIT #33: nam='direct path read temp' ela= 238 file number=201 first dba=4942 block cnt=1 obj#=101556 tim=761573715052
WAIT #33: nam='direct path read temp' ela= 335 file number=201 first dba=4949 block cnt=1 obj#=101556 tim=761573716733
WAIT #33: nam='direct path read temp' ela= 235 file number=201 first dba=4950 block cnt=1 obj#=101556 tim=761573718257
WAIT #33: nam='direct path read temp' ela= 522 file number=201 first dba=4951 block cnt=1 obj#=101556 tim=761573719886
WAIT #33: nam='direct path read temp' ela= 270 file number=201 first dba=4952 block cnt=1 obj#=101556 tim=761573721269
WAIT #33: nam='direct path read temp' ela= 322 file number=201 first dba=4953 block cnt=1 obj#=101556 tim=761573722709
WAIT #33: nam='direct path read temp' ela= 307 file number=201 first dba=4948 block cnt=1 obj#=101556 tim=761573723237

...

WAIT #33: nam='direct path read temp' ela= 223 file number=201 first dba=2793 block cnt=1 obj#=101556 tim=761574694654
WAIT #33: nam='direct path read temp' ela= 226 file number=201 first dba=2794 block cnt=1 obj#=101556 tim=761574695481
WAIT #33: nam='direct path read temp' ela= 203 file number=201 first dba=2795 block cnt=1 obj#=101556 tim=761574696263
WAIT #33: nam='direct path read temp' ela= 207 file number=201 first dba=2796 block cnt=1 obj#=101556 tim=761574697067
WAIT #33: nam='direct path read temp' ela= 225 file number=201 first dba=2797 block cnt=1 obj#=101556 tim=761574697880
WAIT #33: nam='direct path read temp' ela= 239 file number=201 first dba=2799 block cnt=1 obj#=101556 tim=761574703204
WAIT #33: nam='direct path read temp' ela= 222 file number=201 first dba=2800 block cnt=1 obj#=101556 tim=761574704035
WAIT #33: nam='direct path read temp' ela= 223 file number=201 first dba=2801 block cnt=1 obj#=101556 tim=761574704855
WAIT #33: nam='direct path read temp' ela= 225 file number=201 first dba=2802 block cnt=1 obj#=101556 tim=761574705674
WAIT #33: nam='direct path read temp' ela= 210 file number=201 first dba=2803 block cnt=1 obj#=101556 tim=761574706447
WAIT #33: nam='direct path read temp' ela= 226 file number=201 first dba=2804 block cnt=1 obj#=101556 tim=761574707252
WAIT #33: nam='direct path read temp' ela= 211 file number=201 first dba=2805 block cnt=1 obj#=101556 tim=761574708047
WAIT #33: nam='direct path read temp' ela= 213 file number=201 first dba=2806 block cnt=1 obj#=101556 tim=761574708852
WAIT #33: nam='direct path read temp' ela= 225 file number=201 first dba=2807 block cnt=1 obj#=101556 tim=761574709663
WAIT #33: nam='direct path read temp' ela= 232 file number=201 first dba=2808 block cnt=1 obj#=101556 tim=761574710748
WAIT #33: nam='direct path read temp' ela= 206 file number=201 first dba=2809 block cnt=1 obj#=101556 tim=761574714850
WAIT #33: nam='direct path read temp' ela= 208 file number=201 first dba=2810 block cnt=1 obj#=101556 tim=761574715640

We start off doing something quite surprising – jumping back and fore when we should be reading a continuous stream of blocks and even re-reading a few blocks multiple times (possibly this is a small set of “map” blocks) before settling down and reading great long continuous chains of adjacent blocks: one block at a time!

Summary:

This is a small demonstration – it is repeatable, and I built it to raise an SR for a problem where a client had to process an 8GB data set to the temporary tablespace, did a nine pass workarea operation (that should have been a one-pass operation) and ended up doing 500,000 single block reads (16KB block size) to return the final result set. The I/O to the temporary tablespace was the largest time component of the entire query by a significant margin – probably taking about four times as long as it should have.

The code to handle analytic sorts (the WINDOW SORT operation) has some serious defects which show up if the sort spills to disc – and a sort of more the 100MB  will spill to disc if you set workarea_size_policy to auto – no matter how large your pga_aggregate_target (and the derived _smm_max_size)

On the plus side, by adjusting a couple of hidden parameters I was able to bypass the 100MB limit for the “smaller” analytic sorts and do some damage limitation on the merge passes for larger analytic sorts; but I couldn’t find any way of avoiding the single block reads after the last (apparently redundant) write.

Workarounds:

As ever, you need to get approval from Oracle support for using hidden parameters, but if you need to keep large analytic sorts in memory the limit is set (suprisingly) by the hidden parameter _smm_isort_cap which defaults 100MB – not by the _smm_max_size.

If you have very large analytic sorts that really have to spill to disc then you may need to switch a session to manual workarea_size_policy so that the memory doesn’t shrink in the merge phase, and then set the hidden parameter _sort_multiblock_read_count to something reasonably large (the equivalent of 256KB to 1MB perhaps – the value is the number of Oracle blocks for a multiblock read).

Finally, if you find a way to get a large multiblock read on the final read – please let me know.

Footnote: While waiting for permission from the client to publish this note, I passed my test case to the OakTable Network for comment, and Charles Hooper ran it on his copy of 11.2. The problem with the memory management and multi-pass sort seems to be fixed in that version – but the (apparently) redundant final write is still there, and the final read is still done with single block reads. I’m still trying to think  of a good reason why they could be necessary.

Update: It’s not just the WINDOW SORT operation that suffers from the sharp reduction in the workarea size and consequential multipass operation. We’re getting it all over the place in very large sort operations.  The analytics become very visible, though, because they get limited by the _smm_isort_cap and start to spill to disc at 100MB whereas the simple sorts use the _smm_max_size limit and rarely spill to disc.  (Aggregates have the same problem – they also follow the _smm_isort_cap limit, but that’s s a story for another day).

Update 2: The problem of the multi-pass sort is bug 6817844 – the bug note states that this is fixed in 11.2, but it’s actually in the list of bugs fixed in 11.1.0.7 (Metalink note 601739.1). A workaround suggested in the bug note is to set hidden parameter _newsort_enabled to false – and that suggestion is worth a little discussion in a separate blog entry, if I can find the time.

Update 3: 1st Oct 2009: We’ve now got a backport of the patch to 10.2.0.4 (for AIX) and installed it. It seems to be working, the example I had where a query turned into a 9-pass sort operation now runs as a one-pass operation. I still have an issue with the sizes of the direct path reads and writes – especially the single block read on the final pass – but the worst part of the problem has been fixed.

Update 4: 3rd Oct 2009: In a comment on one of my postings about bugs, Timur Akhmadeev has referenced an OTN thread that references Metalink document id 330818.1 and bug 4047116, with the suggestion that in similar circumstances to the above, you can improve the I/O behaviour by setting two hidden parameters (_smm_auto_min_io_size and _smm_auto_max_io_size) to matching values – with 248 or 1008 being the two suggested sizes.

This had some effect on the I/O sizes in my case, but only while writing and merging intermediate sort runs. However, I still saw alternating single block reads during the merges, and nothing but single block reads for the final read back. Ultimately, this didn’t change the performance of the example I was running on production, so I didn’t pursue it further – but you may want to look at it.

Update Feb 2010

In comment 13, Greg Rahn has identified this as bug 9041800 with a 10.2.0.4 backport already available.