{"id":2668,"date":"2019-07-14T16:22:31","date_gmt":"2019-07-14T16:22:31","guid":{"rendered":"https:\/\/nenadnoveljic.com\/blog\/?p=2668"},"modified":"2020-10-08T14:21:01","modified_gmt":"2020-10-08T14:21:01","slug":"io-sort-cost-calculation","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/io-sort-cost-calculation\/","title":{"rendered":"IO Sort Cost Calculation"},"content":{"rendered":"

Jonathan Lewis wrote an article about scalar subquery costing<\/a>. In the course of subsequent experiments we noticed an unusual discrepancy in the IO sort cost for different block sizes. That was also one of the topics in our exchange in the comments of his blog post.<\/p>\n

This discrepancy is clearly visible in the sort section of the optimizer trace. See below the excerpts for 8k<\/span> and 32k<\/span> database block sizes, respectively:<\/p>\n

SORT ressource         Sort statistics\n      Sort width:         305 Area size:      268288 Max Area size:    53686272\n      Degree:               1\n      Blocks to Sort:<\/span> 196<\/span> Row size:     16 Total Rows:         100000\n      Initial runs:   2 Merge passes:  1 IO Cost \/ pass:<\/span>        108<\/span>\n      Total IO sort cost:<\/span> 304.000000<\/span>      Total CPU sort cost: 119218158\n      Total Temp space used: 1221000\n\nSORT ressource         Sort statistics\n  Sort width:         306 Area size:      268288 Max Area size:    53686272\n  Degree:               1\n  Blocks to Sort:<\/span> 49<\/span> Row size:     16 Total Rows:         100000\n  Initial runs:   2 Merge passes:  1 IO Cost \/ pass:<\/span>         74<\/span>\n  Total IO sort cost:<\/span> 123.000000<\/span>      Total CPU sort cost: 139966334\n  Total Temp space used: 1246000<\/code><\/pre>\n
The only difference in both tests was the block size. Consequently, Blocks to Sort<\/i><\/span> is 4 times higher on the database with the 8k<\/span> block size. But, the Total IO sort cost<\/i><\/span> is almost three times higher for the 8k<\/span> database, which doesn’t seem right, because the data volume is exactly the same. I mean a single IO of 32k<\/span> is usually more efficient than 4 IOs of 8k<\/span>, but by no means by factor three.<\/p>\n
This inconsistency prompted further investigation.<\/p>\n
IO Cost \/ pass<\/h1>\n
There isn’t a simple way for cracking the formula for IO Cost \/ pass<\/i><\/span> based on the system statistics, block sizes etc. So I first had to identify Oracle functions participating in the calculation and then deduce the formula by observing their inputs, outputs and values stored in the registers.<\/p>\n
This technique almost always yields a result. On the downside, it’s very time consuming. First, you have to work out the numbers and the arithmetic operations. But then, to interpret this calculation, you need to know where these operands came from, which can recursively create additional layers of investigation.<\/p>\n
However, the heuristics based on the general optimizer knowledge can dramatically reduce the research time.<\/p>\n
Fortunately, Jonathan had correctly assumed that the calculation depends on the system statistics seek time (IOSEEKTIM) and transfer rate (IOTFRSPEED), which had been set to their default values 10ms and 4k, respectively. So, whenever I observed those numbers somewhere in the registers I reasonably assumed that they had came from the system statistics mentioned. After that, I had to rerun the experiment with changed values to see if the deduced formula still holds.<\/p>\n
But first of all, I had to identify the entry point, i.e. a higher level Oracle function involved in the cost calculation.<\/p>\n
kkeSortCosts<\/h2>\n
I did that by enriching trace with call stacks<\/a>, a troubleshooting technique, which I had described in a previous blog post. Basically, I’m using DTrace for capturing the call stack whenever a string of interest gets written into the trace file:<\/p>\n
sudo -u root \/usr\/sbin\/dtrace -p 6178 -s call_stack_trace.d '\"Total\"'\n\nSORT ressource         Sort statistics\n  Sort width:         306 Area size:      268288 Max Area size:    53686272\n  Degree:               1\n  Blocks to Sort: 49 Row size:     16 Total Rows:         100000\n  Initial runs:   2 Merge pas\nlibc.so.1`__write+0xa\na.out`sdbgrfuwf_write_file+0x42\na.out`sdbgrfwf_write_file+0x3a\na.out`dbgtfdFileWrite+0x210\na.out`dbgtfdFileAccessCbk+0x177\na.out`dbgtfWriteRec+0x585\na.out`dbgtRecVAWriteDisk+0xaa\na.out`dbgtTrcVaList_int+0xa96\na.out`dbgtTrc_int+0xa6\na.out`kkeSortCosts+0x2287\na.out`kkesrcCard+0x63\na.out`kkoqbc+0x36eb\na.out`apakkoqb+0xa1\na.out`apaqbdDescendents+0x20e\na.out`apadrv+0xae5\na.out`opitca+0x9ca\na.out`kksFullTypeCheck+0x4c\noracle`rpiswu2+0x20c\na.out`kksLoadChild+0x29f6\na.out`kxsGetRuntimeLock+0x79d<\/code><\/pre>\n
As you can see, the function kkeSortCosts<\/i> was the one which produced the trace entries, so I assumed it orchestrates the whole sort cost calculation.<\/p>\n
I confirmed that by tracing function calls made by kkeSortCosts<\/i>. kkesIOScaleFactor<\/i> is one of such functions, for which I captured a couple of call stacks:<\/p>\n
dtrace -q -n 'pid$target::kkesIOScaleFactor:entry{ ustack(); }' -p 28898\n\na.out`kkesIOScaleFactor\na.out`kkesScaleIO+0xac\na.out`kkeTbScanIOCost+0x24\n...\na.out`kkesIOScaleFactor\na.out`kkesScaleIO+0xac\na.out`kkeSortCosts+0xdec\n...<\/code><\/pre>\n
As you can see, there are two different cases where the functions kkesIOScaleFactor<\/i> and kkesScaleIO<\/i> are called. One is the table scan cost calculation (kkeTbScanIOCost<\/i>). The other is the sort cost calculation (kkeSortCosts<\/i>).<\/p>\n
Obviously, both kkesScaleIO<\/i> and kkesIOScaleFactor<\/i> are generic functions participating in IO cost calculation; as such, they are undoubtedly worth a more detailed examination.<\/p>\n
kkesScaleIO<\/h2>\n
I set up a breakpoint on the exit from kkesScaleIO<\/i> to record the return values which are passed through the XMM0 register.<\/p>\n
break kkesScaleIO_RETURN_ADDRESS\ncommands 1\np $xmm0\nbacktrace 3\ncontinue\nend<\/code><\/pre>\n
Below are the outputs for 8k<\/span> and 32k<\/span>, respectively:<\/p>\n
$3 = {v4_float = {0, 3.171875, 0, 0}, v2_double = {54<\/span>, 0}, v16_int8 = {0, 0, 0, 0, 0, 0, 75, 64, 0, 0, 0, 0, 0, 0, 0, 0}, v8_int16 = {0, \n    0, 0, 16459, 0, 0, 0, 0}, v4_int32 = {0, 1078657024, 0, 0}, v2_int64 = {4632796641680687104, 0}, uint128 = 4632796641680687104}\n#0  0x00000000104e5dc3 in kkesScaleIO ()\n#1  0x000000000a4e5dbc in kkeSortCosts ()\n#2  0x0000000010550133 in kkesrcCard ()<\/code><\/pre>\n
$6 = {v4_float = {0, 3.0390625, 0, 0}, v2_double = {37<\/span>, 0}, v16_int8 = {0, 0, 0, 0, 0, -128, 66, 64, 0, 0, 0, 0, 0, 0, 0, 0}, v8_int16 = {\n    0, 0, -32768, 16450, 0, 0, 0, 0}, v4_int32 = {0, 1078099968, 0, 0}, v2_int64 = {4630404104378646528, 0}, \n  uint128 = 4630404104378646528}\n#0  0x00000000104e5dc3 in kkesScaleIO ()\n#1  0x000000000a4e5dbc in kkeSortCosts ()\n#2  0x0000000010550133 in kkesrcCard ()<\/code><\/pre>\n
By the way, I also included backtrace, just to make sure that the output observed is for the sort cost calculation (as opposed to the tablescan cost calculation).<\/p>\n
Subsequently, I compared the return values 54<\/span> and 37<\/span> with the numbers in the optimizer trace. It was easy to establish the following relationship:<\/p>\n
<\/a><\/p>\n
 (2) <\/span>   <\/span>\"\begin{equation*} <\/p>\n
where:<\/p>\n
Blocks to Sort<\/h1>\n
By simple eyeballing I first identified that Total IO sort cost<\/i><\/span> is the sum of two other values exposed in the sort section in the optimizer trace: Blocks to Sort<\/i><\/span> and IO Cost \/ pass<\/i><\/span>:<\/p>\n
<\/a><\/p>\n
 (1) <\/span>   <\/span>\"\begin{equation*} <\/p>\n
Blocks to Sort<\/i><\/span> is the fixed part of the cost calculation. Therefore, it’s the main contributor to the relatively large difference between the cost calculations for different block sizes.<\/p>\n
A more challenging part is to figure out the IO Cost \/ pass<\/i><\/span> calculation, the other summand in the equation 1<\/a>.<\/p>\n