Recently one of my students asked me if there is any correlation between the AU size in ASM diskgroup and parameter db_file_multiblock_read_count. I made some tests but results are very strange.
I have 4 same tables, located in 4 different diskgroups:
1 select t.table_name, g.name, t.blocks, g.ALLOCATION_UNIT_SIZE
2 from dba_tables t, dba_data_files d, v$asm_diskgroup g
3 where t.tablespace_name=d.tablespace_name
4 and g.name=substr(d.file_name,2,instr(d.file_name,'/')-2)
5 and t.owner='SH'
6* and t.table_name like 'SALES%'
SQL> /
TABLE_NAME NAME BLOCKS ALLOCATION_UNIT_SIZE
---------- ------------------------------ ---------- --------------------
SALES16M DATA16M 93551 16777216
SALES32M DATA32M 93551 33554432
SALES1M DATA1M 93551 1048576
SALES4M DATA4M 93551 4194304
15 LINESTEXT / UTF-8
All tables are smaller then a hidden parameter "_small_table_threshold" so table access full on all tables will be using db file scattered read.
SQL> ;
1 select p.ksppinm, v.ksppstvl
2 from x$ksppi p, x$ksppcv v
3 where p.indx=v.indx
4* and p.ksppinm='_small_table_threshold'
SQL> /
KSPPINM KSPPSTVL
---------------------------------------- ------------------------------
_small_table_threshold 101527
11 LINESTEXT / UTF-8
Let’s start the main test. Parameter db_file_multiblock_read_count is set to the default value
[oracle@rico ~]$ sqlplus sh/sh
SQL*Plus: Release 12.1.0.2.0 Production on Fri Jul 17 10:30:36 2015
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Wed Jul 01 2015 11:16:33 +02:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
SQL> sho parameters db_file_multiblock
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 128
SQL>
20 LINESTEXT / UTF-8
I will identify the server process, correlated with my session
SQL> ;
1 select spid
2 from v$process p, v$session s
3 where p.addr=s.paddr
4* and s.username='SH'
SQL> /
SPID
------------------------
10430
12 LINESTEXT / UTF-8
Now I will use strace on this server process:
[root@rico ~]# strace -c -p 10430
Process 10430 attached - interrupt to quit
3 LINESTEXT / UTF-8
I will gather results for the following queries:
SQL> select count(1) from SALES16M;
COUNT(1)
----------
19295703
SQL> select count(1) from SALES32M;
COUNT(1)
----------
19295703
SQL> select count(1) from SALES1M;
COUNT(1)
----------
19295703
SQL> select count(1) from SALES4M;
COUNT(1)
----------
19295703
24 LINESTEXT / UTF-8
Results for SALES16M
[root@rico ~]# strace -c -p 10430
Process 10430 attached - interrupt to quit
^CProcess 10430 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.053000 71 750 pread
0.00 0.000000 0 31 read
0.00 0.000000 0 2 write
0.00 0.000000 0 16 7 open
0.00 0.000000 0 9 close
0.00 0.000000 0 1 stat
0.00 0.000000 0 1 fstat
0.00 0.000000 0 28 lseek
0.00 0.000000 0 3 mmap
0.00 0.000000 0 2 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 1 uname
0.00 0.000000 0 10 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 164 getrusage
0.00 0.000000 0 28 times
0.00 0.000000 0 1 getuid
0.00 0.000000 0 1 io_getevents
0.00 0.000000 0 1 io_submit
------ ----------- ----------- --------- --------- ----------------
100.00 0.053000 1051 7 total
27 LINESTEXT / UTF-8
Results for SALES32M
[root@rico ~]# strace -c -p 10430
Process 10430 attached - interrupt to quit
^CProcess 10430 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
98.16 0.053462 72 747 pread
1.84 0.001000 500 2 read
0.00 0.000000 0 2 write
0.00 0.000000 0 1 open
0.00 0.000000 0 1 close
0.00 0.000000 0 1 mmap
0.00 0.000000 0 3 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 164 getrusage
0.00 0.000000 0 28 times
------ ----------- ----------- --------- --------- ----------------
100.00 0.054462 950 total
18 LINESTEXT / UTF-8
Results for SALES1M
[root@rico ~]# strace -c -p 10430
Process 10430 attached - interrupt to quit
^CProcess 10430 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
48.58 0.015000 26 583 io_getevents
39.99 0.012349 75 164 pread
11.43 0.003528 6 583 io_submit
0.00 0.000000 0 3 read
0.00 0.000000 0 2 write
0.00 0.000000 0 2 open
0.00 0.000000 0 2 close
0.00 0.000000 0 1 semctl
0.00 0.000000 0 3 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 164 getrusage
0.00 0.000000 0 29 times
0.00 0.000000 0 3 semtimedop
------ ----------- ----------- --------- --------- ----------------
100.00 0.030877 1540 total
21 LINESTEXT / UTF-8
Results for SALES4M
[root@rico ~]# strace -c -p 10430
Process 10430 attached - interrupt to quit
^CProcess 10430 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
95.16 0.043000 65 664 pread
2.62 0.001186 14 83 io_submit
2.21 0.001000 12 83 io_getevents
0.00 0.000000 0 2 read
0.00 0.000000 0 2 write
0.00 0.000000 0 21 getrusage
0.00 0.000000 0 12 times
------ ----------- ----------- --------- --------- ----------------
100.00 0.045186 867 total
15 LINESTEXT / UTF-8
As we can see, the ASYNC IO represented by syscalls: io_submit and io_getevents are mostly used while scanning table located in diskgroup with 1MB AU.
At first I thought that this is correlated with db_file_multiblock_read_count. The default value (128) multiplied by 8k (block size for my database) is exactly 1M. So I made a few more tests with altered values for this parameter. First results where promising – I have managed to get ASYNC IO for all of the tables.
But then I made the final (a little stupid :)) test. After creating a session I have altered value of the db_file_multiblock_read_count to 128. Yes: 128. So the same as default:
[oracle@rico ~]$ sqlplus sh/sh
SQL*Plus: Release 12.1.0.2.0 Production on Fri Jul 17 10:49:25 2015
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Fri Jul 17 2015 10:48:43 +02:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
SQL> sho parameters db_file_multiblock
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 128
SQL> alter session set db_file_multiblock_read_count=128;
Session altered.
23 LINESTEXT / UTF-8
Let’s check the results now:
SALES16M
[root@rico ~]# strace -c -p 11208
Process 11208 attached - interrupt to quit
^CProcess 11208 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
53.96 0.007032 9 747 io_submit
46.04 0.006000 8 747 io_getevents
0.00 0.000000 0 31 read
0.00 0.000000 0 2 write
0.00 0.000000 0 16 7 open
0.00 0.000000 0 9 close
0.00 0.000000 0 1 stat
0.00 0.000000 0 1 fstat
0.00 0.000000 0 28 lseek
0.00 0.000000 0 8 mmap
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 4 pread
0.00 0.000000 0 1 uname
0.00 0.000000 0 10 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 164 getrusage
0.00 0.000000 0 34 times
0.00 0.000000 0 1 getuid
------ ----------- ----------- --------- --------- ----------------
100.00 0.013032 1807 7 total
27 LINESTEXT / UTF-8
SALES32M
[root@rico ~]# strace -c -p 11208
Process 11208 attached - interrupt to quit
^CProcess 11208 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
54.18 0.008278 11 746 io_submit
45.82 0.007000 9 746 io_getevents
0.00 0.000000 0 2 read
0.00 0.000000 0 2 write
0.00 0.000000 0 1 open
0.00 0.000000 0 1 close
0.00 0.000000 0 1 pread
0.00 0.000000 0 3 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 164 getrusage
0.00 0.000000 0 28 times
------ ----------- ----------- --------- --------- ----------------
100.00 0.015278 1695 total
19 LINESTEXT / UTF-8
SALES1M
[root@rico ~]# strace -c -p 11208
Process 11208 attached - interrupt to quit
^CProcess 11208 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
65.36 0.010000 13 749 io_getevents
34.64 0.005300 7 746 io_submit
0.00 0.000000 0 3 read
0.00 0.000000 0 2 write
0.00 0.000000 0 2 open
0.00 0.000000 0 2 close
0.00 0.000000 0 1 pread
0.00 0.000000 0 1 semctl
0.00 0.000000 0 3 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 164 getrusage
0.00 0.000000 0 28 times
0.00 0.000000 0 2 semtimedop
------ ----------- ----------- --------- --------- ----------------
100.00 0.015300 1704 total
21 LINESTEXT / UTF-8
SALES4M
[root@rico ~]# strace -c -p 11208
Process 11208 attached - interrupt to quit
^CProcess 11208 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
50.10 0.006000 8 746 io_getevents
49.90 0.005975 8 746 io_submit
0.00 0.000000 0 2 read
0.00 0.000000 0 2 write
0.00 0.000000 0 1 pread
0.00 0.000000 0 21 getrusage
0.00 0.000000 0 12 times
------ ----------- ----------- --------- --------- ----------------
100.00 0.011975 1530 total
15 LINESTEXT / UTF-8
So EVERYTHING is being read with ASYNC IO!!! And this not the craziest thing – the other sessions are also using ASYNC IO for those tables now. Without altering the parameter. I have tried to flush buffer_cache and shared_pool, but with no success. The situation goes back to square one after restarting the instance.
I occurs that it takes only one session to set the parameter to any value – even the same value as it already was by default. And when the first query will use db file scattered read in async mode – all the other sessions, querying tables on ASM will also use io_getevents and io_submit instead of pread. (!!!)
[oracle@rico ~]$ sqlplus sh/sh
SQL*Plus: Release 12.1.0.2.0 Production on Fri Jul 17 10:59:22 2015
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Fri Jul 17 2015 10:56:53 +02:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
SQL> alter session set db_file_multiblock_read_count=128;
Session altered.
SQL> select count(1) from sales16m;
COUNT(1)
----------
19295703
SQL> Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
[oracle@rico ~]$ sqlplus sh/sh
SQL*Plus: Release 12.1.0.2.0 Production on Fri Jul 17 10:59:51 2015
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Fri Jul 17 2015 10:59:22 +02:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
SQL> select count(1) from SALES4M;
COUNT(1)
----------
19295703
SQL> Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
[oracle@rico ~]$ sqlplus sh/sh
SQL*Plus: Release 12.1.0.2.0 Production on Fri Jul 17 11:00:43 2015
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Fri Jul 17 2015 10:59:51 +02:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
SQL> select count(1) from sales32m;
COUNT(1)
----------
19295703
67 LINESTEXT / UTF-8
The appropriate strace results are:
[root@rico ~]# strace -c -p 11782
Process 11782 attached - interrupt to quit
^CProcess 11782 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
53.97 0.006000 8 747 io_getevents
45.60 0.005069 7 747 io_submit
0.43 0.000048 1 34 times
0.00 0.000000 0 31 read
0.00 0.000000 0 2 write
0.00 0.000000 0 16 7 open
0.00 0.000000 0 9 close
0.00 0.000000 0 1 stat
0.00 0.000000 0 1 fstat
0.00 0.000000 0 28 lseek
0.00 0.000000 0 7 mmap
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 4 pread
0.00 0.000000 0 1 uname
0.00 0.000000 0 10 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 164 getrusage
0.00 0.000000 0 1 getuid
------ ----------- ----------- --------- --------- ----------------
100.00 0.011117 1806 7 total
[root@rico ~]# strace -c -p 11793
Process 11793 attached - interrupt to quit
^CProcess 11793 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
51.71 0.007000 10 731 io_getevents
48.29 0.006536 9 731 io_submit
0.00 0.000000 0 32 read
0.00 0.000000 0 2 write
0.00 0.000000 0 17 7 open
0.00 0.000000 0 10 close
0.00 0.000000 0 1 stat
0.00 0.000000 0 1 fstat
0.00 0.000000 0 28 lseek
0.00 0.000000 0 9 mmap
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 17 pread
0.00 0.000000 0 1 uname
0.00 0.000000 0 1 semctl
0.00 0.000000 0 10 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 209 getrusage
0.00 0.000000 0 50 times
0.00 0.000000 0 1 getuid
0.00 0.000000 0 2 semtimedop
------ ----------- ----------- --------- --------- ----------------
100.00 0.013536 1856 7 total
[root@rico ~]# strace -c -p 11823
Process 11823 attached - interrupt to quit
^CProcess 11823 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
51.65 0.005342 7 731 io_submit
48.35 0.005000 7 731 io_getevents
0.00 0.000000 0 31 read
0.00 0.000000 0 2 write
0.00 0.000000 0 16 7 open
0.00 0.000000 0 9 close
0.00 0.000000 0 1 stat
0.00 0.000000 0 1 fstat
0.00 0.000000 0 28 lseek
0.00 0.000000 0 9 mmap
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 17 pread
0.00 0.000000 0 1 uname
0.00 0.000000 0 10 fcntl
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 209 getrusage
0.00 0.000000 0 50 times
0.00 0.000000 0 1 getuid
------ ----------- ----------- --------- --------- ----------------
100.00 0.010342 1850 7 total
81 LINESTEXT / UTF-8
Results from perf seams to confirm this strange behaviour.
Before setting the parameter:
[root@rico ~]# perf record -p 13521
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.061 MB perf.data (~2644 samples) ]
[root@rico ~]# perf report | grep aio
0.06% oracle_13521_or [kernel.kallsyms] [k] do_aio_read
[root@rico ~]# perf report | grep pread
0.06% oracle_13521_or libpthread-2.12.so [.] __pread_nocancel
9 LINESTEXT / UTF-8
After setting the parameter:
[root@rico ~]# perf record -p 13573
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.061 MB perf.data (~2680 samples) ]
[root@rico ~]# perf report | grep pread
[root@rico ~]# perf report | grep aio
0.18% oracle_13573_or libaio.so.1.0.1 [.] 0x0000000000000615
0.06% oracle_13573_or oracle [.] ksfdaio
0.06% oracle_13573_or [kernel.kallsyms] [k] aio_put_req
0.06% oracle_13573_or [kernel.kallsyms] [k] aio_run_iocb
11 LINESTEXT / UTF-8
I made tests on: Oracle 12.1.0.2 EE (OEL 6.6) and Oracle 11.2.0.3 EE (OEL 6.3)
So the conclusion is: WTF?!