Martins Blog

Trying to explain complex things in simple terms

Interesting observations executing SLOB2 with ext4 and xfs on SSD

Posted by Martin Bach on October 31, 2014

My lab server has 2 SSDs, one is connected using SATA 2 and another is connected using SATA 3. I’d expect the SATA 3 connected device to be equally well equipped or even better to do work than the “old” interface. I ran SLOB on these devices to find out if there was a difference. To my great surprise the SATA2 – connected SSD performed a lot better than the SATA 3 device, as shown in the AWR report! Initially I was not entirely sure why, since the FIO results on both devices are roughly equal. You will see why though when reading this post. In summary: use XFS for any concurrent writes. Or maybe ASM.

Let’s investigate

Let’s do a little I/O investigation because a) it’s cool and b) you can.

This is Oracle Linux 6.5 with UEK 3. A word of warning though-ext4 has been, let’s say, a little flaky. I first found out about that in 2011 (https://martincarstenbach.wordpress.com/2011/11/04/an-interesting-problem-with-ext4-on-oracle-linux-5-5/) and Oracle now published a MOS note: ORA-1578 ORA-353 ORA-19599 Corrupt blocks with zeros when filesystemio_options=SETALL on ext4 file system using Linux (Doc ID 1487957.1). I am on a reasonably recent version so the observations in this post are probably not related to the above notes. The device in /dev/sda uses SATA2 and the file system /u01/app/oracle/oradata is XFS formatted. The other SSD, /dev/sde uses EXT4 but is connected via SATA3 provided by a PCIe v2 x4 card. I wish I had PCIe v3 but my Opteron 6200 system doesn’t support native SATA6G.

SLOB

I created a 12c non-CDB database for SLOB with the IOPS tablespace on my SATA 2 SSD that’s mounted on XFS. Every test has been repeated four times. Should you want to follow along, here is my slob.conf:

[/m/kvm/oracle]$ cat ~/SLOB2/SLOB/slob.conf 

UPDATE_PCT=20
RUN_TIME=120
WORK_LOOP=0
SCALE=10000
WORK_UNIT=256
REDO_STRESS=HEAVY
LOAD_PARALLEL_DEGREE=8
SHARED_DATA_MODULUS=0

# Settings for SQL*Net connectivity:
#ADMIN_SQLNET_SERVICE=slob
#SQLNET_SERVICE_BASE=slob
#SQLNET_SERVICE_MAX=2
#SYSDBA_PASSWD="change_on_install"

export UPDATE_PCT RUN_TIME WORK_LOOP SCALE WORK_UNIT LOAD_PARALLEL_DEGREE REDO_STRESS SHARED_DATA_MODULUS

[oracle@ol62 - /u01/app/oracle/product/12.1.0.2/dbhome_1: SLOB12]

Notice the UPDATE_PCT-that will become important later. The SLOB configuration has been created using a call to ./setup.sh with IOPS as the target tablespace and 128 users which is the default. My database uses this initialisation file shown below, which is more or lesse the same as the default (and my buffer cache is indeed 16M)

[oracle@ol62 - /u01/app/oracle/product/12.1.0.2/dbhome_1: SLOB12]
[/m/kvm/oracle]$ cat /u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initSLOB12.ora 

#set the following to paths that make sense on your system:
db_create_file_dest = '/u01/app/oracle/oradata'
control_files='/u01/app/oracle/oradata/SLOB12/controlfile/o1_mf_b52b4lvk_.ctl'

db_name = SLOB12
compatible = 12.1.0.2.0
undo_management = auto
db_block_size = 8192
db_files = 2000
processes = 500
shared_pool_size = 1G
db_cache_size = 10M     # Will force maximum physical I/O
#db_cache_size = 15G    # Sufficient for cached runs with reference scale (10,000 rows) and 128 sessions
filesystemio_options = setall
parallel_max_servers = 0
log_buffer = 134217728
cpu_count = 2
pga_aggregate_target = 1G
remote_login_passwordfile = exclusive
workarea_size_policy = auto
recyclebin = off

# The following are needed to force db file sequential read. Omit for direct path short scans.
# If you would like to investigate a blend of short scans mixed with single-block random I/O
# then comment out these three parameters :
_db_block_prefetch_limit = 0
_db_block_prefetch_quota = 0
_db_file_noncontig_mblock_read_count = 0

# Uncomment the following if suffering library cache contention (at larger numbers of sessions) or high log file sync waits
# at CPU-saturated levels.
#_cursor_obsolete_threshold=130
#_high_priority_processes=LGWR

[oracle@ol62 - /u01/app/oracle/product/12.1.0.2/dbhome_1: SLOB12]

After the fourth execution of ./runit.sh 16 I moved the IOPS data file from /dev/sda to /dev/sde and ran another 4 tests.

Observations

I ran an AWR difference report to compare the performance of the XFS and EXT4 SSDs. The most interesting bit is right on the top. Apologies for the very wide output-that’s the way the text report lays it out.

WORKLOAD REPOSITORY COMPARE PERIOD REPORT

Snapshot Set    DB Id    Instance     Inst Num Release     Cluster Host          Std Block Size
------------ ----------- ------------ -------- ----------- ------- ------------ ---------------
First (1st)   1269760792 SLOB12              1 12.1.0.2.0  NO      ol62.localdo     8192
Second (2nd)  1269760792 SLOB12              1 12.1.0.2.0  NO      ol62.localdo     8192

Snapshot Set  Begin Snap Id Begin Snap Time            End Snap Id End Snap Time                  Avg Active Users           Elapsed Time (min)            DB time (min)
------------ -------------- ------------------------- ------------ ------------------------- -------------------------- -------------------------- --------------------------
1st                      41 31-Oct-14 12:18:14 (Fri)           42 31-Oct-14 12:20:17 (Fri)                      15.8                       2.0                      32.1
2nd                      49 31-Oct-14 12:38:18 (Fri)           50 31-Oct-14 12:40:20 (Fri)                      15.8                       2.0                      32.3
                                                                                      ~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                                                      %Diff:                     0.2%                       0.0%                       0.5%

Host Configuration Comparison
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                     1st                  2nd                 Diff     %Diff
----------------------------------- -------------------- -------------------- -------------------- ---------
Number of CPUs:                                       24                   24                    0       0.0
Number of CPU Cores:                                  24                   24                    0       0.0
Number of CPU Sockets:                                 2                    2                    0       0.0
Physical Memory:                                64413.7M             64413.7M                   0M       0.0
Load at Start Snapshot:                             9.13                 9.57                  .44       4.8
Load at End Snapshot:                              15.38                 15.6                  .22       1.4
%User Time:                                         1.24                  .64                  -.6     -48.4
%System Time:                                        .75                  .74                 -.02      -1.3
%Idle Time:                                        97.89                 98.6                  .71       0.7
%IO Wait Time:                                     35.21                 9.06               -26.15     -74.3
Cache Sizes
~~~~~~~~~~~
                          1st (M)    2nd (M)   Diff (M)    %Diff
---------------------- ---------- ---------- ---------- --------
Memory Target
.....SGA Target
..........Buffer Cache       16.0       16.0        0.0      0.0
..........Shared Pool     1,024.0    1,024.0        0.0      0.0
..........Large Pool
..........Java Pool          16.0       16.0        0.0      0.0
..........Streams Pool
.....PGA Target           1,024.0    1,024.0        0.0      0.0
Log Buffer                  128.0      128.0        0.0      0.0
In-Memory Area

Workload Comparison
~~~~~~~~~~~~~~~~~~~                      1st Per Sec          2nd Per Sec      %Diff              1st Per Txn          2nd Per Txn      %Diff
                                     ---------------      ---------------     ------          ---------------      ---------------     ------
                       DB time:                 15.8                 15.8        0.2                      2.5                  4.4       78.7
                      CPU time:                  0.5                  0.3      -29.8                      0.1                  0.1       28.6
           Background CPU time:                  0.1                  0.1      -40.0                      0.0                  0.0        0.0
             Redo size (bytes):          8,721,293.5          4,652,147.0      -46.7              1,379,498.8          1,311,306.6       -4.9
         Logical read (blocks):             10,403.9              5,231.1      -49.7                  1,645.6              1,474.5      -10.4
                 Block changes:              5,216.5              2,640.2      -49.4                    825.1                744.2       -9.8
        Physical read (blocks):              7,412.5              3,750.0      -49.4                  1,172.5              1,057.0       -9.8
       Physical write (blocks):              3,369.0              1,729.0      -48.7                    532.9                487.4       -8.5
              Read IO requests:              7,411.8              3,749.3      -49.4                  1,172.4              1,056.8       -9.9
             Write IO requests:              3,018.0              1,538.2      -49.0                    477.4                433.6       -9.2
                  Read IO (MB):                 57.9                 29.3      -49.4                      9.2                  8.3       -9.8
                 Write IO (MB):                 26.3                 13.5      -48.7                      4.2                  3.8       -8.4
                  IM scan rows:                  0.0                  0.0        0.0                      0.0                  0.0        0.0
       Session Logical Read IM:
                    User calls:                  1.4                  1.4       -1.4                      0.2                  0.4       77.3
                  Parses (SQL):                  5.9                  6.3        7.5                      0.9                  1.8       91.4
             Hard parses (SQL):                  0.1                  0.3      107.1                      0.0                  0.1      300.0
            SQL Work Area (MB):                  0.6                  0.4      -25.9                      0.1                  0.1      -25.9
                        Logons:                  0.1                  0.1        0.0                      0.0                  0.0      100.0
                Executes (SQL):                 38.1                 23.7      -37.6                      6.0                  6.7       11.1
                  Transactions:                  6.3                  3.5      -43.8

                                               First               Second       Diff
                                     ---------------      ---------------     ------
     % Blocks changed per Read:                 50.1                 50.5        0.3
              Recursive Call %:                 98.1                 97.6       -0.6
    Rollback per transaction %:                  0.0                  0.0        0.0
                 Rows per Sort:                 68.3                 35.4      -32.9
    Avg DB time per Call (sec):                 11.3                 11.5        0.2</pre>
<pre>...

I copied the header  from the report  to show you that nothing really changed between the test executions, and that I’m going to do a lot of I/O since the buffer cache is only 16 MB.

What is striking is that the physical reads and writes are roughly half of what I saw during the first batch of executions. The culprit is found quickly. In this scenario I chose SLOB is primarily performing sequential reads:

Top Timed Events   First DB/Inst: SLOB12/SLOB12 Snaps: 41-42 (Elapsed time: 122.27 sec  DB time: 1925.83 sec),  Second DB/Inst: SLOB12/SLOB12 Snaps: 49-50 (Elapsed time: 122.614 sec  DB time: 1935.33 sec)
-> Events with a "-" did not make the Top list in this set of snapshots, but are displayed for comparison purposes

                                               1st                                                                                                2nd
------------------------------------------------------------------------------------------------   ------------------------------------------------------------------------------------------------
Event                          Wait Class           Waits      Time(s)  Avg Time(ms)    %DB time   Event                          Wait Class           Waits      Time(s)  Avg Time(ms)    %DB time
------------------------------ ------------- ------------ ------------ ------------- -----------   ------------------------------ ------------- ------------ ------------ ------------- -----------
 db file sequential read       User I/O           906,150      1,899.1           2.1        98.6    db file sequential read       User I/O           459,637      1,920.9           4.2        99.3
 db file parallel write        System I/O         116,318         60.0           0.5         3.1    db file async I/O submit      System I/O           2,975         97.2          32.7         5.0
 CPU time                                             N/A         57.7           N/A         3.0    CPU time                                             N/A         40.2           N/A         2.1
 log file parallel write       System I/O           3,485         47.4          13.6         2.5    log file parallel write       System I/O           1,881          3.2           1.7         0.2
 db file async I/O submit      System I/O           7,425          3.7           0.5         0.2    db file parallel write        System I/O           4,670          0.9           0.2         0.0
...

The IO times for the second interval (the EXT4 case) are twice as what they are on the first. But why? I thought at first that the PCIe card adds the extra latency. And I came up with a few other ideas that all remained that: ideas. Ideas are nice, but proof is better. Maybe there is indeed something odd? Or maybe there is something in the way that Oracle uses the device? To find out I used FIO. FIO is my favourite I/O benchmark when it comes to measuring raw performance. If the FIO benchmark results match the Oracle results then indeed there must be something wrong with the SSD or the way it is addressed. I spent a bit of time to compile FIO and ran a set of tests.

FIO

I was really quite curious to see what was happening during the execution of FIO-was the SATA3 SSD really slower? So I started FIO tests, using FIO 2.1.3. Using the same test harness, just the destination is different:

[~/fio-2.1.13]$ cat rand-read-sd*
[rand-read]
numjobs=4
rw=randread
directory=/u01/fio/data
size=5G
bs=8k
ioengine=libaio
buffered=0
iodepth=8

[rand-read]
numjobs=4
rw=randread
directory=/m/kvm/oracle
size=5G
bs=8k
ioengine=libaio
buffered=0
iodepth=8

[oracle@ol62 - /u01/app/oracle/product/12.1.0.2/dbhome_1: SLOB12]
[~/fio-2.1.13]$

The /u01 file system sits on /dev/sda, and uses XFS. /m/kvm/oracle is on /dev/sde, using EXT4. Here is the output from the tests:

[~/fio-2.1.13]$ ./fio rand-read-sde.fio
rand-read: (g=0): rw=randread, bs=8K-8K/8K-8K/8K-8K, ioengine=libaio, iodepth=8
...
fio-2.1.13
Starting 4 processes
rand-read: Laying out IO file(s) (1 file(s) / 5120MB)
rand-read: Laying out IO file(s) (1 file(s) / 5120MB)
rand-read: Laying out IO file(s) (1 file(s) / 5120MB)
Jobs: 3 (f=3): [r(3),_(1)] [99.2% done] [192.8MB/0KB/0KB /s] [24.7K/0/0 iops] [eta 00m:01s]
rand-read: (groupid=0, jobs=1): err= 0: pid=6124: Thu Oct 30 15:41:15 2014
  read : io=5120.0MB, bw=44174KB/s, iops=5521, runt=118686msec
    slat (usec): min=4, max=109, avg=13.06, stdev= 6.14
    clat (usec): min=128, max=43082, avg=1434.23, stdev=586.65
     lat (usec): min=140, max=43094, avg=1447.47, stdev=586.41
    clat percentiles (usec):
     |  1.00th=[  516],  5.00th=[  708], 10.00th=[  820], 20.00th=[  988],
     | 30.00th=[ 1112], 40.00th=[ 1240], 50.00th=[ 1352], 60.00th=[ 1480],
     | 70.00th=[ 1608], 80.00th=[ 1816], 90.00th=[ 2160], 95.00th=[ 2480],
     | 99.00th=[ 3184], 99.50th=[ 3472], 99.90th=[ 4192], 99.95th=[ 4576],
     | 99.99th=[ 6752]
    bw (KB  /s): min=27088, max=70928, per=24.99%, avg=44119.50, stdev=6314.88
    lat (usec) : 250=0.01%, 500=0.78%, 750=6.02%, 1000=14.12%
    lat (msec) : 2=65.54%, 4=13.37%, 10=0.15%, 20=0.01%, 50=0.01%
  cpu          : usr=1.89%, sys=11.05%, ctx=421189, majf=0, minf=44
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
rand-read: (groupid=0, jobs=1): err= 0: pid=6125: Thu Oct 30 15:41:15 2014
  read : io=5120.0MB, bw=44138KB/s, iops=5517, runt=118784msec
    slat (usec): min=4, max=108, avg=13.14, stdev= 6.14
    clat (usec): min=117, max=43252, avg=1435.31, stdev=587.66
     lat (usec): min=124, max=43264, avg=1448.64, stdev=587.40
    clat percentiles (usec):
     |  1.00th=[  502],  5.00th=[  700], 10.00th=[  820], 20.00th=[  988],
     | 30.00th=[ 1128], 40.00th=[ 1240], 50.00th=[ 1352], 60.00th=[ 1480],
     | 70.00th=[ 1624], 80.00th=[ 1816], 90.00th=[ 2160], 95.00th=[ 2480],
     | 99.00th=[ 3152], 99.50th=[ 3472], 99.90th=[ 4192], 99.95th=[ 4640],
     | 99.99th=[ 6688]
    bw (KB  /s): min=27504, max=69760, per=24.91%, avg=43972.22, stdev=6169.69
    lat (usec) : 250=0.07%, 500=0.92%, 750=5.84%, 1000=13.94%
    lat (msec) : 2=65.68%, 4=13.40%, 10=0.16%, 20=0.01%, 50=0.01%
  cpu          : usr=1.89%, sys=11.10%, ctx=421379, majf=0, minf=46
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
rand-read: (groupid=0, jobs=1): err= 0: pid=6126: Thu Oct 30 15:41:15 2014
  read : io=5120.0MB, bw=44230KB/s, iops=5528, runt=118538msec
    slat (usec): min=4, max=120, avg=12.59, stdev= 5.61
    clat (usec): min=185, max=42871, avg=1433.09, stdev=581.75
     lat (usec): min=196, max=42881, avg=1445.85, stdev=581.45
    clat percentiles (usec):
     |  1.00th=[  532],  5.00th=[  716], 10.00th=[  828], 20.00th=[  988],
     | 30.00th=[ 1128], 40.00th=[ 1240], 50.00th=[ 1352], 60.00th=[ 1464],
     | 70.00th=[ 1608], 80.00th=[ 1800], 90.00th=[ 2128], 95.00th=[ 2480],
     | 99.00th=[ 3152], 99.50th=[ 3440], 99.90th=[ 4192], 99.95th=[ 4576],
     | 99.99th=[ 7008]
    bw (KB  /s): min=27600, max=65952, per=25.01%, avg=44149.65, stdev=5945.98
    lat (usec) : 250=0.01%, 500=0.63%, 750=5.90%, 1000=14.17%
    lat (msec) : 2=65.89%, 4=13.25%, 10=0.15%, 20=0.01%, 50=0.01%
  cpu          : usr=1.74%, sys=11.20%, ctx=426219, majf=0, minf=44
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
rand-read: (groupid=0, jobs=1): err= 0: pid=6127: Thu Oct 30 15:41:15 2014
  read : io=5120.0MB, bw=47359KB/s, iops=5919, runt=110704msec
    slat (usec): min=4, max=114, avg=12.83, stdev= 5.90
    clat (usec): min=188, max=42988, avg=1337.06, stdev=571.06
     lat (usec): min=198, max=43000, avg=1350.07, stdev=570.63
    clat percentiles (usec):
     |  1.00th=[  446],  5.00th=[  620], 10.00th=[  748], 20.00th=[  900],
     | 30.00th=[ 1020], 40.00th=[ 1144], 50.00th=[ 1256], 60.00th=[ 1368],
     | 70.00th=[ 1512], 80.00th=[ 1704], 90.00th=[ 2040], 95.00th=[ 2352],
     | 99.00th=[ 3024], 99.50th=[ 3280], 99.90th=[ 3984], 99.95th=[ 4384],
     | 99.99th=[ 6624]
    bw (KB  /s): min=33664, max=51008, per=26.83%, avg=47369.34, stdev=4051.34
    lat (usec) : 250=0.01%, 500=1.45%, 750=8.72%, 1000=17.95%
    lat (msec) : 2=61.12%, 4=10.65%, 10=0.09%, 20=0.01%, 50=0.01%
  cpu          : usr=1.98%, sys=11.60%, ctx=410433, majf=0, minf=44
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs):
   READ: io=20480MB, aggrb=176551KB/s, minb=44137KB/s, maxb=47359KB/s, mint=110704msec, maxt=118784msec

Disk stats (read/write):
  sde: ios=2619049/4, merge=0/1, ticks=3663514/6, in_queue=3662827, util=100.00%

The best tool to look at IO without tracing block devices is collectl (in my opinion). I ran the extended disk stats in parallel:

[root@ol62 queue]# collectl -sD -i 5 --iosize --dskfilt sde
waiting for 5 second sample...

# DISK STATISTICS (/sec)
#          <---------reads---------><---------writes---------><--------averages--------> Pct
#Name       KBytes Merged  IOs Size  KBytes Merged  IOs Size  RWSize  QLen  Wait SvcTim Util
sde              0      0    0    0  125340    129  123 1021    1020   219  1749      8   99
sde              0      0    0    0  119608     58  118 1017    1017   156  1666      7   88
sde         146968      0  18K    8       0      0    0    0       8    31     1      0   89
sde         165435      0  20K    8       2      0    0    6       7    31     1      0   99
sde         187097      0  23K    8       0      0    0    0       8    31     1      0  100
sde         187113      0  23K    8       0      0    0    0       8    31     1      0   99
sde         157684      0  19K    8       0      0    0    0       8    31     1      0   99
sde         186542      0  23K    8       1      0    0    4       7    31     1      0  100
sde         186721      0  23K    8       0      0    0    0       8    31     1      0   99
sde         158416      0  19K    8       0      0    0    0       8    31     1      0  100
sde         187168      0  23K    8       0      0    0    0       8    31     1      0   99
sde         186027      0  23K    8       0      0    0    0       8    31     1      0  100
sde         158366      0  19K    8       0      0    0    0       8    31     1      0   99
sde         186028      0  23K    8       0      0    0    0       8    31     1      0   99
sde         186416      0  23K    8       0      0    0    0       8    31     1      0  100
sde         159102      0  19K    8       0      0    0    0       8    31     1      0  100
sde         186348      0  23K    8       0      0    0    0       8    31     1      0  100
sde         186859      0  23K    8       0      0    0    0       8    31     1      0   99
sde         153996      0  19K    8       0      0    0    0       8    31     1      0   99
sde         186043      0  23K    8       0      0    0    0       8    31     1      0  100
sde         185348      0  23K    8       0      0    0    0       8    31     1      0   99
sde         158150      0  19K    8       0      0    0    0       8    31     1      0   99
sde         186148      0  23K    8       0      0    0    0       8    31     1      0   99
sde         185900      0  23K    8       0      0    0    0       8    31     1      0   99
sde         159353      0  19K    8       0      0    0    0       8    25     1      0   99
sde         167065      0  20K    8       0      0    0    0       8    22     0      0   86
sde              0      0    0    0       0      0    0    0       0     0     0      0    0

This matches the FIO output-and indeed, the device can do around 23k IOPS with an 8k IO size. What about the XFS mount?

[~/fio-2.1.13]$ ./fio rand-read-sda.fio
rand-read: (g=0): rw=randread, bs=8K-8K/8K-8K/8K-8K, ioengine=libaio, iodepth=8
...
fio-2.1.13
Starting 4 processes
rand-read: Laying out IO file(s) (1 file(s) / 5120MB)
rand-read: Laying out IO file(s) (1 file(s) / 5120MB)
rand-read: Laying out IO file(s) (1 file(s) / 5120MB)
Jobs: 4 (f=4): [r(4)] [100.0% done] [191.3MB/0KB/0KB /s] [24.5K/0/0 iops] [eta 00m:00s]
rand-read: (groupid=0, jobs=1): err= 0: pid=6329: Thu Oct 30 15:52:03 2014
  read : io=5120.0MB, bw=49087KB/s, iops=6135, runt=106809msec
    slat (usec): min=3, max=93, avg= 7.90, stdev= 6.40
    clat (usec): min=280, max=35113, avg=1294.26, stdev=152.91
     lat (usec): min=285, max=35130, avg=1302.35, stdev=152.60
    clat percentiles (usec):
     |  1.00th=[ 1112],  5.00th=[ 1160], 10.00th=[ 1192], 20.00th=[ 1240],
     | 30.00th=[ 1272], 40.00th=[ 1272], 50.00th=[ 1288], 60.00th=[ 1304],
     | 70.00th=[ 1320], 80.00th=[ 1352], 90.00th=[ 1384], 95.00th=[ 1416],
     | 99.00th=[ 1480], 99.50th=[ 1512], 99.90th=[ 1672], 99.95th=[ 2224],
     | 99.99th=[ 3024]
    bw (KB  /s): min=46000, max=49536, per=25.02%, avg=49124.10, stdev=291.98
    lat (usec) : 500=0.01%, 750=0.01%, 1000=0.03%
    lat (msec) : 2=99.89%, 4=0.07%, 10=0.01%, 20=0.01%, 50=0.01%
  cpu          : usr=2.39%, sys=8.05%, ctx=505195, majf=0, minf=43
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
rand-read: (groupid=0, jobs=1): err= 0: pid=6330: Thu Oct 30 15:52:03 2014
  read : io=5120.0MB, bw=49093KB/s, iops=6136, runt=106795msec
    slat (usec): min=3, max=114, avg= 7.55, stdev= 5.74
    clat (usec): min=263, max=35353, avg=1294.46, stdev=155.68
     lat (usec): min=271, max=35369, avg=1302.21, stdev=155.46
    clat percentiles (usec):
     |  1.00th=[ 1112],  5.00th=[ 1160], 10.00th=[ 1192], 20.00th=[ 1256],
     | 30.00th=[ 1272], 40.00th=[ 1288], 50.00th=[ 1288], 60.00th=[ 1304],
     | 70.00th=[ 1320], 80.00th=[ 1352], 90.00th=[ 1384], 95.00th=[ 1416],
     | 99.00th=[ 1480], 99.50th=[ 1512], 99.90th=[ 1672], 99.95th=[ 2224],
     | 99.99th=[ 3184]
    bw (KB  /s): min=45728, max=49472, per=25.02%, avg=49123.20, stdev=300.30
    lat (usec) : 500=0.01%, 750=0.01%, 1000=0.02%
    lat (msec) : 2=99.89%, 4=0.07%, 10=0.01%, 20=0.01%, 50=0.01%
  cpu          : usr=2.42%, sys=7.88%, ctx=549312, majf=0, minf=46
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
rand-read: (groupid=0, jobs=1): err= 0: pid=6331: Thu Oct 30 15:52:03 2014
  read : io=5120.0MB, bw=49080KB/s, iops=6134, runt=106824msec
    slat (usec): min=3, max=137, avg= 7.70, stdev= 5.87
    clat (usec): min=266, max=35102, avg=1294.64, stdev=147.64
     lat (usec): min=274, max=35121, avg=1302.52, stdev=147.39
    clat percentiles (usec):
     |  1.00th=[ 1112],  5.00th=[ 1160], 10.00th=[ 1208], 20.00th=[ 1256],
     | 30.00th=[ 1272], 40.00th=[ 1272], 50.00th=[ 1288], 60.00th=[ 1304],
     | 70.00th=[ 1320], 80.00th=[ 1352], 90.00th=[ 1384], 95.00th=[ 1416],
     | 99.00th=[ 1480], 99.50th=[ 1512], 99.90th=[ 2064], 99.95th=[ 2256],
     | 99.99th=[ 3600]
    bw (KB  /s): min=45888, max=49536, per=25.02%, avg=49110.62, stdev=295.81
    lat (usec) : 500=0.01%, 750=0.01%, 1000=0.04%
    lat (msec) : 2=99.84%, 4=0.10%, 10=0.01%, 20=0.01%, 50=0.01%
  cpu          : usr=2.32%, sys=8.07%, ctx=536841, majf=0, minf=44
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8
rand-read: (groupid=0, jobs=1): err= 0: pid=6332: Thu Oct 30 15:52:03 2014
  read : io=5120.0MB, bw=49080KB/s, iops=6134, runt=106824msec
    slat (usec): min=3, max=106, avg= 7.66, stdev= 5.93
    clat (usec): min=274, max=35268, avg=1294.67, stdev=157.16
     lat (usec): min=281, max=35286, avg=1302.53, stdev=156.91
    clat percentiles (usec):
     |  1.00th=[ 1112],  5.00th=[ 1160], 10.00th=[ 1208], 20.00th=[ 1256],
     | 30.00th=[ 1272], 40.00th=[ 1272], 50.00th=[ 1288], 60.00th=[ 1304],
     | 70.00th=[ 1320], 80.00th=[ 1352], 90.00th=[ 1384], 95.00th=[ 1416],
     | 99.00th=[ 1480], 99.50th=[ 1512], 99.90th=[ 1944], 99.95th=[ 2224],
     | 99.99th=[ 3536]
    bw (KB  /s): min=45840, max=49536, per=25.02%, avg=49109.56, stdev=303.79
    lat (usec) : 500=0.01%, 750=0.01%, 1000=0.05%
    lat (msec) : 2=99.84%, 4=0.09%, 10=0.01%, 20=0.01%, 50=0.01%
  cpu          : usr=2.50%, sys=7.83%, ctx=533469, majf=0, minf=44
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=100.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=655360/w=0/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs):
   READ: io=20480MB, aggrb=196318KB/s, minb=49079KB/s, maxb=49092KB/s, mint=106795msec, maxt=106824msec

Disk stats (read/write):
  sda: ios=2620077/60, merge=0/2, ticks=3348979/94, in_queue=3348631, util=100.00%
[oracle@ol62 - /u01/app/oracle/product/12.1.0.2/dbhome_1: SLOB12]
[~/fio-2.1.13]$

Here is some of the corresponding collectl output:

[root@ol62 queue]# collectl -sD -i 5 --iosize --dskfilt sda
waiting for 5 second sample...

# DISK STATISTICS (/sec)
#          <---------reads---------><---------writes---------><--------averages--------> Pct
#Name       KBytes Merged  IOs Size  KBytes Merged  IOs Size  RWSize  QLen  Wait SvcTim Util
sda         196313      0  24K    8       5      0    1    9       8    31     1      0   99
sda         196681      0  24K    8       6      0    0   16       8    31     1      0  100
sda         196369      0  24K    8       7      0    1   12       8    31     1      0   99
sda         196217      0  24K    8       4      0    0   10       8    31     1      0  100
sda         196300      0  24K    8      14      0    2    6       8    31     1      0  100
sda         196699      0  24K    8       6      0    0   16       8    31     1      0   99
sda         196340      0  24K    8       3      0    0   16       8    31     1      0   99
sda         196350      0  24K    8       6      0    0   16       8    31     1      0  100
sda         196379      0  24K    8       6      0    0   16       8    31     1      0   99
sda         196560      0  24K    8       3      0    0   16       8    31     1      0   99
sda         196259      0  24K    8       8      0    1    8       8    31     1      0   99

Summary Number 1

So it would appear that the SSDs are more or less equal from FIO’s point of view. If you followed closely (hurray if you did-I appreciate this is a long post!) you will have noticed the following:

  • The SLOB test used updates (20%). There is furthermore just one data file for the IOPS tablespace (-> there is concurrency!)
  • The FIO test was based on random reads, no writes. It’s 4 jobs also worked on 4 distinct files.

I have tried to avoid the effect of file system buffering by setting buffer to 0 and I’m also using asynchronous IO as provided by libaio (just as Oracle does).

Theory Number 2

It would appear that XFS is better suited for concurrent writes. Let’s put that theory into action. I reformatted the SATA3 SSD with XFS and ran another test. Feast your eyes-comparing the AWR reports of the EXT4 test execution to XFS on /dev/sde:

WORKLOAD REPOSITORY COMPARE PERIOD REPORT

Snapshot Set    DB Id    Instance     Inst Num Release     Cluster Host          Std Block Size
------------ ----------- ------------ -------- ----------- ------- ------------ ---------------
First (1st)   1269760792 SLOB12              1 12.1.0.2.0  NO      ol62.localdo     8192
Second (2nd)  1269760792 SLOB12              1 12.1.0.2.0  NO      ol62.localdo     8192

Snapshot Set  Begin Snap Id Begin Snap Time            End Snap Id End Snap Time                  Avg Active Users           Elapsed Time (min)            DB time (min)
------------ -------------- ------------------------- ------------ ------------------------- -------------------------- -------------------------- --------------------------
1st                      49 31-Oct-14 12:38:18 (Fri)           50 31-Oct-14 12:40:20 (Fri)                      15.8                       2.0                      32.3
2nd                      55 31-Oct-14 15:35:23 (Fri)           56 31-Oct-14 15:37:25 (Fri)                      15.7                       2.0                      32.1
                                                                                      ~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                                                      %Diff:                     0.2%                      -0.5%                      -0.6%

Host Configuration Comparison
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                     1st                  2nd                 Diff     %Diff
----------------------------------- -------------------- -------------------- -------------------- ---------
Number of CPUs:                                       24                   24                    0       0.0
Number of CPU Cores:                                  24                   24                    0       0.0
Number of CPU Sockets:                                 2                    2                    0       0.0
Physical Memory:                                64413.7M             64413.7M                   0M       0.0
Load at Start Snapshot:                             9.57                 1.77                 -7.8     -81.5
Load at End Snapshot:                               15.6                14.15                -1.45      -9.3
%User Time:                                          .64                 2.07                 1.43     223.4
%System Time:                                        .74                 1.48                  .75     100.0
%Idle Time:                                         98.6                 96.4                 -2.2      -2.2
%IO Wait Time:                                      9.06                53.29                44.23     488.2
Cache Sizes
~~~~~~~~~~~
                          1st (M)    2nd (M)   Diff (M)    %Diff
---------------------- ---------- ---------- ---------- --------
Memory Target
.....SGA Target
..........Buffer Cache       16.0       16.0        0.0      0.0
..........Shared Pool     1,024.0    1,024.0        0.0      0.0
..........Large Pool
..........Java Pool          16.0       16.0        0.0      0.0
..........Streams Pool
.....PGA Target           1,024.0    1,024.0        0.0      0.0
Log Buffer                  128.0      128.0        0.0      0.0
In-Memory Area

Workload Comparison
~~~~~~~~~~~~~~~~~~~                      1st Per Sec          2nd Per Sec      %Diff              1st Per Txn          2nd Per Txn      %Diff
                                     ---------------      ---------------     ------          ---------------      ---------------     ------
                       DB time:                 15.8                 15.8        0.2                      4.4                  1.5      -66.7
                      CPU time:                  0.3                  0.9      175.8                      0.1                  0.1        0.0
           Background CPU time:                  0.1                  0.1      133.3                      0.0                  0.0      -50.0
             Redo size (bytes):          4,652,147.0         15,186,494.1      226.4              1,311,306.6          1,426,136.0        8.8
         Logical read (blocks):              5,231.1             16,957.8      224.2                  1,474.5              1,592.5        8.0
                 Block changes:              2,640.2              8,922.1      237.9                    744.2                837.9       12.6
        Physical read (blocks):              3,750.0             12,560.9      235.0                  1,057.0              1,179.6       11.6
       Physical write (blocks):              1,729.0              5,855.0      238.6                    487.4                549.8       12.8
              Read IO requests:              3,749.3             12,560.8      235.0                  1,056.8              1,179.6       11.6
             Write IO requests:              1,538.2              5,219.5      239.3                    433.6                490.2       13.0
                  Read IO (MB):                 29.3                 98.1      234.9                      8.3                  9.2       11.6
                 Write IO (MB):                 13.5                 45.7      238.6                      3.8                  4.3       12.9
                  IM scan rows:                  0.0                  0.0        0.0                      0.0                  0.0        0.0
       Session Logical Read IM:
                    User calls:                  1.4                  1.4        2.9                      0.4                  0.1      -66.7
                  Parses (SQL):                  6.3                 10.3       62.7                      1.8                  1.0      -45.5
             Hard parses (SQL):                  0.3                  0.0      -86.2                      0.1                  0.0     -100.0
            SQL Work Area (MB):                  0.4                  0.2      -48.8                      0.1                  0.0      -48.8
                        Logons:                  0.1                  0.1        0.0                      0.0                  0.0      -50.0
                Executes (SQL):                 23.7                 58.0      144.3                      6.7                  5.4      -18.5
                  Transactions:                  3.5                 10.6      200.0

                                               First               Second       Diff
                                     ---------------      ---------------     ------
     % Blocks changed per Read:                 50.5                 52.6        2.1
              Recursive Call %:                 97.6                 99.0        1.5
    Rollback per transaction %:                  0.0                  0.0        0.0
                 Rows per Sort:                 35.4                 49.6       14.2
    Avg DB time per Call (sec):                 11.5                 11.3       -0.3

Top Timed Events   First DB/Inst: SLOB12/SLOB12 Snaps: 49-50 (Elapsed time: 122.614 sec  DB time: 1935.33 sec),  Second DB/Inst: SLOB12/SLOB12 Snaps: 55-56 (Elapsed time: 121.705 sec  DB time: 1923.77 sec)
-> Events with a "-" did not make the Top list in this set of snapshots, but are displayed for comparison purposes

                                               1st                                                                                                2nd
------------------------------------------------------------------------------------------------   ------------------------------------------------------------------------------------------------
Event                          Wait Class           Waits      Time(s)  Avg Time(ms)    %DB time   Event                          Wait Class           Waits      Time(s)  Avg Time(ms)    %DB time
------------------------------ ------------- ------------ ------------ ------------- -----------   ------------------------------ ------------- ------------ ------------ ------------- -----------
 db file sequential read       User I/O           459,637      1,920.9           4.2        99.3    db file sequential read       User I/O         1,528,725      1,840.4           1.2        95.7
 db file async I/O submit      System I/O           2,975         97.2          32.7         5.0    CPU time                                             N/A        110.3           N/A         5.7
 CPU time                                             N/A         40.2           N/A         2.1    db file parallel write        System I/O         114,997         34.3           0.3         1.8
 log file parallel write       System I/O           1,881          3.2           1.7         0.2    free buffer waits             Configuration        2,318         28.0          12.1         1.5
 db file parallel write        System I/O           4,670          0.9           0.2         0.0    log file parallel write       System I/O           6,897         14.3           2.1         0.7
 control file sequential read  System I/O             499          0.2           0.3         0.0    db file async I/O submit      System I/O          12,819          5.2           0.4         0.3
 oracle thread bootstrap       Other                    7          0.1          18.1         0.0    buffer busy waits             Concurrency            407          2.7           6.7         0.1
 Disk file operations I/O      User I/O                77          0.1           0.9         0.0    Data file init write          User I/O               152          0.9           5.7         0.0
 library cache: mutex X        Concurrency             22          0.1           2.7         0.0    read by other session         User I/O                60          0.7          11.9         0.0
 Data file init write          User I/O                 5          0.0           5.6         0.0    enq: HW - contention          Configuration           18          0.7          39.3         0.0
-read by other session         User I/O                18          0.0           0.6         0.0   -control file sequential read  System I/O             841          0.5           0.5         0.0
-buffer busy waits             Concurrency             82          0.0           0.0         0.0   -oracle thread bootstrap       Other                    7          0.1          17.2         0.0
-                                                     N/A          N/A           N/A         N/A   -Disk file operations I/O      User I/O               136          0.1           0.8         0.0
-                                                     N/A          N/A           N/A         N/A   -library cache: mutex X        Concurrency             21          0.0           1.4         0.0
                          --------------------------------------------------------------------------------------------------------------------

Everything is just better – the IO times, the redo size, the number of IOPS etc. That’s what I would have expected from the outset. Good to know-I’ll no longer use EXT4 for Oracle databases. After discussing this with @fritshoogland he showed me a post by @kevinclosson that didn’t come to mind at the time:

http://kevinclosson.net/2012/03/06/yes-file-systems-still-need-to-support-concurrent-writes-yet-another-look-at-xfs-versus-ext4/

One Response to “Interesting observations executing SLOB2 with ext4 and xfs on SSD”

  1. Jeremy said

    What I’d find interesting now would be if you had time to reformat the drive with ASM and see how that AWR report compared to xfs!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
%d bloggers like this: