[20081217-05:02:15.392616883] PROCESSING COMMAND : 'clearprofilers' [20081217-05:02:15.660311245] PROCESSING COMMAND : 'useprofiler iostat 5' [20081217-05:02:15.767202390] Checking for sar... [20081217-05:02:15.769853709] found [20081217-05:02:15.910643951] PROCESSING COMMAND : 'useprofiler sar 5' [20081217-05:02:16.018674148] Checking for sar... [20081217-05:02:16.021834591] found [20081217-05:02:16.161949008] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081217-05:02:16.270182130] Checking for sar... [20081217-05:02:16.272759956] found [20081217-05:02:16.443714317] PROCESSING COMMAND : 'useprofiler oprofile' [20081217-05:02:16.653294428] Checking for binutils-2.18 ... [20081217-05:02:16.663806683] Already installed. [20081217-05:02:16.713767799] Checking for oprofile-0.9.4-autobench ... [20081217-05:02:16.724482071] Already installed. [20081217-05:02:16.775755014] opcontrol: oprofile 0.9.4 compiled on Nov 19 2008 09:09:21 [20081217-05:02:16.855910452] Daemon not running [20081217-05:02:16.878030163] Unloading oprofile module [20081217-05:02:17.096486366] Daemon not running [20081217-05:02:18.743288349] OPROFILE : using callgraph [5] [20081217-05:02:18.972530901] Daemon not running [20081217-05:02:18.974645076] Separate options: none [20081217-05:02:18.976744703] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-05:02:18.978975885] Image filter: none [20081217-05:02:18.980968957] Call-graph depth: 5 [20081217-05:02:19.188285562] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081217-05:02:19.261874627] PROCESSING COMMAND : 'set-sched noop' [20081217-05:02:19.645215945] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2008-12-17_0502 jfs-baseline' [20081217-05:02:19.842747575] Connecting to hks.austin.ibm.com... [20081217-05:02:19.845177756] Remote working directory: /opt [20081217-05:02:19.847387027] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081217-05:02:19.850451754] Couldn't create directory: Failure [20081217-05:02:19.852578431] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081217-05:02:19.854580451] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081217-05:02:19.856405546] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502 [20081217-05:02:19.858527308] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502 [20081217-05:02:19.860762333] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline [20081217-05:02:19.928757306] PROCESSING COMMAND : 'mkfs.jfs -V 2>&1' [20081217-05:02:19.960206998] mkfs.jfs version 1.1.13, 17-Jul-2008 [20081217-05:02:20.054588327] PROCESSING COMMAND : 'mkfs.jfs -q /dev/ffsbdev1' [20081217-05:02:20.665496701] mkfs.jfs version 1.1.13, 17-Jul-2008 [20081217-05:02:20.667814958] [20081217-05:02:20.670027962] [20081217-05:02:20.672359460] Format completed successfully. [20081217-05:02:20.674379432] [20081217-05:02:20.676489724] 71687000 kilobytes total disk space. [20081217-05:02:20.822151452] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:02:20.928485299] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20081217-05:02:20.972584083] new log requested [20081217-05:02:20.995822611] Running command ffsb [20081217-05:02:29.238487616] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081217-05:02:29.251698844] Importing argument : num_threads=1 [20081217-05:02:29.277803520] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:02:29.356261509] FFSB version 6.0-RC2 started [20081217-05:02:29.358520383] [20081217-05:02:29.360528140] benchmark time = 300 [20081217-05:02:29.362265082] ThreadGroup 0 [20081217-05:02:29.364144887] ================ [20081217-05:02:29.365986018] num_threads = 1 [20081217-05:02:29.367777553] [20081217-05:02:29.369727885] read_random = off [20081217-05:02:29.371866838] read_size = 0 (0B) [20081217-05:02:29.374057058] read_blocksize = 4096 (4KB) [20081217-05:02:29.375910004] read_skip = off [20081217-05:02:29.377767015] read_skipsize = 0 (0B) [20081217-05:02:29.379674778] [20081217-05:02:29.381434868] write_random = off [20081217-05:02:29.383291120] write_size = 0 (0B) [20081217-05:02:29.385140470] fsync_file = 0 [20081217-05:02:29.386893452] write_blocksize = 0 (0B) [20081217-05:02:29.388746952] wait time = 0 [20081217-05:02:29.390605510] [20081217-05:02:29.392330920] op weights [20081217-05:02:29.394185581] read = 0 (0.00%) [20081217-05:02:29.396038224] readall = 1 (100.00%) [20081217-05:02:29.397780090] write = 0 (0.00%) [20081217-05:02:29.399729326] create = 0 (0.00%) [20081217-05:02:29.401594310] append = 0 (0.00%) [20081217-05:02:29.403643874] delete = 0 (0.00%) [20081217-05:02:29.405799400] metaop = 0 (0.00%) [20081217-05:02:29.407726786] createdir = 0 (0.00%) [20081217-05:02:29.409596042] stat = 0 (0.00%) [20081217-05:02:29.411385745] writeall = 0 (0.00%) [20081217-05:02:29.413248775] writeall_fsync = 0 (0.00%) [20081217-05:02:29.415023622] open_close = 0 (0.00%) [20081217-05:02:29.416916256] write_fsync = 0 (0.00%) [20081217-05:02:29.418795802] create_fsync = 0 (0.00%) [20081217-05:02:29.420585625] append_fsync = 0 (0.00%) [20081217-05:02:29.422457012] [20081217-05:02:29.424229011] FileSystem /mnt/ffsb1 [20081217-05:02:29.426055609] ========== [20081217-05:02:29.427919453] num_dirs = 0 [20081217-05:02:29.429671827] starting files = 1024 [20081217-05:02:29.431515331] [20081217-05:02:29.433276643] min file size = 36700160 (35MB) [20081217-05:02:29.435181370] max file size = 36700160 (35MB) [20081217-05:02:29.437086978] directio = off [20081217-05:02:29.438871503] alignedio = on [20081217-05:02:29.440744611] bufferedio = off [20081217-05:02:29.442531625] [20081217-05:02:29.444381676] aging is off [20081217-05:02:29.446155174] current utilization = 0.01% [20081217-05:02:29.448031506] [20081217-05:02:29.449887814] checking existing fs: /mnt/ffsb1 [20081217-05:02:29.451646552] opendir: No such file or directory [20081217-05:02:29.453543607] recreating new fileset [20081217-05:10:28.035379813] fs setup took 478 secs [20081217-05:10:29.348586029] Syncing()...1 sec [20081217-05:10:29.350946549] Starting Actual Benchmark At: Wed Dec 17 05:10:29 2008 [20081217-05:10:29.383589415] [20081217-05:15:31.053175380] Syncing()...1 sec [20081217-05:15:31.102294394] FFSB benchmark finished at: Wed Dec 17 05:15:30 2008 [20081217-05:15:31.104909635] [20081217-05:15:31.107426998] Results: [20081217-05:15:31.161687678] Benchmark took 301.40 sec [20081217-05:15:31.164229820] [20081217-05:15:31.167021304] Total Results [20081217-05:15:31.182021548] =============== [20081217-05:15:31.184238984] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:15:31.186542070] ======= ============ ========= ======= =========== ========== [20081217-05:15:31.188917474] readall : 6693120 22206.42 100.000% 100.000% 86.7MB/sec [20081217-05:15:31.191143449] - [20081217-05:15:31.193321341] 22206.42 Transactions per Second [20081217-05:15:31.195453750] [20081217-05:15:31.197640340] Throughput Results [20081217-05:15:31.213562857] =================== [20081217-05:15:31.215918476] Read Throughput: 86.7MB/sec [20081217-05:15:31.218218810] [20081217-05:15:31.220716381] System Call Latency statistics in millisecs [20081217-05:15:31.222827393] ===== [20081217-05:15:31.224998161] Min Avg Max Total Calls [20081217-05:15:31.227148896] ======== ======== ======== ============ [20081217-05:15:31.229433459] [ open] 0.014000 0.305692 19.601000 747 [20081217-05:15:31.231599573] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:15:31.239289276] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:15:31.241734664] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:15:31.243926555] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:15:31.246126122] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:15:31.248446246] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:15:31.250529000] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:15:31.252748456] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:15:31.254869309] msec_range[8] 10.000000 - 20.000000 : 4 [20081217-05:15:31.257078846] msec_range[9] 5.000000 - 10.000000 : 11 [20081217-05:15:31.259177657] msec_range[10] 2.000000 - 5.000000 : 14 [20081217-05:15:31.261367144] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:15:31.263446397] msec_range[12] 0.500000 - 1.000000 : 3 [20081217-05:15:31.265624888] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-05:15:31.267716611] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-05:15:31.269949089] msec_range[15] 0.050000 - 0.100000 : 154 [20081217-05:15:31.272420022] msec_range[16] 0.020000 - 0.050000 : 536 [20081217-05:15:31.276824407] msec_range[17] 0.010000 - 0.020000 : 19 [20081217-05:15:31.279355688] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-05:15:31.282150563] [20081217-05:15:31.284689113] [ read] 0.004000 0.044462 85.193001 6693120 [20081217-05:15:31.286904877] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:15:31.289337003] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:15:31.291659430] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:15:31.293903326] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:15:31.296037473] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:15:31.298457348] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:15:31.300679742] msec_range[6] 50.000000 - 100.000000 : 3 [20081217-05:15:31.302884705] msec_range[7] 20.000000 - 50.000000 : 12 [20081217-05:15:31.304949086] msec_range[8] 10.000000 - 20.000000 : 105 [20081217-05:15:31.307115511] msec_range[9] 5.000000 - 10.000000 : 26168 [20081217-05:15:31.309265292] msec_range[10] 2.000000 - 5.000000 : 25159 [20081217-05:15:31.311461637] msec_range[11] 1.000000 - 2.000000 : 135 [20081217-05:15:31.313520071] msec_range[12] 0.500000 - 1.000000 : 76 [20081217-05:15:31.315701209] msec_range[13] 0.200000 - 0.500000 : 423 [20081217-05:15:31.317838216] msec_range[14] 0.100000 - 0.200000 : 651 [20081217-05:15:31.320027681] msec_range[15] 0.050000 - 0.100000 : 587 [20081217-05:15:31.322145114] msec_range[16] 0.020000 - 0.050000 : 2041 [20081217-05:15:31.324310526] msec_range[17] 0.010000 - 0.020000 : 546831 [20081217-05:15:31.326401194] msec_range[18] 0.000000 - 0.010000 : 6090929 [20081217-05:15:31.328537683] [20081217-05:15:31.330557918] [ close] 0.003000 0.006802 0.043000 747 [20081217-05:15:31.332727701] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:15:31.334825476] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:15:31.337020607] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:15:31.339045879] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:15:31.341448845] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:15:31.344001393] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:15:31.346377495] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:15:31.348592041] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:15:31.350975352] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:15:31.353197566] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:15:31.355407975] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:15:31.357611886] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:15:31.359886301] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:15:31.362078173] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:15:31.365765614] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:15:31.368185903] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:15:31.370542173] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-05:15:31.372873052] msec_range[17] 0.010000 - 0.020000 : 88 [20081217-05:15:31.375137025] msec_range[18] 0.000000 - 0.010000 : 658 [20081217-05:15:31.377225157] [20081217-05:15:31.379410642] [20081217-05:15:31.381498438] [20081217-05:15:31.383702633] [20081217-05:15:31.385835938] 1.6% User Time [20081217-05:15:31.388018743] 16.5% System Time [20081217-05:15:31.390186361] 18.1% CPU Utilization [20081217-05:15:31.392387745] Profilers reporting [20081217-05:15:50.251227047] Profilers postprocessing [20081217-05:15:50.648501161] Processing File : iostat.001 [20081217-05:15:50.650845392] Discovered iostat_interval=[5] [20081217-05:15:51.253271121] Processing Directory : sar.breakout.001 [20081217-05:15:51.255737287] Discovered sar_interval=[5] [20081217-05:15:51.419064444] Processing File : mpstat.001 [20081217-05:15:51.421219218] Discovered mpstat_interval=[5] [20081217-05:15:52.552947276] Stopping profiling. [20081217-05:15:52.558232670] Killing daemon. [20081217-05:15:54.819876116] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_05.02.20/analysis/oprofile.001 [20081217-05:15:54.822040500] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_05.02.20/analysis/oprofile-brief.001 [20081217-05:15:56.728304678] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:15:58.679891676] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:15:59.236316438] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:15:59.341024566] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20081217-05:15:59.384557437] new log requested [20081217-05:15:59.407679856] Running command ffsb [20081217-05:16:07.736497578] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081217-05:16:07.749745787] Importing argument : num_threads=8 [20081217-05:16:07.775481339] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:16:07.854273204] FFSB version 6.0-RC2 started [20081217-05:16:07.856414874] [20081217-05:16:07.882291102] benchmark time = 300 [20081217-05:16:07.884522281] ThreadGroup 0 [20081217-05:16:07.886367495] ================ [20081217-05:16:07.888180712] num_threads = 8 [20081217-05:16:07.889966698] [20081217-05:16:07.891826719] read_random = off [20081217-05:16:07.893564424] read_size = 0 (0B) [20081217-05:16:07.895385756] read_blocksize = 4096 (4KB) [20081217-05:16:07.897160617] read_skip = off [20081217-05:16:07.899045692] read_skipsize = 0 (0B) [20081217-05:16:07.900810210] [20081217-05:16:07.902592500] write_random = off [20081217-05:16:07.904363323] write_size = 0 (0B) [20081217-05:16:07.906221439] fsync_file = 0 [20081217-05:16:07.908002194] write_blocksize = 0 (0B) [20081217-05:16:07.909822268] wait time = 0 [20081217-05:16:07.911600697] [20081217-05:16:07.913771663] op weights [20081217-05:16:07.915971092] read = 0 (0.00%) [20081217-05:16:07.917950871] readall = 1 (100.00%) [20081217-05:16:07.919942798] write = 0 (0.00%) [20081217-05:16:07.921737893] create = 0 (0.00%) [20081217-05:16:07.923575539] append = 0 (0.00%) [20081217-05:16:07.925385556] delete = 0 (0.00%) [20081217-05:16:07.927253917] metaop = 0 (0.00%) [20081217-05:16:07.929059591] createdir = 0 (0.00%) [20081217-05:16:07.930888505] stat = 0 (0.00%) [20081217-05:16:07.932708002] writeall = 0 (0.00%) [20081217-05:16:07.934687426] writeall_fsync = 0 (0.00%) [20081217-05:16:07.936428297] open_close = 0 (0.00%) [20081217-05:16:07.938249457] write_fsync = 0 (0.00%) [20081217-05:16:07.940126061] create_fsync = 0 (0.00%) [20081217-05:16:07.941873919] append_fsync = 0 (0.00%) [20081217-05:16:07.943710537] [20081217-05:16:07.945469683] FileSystem /mnt/ffsb1 [20081217-05:16:07.947299903] ========== [20081217-05:16:07.949028446] num_dirs = 0 [20081217-05:16:07.950832883] starting files = 1024 [20081217-05:16:07.952591660] [20081217-05:16:07.954494213] min file size = 36700160 (35MB) [20081217-05:16:07.956404414] max file size = 36700160 (35MB) [20081217-05:16:07.958219398] directio = off [20081217-05:16:07.960112802] alignedio = on [20081217-05:16:07.961891078] bufferedio = off [20081217-05:16:07.963738728] [20081217-05:16:07.965567677] aging is off [20081217-05:16:07.967327052] current utilization = 51.23% [20081217-05:16:07.969188338] [20081217-05:16:07.971080172] checking existing fs: /mnt/ffsb1 [20081217-05:16:08.098460905] fs setup took 0 secs [20081217-05:16:08.336297230] Syncing()...0 sec [20081217-05:16:08.338162862] Starting Actual Benchmark At: Wed Dec 17 05:16:08 2008 [20081217-05:16:08.351112566] [20081217-05:21:12.520612887] Syncing()...0 sec [20081217-05:21:12.540313659] FFSB benchmark finished at: Wed Dec 17 05:21:12 2008 [20081217-05:21:12.543139995] [20081217-05:21:12.545819219] Results: [20081217-05:21:12.577800898] Benchmark took 304.00 sec [20081217-05:21:12.580531332] [20081217-05:21:12.583099580] Total Results [20081217-05:21:12.598592662] =============== [20081217-05:21:12.600714714] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:21:12.603178357] ======= ============ ========= ======= =========== ========== [20081217-05:21:12.605326521] readall : 6702080 22046.44 100.000% 100.000% 86.1MB/sec [20081217-05:21:12.607851765] - [20081217-05:21:12.610370156] 22046.44 Transactions per Second [20081217-05:21:12.612739210] [20081217-05:21:12.614972634] Throughput Results [20081217-05:21:12.629470275] =================== [20081217-05:21:12.631805722] Read Throughput: 86.1MB/sec [20081217-05:21:12.633969741] [20081217-05:21:12.636206073] System Call Latency statistics in millisecs [20081217-05:21:12.638542960] ===== [20081217-05:21:12.640773885] Min Avg Max Total Calls [20081217-05:21:12.643028463] ======== ======== ======== ============ [20081217-05:21:12.645095440] [ open] 0.006000 18.474468 1656.668945 748 [20081217-05:21:12.647420699] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:21:12.649550124] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:21:12.651755603] msec_range[2] 1000.000000 - 2000.000000 : 3 [20081217-05:21:12.653837694] msec_range[3] 500.000000 - 1000.000000 : 8 [20081217-05:21:12.656037866] msec_range[4] 200.000000 - 500.000000 : 11 [20081217-05:21:12.658151818] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:21:12.660301608] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:21:12.662353689] msec_range[7] 20.000000 - 50.000000 : 5 [20081217-05:21:12.664481683] msec_range[8] 10.000000 - 20.000000 : 10 [20081217-05:21:12.666577943] msec_range[9] 5.000000 - 10.000000 : 6 [20081217-05:21:12.668725948] msec_range[10] 2.000000 - 5.000000 : 6 [20081217-05:21:12.670777014] msec_range[11] 1.000000 - 2.000000 : 2 [20081217-05:21:12.672906171] msec_range[12] 0.500000 - 1.000000 : 14 [20081217-05:21:12.675038741] msec_range[13] 0.200000 - 0.500000 : 17 [20081217-05:21:12.677445082] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-05:21:12.748370488] msec_range[15] 0.050000 - 0.100000 : 34 [20081217-05:21:12.750908259] msec_range[16] 0.020000 - 0.050000 : 489 [20081217-05:21:12.753346668] msec_range[17] 0.010000 - 0.020000 : 132 [20081217-05:21:12.755937361] msec_range[18] 0.000000 - 0.010000 : 10 [20081217-05:21:12.758592194] [20081217-05:21:12.760915999] [ read] 0.001000 0.358592 2035.620972 6702080 [20081217-05:21:12.763406552] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:21:12.765695216] msec_range[1] 2000.000000 - 5000.000000 : 597 [20081217-05:21:12.768044759] msec_range[2] 1000.000000 - 2000.000000 : 285 [20081217-05:21:12.770302577] msec_range[3] 500.000000 - 1000.000000 : 338 [20081217-05:21:12.772847407] msec_range[4] 200.000000 - 500.000000 : 507 [20081217-05:21:12.775230763] msec_range[5] 100.000000 - 200.000000 : 84 [20081217-05:21:12.777452039] msec_range[6] 50.000000 - 100.000000 : 40 [20081217-05:21:12.779583101] msec_range[7] 20.000000 - 50.000000 : 188 [20081217-05:21:12.781815506] msec_range[8] 10.000000 - 20.000000 : 307 [20081217-05:21:12.784119698] msec_range[9] 5.000000 - 10.000000 : 29110 [20081217-05:21:12.786545736] msec_range[10] 2.000000 - 5.000000 : 19778 [20081217-05:21:12.788964131] msec_range[11] 1.000000 - 2.000000 : 60 [20081217-05:21:12.791161701] msec_range[12] 0.500000 - 1.000000 : 34 [20081217-05:21:12.793347362] msec_range[13] 0.200000 - 0.500000 : 126 [20081217-05:21:12.795595748] msec_range[14] 0.100000 - 0.200000 : 246 [20081217-05:21:12.798137235] msec_range[15] 0.050000 - 0.100000 : 772 [20081217-05:21:12.800348804] msec_range[16] 0.020000 - 0.050000 : 2224 [20081217-05:21:12.802519486] msec_range[17] 0.010000 - 0.020000 : 73688 [20081217-05:21:12.804636690] msec_range[18] 0.000000 - 0.010000 : 6573696 [20081217-05:21:12.807095004] [20081217-05:21:12.809595815] [ close] 0.002000 0.005987 0.032000 748 [20081217-05:21:12.811921460] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:21:12.814294042] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:21:12.816582142] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:21:12.818715702] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:21:12.820946145] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:21:12.823159352] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:21:12.825401729] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:21:12.827545519] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:21:12.829753724] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:21:12.832126508] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:21:12.835115344] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:21:12.837352138] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:21:12.839842277] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:21:12.842229412] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:21:12.844730438] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:21:12.847304794] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:21:12.849715086] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-05:21:12.852104077] msec_range[17] 0.010000 - 0.020000 : 17 [20081217-05:21:12.854357175] msec_range[18] 0.000000 - 0.010000 : 730 [20081217-05:21:12.856504563] [20081217-05:21:12.858676216] [20081217-05:21:12.860836576] [20081217-05:21:12.863154513] [20081217-05:21:12.865337127] 1.3% User Time [20081217-05:21:12.867583226] 13.1% System Time [20081217-05:21:12.869680084] 14.4% CPU Utilization [20081217-05:21:12.871882516] Profilers reporting [20081217-05:21:12.937126730] /autobench/scripts/doprofilers: line 33: 29931 Terminated ${CMDS[$i]} [20081217-05:21:12.966333761] /autobench/scripts/doprofilers: line 33: 29934 Terminated ${CMDS[$i]} [20081217-05:21:12.994501200] /autobench/scripts/doprofilers: line 33: 29959 Terminated ${CMDS[$i]} [20081217-05:21:22.882513240] Profilers postprocessing [20081217-05:21:23.144789372] Processing File : iostat.001 [20081217-05:21:23.147149532] Discovered iostat_interval=[5] [20081217-05:21:23.709575780] Processing Directory : sar.breakout.001 [20081217-05:21:23.711818857] Discovered sar_interval=[5] [20081217-05:21:23.879921103] Processing File : mpstat.001 [20081217-05:21:23.882047781] Discovered mpstat_interval=[5] [20081217-05:21:25.014290091] Stopping profiling. [20081217-05:21:25.019210060] Killing daemon. [20081217-05:21:27.281133173] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-12-17_05.15.59/analysis/oprofile.001 [20081217-05:21:27.283421436] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-12-17_05.15.59/analysis/oprofile-brief.001 [20081217-05:21:29.051007558] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:21:30.866074547] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:21:31.419670817] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:21:31.526659687] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20081217-05:21:31.570646417] new log requested [20081217-05:21:31.593126739] Running command ffsb [20081217-05:21:39.715178852] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081217-05:21:39.728048840] Importing argument : num_threads=32 [20081217-05:21:39.753564045] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:21:39.826916784] FFSB version 6.0-RC2 started [20081217-05:21:39.829133980] [20081217-05:21:39.948171869] benchmark time = 300 [20081217-05:21:39.950125717] ThreadGroup 0 [20081217-05:21:39.952041951] ================ [20081217-05:21:39.954233745] num_threads = 32 [20081217-05:21:39.956259866] [20081217-05:21:39.958488911] read_random = off [20081217-05:21:39.960386115] read_size = 0 (0B) [20081217-05:21:39.962215264] read_blocksize = 4096 (4KB) [20081217-05:21:39.963970230] read_skip = off [20081217-05:21:39.965828503] read_skipsize = 0 (0B) [20081217-05:21:39.967596763] [20081217-05:21:39.969409383] write_random = off [20081217-05:21:39.971152231] write_size = 0 (0B) [20081217-05:21:39.973034737] fsync_file = 0 [20081217-05:21:39.974771480] write_blocksize = 0 (0B) [20081217-05:21:39.976574010] wait time = 0 [20081217-05:21:39.978312288] [20081217-05:21:39.980247775] op weights [20081217-05:21:39.982115845] read = 0 (0.00%) [20081217-05:21:39.983898501] readall = 1 (100.00%) [20081217-05:21:39.985626965] write = 0 (0.00%) [20081217-05:21:39.987494477] create = 0 (0.00%) [20081217-05:21:39.989398246] append = 0 (0.00%) [20081217-05:21:39.991189512] delete = 0 (0.00%) [20081217-05:21:39.993041787] metaop = 0 (0.00%) [20081217-05:21:39.994819530] createdir = 0 (0.00%) [20081217-05:21:39.996598365] stat = 0 (0.00%) [20081217-05:21:39.998387694] writeall = 0 (0.00%) [20081217-05:21:40.000285577] writeall_fsync = 0 (0.00%) [20081217-05:21:40.002204030] open_close = 0 (0.00%) [20081217-05:21:40.003994831] write_fsync = 0 (0.00%) [20081217-05:21:40.005837906] create_fsync = 0 (0.00%) [20081217-05:21:40.007589776] append_fsync = 0 (0.00%) [20081217-05:21:40.009410781] [20081217-05:21:40.011169004] FileSystem /mnt/ffsb1 [20081217-05:21:40.013118349] ========== [20081217-05:21:40.014957165] num_dirs = 0 [20081217-05:21:40.016738857] starting files = 1024 [20081217-05:21:40.018473637] [20081217-05:21:40.020333593] min file size = 36700160 (35MB) [20081217-05:21:40.022146493] max file size = 36700160 (35MB) [20081217-05:21:40.023940304] directio = off [20081217-05:21:40.025662238] alignedio = on [20081217-05:21:40.027511895] bufferedio = off [20081217-05:21:40.029220638] [20081217-05:21:40.031033143] aging is off [20081217-05:21:40.032758250] current utilization = 51.23% [20081217-05:21:40.034631462] [20081217-05:21:40.036443894] checking existing fs: /mnt/ffsb1 [20081217-05:21:40.236804706] fs setup took 0 secs [20081217-05:21:40.825684889] Syncing()...0 sec [20081217-05:21:40.827815418] Starting Actual Benchmark At: Wed Dec 17 05:21:40 2008 [20081217-05:21:40.840588912] [20081217-05:26:49.222461502] Syncing()...0 sec [20081217-05:26:49.274096766] FFSB benchmark finished at: Wed Dec 17 05:26:49 2008 [20081217-05:26:49.276930771] [20081217-05:26:49.279626356] Results: [20081217-05:26:49.329634378] Benchmark took 308.21 sec [20081217-05:26:49.332377502] [20081217-05:26:49.334935122] Total Results [20081217-05:26:49.350650584] =============== [20081217-05:26:49.353129065] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:26:49.355683721] ======= ============ ========= ======= =========== ========== [20081217-05:26:49.358105745] readall : 6218240 20175.57 100.000% 100.000% 78.8MB/sec [20081217-05:26:49.360361524] - [20081217-05:26:49.362594344] 20175.57 Transactions per Second [20081217-05:26:49.364908558] [20081217-05:26:49.367063167] Throughput Results [20081217-05:26:49.381836726] =================== [20081217-05:26:49.383921087] Read Throughput: 78.8MB/sec [20081217-05:26:49.386308397] [20081217-05:26:49.388586896] System Call Latency statistics in millisecs [20081217-05:26:49.391208680] ===== [20081217-05:26:49.393910143] Min Avg Max Total Calls [20081217-05:26:49.396435573] ======== ======== ======== ============ [20081217-05:26:49.398689549] [ open] 0.006000 160.990308 2490.468018 694 [20081217-05:26:49.401008908] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:26:49.405334681] msec_range[1] 2000.000000 - 5000.000000 : 4 [20081217-05:26:49.408804408] msec_range[2] 1000.000000 - 2000.000000 : 15 [20081217-05:26:49.412638024] msec_range[3] 500.000000 - 1000.000000 : 70 [20081217-05:26:49.415215722] msec_range[4] 200.000000 - 500.000000 : 89 [20081217-05:26:49.417748094] msec_range[5] 100.000000 - 200.000000 : 7 [20081217-05:26:49.420346389] msec_range[6] 50.000000 - 100.000000 : 3 [20081217-05:26:49.422592119] msec_range[7] 20.000000 - 50.000000 : 5 [20081217-05:26:49.424826013] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-05:26:49.426936675] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:26:49.429158661] msec_range[10] 2.000000 - 5.000000 : 2 [20081217-05:26:49.431266283] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-05:26:49.433464851] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:26:49.435583173] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-05:26:49.437808444] msec_range[14] 0.100000 - 0.200000 : 4 [20081217-05:26:49.439954774] msec_range[15] 0.050000 - 0.100000 : 145 [20081217-05:26:49.442278390] msec_range[16] 0.020000 - 0.050000 : 268 [20081217-05:26:49.444775109] msec_range[17] 0.010000 - 0.020000 : 41 [20081217-05:26:49.447478889] msec_range[18] 0.000000 - 0.010000 : 38 [20081217-05:26:49.449952403] [20081217-05:26:49.452340975] [ read] 0.001000 1.548438 2538.968018 6218240 [20081217-05:26:49.454853871] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:26:49.457099304] msec_range[1] 2000.000000 - 5000.000000 : 96 [20081217-05:26:49.459414275] msec_range[2] 1000.000000 - 2000.000000 : 973 [20081217-05:26:49.461646453] msec_range[3] 500.000000 - 1000.000000 : 9990 [20081217-05:26:49.463750427] msec_range[4] 200.000000 - 500.000000 : 3473 [20081217-05:26:49.494478986] msec_range[5] 100.000000 - 200.000000 : 95 [20081217-05:26:49.496922698] msec_range[6] 50.000000 - 100.000000 : 76 [20081217-05:26:49.499268179] msec_range[7] 20.000000 - 50.000000 : 75 [20081217-05:26:49.501836935] msec_range[8] 10.000000 - 20.000000 : 18 [20081217-05:26:49.504302928] msec_range[9] 5.000000 - 10.000000 : 16412 [20081217-05:26:49.506477960] msec_range[10] 2.000000 - 5.000000 : 17311 [20081217-05:26:49.508947169] msec_range[11] 1.000000 - 2.000000 : 53 [20081217-05:26:49.511371724] msec_range[12] 0.500000 - 1.000000 : 39 [20081217-05:26:49.513661110] msec_range[13] 0.200000 - 0.500000 : 197 [20081217-05:26:49.515955365] msec_range[14] 0.100000 - 0.200000 : 355 [20081217-05:26:49.518266452] msec_range[15] 0.050000 - 0.100000 : 853 [20081217-05:26:49.520651950] msec_range[16] 0.020000 - 0.050000 : 1878 [20081217-05:26:49.522977137] msec_range[17] 0.010000 - 0.020000 : 489491 [20081217-05:26:49.525372591] msec_range[18] 0.000000 - 0.010000 : 5676855 [20081217-05:26:49.527768683] [20081217-05:26:49.530054398] [ close] 0.001000 0.006408 0.014000 694 [20081217-05:26:49.532627516] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:26:49.534966417] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:26:49.537353483] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:26:49.539589413] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:26:49.542117034] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:26:49.544399796] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:26:49.546582184] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:26:49.548725788] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:26:49.551016755] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:26:49.553664651] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:26:49.555890291] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:26:49.558188608] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:26:49.560334178] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:26:49.562538541] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:26:49.564735278] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:26:49.567055027] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:26:49.569456204] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-05:26:49.571741922] msec_range[17] 0.010000 - 0.020000 : 90 [20081217-05:26:49.574020867] msec_range[18] 0.000000 - 0.010000 : 604 [20081217-05:26:49.576227890] [20081217-05:26:49.578454774] [20081217-05:26:49.580565977] [20081217-05:26:49.582786081] [20081217-05:26:49.584899658] 1.4% User Time [20081217-05:26:49.587161107] 13.4% System Time [20081217-05:26:49.589344889] 14.7% CPU Utilization [20081217-05:26:49.591689352] Profilers reporting [20081217-05:27:07.044770644] Profilers postprocessing [20081217-05:27:07.327432542] Processing File : iostat.001 [20081217-05:27:07.329640361] Discovered iostat_interval=[5] [20081217-05:27:07.905088150] Processing Directory : sar.breakout.001 [20081217-05:27:07.907367848] Discovered sar_interval=[5] [20081217-05:27:08.069606741] Processing File : mpstat.001 [20081217-05:27:08.071916698] Discovered mpstat_interval=[5] [20081217-05:27:09.204068057] Stopping profiling. [20081217-05:27:09.209334824] Killing daemon. [20081217-05:27:11.674381793] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-12-17_05.21.31/analysis/oprofile.001 [20081217-05:27:11.676747492] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-12-17_05.21.31/analysis/oprofile-brief.001 [20081217-05:27:13.329585858] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:27:15.296692830] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:27:15.919710833] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:27:16.038745366] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=1' [20081217-05:27:16.083711198] new log requested [20081217-05:27:16.106779696] Running command ffsb [20081217-05:27:24.280810687] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081217-05:27:24.294358183] Importing argument : num_threads=1 [20081217-05:27:24.320655001] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:27:24.399142655] FFSB version 6.0-RC2 started [20081217-05:27:24.401477578] [20081217-05:27:24.403352931] benchmark time = 300 [20081217-05:27:24.405526850] ThreadGroup 0 [20081217-05:27:24.407572437] ================ [20081217-05:27:24.409760499] num_threads = 1 [20081217-05:27:24.411570858] [20081217-05:27:24.413436139] read_random = on [20081217-05:27:24.415195284] read_size = 1048576 (1MB) [20081217-05:27:24.417071272] read_blocksize = 4096 (4KB) [20081217-05:27:24.418862808] read_skip = off [20081217-05:27:24.420680899] read_skipsize = 0 (0B) [20081217-05:27:24.422428068] [20081217-05:27:24.424270057] write_random = off [20081217-05:27:24.426002974] write_size = 0 (0B) [20081217-05:27:24.427878656] fsync_file = 0 [20081217-05:27:24.429607526] write_blocksize = 0 (0B) [20081217-05:27:24.431436596] wait time = 0 [20081217-05:27:24.433179080] [20081217-05:27:24.435026618] op weights [20081217-05:27:24.436932042] read = 1 (100.00%) [20081217-05:27:24.438697687] readall = 0 (0.00%) [20081217-05:27:24.440524940] write = 0 (0.00%) [20081217-05:27:24.442299736] create = 0 (0.00%) [20081217-05:27:24.444163493] append = 0 (0.00%) [20081217-05:27:24.445933753] delete = 0 (0.00%) [20081217-05:27:24.447762131] metaop = 0 (0.00%) [20081217-05:27:24.449541881] createdir = 0 (0.00%) [20081217-05:27:24.451388593] stat = 0 (0.00%) [20081217-05:27:24.453133732] writeall = 0 (0.00%) [20081217-05:27:24.454882641] writeall_fsync = 0 (0.00%) [20081217-05:27:24.456671213] open_close = 0 (0.00%) [20081217-05:27:24.458495640] write_fsync = 0 (0.00%) [20081217-05:27:24.460250714] create_fsync = 0 (0.00%) [20081217-05:27:24.462067638] append_fsync = 0 (0.00%) [20081217-05:27:24.463838509] [20081217-05:27:24.465670274] FileSystem /mnt/ffsb1 [20081217-05:27:24.467436202] ========== [20081217-05:27:24.469260174] num_dirs = 0 [20081217-05:27:24.470997187] starting files = 1024 [20081217-05:27:24.472845817] [20081217-05:27:24.474578930] min file size = 36700160 (35MB) [20081217-05:27:24.476431184] max file size = 36700160 (35MB) [20081217-05:27:24.478153636] directio = off [20081217-05:27:24.479989237] alignedio = on [20081217-05:27:24.481753668] bufferedio = off [20081217-05:27:24.483564223] [20081217-05:27:24.485279573] aging is off [20081217-05:27:24.487158878] current utilization = 51.23% [20081217-05:27:24.488985270] [20081217-05:27:24.490886391] checking existing fs: /mnt/ffsb1 [20081217-05:27:24.733905084] fs setup took 0 secs [20081217-05:27:25.146321682] Syncing()...0 sec [20081217-05:27:25.148295625] Starting Actual Benchmark At: Wed Dec 17 05:27:25 2008 [20081217-05:27:25.161196291] [20081217-05:32:25.931379097] Syncing()...0 sec [20081217-05:32:25.934395775] FFSB benchmark finished at: Wed Dec 17 05:32:25 2008 [20081217-05:32:25.937208941] [20081217-05:32:25.939492054] Results: [20081217-05:32:25.954962027] Benchmark took 300.78 sec [20081217-05:32:25.957201522] [20081217-05:32:25.959597659] Total Results [20081217-05:32:25.975141964] =============== [20081217-05:32:25.979417876] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:32:25.981958607] ======= ============ ========= ======= =========== ========== [20081217-05:32:25.984557631] read : 101376 337.04 100.000% 100.000% 1.32MB/sec [20081217-05:32:25.987275239] - [20081217-05:32:25.991987757] 337.04 Transactions per Second [20081217-05:32:25.995371640] [20081217-05:32:25.998031668] Throughput Results [20081217-05:32:26.012411515] =================== [20081217-05:32:26.014802218] Read Throughput: 1.32MB/sec [20081217-05:32:26.017341181] [20081217-05:32:26.019931355] System Call Latency statistics in millisecs [20081217-05:32:26.023012419] ===== [20081217-05:32:26.026641989] Min Avg Max Total Calls [20081217-05:32:26.029255511] ======== ======== ======== ============ [20081217-05:32:26.032498431] [ open] 0.009000 0.012626 0.033000 396 [20081217-05:32:26.035331287] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:32:26.038088430] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:32:26.040902357] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:32:26.043671075] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:32:26.046308761] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:32:26.049027518] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:32:26.051488663] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:32:26.053798937] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:32:26.056543137] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:32:26.059640313] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:32:26.062701174] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:32:26.065948822] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:32:26.068889763] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:32:26.071479688] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:32:26.073791324] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:32:26.076500694] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:32:26.079194844] msec_range[16] 0.020000 - 0.050000 : 12 [20081217-05:32:26.081757793] msec_range[17] 0.010000 - 0.020000 : 377 [20081217-05:32:26.085536782] msec_range[18] 0.000000 - 0.010000 : 7 [20081217-05:32:26.088368229] [20081217-05:32:26.091232528] [ read] 0.001000 2.961315 90.624001 101376 [20081217-05:32:26.094034450] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:32:26.096932664] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:32:26.099461048] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:32:26.102008358] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:32:26.105242128] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:32:26.107905195] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:32:26.110375732] msec_range[6] 50.000000 - 100.000000 : 3 [20081217-05:32:26.112941949] msec_range[7] 20.000000 - 50.000000 : 19 [20081217-05:32:26.115642523] msec_range[8] 10.000000 - 20.000000 : 2015 [20081217-05:32:26.118053620] msec_range[9] 5.000000 - 10.000000 : 862 [20081217-05:32:26.120756868] msec_range[10] 2.000000 - 5.000000 : 65402 [20081217-05:32:26.123669870] msec_range[11] 1.000000 - 2.000000 : 21312 [20081217-05:32:26.127298578] msec_range[12] 0.500000 - 1.000000 : 467 [20081217-05:32:26.129826494] msec_range[13] 0.200000 - 0.500000 : 8737 [20081217-05:32:26.132457854] msec_range[14] 0.100000 - 0.200000 : 343 [20081217-05:32:26.134984295] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:32:26.137469405] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-05:32:26.139982337] msec_range[17] 0.010000 - 0.020000 : 12 [20081217-05:32:26.142717910] msec_range[18] 0.000000 - 0.010000 : 2203 [20081217-05:32:26.145422230] [20081217-05:32:26.147955752] [ lseek] 0.000000 0.001080 0.013000 101376 [20081217-05:32:26.150536976] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:32:26.153447812] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:32:26.156362093] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:32:26.159957658] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:32:26.163123844] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:32:26.165489909] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:32:26.168096856] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:32:26.171614866] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:32:26.174043237] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:32:26.177719158] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:32:26.180491252] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:32:26.183296647] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:32:26.185908057] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:32:26.189069926] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:32:26.191868763] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:32:26.195010972] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:32:26.198147908] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-05:32:26.200670645] msec_range[17] 0.010000 - 0.020000 : 8 [20081217-05:32:26.203373848] msec_range[18] 0.000000 - 0.010000 : 101368 [20081217-05:32:26.205910691] [20081217-05:32:26.208420390] [ close] 0.002000 0.003649 0.009000 396 [20081217-05:32:26.210910164] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:32:26.213494845] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:32:26.216233632] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:32:26.219204192] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:32:26.221850512] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:32:26.224261387] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:32:26.226952419] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:32:26.229512149] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:32:26.232097582] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:32:26.234527271] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:32:26.237115290] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:32:26.239552219] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:32:26.242095744] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:32:26.244692292] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:32:26.246989223] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:32:26.249197199] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:32:26.251507209] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-05:32:26.253726737] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-05:32:26.256138704] msec_range[18] 0.000000 - 0.010000 : 396 [20081217-05:32:26.258567701] [20081217-05:32:26.260704953] [20081217-05:32:26.262922974] [20081217-05:32:26.265308642] [20081217-05:32:26.267798785] 0.1% User Time [20081217-05:32:26.270096318] 0.8% System Time [20081217-05:32:26.272356296] 0.8% CPU Utilization [20081217-05:32:26.274635709] Profilers reporting [20081217-05:32:26.276746392] /autobench/scripts/doprofilers: line 33: 9335 Terminated ${CMDS[$i]} [20081217-05:32:32.870343370] Profilers postprocessing [20081217-05:32:32.957078809] Processing File : iostat.001 [20081217-05:32:32.959417059] Discovered iostat_interval=[5] [20081217-05:32:33.485506216] Processing Directory : sar.breakout.001 [20081217-05:32:33.487823537] Discovered sar_interval=[5] [20081217-05:32:33.647947516] Processing File : mpstat.001 [20081217-05:32:33.650128048] Discovered mpstat_interval=[5] [20081217-05:32:34.782806876] Stopping profiling. [20081217-05:32:34.787871583] Killing daemon. [20081217-05:32:35.952664157] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_05.27.16/analysis/oprofile.001 [20081217-05:32:35.954852058] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_05.27.16/analysis/oprofile-brief.001 [20081217-05:32:37.174750569] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:32:38.424130729] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:32:38.712059774] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:32:38.818035843] PROCESSING COMMAND : 'run random_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=8' [20081217-05:32:38.861843855] new log requested [20081217-05:32:38.884510167] Running command ffsb [20081217-05:32:46.170689859] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081217-05:32:46.183452752] Importing argument : num_threads=8 [20081217-05:32:46.209166244] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:32:46.273616271] FFSB version 6.0-RC2 started [20081217-05:32:46.275777103] [20081217-05:32:46.304926421] benchmark time = 300 [20081217-05:32:46.306994067] ThreadGroup 0 [20081217-05:32:46.308965697] ================ [20081217-05:32:46.311110225] num_threads = 8 [20081217-05:32:46.313225973] [20081217-05:32:46.315231552] read_random = on [20081217-05:32:46.317249885] read_size = 1048576 (1MB) [20081217-05:32:46.319209978] read_blocksize = 4096 (4KB) [20081217-05:32:46.321025756] read_skip = off [20081217-05:32:46.322854229] read_skipsize = 0 (0B) [20081217-05:32:46.324655035] [20081217-05:32:46.326524833] write_random = off [20081217-05:32:46.328317332] write_size = 0 (0B) [20081217-05:32:46.330139271] fsync_file = 0 [20081217-05:32:46.331920400] write_blocksize = 0 (0B) [20081217-05:32:46.333793693] wait time = 0 [20081217-05:32:46.335565210] [20081217-05:32:46.337367994] op weights [20081217-05:32:46.339125612] read = 1 (100.00%) [20081217-05:32:46.341001295] readall = 0 (0.00%) [20081217-05:32:46.342789248] write = 0 (0.00%) [20081217-05:32:46.344609525] create = 0 (0.00%) [20081217-05:32:46.346449743] append = 0 (0.00%) [20081217-05:32:46.348173696] delete = 0 (0.00%) [20081217-05:32:46.350025602] metaop = 0 (0.00%) [20081217-05:32:46.351816285] createdir = 0 (0.00%) [20081217-05:32:46.353696578] stat = 0 (0.00%) [20081217-05:32:46.355475308] writeall = 0 (0.00%) [20081217-05:32:46.357286735] writeall_fsync = 0 (0.00%) [20081217-05:32:46.359066060] open_close = 0 (0.00%) [20081217-05:32:46.360945073] write_fsync = 0 (0.00%) [20081217-05:32:46.362729955] create_fsync = 0 (0.00%) [20081217-05:32:46.364525707] append_fsync = 0 (0.00%) [20081217-05:32:46.366275544] [20081217-05:32:46.368138516] FileSystem /mnt/ffsb1 [20081217-05:32:46.369910405] ========== [20081217-05:32:46.371711411] num_dirs = 0 [20081217-05:32:46.373439867] starting files = 1024 [20081217-05:32:46.375269556] [20081217-05:32:46.377048292] min file size = 36700160 (35MB) [20081217-05:32:46.378838887] max file size = 36700160 (35MB) [20081217-05:32:46.380599201] directio = off [20081217-05:32:46.382437762] alignedio = on [20081217-05:32:46.384151511] bufferedio = off [20081217-05:32:46.385966366] [20081217-05:32:46.387691561] aging is off [20081217-05:32:46.389517537] current utilization = 51.23% [20081217-05:32:46.391308363] [20081217-05:32:46.393140065] checking existing fs: /mnt/ffsb1 [20081217-05:32:46.688455219] fs setup took 0 secs [20081217-05:32:47.394622030] Syncing()...0 sec [20081217-05:32:47.396458006] Starting Actual Benchmark At: Wed Dec 17 05:32:47 2008 [20081217-05:32:47.409902219] [20081217-05:37:49.125066429] Syncing()...0 sec [20081217-05:37:49.127975626] FFSB benchmark finished at: Wed Dec 17 05:37:49 2008 [20081217-05:37:49.130671499] [20081217-05:37:49.133378738] Results: [20081217-05:37:49.148696151] Benchmark took 301.73 sec [20081217-05:37:49.151253366] [20081217-05:37:49.153810349] Total Results [20081217-05:37:49.173173255] =============== [20081217-05:37:49.175555142] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:37:49.178330076] ======= ============ ========= ======= =========== ========== [20081217-05:37:49.181661520] read : 114432 379.26 100.000% 100.000% 1.48MB/sec [20081217-05:37:49.184412384] - [20081217-05:37:49.186996491] 379.26 Transactions per Second [20081217-05:37:49.190172166] [20081217-05:37:49.192876309] Throughput Results [20081217-05:37:49.209140062] =================== [20081217-05:37:49.211512077] Read Throughput: 1.48MB/sec [20081217-05:37:49.214223309] [20081217-05:37:49.216940678] System Call Latency statistics in millisecs [20081217-05:37:49.219236779] ===== [20081217-05:37:49.221767215] Min Avg Max Total Calls [20081217-05:37:49.225006252] ======== ======== ======== ============ [20081217-05:37:49.228846388] [ open] 0.006000 0.016038 0.174000 447 [20081217-05:37:49.232039478] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:37:49.235671686] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:37:49.238759068] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:37:49.241517791] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:37:49.244094666] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:37:49.247544327] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:37:49.252407679] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:37:49.255468108] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:37:49.258521735] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:37:49.261470920] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:37:49.264791492] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:37:49.269019699] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:37:49.271200552] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:37:49.273314031] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:37:49.276003233] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-05:37:49.278702101] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:37:49.282355002] msec_range[16] 0.020000 - 0.050000 : 122 [20081217-05:37:49.285299366] msec_range[17] 0.010000 - 0.020000 : 245 [20081217-05:37:49.289006352] msec_range[18] 0.000000 - 0.010000 : 79 [20081217-05:37:49.291694821] [20081217-05:37:49.294357054] [ read] 0.002000 21.010368 2010.339966 114432 [20081217-05:37:49.296862040] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:37:49.301457393] msec_range[1] 2000.000000 - 5000.000000 : 1 [20081217-05:37:49.304162646] msec_range[2] 1000.000000 - 2000.000000 : 17 [20081217-05:37:49.306254422] msec_range[3] 500.000000 - 1000.000000 : 133 [20081217-05:37:49.308804055] msec_range[4] 200.000000 - 500.000000 : 1014 [20081217-05:37:49.311643889] msec_range[5] 100.000000 - 200.000000 : 3338 [20081217-05:37:49.314024149] msec_range[6] 50.000000 - 100.000000 : 7726 [20081217-05:37:49.316667683] msec_range[7] 20.000000 - 50.000000 : 16712 [20081217-05:37:49.319379590] msec_range[8] 10.000000 - 20.000000 : 16116 [20081217-05:37:49.321853668] msec_range[9] 5.000000 - 10.000000 : 16402 [20081217-05:37:49.324664885] msec_range[10] 2.000000 - 5.000000 : 35268 [20081217-05:37:49.328049659] msec_range[11] 1.000000 - 2.000000 : 14337 [20081217-05:37:49.330901353] msec_range[12] 0.500000 - 1.000000 : 386 [20081217-05:37:49.333580034] msec_range[13] 0.200000 - 0.500000 : 461 [20081217-05:37:49.336371261] msec_range[14] 0.100000 - 0.200000 : 16 [20081217-05:37:49.339817237] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:37:49.342576461] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-05:37:49.345975315] msec_range[17] 0.010000 - 0.020000 : 374 [20081217-05:37:49.349480895] msec_range[18] 0.000000 - 0.010000 : 2130 [20081217-05:37:49.353383933] [20081217-05:37:49.356765281] [ lseek] 0.000000 0.001140 0.040000 114432 [20081217-05:37:49.359271205] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:37:49.362440287] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:37:49.365262925] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:37:49.367946981] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:37:49.371343846] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:37:49.373696028] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:37:49.376210538] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:37:49.378870002] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:37:49.381344827] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:37:49.383862095] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:37:49.386732156] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:37:49.389361257] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:37:49.392019935] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:37:49.394728734] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:37:49.397258984] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:37:49.399805483] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:37:49.402105059] msec_range[16] 0.020000 - 0.050000 : 4 [20081217-05:37:49.404992835] msec_range[17] 0.010000 - 0.020000 : 34 [20081217-05:37:49.407607437] msec_range[18] 0.000000 - 0.010000 : 114394 [20081217-05:37:49.410154413] [20081217-05:37:49.412564717] [ close] 0.002000 0.004226 0.010000 447 [20081217-05:37:49.414783331] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:37:49.417474962] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:37:49.420809928] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:37:49.423737413] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:37:49.426326733] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:37:49.428660661] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:37:49.430984092] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:37:49.433264471] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:37:49.435570206] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:37:49.437862207] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:37:49.440323509] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:37:49.442740311] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:37:49.445163774] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:37:49.447410108] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:37:49.449562345] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:37:49.451794691] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:37:49.454592403] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-05:37:49.456790148] msec_range[17] 0.010000 - 0.020000 : 6 [20081217-05:37:49.459052698] msec_range[18] 0.000000 - 0.010000 : 441 [20081217-05:37:49.461330613] [20081217-05:37:49.463492329] [20081217-05:37:49.465743685] [20081217-05:37:49.467964667] [20081217-05:37:49.470102217] 0.1% User Time [20081217-05:37:49.472363512] 1.1% System Time [20081217-05:37:49.474568946] 1.1% CPU Utilization [20081217-05:37:49.476785850] Profilers reporting [20081217-05:37:49.478992237] /autobench/scripts/doprofilers: line 33: 15104 Terminated ${CMDS[$i]} [20081217-05:37:49.481267345] /autobench/scripts/doprofilers: line 33: 15123 Terminated ${CMDS[$i]} [20081217-05:37:49.483448972] /autobench/scripts/doprofilers: line 33: 15157 Terminated ${CMDS[$i]} [20081217-05:38:01.050601262] Profilers postprocessing [20081217-05:38:01.138061418] Processing File : iostat.001 [20081217-05:38:01.140440940] Discovered iostat_interval=[5] [20081217-05:38:01.665032394] Processing Directory : sar.breakout.001 [20081217-05:38:01.667264742] Discovered sar_interval=[5] [20081217-05:38:01.825968752] Processing File : mpstat.001 [20081217-05:38:01.828195333] Discovered mpstat_interval=[5] [20081217-05:38:02.961343916] Stopping profiling. [20081217-05:38:02.966159395] Killing daemon. [20081217-05:38:04.135285560] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-12-17_05.32.38/analysis/oprofile.001 [20081217-05:38:04.137429141] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-12-17_05.32.38/analysis/oprofile-brief.001 [20081217-05:38:05.600214340] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:38:06.892435248] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:38:07.221511691] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:38:07.333415550] PROCESSING COMMAND : 'run random_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=32' [20081217-05:38:07.377458144] new log requested [20081217-05:38:07.400176968] Running command ffsb [20081217-05:38:14.814487441] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081217-05:38:14.827485061] Importing argument : num_threads=32 [20081217-05:38:14.853496762] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:38:14.918228856] FFSB version 6.0-RC2 started [20081217-05:38:14.920433130] [20081217-05:38:15.041884830] benchmark time = 300 [20081217-05:38:15.043840824] ThreadGroup 0 [20081217-05:38:15.045870924] ================ [20081217-05:38:15.047764170] num_threads = 32 [20081217-05:38:15.049489314] [20081217-05:38:15.051368818] read_random = on [20081217-05:38:15.053162117] read_size = 1048576 (1MB) [20081217-05:38:15.055075456] read_blocksize = 4096 (4KB) [20081217-05:38:15.056822008] read_skip = off [20081217-05:38:15.058686336] read_skipsize = 0 (0B) [20081217-05:38:15.060458131] [20081217-05:38:15.062343295] write_random = off [20081217-05:38:15.064102401] write_size = 0 (0B) [20081217-05:38:15.065902334] fsync_file = 0 [20081217-05:38:15.067644388] write_blocksize = 0 (0B) [20081217-05:38:15.069527777] wait time = 0 [20081217-05:38:15.071542718] [20081217-05:38:15.073747486] op weights [20081217-05:38:15.075747360] read = 1 (100.00%) [20081217-05:38:15.077535863] readall = 0 (0.00%) [20081217-05:38:15.079587435] write = 0 (0.00%) [20081217-05:38:15.081577527] create = 0 (0.00%) [20081217-05:38:15.083343051] append = 0 (0.00%) [20081217-05:38:15.085197346] delete = 0 (0.00%) [20081217-05:38:15.087271794] metaop = 0 (0.00%) [20081217-05:38:15.089145587] createdir = 0 (0.00%) [20081217-05:38:15.090980358] stat = 0 (0.00%) [20081217-05:38:15.092786961] writeall = 0 (0.00%) [20081217-05:38:15.094701787] writeall_fsync = 0 (0.00%) [20081217-05:38:15.096475002] open_close = 0 (0.00%) [20081217-05:38:15.098292216] write_fsync = 0 (0.00%) [20081217-05:38:15.100068547] create_fsync = 0 (0.00%) [20081217-05:38:15.101945082] append_fsync = 0 (0.00%) [20081217-05:38:15.103677107] [20081217-05:38:15.105478710] FileSystem /mnt/ffsb1 [20081217-05:38:15.107284741] ========== [20081217-05:38:15.109137572] num_dirs = 0 [20081217-05:38:15.110907536] starting files = 1024 [20081217-05:38:15.112698462] [20081217-05:38:15.114464240] min file size = 36700160 (35MB) [20081217-05:38:15.116340279] max file size = 36700160 (35MB) [20081217-05:38:15.118090414] directio = off [20081217-05:38:15.119891870] alignedio = on [20081217-05:38:15.121750011] bufferedio = off [20081217-05:38:15.123488589] [20081217-05:38:15.125313016] aging is off [20081217-05:38:15.127057422] current utilization = 51.23% [20081217-05:38:15.128901351] [20081217-05:38:15.130659690] checking existing fs: /mnt/ffsb1 [20081217-05:38:15.378903175] fs setup took 0 secs [20081217-05:38:16.290991577] Syncing()...0 sec [20081217-05:38:16.293100084] Starting Actual Benchmark At: Wed Dec 17 05:38:16 2008 [20081217-05:38:16.306173102] [20081217-05:43:26.339241131] Syncing()...0 sec [20081217-05:43:26.342254920] FFSB benchmark finished at: Wed Dec 17 05:43:26 2008 [20081217-05:43:26.344894270] [20081217-05:43:26.347485221] Results: [20081217-05:43:26.362942707] Benchmark took 310.05 sec [20081217-05:43:26.365715094] [20081217-05:43:26.368208809] Total Results [20081217-05:43:26.384049445] =============== [20081217-05:43:26.386838956] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:43:26.389491142] ======= ============ ========= ======= =========== ========== [20081217-05:43:26.391996752] read : 147200 474.77 100.000% 100.000% 1.85MB/sec [20081217-05:43:26.394695517] - [20081217-05:43:26.397393137] 474.77 Transactions per Second [20081217-05:43:26.399851942] [20081217-05:43:26.403794542] Throughput Results [20081217-05:43:26.421198463] =================== [20081217-05:43:26.424582461] Read Throughput: 1.85MB/sec [20081217-05:43:26.428186423] [20081217-05:43:26.431002166] System Call Latency statistics in millisecs [20081217-05:43:26.433958842] ===== [20081217-05:43:26.437526876] Min Avg Max Total Calls [20081217-05:43:26.441152397] ======== ======== ======== ============ [20081217-05:43:26.444790510] [ open] 0.006000 0.015595 0.035000 575 [20081217-05:43:26.447537372] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:43:26.451306087] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:43:26.454799608] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:43:26.457646808] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:43:26.460354642] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:43:26.463683337] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:43:26.466178263] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:43:26.468950299] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:43:26.472234675] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:43:26.476343545] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:43:26.479225314] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:43:26.481815125] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:43:26.484449625] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:43:26.487334218] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:43:26.490598803] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:43:26.493169220] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:43:26.499266702] msec_range[16] 0.020000 - 0.050000 : 147 [20081217-05:43:26.502468090] msec_range[17] 0.010000 - 0.020000 : 316 [20081217-05:43:26.506627215] msec_range[18] 0.000000 - 0.010000 : 112 [20081217-05:43:26.510296830] [20081217-05:43:26.513004073] [ read] 0.002000 66.473477 2021.314941 147200 [20081217-05:43:26.515684366] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:43:26.518705481] msec_range[1] 2000.000000 - 5000.000000 : 195 [20081217-05:43:26.521516888] msec_range[2] 1000.000000 - 2000.000000 : 882 [20081217-05:43:26.524021963] msec_range[3] 500.000000 - 1000.000000 : 2813 [20081217-05:43:26.526475591] msec_range[4] 200.000000 - 500.000000 : 8411 [20081217-05:43:26.529090520] msec_range[5] 100.000000 - 200.000000 : 9760 [20081217-05:43:26.531841482] msec_range[6] 50.000000 - 100.000000 : 12999 [20081217-05:43:26.534680083] msec_range[7] 20.000000 - 50.000000 : 23605 [20081217-05:43:26.537289133] msec_range[8] 10.000000 - 20.000000 : 22819 [20081217-05:43:26.540063121] msec_range[9] 5.000000 - 10.000000 : 23634 [20081217-05:43:26.542959305] msec_range[10] 2.000000 - 5.000000 : 29081 [20081217-05:43:26.546323021] msec_range[11] 1.000000 - 2.000000 : 9373 [20081217-05:43:26.549124678] msec_range[12] 0.500000 - 1.000000 : 143 [20081217-05:43:26.553485599] msec_range[13] 0.200000 - 0.500000 : 71 [20081217-05:43:26.556109640] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:43:26.558462078] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:43:26.560791927] msec_range[16] 0.020000 - 0.050000 : 3 [20081217-05:43:26.563379626] msec_range[17] 0.010000 - 0.020000 : 567 [20081217-05:43:26.566286657] msec_range[18] 0.000000 - 0.010000 : 2844 [20081217-05:43:26.569194056] [20081217-05:43:26.571803779] [ lseek] 0.000000 0.001180 0.032000 147200 [20081217-05:43:26.574392553] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:43:26.576717353] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:43:26.579919122] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:43:26.583011929] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:43:26.585560752] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:43:26.588334671] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:43:26.592746987] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:43:26.595892074] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:43:26.600659120] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:43:26.603478365] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:43:26.606105905] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:43:26.609127832] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:43:26.612103755] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:43:26.614570438] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:43:26.616969339] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:43:26.619163273] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:43:26.621770576] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-05:43:26.625435787] msec_range[17] 0.010000 - 0.020000 : 51 [20081217-05:43:26.628095539] msec_range[18] 0.000000 - 0.010000 : 147148 [20081217-05:43:26.630946990] [20081217-05:43:26.633290726] [ close] 0.002000 0.004339 0.012000 575 [20081217-05:43:26.635972222] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:43:26.638528584] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:43:26.640958732] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:43:26.643368727] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:43:26.645796633] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:43:26.648248067] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:43:26.651387470] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:43:26.653767396] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:43:26.656074427] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:43:26.658576855] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:43:26.661197474] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:43:26.663736450] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:43:26.666179018] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:43:26.668444820] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:43:26.670781776] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:43:26.672888912] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:43:26.675137127] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-05:43:26.677293688] msec_range[17] 0.010000 - 0.020000 : 10 [20081217-05:43:26.679577274] msec_range[18] 0.000000 - 0.010000 : 565 [20081217-05:43:26.681785279] [20081217-05:43:26.684216190] [20081217-05:43:26.686571120] [20081217-05:43:26.688705525] [20081217-05:43:26.690982676] 0.1% User Time [20081217-05:43:26.693319785] 1.4% System Time [20081217-05:43:26.695544616] 1.4% CPU Utilization [20081217-05:43:26.697839839] Profilers reporting [20081217-05:43:26.700161764] /autobench/scripts/doprofilers: line 33: 21070 Terminated ${CMDS[$i]} [20081217-05:43:38.965041076] Profilers postprocessing [20081217-05:43:39.052343814] Processing File : iostat.001 [20081217-05:43:39.054686130] Discovered iostat_interval=[5] [20081217-05:43:39.588987302] Processing Directory : sar.breakout.001 [20081217-05:43:39.591302367] Discovered sar_interval=[5] [20081217-05:43:39.753845862] Processing File : mpstat.001 [20081217-05:43:39.756023322] Discovered mpstat_interval=[5] [20081217-05:43:40.887667376] Stopping profiling. [20081217-05:43:40.892702468] Killing daemon. [20081217-05:43:42.060901025] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-12-17_05.38.07/analysis/oprofile.001 [20081217-05:43:42.063146594] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-12-17_05.38.07/analysis/oprofile-brief.001 [20081217-05:43:43.081919571] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:43:44.510700844] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:43:44.952037064] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:43:45.058410150] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=1' [20081217-05:43:45.102987759] new log requested [20081217-05:43:45.125737053] Running command ffsb [20081217-05:43:52.600369923] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081217-05:43:52.613907234] Importing argument : num_threads=1 [20081217-05:43:52.640945949] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:43:52.706039782] FFSB version 6.0-RC2 started [20081217-05:43:52.708308029] [20081217-05:43:52.710105087] benchmark time = 300 [20081217-05:43:52.712119055] ThreadGroup 0 [20081217-05:43:52.714359066] ================ [20081217-05:43:52.716416593] num_threads = 1 [20081217-05:43:52.718562100] [20081217-05:43:52.720412060] read_random = off [20081217-05:43:52.722283873] read_size = 0 (0B) [20081217-05:43:52.724060815] read_blocksize = 0 (0B) [20081217-05:43:52.725905511] read_skip = off [20081217-05:43:52.727844838] read_skipsize = 0 (0B) [20081217-05:43:52.729673138] [20081217-05:43:52.731529226] write_random = on [20081217-05:43:52.733412987] write_size = 1048576 (1MB) [20081217-05:43:52.735170990] fsync_file = 0 [20081217-05:43:52.737037092] write_blocksize = 4096 (4KB) [20081217-05:43:52.738816698] wait time = 0 [20081217-05:43:52.740668808] [20081217-05:43:52.742421613] op weights [20081217-05:43:52.744303291] read = 0 (0.00%) [20081217-05:43:52.746286932] readall = 0 (0.00%) [20081217-05:43:52.748095526] write = 1 (100.00%) [20081217-05:43:52.749948255] create = 0 (0.00%) [20081217-05:43:52.751802229] append = 0 (0.00%) [20081217-05:43:52.753583392] delete = 0 (0.00%) [20081217-05:43:52.755465720] metaop = 0 (0.00%) [20081217-05:43:52.757383159] createdir = 0 (0.00%) [20081217-05:43:52.759216255] stat = 0 (0.00%) [20081217-05:43:52.761072555] writeall = 0 (0.00%) [20081217-05:43:52.763157662] writeall_fsync = 0 (0.00%) [20081217-05:43:52.764944873] open_close = 0 (0.00%) [20081217-05:43:52.766803952] write_fsync = 0 (0.00%) [20081217-05:43:52.768564140] create_fsync = 0 (0.00%) [20081217-05:43:52.770412949] append_fsync = 0 (0.00%) [20081217-05:43:52.772270686] [20081217-05:43:52.774009226] FileSystem /mnt/ffsb1 [20081217-05:43:52.775851839] ========== [20081217-05:43:52.777605974] num_dirs = 0 [20081217-05:43:52.779484904] starting files = 1024 [20081217-05:43:52.781445070] [20081217-05:43:52.783252168] min file size = 36700160 (35MB) [20081217-05:43:52.785096729] max file size = 36700160 (35MB) [20081217-05:43:52.786892413] directio = off [20081217-05:43:52.788739629] alignedio = on [20081217-05:43:52.790511248] bufferedio = off [20081217-05:43:52.792387030] [20081217-05:43:52.794324606] aging is off [20081217-05:43:52.796105942] current utilization = 51.23% [20081217-05:43:52.797891973] [20081217-05:43:52.799789224] checking existing fs: /mnt/ffsb1 [20081217-05:43:53.075133102] fs setup took 0 secs [20081217-05:43:54.063253500] Syncing()...0 sec [20081217-05:43:54.065504074] Starting Actual Benchmark At: Wed Dec 17 05:43:54 2008 [20081217-05:43:54.078355441] [20081217-05:49:46.902351458] Syncing()...52 sec [20081217-05:49:46.905243505] FFSB benchmark finished at: Wed Dec 17 05:49:46 2008 [20081217-05:49:46.908052777] [20081217-05:49:46.910921401] Results: [20081217-05:49:46.926421596] Benchmark took 352.84 sec [20081217-05:49:46.929152768] [20081217-05:49:46.931655824] Total Results [20081217-05:49:46.947370165] =============== [20081217-05:49:46.950027307] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:49:46.953044914] ======= ============ ========= ======= =========== ========== [20081217-05:49:46.956128706] write : 240128 680.56 100.000% 100.000% 93MB/sec [20081217-05:49:46.958598526] - [20081217-05:49:46.963140526] 680.56 Transactions per Second [20081217-05:49:46.965728953] [20081217-05:49:46.968592350] Throughput Results [20081217-05:49:46.983915049] =================== [20081217-05:49:46.986531549] Write Throughput: 93MB/sec [20081217-05:49:46.991584472] [20081217-05:49:46.994219794] System Call Latency statistics in millisecs [20081217-05:49:46.996902270] ===== [20081217-05:49:47.000398135] Min Avg Max Total Calls [20081217-05:49:47.003413126] ======== ======== ======== ============ [20081217-05:49:47.006345832] [ open] 0.006000 0.010311 0.075000 938 [20081217-05:49:47.009022663] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:49:47.011850965] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:49:47.014382181] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:49:47.016805096] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:49:47.019177554] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:49:47.021796925] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:49:47.024506855] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:49:47.026815830] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:49:47.028920226] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:49:47.030990899] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:49:47.033589318] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:49:47.036251074] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:49:47.038623883] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:49:47.041564890] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:49:47.044275698] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:49:47.046962875] msec_range[15] 0.050000 - 0.100000 : 2 [20081217-05:49:47.049844398] msec_range[16] 0.020000 - 0.050000 : 81 [20081217-05:49:47.052496125] msec_range[17] 0.010000 - 0.020000 : 220 [20081217-05:49:47.055125223] msec_range[18] 0.000000 - 0.010000 : 635 [20081217-05:49:47.057719136] [20081217-05:49:47.059976158] [ write] 0.004000 1.247789 2861.791016 240128 [20081217-05:49:47.062386401] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:49:47.065353563] msec_range[1] 2000.000000 - 5000.000000 : 132 [20081217-05:49:47.068220571] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:49:47.070996242] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:49:47.073654589] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:49:47.076507817] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:49:47.079213003] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:49:47.081770088] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:49:47.085061574] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:49:47.090367876] msec_range[9] 5.000000 - 10.000000 : 1 [20081217-05:49:47.094608739] msec_range[10] 2.000000 - 5.000000 : 2 [20081217-05:49:47.097724584] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:49:47.101601821] msec_range[12] 0.500000 - 1.000000 : 6 [20081217-05:49:47.104662304] msec_range[13] 0.200000 - 0.500000 : 14 [20081217-05:49:47.109004516] msec_range[14] 0.100000 - 0.200000 : 41 [20081217-05:49:47.111905625] msec_range[15] 0.050000 - 0.100000 : 414 [20081217-05:49:47.116500535] msec_range[16] 0.020000 - 0.050000 : 12482 [20081217-05:49:47.118908766] msec_range[17] 0.010000 - 0.020000 : 54051 [20081217-05:49:47.121564533] msec_range[18] 0.000000 - 0.010000 : 172985 [20081217-05:49:47.124518614] [20081217-05:49:47.127137506] [ lseek] 0.000000 0.000898 0.207000 240128 [20081217-05:49:47.129405095] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:49:47.131873403] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:49:47.134742031] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:49:47.137649569] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:49:47.143127299] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:49:47.145697136] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:49:47.150376013] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:49:47.153410540] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:49:47.156206535] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:49:47.158848688] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:49:47.161302568] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:49:47.163683931] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:49:47.166077243] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:49:47.168813703] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-05:49:47.173354231] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-05:49:47.176070901] msec_range[15] 0.050000 - 0.100000 : 12 [20081217-05:49:47.178612170] msec_range[16] 0.020000 - 0.050000 : 104 [20081217-05:49:47.181859112] msec_range[17] 0.010000 - 0.020000 : 100 [20081217-05:49:47.184519579] msec_range[18] 0.000000 - 0.010000 : 239910 [20081217-05:49:47.186847753] [20081217-05:49:47.189113122] [ close] 0.001000 0.002943 0.047000 938 [20081217-05:49:47.191813654] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:49:47.194363663] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:49:47.196843287] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:49:47.199137268] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:49:47.201736593] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:49:47.204441886] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:49:47.207759059] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:49:47.210196188] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:49:47.212678128] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:49:47.214939612] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:49:47.217488272] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:49:47.220124036] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:49:47.222639989] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:49:47.224972353] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:49:47.227306332] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:49:47.229531522] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:49:47.232023202] msec_range[16] 0.020000 - 0.050000 : 2 [20081217-05:49:47.234298972] msec_range[17] 0.010000 - 0.020000 : 10 [20081217-05:49:47.236455588] msec_range[18] 0.000000 - 0.010000 : 926 [20081217-05:49:47.238801695] [20081217-05:49:47.241005201] [20081217-05:49:47.243644266] [20081217-05:49:47.245857235] [20081217-05:49:47.248074568] 0.1% User Time [20081217-05:49:47.250161224] 1.1% System Time [20081217-05:49:47.252602473] 1.2% CPU Utilization [20081217-05:49:47.254944372] Profilers reporting [20081217-05:49:47.257287839] /autobench/scripts/doprofilers: line 33: 26846 Terminated ${CMDS[$i]} [20081217-05:49:47.259546808] /autobench/scripts/doprofilers: line 33: 26853 Terminated ${CMDS[$i]} [20081217-05:49:47.261735629] /autobench/scripts/doprofilers: line 33: 26889 Terminated ${CMDS[$i]} [20081217-05:50:00.330581461] Profilers postprocessing [20081217-05:50:00.418814710] Processing File : iostat.001 [20081217-05:50:00.421248008] Discovered iostat_interval=[5] [20081217-05:50:00.987344083] Processing Directory : sar.breakout.001 [20081217-05:50:00.989670299] Discovered sar_interval=[5] [20081217-05:50:01.162821685] Processing File : mpstat.001 [20081217-05:50:01.165048041] Discovered mpstat_interval=[5] [20081217-05:50:02.299027329] Stopping profiling. [20081217-05:50:02.303524892] Killing daemon. [20081217-05:50:03.472509903] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_05.43.45/analysis/oprofile.001 [20081217-05:50:03.474658603] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_05.43.45/analysis/oprofile-brief.001 [20081217-05:50:04.493135161] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:50:05.937799662] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:50:06.373063249] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:50:06.477125493] PROCESSING COMMAND : 'run random_writes__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=8' [20081217-05:50:06.521717053] new log requested [20081217-05:50:06.544850445] Running command ffsb [20081217-05:50:13.866732845] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081217-05:50:13.879904584] Importing argument : num_threads=8 [20081217-05:50:13.906437368] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:50:13.970763357] FFSB version 6.0-RC2 started [20081217-05:50:13.973061587] [20081217-05:50:14.002223340] benchmark time = 300 [20081217-05:50:14.004421792] ThreadGroup 0 [20081217-05:50:14.006300625] ================ [20081217-05:50:14.008173448] num_threads = 8 [20081217-05:50:14.009982533] [20081217-05:50:14.011801327] read_random = off [20081217-05:50:14.013544603] read_size = 0 (0B) [20081217-05:50:14.015387843] read_blocksize = 0 (0B) [20081217-05:50:14.017137275] read_skip = off [20081217-05:50:14.018948908] read_skipsize = 0 (0B) [20081217-05:50:14.020719061] [20081217-05:50:14.022573031] write_random = on [20081217-05:50:14.024361289] write_size = 1048576 (1MB) [20081217-05:50:14.026160117] fsync_file = 0 [20081217-05:50:14.027906582] write_blocksize = 4096 (4KB) [20081217-05:50:14.029730205] wait time = 0 [20081217-05:50:14.031511158] [20081217-05:50:14.033301523] op weights [20081217-05:50:14.035038359] read = 0 (0.00%) [20081217-05:50:14.037143937] readall = 0 (0.00%) [20081217-05:50:14.039022542] write = 1 (100.00%) [20081217-05:50:14.041106327] create = 0 (0.00%) [20081217-05:50:14.043073229] append = 0 (0.00%) [20081217-05:50:14.044863771] delete = 0 (0.00%) [20081217-05:50:14.046717764] metaop = 0 (0.00%) [20081217-05:50:14.048525391] createdir = 0 (0.00%) [20081217-05:50:14.050444707] stat = 0 (0.00%) [20081217-05:50:14.052205360] writeall = 0 (0.00%) [20081217-05:50:14.053956043] writeall_fsync = 0 (0.00%) [20081217-05:50:14.055776680] open_close = 0 (0.00%) [20081217-05:50:14.057688673] write_fsync = 0 (0.00%) [20081217-05:50:14.059455606] create_fsync = 0 (0.00%) [20081217-05:50:14.061251420] append_fsync = 0 (0.00%) [20081217-05:50:14.063021450] [20081217-05:50:14.064843026] FileSystem /mnt/ffsb1 [20081217-05:50:14.066624379] ========== [20081217-05:50:14.068465287] num_dirs = 0 [20081217-05:50:14.070353155] starting files = 1024 [20081217-05:50:14.072141806] [20081217-05:50:14.073994586] min file size = 36700160 (35MB) [20081217-05:50:14.075788162] max file size = 36700160 (35MB) [20081217-05:50:14.077661546] directio = off [20081217-05:50:14.079391218] alignedio = on [20081217-05:50:14.081211844] bufferedio = off [20081217-05:50:14.082989268] [20081217-05:50:14.084817778] aging is off [20081217-05:50:14.086756299] current utilization = 51.23% [20081217-05:50:14.088573808] [20081217-05:50:14.090350198] checking existing fs: /mnt/ffsb1 [20081217-05:50:14.411162080] fs setup took 0 secs [20081217-05:50:15.464615169] Syncing()...1 sec [20081217-05:50:15.467321183] Starting Actual Benchmark At: Wed Dec 17 05:50:15 2008 [20081217-05:50:15.481184623] [20081217-05:56:12.010415352] Syncing()...39 sec [20081217-05:56:12.013199366] FFSB benchmark finished at: Wed Dec 17 05:56:12 2008 [20081217-05:56:12.016181530] [20081217-05:56:12.018730461] Results: [20081217-05:56:12.033771488] Benchmark took 356.55 sec [20081217-05:56:12.036161897] [20081217-05:56:12.038953404] Total Results [20081217-05:56:12.057768084] =============== [20081217-05:56:12.060990940] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:56:12.063687895] ======= ============ ========= ======= =========== ========== [20081217-05:56:12.066261769] write : 214272 600.97 100.000% 100.000% 82.2MB/sec [20081217-05:56:12.068756326] - [20081217-05:56:12.071270302] 600.97 Transactions per Second [20081217-05:56:12.073829115] [20081217-05:56:12.076440684] Throughput Results [20081217-05:56:12.092206077] =================== [20081217-05:56:12.096480052] Write Throughput: 82.2MB/sec [20081217-05:56:12.099253140] [20081217-05:56:12.102077748] System Call Latency statistics in millisecs [20081217-05:56:12.105014591] ===== [20081217-05:56:12.107613566] Min Avg Max Total Calls [20081217-05:56:12.111858785] ======== ======== ======== ============ [20081217-05:56:12.115372543] [ open] 0.006000 0.011234 0.542000 837 [20081217-05:56:12.118200487] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:56:12.121094357] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:56:12.123763626] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:56:12.126553578] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:56:12.129246396] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:56:12.131765432] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:56:12.134418445] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:56:12.137624598] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:56:12.142590077] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:56:12.145891784] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:56:12.148150760] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:56:12.150881130] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:56:12.153612616] msec_range[12] 0.500000 - 1.000000 : 1 [20081217-05:56:12.155941119] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:56:12.159060972] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:56:12.161880885] msec_range[15] 0.050000 - 0.100000 : 2 [20081217-05:56:12.164555559] msec_range[16] 0.020000 - 0.050000 : 60 [20081217-05:56:12.167015264] msec_range[17] 0.010000 - 0.020000 : 275 [20081217-05:56:12.169461711] msec_range[18] 0.000000 - 0.010000 : 499 [20081217-05:56:12.172224829] [20081217-05:56:12.175019048] [ write] 0.004000 11.214944 36860.730469 214272 [20081217-05:56:12.177760550] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:56:12.180449256] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:56:12.183379612] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:56:12.186043800] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:56:12.188872317] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:56:12.192220358] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:56:12.194660659] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:56:12.197293744] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:56:12.200089172] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-05:56:12.202876985] msec_range[9] 5.000000 - 10.000000 : 4 [20081217-05:56:12.210168819] msec_range[10] 2.000000 - 5.000000 : 3 [20081217-05:56:12.213490807] msec_range[11] 1.000000 - 2.000000 : 5 [20081217-05:56:12.216438816] msec_range[12] 0.500000 - 1.000000 : 13 [20081217-05:56:12.219153511] msec_range[13] 0.200000 - 0.500000 : 30 [20081217-05:56:12.221679758] msec_range[14] 0.100000 - 0.200000 : 100 [20081217-05:56:12.227644668] msec_range[15] 0.050000 - 0.100000 : 809 [20081217-05:56:12.230860905] msec_range[16] 0.020000 - 0.050000 : 20745 [20081217-05:56:12.234132121] msec_range[17] 0.010000 - 0.020000 : 52101 [20081217-05:56:12.238694675] msec_range[18] 0.000000 - 0.010000 : 140335 [20081217-05:56:12.241076040] [20081217-05:56:12.243318329] [ lseek] 0.000000 0.596838 18971.052734 214272 [20081217-05:56:12.245763509] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:56:12.249608537] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:56:12.253062724] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:56:12.255971286] msec_range[3] 500.000000 - 1000.000000 : 1 [20081217-05:56:12.258946346] msec_range[4] 200.000000 - 500.000000 : 2 [20081217-05:56:12.261555758] msec_range[5] 100.000000 - 200.000000 : 1 [20081217-05:56:12.263517820] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:56:12.265820132] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:56:12.268210196] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:56:12.271070988] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:56:12.274088295] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:56:12.276740745] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-05:56:12.280878770] msec_range[12] 0.500000 - 1.000000 : 4 [20081217-05:56:12.283362547] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-05:56:12.285768667] msec_range[14] 0.100000 - 0.200000 : 11 [20081217-05:56:12.288371665] msec_range[15] 0.050000 - 0.100000 : 54 [20081217-05:56:12.290987151] msec_range[16] 0.020000 - 0.050000 : 234 [20081217-05:56:12.295913448] msec_range[17] 0.010000 - 0.020000 : 367 [20081217-05:56:12.298270151] msec_range[18] 0.000000 - 0.010000 : 213589 [20081217-05:56:12.300744313] [20081217-05:56:12.303309165] [ close] 0.001000 0.003215 0.039000 837 [20081217-05:56:12.305784612] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:56:12.310010940] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:56:12.312322788] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:56:12.314563424] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:56:12.316936315] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:56:12.319298934] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:56:12.321639999] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:56:12.323979317] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:56:12.326676617] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:56:12.329165897] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:56:12.331389385] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:56:12.333585675] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:56:12.335867119] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:56:12.337943079] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:56:12.340200278] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:56:12.342648190] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:56:12.344679466] msec_range[16] 0.020000 - 0.050000 : 2 [20081217-05:56:12.346854621] msec_range[17] 0.010000 - 0.020000 : 19 [20081217-05:56:12.348940221] msec_range[18] 0.000000 - 0.010000 : 816 [20081217-05:56:12.351141437] [20081217-05:56:12.353582424] [20081217-05:56:12.356601365] [20081217-05:56:12.358868948] [20081217-05:56:12.360915772] 0.1% User Time [20081217-05:56:12.363509088] 1.0% System Time [20081217-05:56:12.365845532] 1.2% CPU Utilization [20081217-05:56:12.367888483] Profilers reporting [20081217-05:56:12.370074528] /autobench/scripts/doprofilers: line 33: 32735 Terminated ${CMDS[$i]} [20081217-05:56:12.372365829] /autobench/scripts/doprofilers: line 33: 316 Terminated ${CMDS[$i]} [20081217-05:56:28.138239682] Profilers postprocessing [20081217-05:56:28.225725152] Processing File : iostat.001 [20081217-05:56:28.227869095] Discovered iostat_interval=[5] [20081217-05:56:28.799154678] Processing Directory : sar.breakout.001 [20081217-05:56:28.801412740] Discovered sar_interval=[5] [20081217-05:56:28.975934089] Processing File : mpstat.001 [20081217-05:56:28.978225199] Discovered mpstat_interval=[5] [20081217-05:56:30.110994869] Stopping profiling. [20081217-05:56:30.115434185] Killing daemon. [20081217-05:56:31.284707701] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-12-17_05.50.06/analysis/oprofile.001 [20081217-05:56:31.286899410] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-12-17_05.50.06/analysis/oprofile-brief.001 [20081217-05:56:32.619740097] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-05:56:34.104804974] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:56:34.525693777] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:56:34.630965707] PROCESSING COMMAND : 'run random_writes__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=32' [20081217-05:56:34.674224117] new log requested [20081217-05:56:34.697149724] Running command ffsb [20081217-05:56:41.984087997] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081217-05:56:41.997566792] Importing argument : num_threads=32 [20081217-05:56:42.024147822] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:56:42.089874216] FFSB version 6.0-RC2 started [20081217-05:56:42.091980246] [20081217-05:56:42.212930473] benchmark time = 300 [20081217-05:56:42.215158787] ThreadGroup 0 [20081217-05:56:42.217273357] ================ [20081217-05:56:42.219241350] num_threads = 32 [20081217-05:56:42.221140396] [20081217-05:56:42.222967658] read_random = off [20081217-05:56:42.224729025] read_size = 0 (0B) [20081217-05:56:42.226573446] read_blocksize = 0 (0B) [20081217-05:56:42.228359230] read_skip = off [20081217-05:56:42.230187027] read_skipsize = 0 (0B) [20081217-05:56:42.231933052] [20081217-05:56:42.233768596] write_random = on [20081217-05:56:42.235561418] write_size = 1048576 (1MB) [20081217-05:56:42.237372923] fsync_file = 0 [20081217-05:56:42.239103319] write_blocksize = 4096 (4KB) [20081217-05:56:42.240936351] wait time = 0 [20081217-05:56:42.242702525] [20081217-05:56:42.244503565] op weights [20081217-05:56:42.246186891] read = 0 (0.00%) [20081217-05:56:42.248027622] readall = 0 (0.00%) [20081217-05:56:42.249791359] write = 1 (100.00%) [20081217-05:56:42.251598999] create = 0 (0.00%) [20081217-05:56:42.253326100] append = 0 (0.00%) [20081217-05:56:42.255151220] delete = 0 (0.00%) [20081217-05:56:42.256892898] metaop = 0 (0.00%) [20081217-05:56:42.258722231] createdir = 0 (0.00%) [20081217-05:56:42.260442810] stat = 0 (0.00%) [20081217-05:56:42.262273873] writeall = 0 (0.00%) [20081217-05:56:42.264035042] writeall_fsync = 0 (0.00%) [20081217-05:56:42.265898106] open_close = 0 (0.00%) [20081217-05:56:42.267821682] write_fsync = 0 (0.00%) [20081217-05:56:42.269608886] create_fsync = 0 (0.00%) [20081217-05:56:42.271446060] append_fsync = 0 (0.00%) [20081217-05:56:42.273222747] [20081217-05:56:42.275290989] FileSystem /mnt/ffsb1 [20081217-05:56:42.277301081] ========== [20081217-05:56:42.279039500] num_dirs = 0 [20081217-05:56:42.280872266] starting files = 1024 [20081217-05:56:42.282689511] [20081217-05:56:42.284479601] min file size = 36700160 (35MB) [20081217-05:56:42.286212193] max file size = 36700160 (35MB) [20081217-05:56:42.288052398] directio = off [20081217-05:56:42.289841723] alignedio = on [20081217-05:56:42.291643630] bufferedio = off [20081217-05:56:42.293368501] [20081217-05:56:42.295189940] aging is off [20081217-05:56:42.296920124] current utilization = 51.23% [20081217-05:56:42.298772241] [20081217-05:56:42.300486249] checking existing fs: /mnt/ffsb1 [20081217-05:56:42.595010611] fs setup took 0 secs [20081217-05:56:43.536961259] Syncing()...0 sec [20081217-05:56:43.540614055] Starting Actual Benchmark At: Wed Dec 17 05:56:43 2008 [20081217-05:56:43.556165569] [20081217-06:02:51.729017933] Syncing()...28 sec [20081217-06:02:51.731928665] FFSB benchmark finished at: Wed Dec 17 06:02:51 2008 [20081217-06:02:51.734805202] [20081217-06:02:51.737564985] Results: [20081217-06:02:51.753246705] Benchmark took 368.19 sec [20081217-06:02:51.755769661] [20081217-06:02:51.758284547] Total Results [20081217-06:02:51.773805363] =============== [20081217-06:02:51.777644206] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:02:51.781249880] ======= ============ ========= ======= =========== ========== [20081217-06:02:51.783974138] write : 216064 586.83 100.000% 100.000% 80.2MB/sec [20081217-06:02:51.786666076] - [20081217-06:02:51.789830260] 586.83 Transactions per Second [20081217-06:02:51.793566088] [20081217-06:02:51.796278137] Throughput Results [20081217-06:02:51.813199686] =================== [20081217-06:02:51.815984709] Write Throughput: 80.2MB/sec [20081217-06:02:51.819648538] [20081217-06:02:51.822618403] System Call Latency statistics in millisecs [20081217-06:02:51.825622348] ===== [20081217-06:02:51.828329616] Min Avg Max Total Calls [20081217-06:02:51.830960973] ======== ======== ======== ============ [20081217-06:02:51.833695016] [ open] 0.005000 0.016142 2.780000 844 [20081217-06:02:51.836428476] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:02:51.839072872] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:02:51.842159687] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:02:51.844812976] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:02:51.847406898] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:02:51.850035031] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:02:51.852633038] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:02:51.856079940] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:02:51.859996339] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:02:51.862486478] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:02:51.865432244] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-06:02:51.868397229] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:02:51.870932961] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:02:51.873651693] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:02:51.875886165] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-06:02:51.878247320] msec_range[15] 0.050000 - 0.100000 : 3 [20081217-06:02:51.882425150] msec_range[16] 0.020000 - 0.050000 : 133 [20081217-06:02:51.885365650] msec_range[17] 0.010000 - 0.020000 : 325 [20081217-06:02:51.888280804] msec_range[18] 0.000000 - 0.010000 : 381 [20081217-06:02:51.891092974] [20081217-06:02:51.893892761] [ write] 0.004000 43.778480 133908.609375 216064 [20081217-06:02:51.896820123] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:02:51.899665705] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:02:51.902574388] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:02:51.905067709] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:02:51.907495104] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:02:51.909972053] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:02:51.912590188] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:02:51.915774832] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:02:51.918591616] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-06:02:51.921311287] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:02:51.925456288] msec_range[10] 2.000000 - 5.000000 : 4 [20081217-06:02:51.929446249] msec_range[11] 1.000000 - 2.000000 : 6 [20081217-06:02:51.932657388] msec_range[12] 0.500000 - 1.000000 : 10 [20081217-06:02:51.935503629] msec_range[13] 0.200000 - 0.500000 : 67 [20081217-06:02:51.938006827] msec_range[14] 0.100000 - 0.200000 : 285 [20081217-06:02:51.940659103] msec_range[15] 0.050000 - 0.100000 : 1689 [20081217-06:02:51.943394644] msec_range[16] 0.020000 - 0.050000 : 38625 [20081217-06:02:51.945906242] msec_range[17] 0.010000 - 0.020000 : 60157 [20081217-06:02:51.950322498] msec_range[18] 0.000000 - 0.010000 : 115080 [20081217-06:02:51.954951236] [20081217-06:02:51.958749458] [ lseek] 0.000000 4.337266 128506.531250 216064 [20081217-06:02:51.961203683] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:02:51.965783617] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:02:51.968801896] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:02:51.971572352] msec_range[3] 500.000000 - 1000.000000 : 1 [20081217-06:02:51.973973354] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:02:51.976807039] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:02:51.979941160] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:02:51.983217864] msec_range[7] 20.000000 - 50.000000 : 1 [20081217-06:02:51.985924571] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:02:51.988524892] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:02:51.991419958] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-06:02:51.995067001] msec_range[11] 1.000000 - 2.000000 : 2 [20081217-06:02:51.998335438] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-06:02:52.001221646] msec_range[13] 0.200000 - 0.500000 : 7 [20081217-06:02:52.005388928] msec_range[14] 0.100000 - 0.200000 : 34 [20081217-06:02:52.008126722] msec_range[15] 0.050000 - 0.100000 : 150 [20081217-06:02:52.010654774] msec_range[16] 0.020000 - 0.050000 : 477 [20081217-06:02:52.013143621] msec_range[17] 0.010000 - 0.020000 : 669 [20081217-06:02:52.015516506] msec_range[18] 0.000000 - 0.010000 : 214701 [20081217-06:02:52.017898821] [20081217-06:02:52.020152708] [ close] 0.001000 0.004031 0.159000 844 [20081217-06:02:52.023157920] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:02:52.029073086] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:02:52.031357381] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:02:52.033705167] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:02:52.036666430] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:02:52.038776565] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:02:52.040806969] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:02:52.043247576] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:02:52.045828266] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:02:52.048414246] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:02:52.051035965] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:02:52.053551586] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:02:52.055700987] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:02:52.058145807] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:02:52.060524450] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-06:02:52.062807881] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-06:02:52.065131119] msec_range[16] 0.020000 - 0.050000 : 2 [20081217-06:02:52.067299864] msec_range[17] 0.010000 - 0.020000 : 31 [20081217-06:02:52.069510879] msec_range[18] 0.000000 - 0.010000 : 809 [20081217-06:02:52.071785733] [20081217-06:02:52.073966647] [20081217-06:02:52.076166362] [20081217-06:02:52.078370705] [20081217-06:02:52.080604802] 0.1% User Time [20081217-06:02:52.082773900] 1.2% System Time [20081217-06:02:52.085410912] 1.3% CPU Utilization [20081217-06:02:52.087790982] Profilers reporting [20081217-06:02:52.089955887] /autobench/scripts/doprofilers: line 33: 6209 Terminated ${CMDS[$i]} [20081217-06:02:52.092292654] /autobench/scripts/doprofilers: line 33: 6251 Terminated ${CMDS[$i]} [20081217-06:03:05.597459916] Profilers postprocessing [20081217-06:03:05.685229600] Processing File : iostat.001 [20081217-06:03:05.687555268] Discovered iostat_interval=[5] [20081217-06:03:06.262421041] Processing Directory : sar.breakout.001 [20081217-06:03:06.264726980] Discovered sar_interval=[5] [20081217-06:03:06.441083984] Processing File : mpstat.001 [20081217-06:03:06.443467618] Discovered mpstat_interval=[5] [20081217-06:03:07.577541950] Stopping profiling. [20081217-06:03:07.584030082] Killing daemon. [20081217-06:03:08.757465639] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.08-12-17_05.56.34/analysis/oprofile.001 [20081217-06:03:08.759728785] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.08-12-17_05.56.34/analysis/oprofile-brief.001 [20081217-06:03:10.010988399] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline' [20081217-06:03:11.562589501] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-06:03:12.049215805] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-06:03:12.157233091] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb num_threads=1' [20081217-06:03:12.201504312] new log requested [20081217-06:03:12.224837178] Running command ffsb [20081217-06:03:19.585445662] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb [20081217-06:03:19.598513072] Importing argument : num_threads=1 [20081217-06:03:19.625238068] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-06:03:19.690277657] FFSB version 6.0-RC2 started [20081217-06:03:19.692286685] [20081217-06:03:19.694370182] benchmark time = 300 [20081217-06:03:19.696317151] ThreadGroup 0 [20081217-06:03:19.698069014] ================ [20081217-06:03:19.699916984] num_threads = 1 [20081217-06:03:19.701756330] [20081217-06:03:19.703523973] read_random = off [20081217-06:03:19.705348790] read_size = 0 (0B) [20081217-06:03:19.707143486] read_blocksize = 0 (0B) [20081217-06:03:19.708892901] read_skip = off [20081217-06:03:19.710715852] read_skipsize = 0 (0B) [20081217-06:03:19.712714008] [20081217-06:03:19.714912040] write_random = on [20081217-06:03:19.716737454] write_size = 1048576 (1MB) [20081217-06:03:19.718882206] fsync_file = 0 [20081217-06:03:19.720786404] write_blocksize = 4096 (4KB) [20081217-06:03:19.722615480] wait time = 0 [20081217-06:03:19.724389890] [20081217-06:03:19.726401932] op weights [20081217-06:03:19.728367087] read = 0 (0.00%) [20081217-06:03:19.730130486] readall = 0 (0.00%) [20081217-06:03:19.731976147] write = 1 (100.00%) [20081217-06:03:19.733815963] create = 0 (0.00%) [20081217-06:03:19.735542378] append = 0 (0.00%) [20081217-06:03:19.737391529] delete = 0 (0.00%) [20081217-06:03:19.739161124] metaop = 0 (0.00%) [20081217-06:03:19.741005010] createdir = 0 (0.00%) [20081217-06:03:19.742757315] stat = 0 (0.00%) [20081217-06:03:19.744685885] writeall = 0 (0.00%) [20081217-06:03:19.746553402] writeall_fsync = 0 (0.00%) [20081217-06:03:19.748343233] open_close = 0 (0.00%) [20081217-06:03:19.750190957] write_fsync = 0 (0.00%) [20081217-06:03:19.751961523] create_fsync = 0 (0.00%) [20081217-06:03:19.753787814] append_fsync = 0 (0.00%) [20081217-06:03:19.755559447] [20081217-06:03:19.757484806] FileSystem /mnt/ffsb1 [20081217-06:03:19.759394499] ========== [20081217-06:03:19.761169412] num_dirs = 0 [20081217-06:03:19.763001518] starting files = 1024 [20081217-06:03:19.764760093] [20081217-06:03:19.766608147] min file size = 36700160 (35MB) [20081217-06:03:19.768365356] max file size = 36700160 (35MB) [20081217-06:03:19.770297531] directio = on [20081217-06:03:19.772197224] alignedio = on [20081217-06:03:19.773948615] bufferedio = off [20081217-06:03:19.775770059] [20081217-06:03:19.777600666] aging is off [20081217-06:03:19.779338037] current utilization = 51.23% [20081217-06:03:19.781179287] [20081217-06:03:19.782997550] checking existing fs: /mnt/ffsb1 [20081217-06:03:20.106631621] fs setup took 0 secs [20081217-06:03:21.165117023] Syncing()...1 sec [20081217-06:03:21.167157780] Starting Actual Benchmark At: Wed Dec 17 06:03:21 2008 [20081217-06:03:21.180261395] [20081217-06:08:23.781770459] Syncing()...0 sec [20081217-06:08:23.784779498] FFSB benchmark finished at: Wed Dec 17 06:08:23 2008 [20081217-06:08:23.787564101] [20081217-06:08:23.790322684] Results: [20081217-06:08:23.806053543] Benchmark took 302.62 sec [20081217-06:08:23.808708802] [20081217-06:08:23.811072551] Total Results [20081217-06:08:23.826714624] =============== [20081217-06:08:23.829425971] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:08:23.832158421] ======= ============ ========= ======= =========== ========== [20081217-06:08:23.834855635] write : 89600 296.09 100.000% 100.000% 40.5MB/sec [20081217-06:08:23.837622795] - [20081217-06:08:23.840487118] 296.09 Transactions per Second [20081217-06:08:23.843216670] [20081217-06:08:23.845827550] Throughput Results [20081217-06:08:23.861828466] =================== [20081217-06:08:23.864670742] Write Throughput: 40.5MB/sec [20081217-06:08:23.867344068] [20081217-06:08:23.869894447] System Call Latency statistics in millisecs [20081217-06:08:23.872388315] ===== [20081217-06:08:23.876361966] Min Avg Max Total Calls [20081217-06:08:23.878925071] ======== ======== ======== ============ [20081217-06:08:23.882701330] [ open] 0.007000 0.014686 0.032000 350 [20081217-06:08:23.885172476] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:08:23.887890790] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:08:23.890602189] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:08:23.893306686] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:08:23.895864368] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:08:23.898682076] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:08:23.901121472] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:08:23.904325832] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:08:23.906658525] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:08:23.909919926] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:08:23.912506142] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:08:23.916475940] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:08:23.919700795] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:08:23.922860157] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:08:23.925456582] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:08:23.927797016] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:08:23.932824642] msec_range[16] 0.020000 - 0.050000 : 69 [20081217-06:08:23.935490427] msec_range[17] 0.010000 - 0.020000 : 212 [20081217-06:08:23.938877639] msec_range[18] 0.000000 - 0.010000 : 69 [20081217-06:08:23.941501562] [20081217-06:08:23.944013893] [ write] 0.863000 3.363634 151.365005 89600 [20081217-06:08:23.946825792] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:08:23.949883203] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:08:23.952970277] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:08:23.955531626] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:08:23.958093069] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:08:23.961861457] msec_range[5] 100.000000 - 200.000000 : 3 [20081217-06:08:23.966432980] msec_range[6] 50.000000 - 100.000000 : 2 [20081217-06:08:23.970285717] msec_range[7] 20.000000 - 50.000000 : 10 [20081217-06:08:23.973673999] msec_range[8] 10.000000 - 20.000000 : 90 [20081217-06:08:23.977472467] msec_range[9] 5.000000 - 10.000000 : 7675 [20081217-06:08:23.979923474] msec_range[10] 2.000000 - 5.000000 : 66747 [20081217-06:08:23.982477647] msec_range[11] 1.000000 - 2.000000 : 14991 [20081217-06:08:23.985145791] msec_range[12] 0.500000 - 1.000000 : 82 [20081217-06:08:23.987643410] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:08:23.990119080] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:08:23.993442999] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:08:23.996078621] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-06:08:23.998907117] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-06:08:24.001794391] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-06:08:24.004088352] [20081217-06:08:24.006557506] [ lseek] 0.000000 0.001244 0.014000 89600 [20081217-06:08:24.009311488] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:08:24.012080996] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:08:24.015122129] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:08:24.017683980] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:08:24.020317376] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:08:24.022951493] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:08:24.025498938] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:08:24.028077863] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:08:24.032548860] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:08:24.037660662] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:08:24.042316607] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:08:24.045525841] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:08:24.048110845] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:08:24.050507113] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:08:24.053046919] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:08:24.056034621] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:08:24.059477659] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-06:08:24.062746541] msec_range[17] 0.010000 - 0.020000 : 27 [20081217-06:08:24.066082545] msec_range[18] 0.000000 - 0.010000 : 89573 [20081217-06:08:24.068655947] [20081217-06:08:24.071197045] [ close] 0.002000 0.003811 0.013000 350 [20081217-06:08:24.073685408] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:08:24.076059252] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:08:24.078281701] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:08:24.080538502] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:08:24.083347759] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:08:24.085672183] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:08:24.088257227] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:08:24.090835793] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:08:24.093182756] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:08:24.095473609] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:08:24.097765449] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:08:24.100124827] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:08:24.102887467] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:08:24.105237597] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:08:24.107628392] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:08:24.109990662] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:08:24.112190854] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-06:08:24.114445759] msec_range[17] 0.010000 - 0.020000 : 2 [20081217-06:08:24.116600892] msec_range[18] 0.000000 - 0.010000 : 348 [20081217-06:08:24.118847086] [20081217-06:08:24.120962673] [20081217-06:08:24.123182071] [20081217-06:08:24.125439935] [20081217-06:08:24.127611791] 0.1% User Time [20081217-06:08:24.129806142] 0.6% System Time [20081217-06:08:24.131976358] 0.7% CPU Utilization [20081217-06:08:24.134443332] Profilers reporting [20081217-06:08:24.136608970] /autobench/scripts/doprofilers: line 33: 12149 Terminated ${CMDS[$i]} [20081217-06:08:24.138831085] /autobench/scripts/doprofilers: line 33: 12159 Terminated ${CMDS[$i]} [20081217-06:08:24.141108804] /autobench/scripts/doprofilers: line 33: 12194 Terminated ${CMDS[$i]} [20081217-06:08:35.814720226] Profilers postprocessing [20081217-06:08:35.901804072] Processing File : iostat.001 [20081217-06:08:35.904192865] Discovered iostat_interval=[5] [20081217-06:08:36.434987769] Processing Directory : sar.breakout.001 [20081217-06:08:36.437180079] Discovered sar_interval=[5] [20081217-06:08:36.597382035] Processing File : mpstat.001 [20081217-06:08:36.599604139] Discovered mpstat_interval=[5] [20081217-06:08:37.731544237] Stopping profiling. [20081217-06:08:37.736372554] Killing daemon. [20081217-06:08:38.905183080] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_06.03.12/analysis/oprofile.001 [20081217-06:08:38.907433547] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_06.03.12/analysis/oprofile-brief.001 [20081217-06:08:40.208903770] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0502/jfs-baseline'