[20081217-05:31:27.682082875] PROCESSING COMMAND : 'clearprofilers' [20081217-05:31:27.933064133] PROCESSING COMMAND : 'useprofiler iostat 5' [20081217-05:31:28.040537184] Checking for sar... [20081217-05:31:28.042962919] found [20081217-05:31:28.178827162] PROCESSING COMMAND : 'useprofiler sar 5' [20081217-05:31:28.285883185] Checking for sar... [20081217-05:31:28.288077536] found [20081217-05:31:28.424115867] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081217-05:31:28.530877506] Checking for sar... [20081217-05:31:28.533096990] found [20081217-05:31:28.701795964] PROCESSING COMMAND : 'useprofiler oprofile' [20081217-05:31:28.914639495] Checking for binutils-2.18 ... Already installed. [20081217-05:31:28.918826164] mv: cannot stat `lib64/*': No such file or directory [20081217-05:31:28.927723702] rmdir: lib64: No such file or directory [20081217-05:31:28.998930773] Checking for gettext-0.17 ... Already installed. [20081217-05:31:29.045075917] popt32-1.10.4 already installed. [20081217-05:31:29.060249694] popt64-1.10.4 already installed. [20081217-05:31:29.090808580] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-05:31:29.143425613] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-05:31:29.222832870] Daemon not running [20081217-05:31:29.243509887] Unloading oprofile module [20081217-05:31:29.456708425] Daemon not running [20081217-05:31:31.620728509] OPROFILE : using callgraph [5] [20081217-05:31:31.852214661] Daemon not running [20081217-05:31:31.854267098] Separate options: none [20081217-05:31:31.856423521] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-05:31:31.858557103] Image filter: none [20081217-05:31:31.860719368] Call-graph depth: 5 [20081217-05:31:32.064951810] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081217-05:31:32.140667399] PROCESSING COMMAND : 'set-sched noop' [20081217-05:31:32.538405164] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2008-12-17_0531 jfs-baseline' [20081217-05:31:32.778312292] Connecting to hks.austin.ibm.com... [20081217-05:31:32.780417492] Remote working directory: /opt [20081217-05:31:32.782699232] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081217-05:31:32.784694662] Couldn't create directory: Failure [20081217-05:31:32.786911744] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-05:31:32.789013452] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-05:31:32.791142214] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531 [20081217-05:31:32.793038613] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531 [20081217-05:31:32.795085759] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline [20081217-05:31:32.865657277] PROCESSING COMMAND : 'mkfs.jfs -V 2>&1' [20081217-05:31:32.897753914] mkfs.jfs version 1.1.13, 17-Jul-2008 [20081217-05:31:32.994502537] PROCESSING COMMAND : 'mkfs.jfs -q /dev/ffsbdev1' [20081217-05:31:34.029948938] mkfs.jfs version 1.1.13, 17-Jul-2008 [20081217-05:31:34.032443999] [20081217-05:31:34.034822376] [20081217-05:31:34.036674941] Format completed successfully. [20081217-05:31:34.038646510] [20081217-05:31:34.040771770] 2345959424 kilobytes total disk space. [20081217-05:31:34.193220529] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:31:34.273327793] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=1' [20081217-05:31:34.318614672] new log requested [20081217-05:31:34.343012158] Running command ffsb [20081217-05:31:44.097473702] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-05:31:44.114361512] Importing argument : num_threads=1 [20081217-05:31:44.140774535] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:31:44.229006916] Checking for sar... [20081217-05:31:44.231133218] found [20081217-05:31:44.287305749] Checking for sar... [20081217-05:31:44.289475536] found [20081217-05:31:44.345730465] Checking for sar... [20081217-05:31:44.347888726] found [20081217-05:31:44.476170028] Checking for binutils-2.18 ... Already installed. [20081217-05:31:44.480452719] mv: cannot stat `lib64/*': No such file or directory [20081217-05:31:44.483202772] rmdir: lib64: No such file or directory [20081217-05:31:44.542713781] Checking for gettext-0.17 ... Already installed. [20081217-05:31:44.591174012] popt32-1.10.4 already installed. [20081217-05:31:44.602433285] popt64-1.10.4 already installed. [20081217-05:31:44.632894476] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-05:31:44.685423597] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-05:31:44.766358395] Daemon not running [20081217-05:31:44.777107171] Unloading oprofile module [20081217-05:31:44.888186660] Daemon not running [20081217-05:31:45.118270477] OPROFILE : using callgraph [5] [20081217-05:31:45.351987957] Daemon not running [20081217-05:31:45.354087621] Separate options: none [20081217-05:31:45.356093993] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-05:31:45.358305500] Image filter: none [20081217-05:31:45.360109950] Call-graph depth: 5 [20081217-05:31:45.441437859] FFSB version 6.0-RC2 started [20081217-05:31:45.443321826] [20081217-05:31:45.445410428] benchmark time = 300 [20081217-05:31:45.447372834] ThreadGroup 0 [20081217-05:31:45.449448183] ================ [20081217-05:31:45.451448885] num_threads = 1 [20081217-05:31:45.453742963] [20081217-05:31:45.455727801] read_random = off [20081217-05:31:45.457505941] read_size = 0 (0B) [20081217-05:31:45.459432137] read_blocksize = 4096 (4KB) [20081217-05:31:45.461303813] read_skip = off [20081217-05:31:45.463071980] read_skipsize = 0 (0B) [20081217-05:31:45.464945283] [20081217-05:31:45.466808312] write_random = off [20081217-05:31:45.468563438] write_size = 0 (0B) [20081217-05:31:45.470417571] fsync_file = 0 [20081217-05:31:45.472286246] write_blocksize = 0 (0B) [20081217-05:31:45.474050935] wait time = 0 [20081217-05:31:45.475916418] [20081217-05:31:45.477749998] op weights [20081217-05:31:45.479492119] read = 0 (0.00%) [20081217-05:31:45.481352041] readall = 1 (100.00%) [20081217-05:31:45.483200954] write = 0 (0.00%) [20081217-05:31:45.484933545] create = 0 (0.00%) [20081217-05:31:45.486783276] append = 0 (0.00%) [20081217-05:31:45.488651202] delete = 0 (0.00%) [20081217-05:31:45.490438368] metaop = 0 (0.00%) [20081217-05:31:45.492310898] createdir = 0 (0.00%) [20081217-05:31:45.494146103] stat = 0 (0.00%) [20081217-05:31:45.495897199] writeall = 0 (0.00%) [20081217-05:31:45.497759192] writeall_fsync = 0 (0.00%) [20081217-05:31:45.499595796] open_close = 0 (0.00%) [20081217-05:31:45.501348939] write_fsync = 0 (0.00%) [20081217-05:31:45.503203007] create_fsync = 0 (0.00%) [20081217-05:31:45.505161269] append_fsync = 0 (0.00%) [20081217-05:31:45.506898159] [20081217-05:31:45.508785988] FileSystem /mnt/ffsb1 [20081217-05:31:45.510650216] ========== [20081217-05:31:45.512393664] num_dirs = 0 [20081217-05:31:45.514266822] starting files = 1024 [20081217-05:31:45.516131741] [20081217-05:31:45.517911307] min file size = 104857600 (100MB) [20081217-05:31:45.519767150] max file size = 104857600 (100MB) [20081217-05:31:45.521624369] directio = off [20081217-05:31:45.523399088] alignedio = on [20081217-05:31:45.525273495] bufferedio = off [20081217-05:31:45.527145135] [20081217-05:31:45.528880359] aging is off [20081217-05:31:45.530731739] current utilization = 0.01% [20081217-05:31:45.532599604] [20081217-05:31:45.534359366] checking existing fs: /mnt/ffsb1 [20081217-05:31:45.536204279] opendir: No such file or directory [20081217-05:31:45.538017950] recreating new fileset [20081217-05:37:53.304058964] fs setup took 367 secs [20081217-05:37:53.377397419] Syncing()...0 sec [20081217-05:37:53.379724910] Starting Actual Benchmark At: Wed Dec 17 05:37:53 2008 [20081217-05:37:53.437489193] [20081217-05:42:55.571915087] Syncing()...0 sec [20081217-05:42:55.618475745] FFSB benchmark finished at: Wed Dec 17 05:42:55 2008 [20081217-05:42:55.621315082] [20081217-05:42:55.624087677] Results: [20081217-05:42:55.710980260] Benchmark took 301.90 sec [20081217-05:42:55.713763962] [20081217-05:42:55.716485808] Total Results [20081217-05:42:55.731794984] =============== [20081217-05:42:55.733940894] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:42:55.736413185] ======= ============ ========= ======= =========== ========== [20081217-05:42:55.738736306] readall : 13056000 43246.58 100.000% 100.000% 169MB/sec [20081217-05:42:55.740847491] - [20081217-05:42:55.743293336] 43246.58 Transactions per Second [20081217-05:42:55.745817851] [20081217-05:42:55.748225508] Throughput Results [20081217-05:42:55.764293810] =================== [20081217-05:42:55.766454011] Read Throughput: 169MB/sec [20081217-05:42:55.769004599] [20081217-05:42:55.771352103] System Call Latency statistics in millisecs [20081217-05:42:55.773718143] ===== [20081217-05:42:55.775945596] Min Avg Max Total Calls [20081217-05:42:55.778281646] ======== ======== ======== ============ [20081217-05:42:55.780491704] [ open] 0.017000 0.430327 66.707001 510 [20081217-05:42:55.782624391] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:42:55.784792365] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:42:55.787391202] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:42:55.791109904] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:42:55.794673167] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:42:55.799280860] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:42:55.801951462] msec_range[6] 50.000000 - 100.000000 : 1 [20081217-05:42:55.804405849] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:42:55.807178620] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:42:55.809413298] msec_range[9] 5.000000 - 10.000000 : 11 [20081217-05:42:55.811818175] msec_range[10] 2.000000 - 5.000000 : 17 [20081217-05:42:55.814036641] msec_range[11] 1.000000 - 2.000000 : 2 [20081217-05:42:55.816355116] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:42:55.818714574] msec_range[13] 0.200000 - 0.500000 : 4 [20081217-05:42:55.821107385] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:42:55.823364782] msec_range[15] 0.050000 - 0.100000 : 12 [20081217-05:42:55.825979851] msec_range[16] 0.020000 - 0.050000 : 438 [20081217-05:42:55.828239555] msec_range[17] 0.010000 - 0.020000 : 25 [20081217-05:42:55.830363944] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-05:42:55.832420993] [20081217-05:42:55.834587948] [ read] 0.004000 0.022748 264.377991 13056000 [20081217-05:42:55.836833381] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:42:55.838977845] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:42:55.843973136] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:42:55.848045414] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:42:55.850600412] msec_range[4] 200.000000 - 500.000000 : 1 [20081217-05:42:55.852996035] msec_range[5] 100.000000 - 200.000000 : 1 [20081217-05:42:55.855575249] msec_range[6] 50.000000 - 100.000000 : 1 [20081217-05:42:55.857944735] msec_range[7] 20.000000 - 50.000000 : 43 [20081217-05:42:55.860258338] msec_range[8] 10.000000 - 20.000000 : 190 [20081217-05:42:55.862537905] msec_range[9] 5.000000 - 10.000000 : 4565 [20081217-05:42:55.914576385] msec_range[10] 2.000000 - 5.000000 : 43548 [20081217-05:42:55.917007248] msec_range[11] 1.000000 - 2.000000 : 18679 [20081217-05:42:55.919426957] msec_range[12] 0.500000 - 1.000000 : 13911 [20081217-05:42:55.922644070] msec_range[13] 0.200000 - 0.500000 : 34575 [20081217-05:42:55.925667897] msec_range[14] 0.100000 - 0.200000 : 19958 [20081217-05:42:55.928159833] msec_range[15] 0.050000 - 0.100000 : 1493 [20081217-05:42:55.930361303] msec_range[16] 0.020000 - 0.050000 : 3265 [20081217-05:42:55.933161497] msec_range[17] 0.010000 - 0.020000 : 211881 [20081217-05:42:55.935408755] msec_range[18] 0.000000 - 0.010000 : 12703889 [20081217-05:42:55.937628160] [20081217-05:42:55.940557359] [ close] 0.004000 0.006357 0.011000 510 [20081217-05:42:55.943010312] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:42:55.945280738] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:42:55.947428916] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:42:55.949742673] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:42:55.952163348] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:42:55.954680075] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:42:55.957107263] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:42:55.959515584] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:42:55.962070124] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:42:55.964447678] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:42:55.966623467] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:42:55.968895572] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:42:55.971076898] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:42:55.973358203] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:42:55.975507922] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:42:55.977838270] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-05:42:55.980313882] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-05:42:55.982505537] msec_range[17] 0.010000 - 0.020000 : 3 [20081217-05:42:55.985202741] msec_range[18] 0.000000 - 0.010000 : 507 [20081217-05:42:55.987518910] [20081217-05:42:55.989692566] [20081217-05:42:55.991716278] [20081217-05:42:55.993999333] [20081217-05:42:55.996248974] 2.8% User Time [20081217-05:42:55.998540815] 28.0% System Time [20081217-05:42:56.001268909] 30.8% CPU Utilization [20081217-05:42:56.003599608] Profilers reporting [20081217-05:43:14.470055565] Profilers postprocessing [20081217-05:43:15.608527965] Stopping profiling. [20081217-05:43:15.613126132] Killing daemon. [20081217-05:43:18.099847882] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_05.31.34/analysis/oprofile.001 [20081217-05:43:18.102074714] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_05.31.34/analysis/oprofile-brief.001 [20081217-05:43:18.319336959] Processing File : mpstat.001 [20081217-05:43:18.321448172] Discovered mpstat_interval=[5] [20081217-05:43:18.975959618] Processing Directory : sar.breakout.001 [20081217-05:43:18.978229621] Discovered sar_interval=[5] [20081217-05:43:19.342389168] Processing File : iostat.001 [20081217-05:43:19.344574451] Discovered iostat_interval=[5] [20081217-05:43:21.734456894] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-05:43:26.143168764] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:43:27.143314517] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:43:27.237508261] PROCESSING COMMAND : 'run sequential_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=16' [20081217-05:43:27.287017461] new log requested [20081217-05:43:27.315962244] Running command ffsb [20081217-05:43:36.744121618] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-05:43:36.770276004] Importing argument : num_threads=16 [20081217-05:43:36.797052513] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:43:36.892611208] Checking for sar... [20081217-05:43:36.895139649] found [20081217-05:43:36.951926302] Checking for sar... [20081217-05:43:36.954285484] found [20081217-05:43:37.010140178] Checking for sar... [20081217-05:43:37.012192586] found [20081217-05:43:37.171812215] Checking for binutils-2.18 ... Already installed. [20081217-05:43:37.176256905] mv: cannot stat `lib64/*': No such file or directory [20081217-05:43:37.189025182] rmdir: lib64: No such file or directory [20081217-05:43:37.260203008] Checking for gettext-0.17 ... Already installed. [20081217-05:43:37.307240214] popt32-1.10.4 already installed. [20081217-05:43:37.322473817] popt64-1.10.4 already installed. [20081217-05:43:37.353709361] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-05:43:37.406473079] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-05:43:37.486193404] Daemon not running [20081217-05:43:37.506962431] Unloading oprofile module [20081217-05:43:37.722700399] Daemon not running [20081217-05:43:38.614355622] OPROFILE : using callgraph [5] [20081217-05:43:38.847085708] Daemon not running [20081217-05:43:38.849099135] Separate options: none [20081217-05:43:38.851220324] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-05:43:38.853344731] Image filter: none [20081217-05:43:38.855309672] Call-graph depth: 5 [20081217-05:43:38.939651339] FFSB version 6.0-RC2 started [20081217-05:43:38.941796740] [20081217-05:43:38.988990061] benchmark time = 300 [20081217-05:43:38.990934433] ThreadGroup 0 [20081217-05:43:38.993038598] ================ [20081217-05:43:38.995014789] num_threads = 16 [20081217-05:43:38.997028814] [20081217-05:43:38.998820794] read_random = off [20081217-05:43:39.000657228] read_size = 0 (0B) [20081217-05:43:39.002482101] read_blocksize = 4096 (4KB) [20081217-05:43:39.004334491] read_skip = off [20081217-05:43:39.006108972] read_skipsize = 0 (0B) [20081217-05:43:39.007945023] [20081217-05:43:39.009689149] write_random = off [20081217-05:43:39.011522098] write_size = 0 (0B) [20081217-05:43:39.013307933] fsync_file = 0 [20081217-05:43:39.015137802] write_blocksize = 0 (0B) [20081217-05:43:39.016923218] wait time = 0 [20081217-05:43:39.018755306] [20081217-05:43:39.020546378] op weights [20081217-05:43:39.022340613] read = 0 (0.00%) [20081217-05:43:39.024103417] readall = 1 (100.00%) [20081217-05:43:39.026194374] write = 0 (0.00%) [20081217-05:43:39.028104843] create = 0 (0.00%) [20081217-05:43:39.029884722] append = 0 (0.00%) [20081217-05:43:39.031779376] delete = 0 (0.00%) [20081217-05:43:39.033617909] metaop = 0 (0.00%) [20081217-05:43:39.035470431] createdir = 0 (0.00%) [20081217-05:43:39.037204539] stat = 0 (0.00%) [20081217-05:43:39.039062812] writeall = 0 (0.00%) [20081217-05:43:39.040885634] writeall_fsync = 0 (0.00%) [20081217-05:43:39.042626885] open_close = 0 (0.00%) [20081217-05:43:39.044460659] write_fsync = 0 (0.00%) [20081217-05:43:39.046263478] create_fsync = 0 (0.00%) [20081217-05:43:39.047992911] append_fsync = 0 (0.00%) [20081217-05:43:39.049830317] [20081217-05:43:39.051642446] FileSystem /mnt/ffsb1 [20081217-05:43:39.053360626] ========== [20081217-05:43:39.055205319] num_dirs = 0 [20081217-05:43:39.057060959] starting files = 1024 [20081217-05:43:39.058783251] [20081217-05:43:39.060607152] min file size = 104857600 (100MB) [20081217-05:43:39.062405388] max file size = 104857600 (100MB) [20081217-05:43:39.064144956] directio = off [20081217-05:43:39.065977383] alignedio = on [20081217-05:43:39.067781824] bufferedio = off [20081217-05:43:39.069894261] [20081217-05:43:39.071790732] aging is off [20081217-05:43:39.073596252] current utilization = 4.48% [20081217-05:43:39.075443002] [20081217-05:43:39.077398471] checking existing fs: /mnt/ffsb1 [20081217-05:43:39.178468820] fs setup took 0 secs [20081217-05:43:39.696666515] Syncing()...0 sec [20081217-05:43:39.698578693] Starting Actual Benchmark At: Wed Dec 17 05:43:39 2008 [20081217-05:43:39.711957973] [20081217-05:48:45.321037234] Syncing()...2 sec [20081217-05:48:45.379846484] FFSB benchmark finished at: Wed Dec 17 05:48:44 2008 [20081217-05:48:45.382601260] [20081217-05:48:45.385285528] Results: [20081217-05:48:45.439636949] Benchmark took 305.16 sec [20081217-05:48:45.442263533] [20081217-05:48:45.444778582] Total Results [20081217-05:48:45.460314472] =============== [20081217-05:48:45.462899314] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:48:45.465593832] ======= ============ ========= ======= =========== ========== [20081217-05:48:45.468285251] readall : 50969600 167027.26 100.000% 100.000% 652MB/sec [20081217-05:48:45.471089583] - [20081217-05:48:45.474115102] 167027.26 Transactions per Second [20081217-05:48:45.476364058] [20081217-05:48:45.478735912] Throughput Results [20081217-05:48:45.493830351] =================== [20081217-05:48:45.496093795] Read Throughput: 652MB/sec [20081217-05:48:45.498389282] [20081217-05:48:45.500873167] System Call Latency statistics in millisecs [20081217-05:48:45.503545786] ===== [20081217-05:48:45.506019434] Min Avg Max Total Calls [20081217-05:48:45.508880817] ======== ======== ======== ============ [20081217-05:48:45.511358374] [ open] 0.006000 1.437279 44.375000 1991 [20081217-05:48:45.513678370] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:48:45.515896901] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:48:45.518333272] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:48:45.520839548] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:48:45.523216139] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:48:45.525445396] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:48:45.527781631] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:48:45.529957184] msec_range[7] 20.000000 - 50.000000 : 23 [20081217-05:48:45.532210095] msec_range[8] 10.000000 - 20.000000 : 93 [20081217-05:48:45.534331975] msec_range[9] 5.000000 - 10.000000 : 113 [20081217-05:48:45.536544133] msec_range[10] 2.000000 - 5.000000 : 22 [20081217-05:48:45.538697450] msec_range[11] 1.000000 - 2.000000 : 11 [20081217-05:48:45.540976076] msec_range[12] 0.500000 - 1.000000 : 5 [20081217-05:48:45.543381195] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-05:48:45.546007911] msec_range[14] 0.100000 - 0.200000 : 34 [20081217-05:48:45.548928051] msec_range[15] 0.050000 - 0.100000 : 729 [20081217-05:48:45.551422104] msec_range[16] 0.020000 - 0.050000 : 909 [20081217-05:48:45.554592971] msec_range[17] 0.010000 - 0.020000 : 30 [20081217-05:48:45.557498851] msec_range[18] 0.000000 - 0.010000 : 19 [20081217-05:48:45.559911980] [20081217-05:48:45.562275651] [ read] 0.001000 0.094362 93.879997 50969600 [20081217-05:48:45.564862786] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:48:45.567214635] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:48:45.569493388] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:48:45.571653985] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:48:45.573845868] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:48:45.575951667] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:48:45.578362206] msec_range[6] 50.000000 - 100.000000 : 54 [20081217-05:48:45.581006446] msec_range[7] 20.000000 - 50.000000 : 36794 [20081217-05:48:45.583481614] msec_range[8] 10.000000 - 20.000000 : 149621 [20081217-05:48:45.586735001] msec_range[9] 5.000000 - 10.000000 : 135288 [20081217-05:48:45.589134868] msec_range[10] 2.000000 - 5.000000 : 109932 [20081217-05:48:45.591664430] msec_range[11] 1.000000 - 2.000000 : 43651 [20081217-05:48:45.594062317] msec_range[12] 0.500000 - 1.000000 : 37678 [20081217-05:48:45.596677395] msec_range[13] 0.200000 - 0.500000 : 139064 [20081217-05:48:45.599270794] msec_range[14] 0.100000 - 0.200000 : 9623 [20081217-05:48:45.601412605] msec_range[15] 0.050000 - 0.100000 : 78024 [20081217-05:48:45.603717248] msec_range[16] 0.020000 - 0.050000 : 177645 [20081217-05:48:45.605950434] msec_range[17] 0.010000 - 0.020000 : 3985308 [20081217-05:48:45.608173529] msec_range[18] 0.000000 - 0.010000 : 46066918 [20081217-05:48:45.610292611] [20081217-05:48:45.612528405] [ close] 0.002000 0.008198 0.092000 1991 [20081217-05:48:45.614684589] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:48:45.616884607] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:48:45.619001641] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:48:45.621351273] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:48:45.623545517] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:48:45.625695171] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:48:45.627778959] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:48:45.630126689] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:48:45.632678565] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:48:45.634839001] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:48:45.636910569] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:48:45.639084285] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:48:45.641176257] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:48:45.643362993] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:48:45.645536392] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-05:48:45.647730825] msec_range[15] 0.050000 - 0.100000 : 6 [20081217-05:48:45.649861506] msec_range[16] 0.020000 - 0.050000 : 5 [20081217-05:48:45.652013109] msec_range[17] 0.010000 - 0.020000 : 375 [20081217-05:48:45.654103590] msec_range[18] 0.000000 - 0.010000 : 1605 [20081217-05:48:45.656344266] [20081217-05:48:45.658503394] [20081217-05:48:45.660666608] [20081217-05:48:45.662757944] [20081217-05:48:45.665258167] 13.7% User Time [20081217-05:48:45.667453675] 143.9% System Time [20081217-05:48:45.669598078] 157.6% CPU Utilization [20081217-05:48:45.671681254] Profilers reporting [20081217-05:49:10.917508610] Profilers postprocessing [20081217-05:49:12.054147814] Stopping profiling. [20081217-05:49:12.058847670] Killing daemon. [20081217-05:49:14.486909429] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_05.43.27/analysis/oprofile.001 [20081217-05:49:14.489127926] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_05.43.27/analysis/oprofile-brief.001 [20081217-05:49:15.222952828] Processing File : mpstat.001 [20081217-05:49:15.225190977] Discovered mpstat_interval=[5] [20081217-05:49:15.908791416] Processing Directory : sar.breakout.001 [20081217-05:49:15.911027359] Discovered sar_interval=[5] [20081217-05:49:16.255850432] Processing File : iostat.001 [20081217-05:49:16.258029594] Discovered iostat_interval=[5] [20081217-05:49:19.170971363] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-05:49:23.788274699] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:49:24.896133669] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:49:24.989724629] PROCESSING COMMAND : 'run sequential_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=128' [20081217-05:49:25.083182825] new log requested [20081217-05:49:25.108378030] Running command ffsb [20081217-05:49:34.688359563] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-05:49:34.704673310] Importing argument : num_threads=128 [20081217-05:49:34.731103734] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:49:34.827880357] Checking for sar... [20081217-05:49:34.829997990] found [20081217-05:49:34.885978086] Checking for sar... [20081217-05:49:34.888109350] found [20081217-05:49:34.944470917] Checking for sar... [20081217-05:49:34.946912357] found [20081217-05:49:35.161435831] Checking for binutils-2.18 ... Already installed. [20081217-05:49:35.165951991] mv: cannot stat `lib64/*': No such file or directory [20081217-05:49:35.178505485] rmdir: lib64: No such file or directory [20081217-05:49:35.249685043] Checking for gettext-0.17 ... Already installed. [20081217-05:49:35.296174339] popt32-1.10.4 already installed. [20081217-05:49:35.310942559] popt64-1.10.4 already installed. [20081217-05:49:35.342529456] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-05:49:35.395062415] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-05:49:35.475895161] Daemon not running [20081217-05:49:35.493952547] Unloading oprofile module [20081217-05:49:35.719389064] Daemon not running [20081217-05:49:36.987094765] OPROFILE : using callgraph [5] [20081217-05:49:37.219343834] Daemon not running [20081217-05:49:37.221422585] Separate options: none [20081217-05:49:37.223571208] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-05:49:37.225594189] Image filter: none [20081217-05:49:37.227699444] Call-graph depth: 5 [20081217-05:49:37.308171030] FFSB version 6.0-RC2 started [20081217-05:49:37.310374122] [20081217-05:49:37.797718986] benchmark time = 300 [20081217-05:49:37.799894899] ThreadGroup 0 [20081217-05:49:37.801866933] ================ [20081217-05:49:37.804139363] num_threads = 128 [20081217-05:49:37.806185797] [20081217-05:49:37.808101771] read_random = off [20081217-05:49:37.810282853] read_size = 0 (0B) [20081217-05:49:37.812223617] read_blocksize = 4096 (4KB) [20081217-05:49:37.814086402] read_skip = off [20081217-05:49:37.815877708] read_skipsize = 0 (0B) [20081217-05:49:37.817755647] [20081217-05:49:37.819571023] write_random = off [20081217-05:49:37.821435353] write_size = 0 (0B) [20081217-05:49:37.823314629] fsync_file = 0 [20081217-05:49:37.825138308] write_blocksize = 0 (0B) [20081217-05:49:37.827007033] wait time = 0 [20081217-05:49:37.828783920] [20081217-05:49:37.830623995] op weights [20081217-05:49:37.832414821] read = 0 (0.00%) [20081217-05:49:37.834276430] readall = 1 (100.00%) [20081217-05:49:37.836101739] write = 0 (0.00%) [20081217-05:49:37.837876810] create = 0 (0.00%) [20081217-05:49:37.839718883] append = 0 (0.00%) [20081217-05:49:37.841533978] delete = 0 (0.00%) [20081217-05:49:37.843620129] metaop = 0 (0.00%) [20081217-05:49:37.845780253] createdir = 0 (0.00%) [20081217-05:49:37.847577102] stat = 0 (0.00%) [20081217-05:49:37.849437468] writeall = 0 (0.00%) [20081217-05:49:37.851199766] writeall_fsync = 0 (0.00%) [20081217-05:49:37.853058270] open_close = 0 (0.00%) [20081217-05:49:37.854907478] write_fsync = 0 (0.00%) [20081217-05:49:37.856688804] create_fsync = 0 (0.00%) [20081217-05:49:37.858526567] append_fsync = 0 (0.00%) [20081217-05:49:37.860362104] [20081217-05:49:37.862501799] FileSystem /mnt/ffsb1 [20081217-05:49:37.864647152] ========== [20081217-05:49:37.866441867] num_dirs = 0 [20081217-05:49:37.868318467] starting files = 1024 [20081217-05:49:37.870162497] [20081217-05:49:37.872024315] min file size = 104857600 (100MB) [20081217-05:49:37.873834736] max file size = 104857600 (100MB) [20081217-05:49:37.875693641] directio = off [20081217-05:49:37.877636059] alignedio = on [20081217-05:49:37.879723371] bufferedio = off [20081217-05:49:37.881485169] [20081217-05:49:37.883330424] aging is off [20081217-05:49:37.885064976] current utilization = 4.48% [20081217-05:49:37.886909181] [20081217-05:49:37.888843418] checking existing fs: /mnt/ffsb1 [20081217-05:49:37.905072938] fs setup took 0 secs [20081217-05:49:38.596189950] Syncing()...0 sec [20081217-05:49:38.602214823] Starting Actual Benchmark At: Wed Dec 17 05:49:38 2008 [20081217-05:49:38.617815677] [20081217-05:54:48.936475433] Syncing()...3 sec [20081217-05:54:48.981379041] FFSB benchmark finished at: Wed Dec 17 05:54:48 2008 [20081217-05:54:48.984269202] [20081217-05:54:48.986913686] Results: [20081217-05:54:49.087105416] Benchmark took 309.91 sec [20081217-05:54:49.089187079] [20081217-05:54:49.091732717] Total Results [20081217-05:54:49.106604145] =============== [20081217-05:54:49.108887718] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-05:54:49.111371158] ======= ============ ========= ======= =========== ========== [20081217-05:54:49.114026996] readall : 53094400 171322.55 100.000% 100.000% 669MB/sec [20081217-05:54:49.116824094] - [20081217-05:54:49.119744363] 171322.55 Transactions per Second [20081217-05:54:49.121934409] [20081217-05:54:49.124179499] Throughput Results [20081217-05:54:49.139134637] =================== [20081217-05:54:49.141500525] Read Throughput: 669MB/sec [20081217-05:54:49.143922981] [20081217-05:54:49.146062418] System Call Latency statistics in millisecs [20081217-05:54:49.148517979] ===== [20081217-05:54:49.151027436] Min Avg Max Total Calls [20081217-05:54:49.153263367] ======== ======== ======== ============ [20081217-05:54:49.155904865] [ open] 0.006000 64.901068 1166.145996 2074 [20081217-05:54:49.158485437] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:54:49.160886265] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:54:49.163034135] msec_range[2] 1000.000000 - 2000.000000 : 25 [20081217-05:54:49.165330430] msec_range[3] 500.000000 - 1000.000000 : 52 [20081217-05:54:49.167437959] msec_range[4] 200.000000 - 500.000000 : 132 [20081217-05:54:49.169739161] msec_range[5] 100.000000 - 200.000000 : 152 [20081217-05:54:49.172200549] msec_range[6] 50.000000 - 100.000000 : 78 [20081217-05:54:49.175471333] msec_range[7] 20.000000 - 50.000000 : 76 [20081217-05:54:49.178029072] msec_range[8] 10.000000 - 20.000000 : 38 [20081217-05:54:49.180377889] msec_range[9] 5.000000 - 10.000000 : 12 [20081217-05:54:49.183132610] msec_range[10] 2.000000 - 5.000000 : 4 [20081217-05:54:49.185788539] msec_range[11] 1.000000 - 2.000000 : 4 [20081217-05:54:49.188279569] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-05:54:49.191387812] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-05:54:49.193668894] msec_range[14] 0.100000 - 0.200000 : 36 [20081217-05:54:49.196043560] msec_range[15] 0.050000 - 0.100000 : 419 [20081217-05:54:49.198450376] msec_range[16] 0.020000 - 0.050000 : 844 [20081217-05:54:49.201142327] msec_range[17] 0.010000 - 0.020000 : 88 [20081217-05:54:49.203715361] msec_range[18] 0.000000 - 0.010000 : 107 [20081217-05:54:49.206068188] [20081217-05:54:49.208447268] [ read] 0.001000 0.729058 491.428986 53094400 [20081217-05:54:49.210935764] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:54:49.213178051] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:54:49.215484791] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:54:49.217706272] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:54:49.220046509] msec_range[4] 200.000000 - 500.000000 : 35606 [20081217-05:54:49.222266426] msec_range[5] 100.000000 - 200.000000 : 110488 [20081217-05:54:49.224487227] msec_range[6] 50.000000 - 100.000000 : 112360 [20081217-05:54:49.226814635] msec_range[7] 20.000000 - 50.000000 : 138047 [20081217-05:54:49.229193580] msec_range[8] 10.000000 - 20.000000 : 44080 [20081217-05:54:49.231733871] msec_range[9] 5.000000 - 10.000000 : 23458 [20081217-05:54:49.233972990] msec_range[10] 2.000000 - 5.000000 : 14898 [20081217-05:54:49.236356734] msec_range[11] 1.000000 - 2.000000 : 4961 [20081217-05:54:49.238550851] msec_range[12] 0.500000 - 1.000000 : 16676 [20081217-05:54:49.241078444] msec_range[13] 0.200000 - 0.500000 : 190276 [20081217-05:54:49.244038968] msec_range[14] 0.100000 - 0.200000 : 20124 [20081217-05:54:49.246343171] msec_range[15] 0.050000 - 0.100000 : 100484 [20081217-05:54:49.248670291] msec_range[16] 0.020000 - 0.050000 : 154202 [20081217-05:54:49.251092206] msec_range[17] 0.010000 - 0.020000 : 4550912 [20081217-05:54:49.253288712] msec_range[18] 0.000000 - 0.010000 : 47577828 [20081217-05:54:49.255832387] [20081217-05:54:49.258189855] [ close] 0.001000 0.008165 0.117000 2074 [20081217-05:54:49.260425242] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-05:54:49.262524898] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-05:54:49.264759465] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-05:54:49.266892442] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-05:54:49.269053852] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-05:54:49.271175945] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-05:54:49.274077489] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-05:54:49.276838558] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-05:54:49.279011316] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-05:54:49.281118854] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-05:54:49.283530232] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-05:54:49.286234324] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-05:54:49.288327374] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-05:54:49.290713432] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-05:54:49.293107303] msec_range[14] 0.100000 - 0.200000 : 3 [20081217-05:54:49.295520223] msec_range[15] 0.050000 - 0.100000 : 4 [20081217-05:54:49.297745873] msec_range[16] 0.020000 - 0.050000 : 11 [20081217-05:54:49.300219651] msec_range[17] 0.010000 - 0.020000 : 363 [20081217-05:54:49.302376310] msec_range[18] 0.000000 - 0.010000 : 1693 [20081217-05:54:49.304537662] [20081217-05:54:49.306674669] [20081217-05:54:49.308882487] [20081217-05:54:49.310976997] [20081217-05:54:49.313072405] 14.1% User Time [20081217-05:54:49.315167239] 145.7% System Time [20081217-05:54:49.317314842] 159.8% CPU Utilization [20081217-05:54:49.319413112] Profilers reporting [20081217-05:55:16.452674772] Profilers postprocessing [20081217-05:55:17.588839799] Stopping profiling. [20081217-05:55:17.594256654] Killing daemon. [20081217-05:55:20.219361328] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_05.49.25/analysis/oprofile.001 [20081217-05:55:20.221603218] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_05.49.25/analysis/oprofile-brief.001 [20081217-05:55:20.450868059] Processing File : mpstat.001 [20081217-05:55:20.452941219] Discovered mpstat_interval=[5] [20081217-05:55:21.106310976] Processing Directory : sar.breakout.001 [20081217-05:55:21.108611990] Discovered sar_interval=[5] [20081217-05:55:21.467864806] Processing File : iostat.001 [20081217-05:55:21.470032222] Discovered iostat_interval=[5] [20081217-05:55:24.622473843] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-05:55:29.595247013] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-05:55:30.790178731] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-05:55:30.882491040] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=1' [20081217-05:55:30.927284086] new log requested [20081217-05:55:30.951387130] Running command ffsb [20081217-05:55:40.321168305] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-05:55:40.337246275] Importing argument : num_threads=1 [20081217-05:55:40.363498953] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-05:55:40.458661264] Checking for sar... [20081217-05:55:40.460799419] found [20081217-05:55:40.517602549] Checking for sar... [20081217-05:55:40.519841094] found [20081217-05:55:40.575827014] Checking for sar... [20081217-05:55:40.577915899] found [20081217-05:55:40.768399474] Checking for binutils-2.18 ... Already installed. [20081217-05:55:40.772855549] mv: cannot stat `lib64/*': No such file or directory [20081217-05:55:40.785199701] rmdir: lib64: No such file or directory [20081217-05:55:40.856729064] Checking for gettext-0.17 ... Already installed. [20081217-05:55:40.903072120] popt32-1.10.4 already installed. [20081217-05:55:40.918104491] popt64-1.10.4 already installed. [20081217-05:55:40.949619495] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-05:55:41.001264877] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-05:55:41.083232407] Daemon not running [20081217-05:55:41.101069046] Unloading oprofile module [20081217-05:55:41.324371597] Daemon not running [20081217-05:55:42.551744156] OPROFILE : using callgraph [5] [20081217-05:55:42.784425124] Daemon not running [20081217-05:55:42.786428265] Separate options: none [20081217-05:55:42.788601449] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-05:55:42.790661647] Image filter: none [20081217-05:55:42.792533010] Call-graph depth: 5 [20081217-05:55:42.871331363] FFSB version 6.0-RC2 started [20081217-05:55:42.873628546] [20081217-05:55:42.875749128] benchmark time = 300 [20081217-05:55:42.877964881] ThreadGroup 0 [20081217-05:55:42.879845375] ================ [20081217-05:55:42.881681884] num_threads = 1 [20081217-05:55:42.883456759] [20081217-05:55:42.885320664] read_random = on [20081217-05:55:42.887148624] read_size = 5242880 (5MB) [20081217-05:55:42.888957277] read_blocksize = 4096 (4KB) [20081217-05:55:42.890749095] read_skip = off [20081217-05:55:42.892627885] read_skipsize = 0 (0B) [20081217-05:55:42.894388771] [20081217-05:55:42.896486902] write_random = off [20081217-05:55:42.898477461] write_size = 0 (0B) [20081217-05:55:42.900264756] fsync_file = 0 [20081217-05:55:42.902117422] write_blocksize = 0 (0B) [20081217-05:55:42.904168976] wait time = 0 [20081217-05:55:42.906283394] [20081217-05:55:42.908180339] op weights [20081217-05:55:42.910052648] read = 1 (100.00%) [20081217-05:55:42.911849665] readall = 0 (0.00%) [20081217-05:55:42.913711066] write = 0 (0.00%) [20081217-05:55:42.915509655] create = 0 (0.00%) [20081217-05:55:42.917363944] append = 0 (0.00%) [20081217-05:55:42.919091565] delete = 0 (0.00%) [20081217-05:55:42.920969673] metaop = 0 (0.00%) [20081217-05:55:42.922811641] createdir = 0 (0.00%) [20081217-05:55:42.924577817] stat = 0 (0.00%) [20081217-05:55:42.926393850] writeall = 0 (0.00%) [20081217-05:55:42.928195374] writeall_fsync = 0 (0.00%) [20081217-05:55:42.930068778] open_close = 0 (0.00%) [20081217-05:55:42.931854175] write_fsync = 0 (0.00%) [20081217-05:55:42.933680940] create_fsync = 0 (0.00%) [20081217-05:55:42.935519706] append_fsync = 0 (0.00%) [20081217-05:55:42.937290880] [20081217-05:55:42.939220401] FileSystem /mnt/ffsb1 [20081217-05:55:42.941027987] ========== [20081217-05:55:42.942898145] num_dirs = 0 [20081217-05:55:42.944676084] starting files = 1024 [20081217-05:55:42.946476374] [20081217-05:55:42.948221521] min file size = 104857600 (100MB) [20081217-05:55:42.950084764] max file size = 104857600 (100MB) [20081217-05:55:42.951857572] directio = off [20081217-05:55:42.953657497] alignedio = on [20081217-05:55:42.955393561] bufferedio = off [20081217-05:55:42.957229516] [20081217-05:55:42.958991302] aging is off [20081217-05:55:42.960802082] current utilization = 4.48% [20081217-05:55:42.962538226] [20081217-05:55:42.964373455] checking existing fs: /mnt/ffsb1 [20081217-05:55:43.039257861] fs setup took 0 secs [20081217-05:55:43.925716363] Syncing()...0 sec [20081217-05:55:43.939415650] Starting Actual Benchmark At: Wed Dec 17 05:55:43 2008 [20081217-05:55:43.952401749] [20081217-06:00:46.201201701] Syncing()...0 sec [20081217-06:00:46.204389262] FFSB benchmark finished at: Wed Dec 17 06:00:46 2008 [20081217-06:00:46.207679367] [20081217-06:00:46.209957893] Results: [20081217-06:00:46.225300528] Benchmark took 302.27 sec [20081217-06:00:46.227564467] [20081217-06:00:46.229906285] Total Results [20081217-06:00:46.245357435] =============== [20081217-06:00:46.248190942] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:00:46.250974582] ======= ============ ========= ======= =========== ========== [20081217-06:00:46.254531804] read : 194560 643.65 100.000% 100.000% 2.51MB/sec [20081217-06:00:46.257298937] - [20081217-06:00:46.260103687] 643.65 Transactions per Second [20081217-06:00:46.263017445] [20081217-06:00:46.265771472] Throughput Results [20081217-06:00:46.282832776] =================== [20081217-06:00:46.285504461] Read Throughput: 2.51MB/sec [20081217-06:00:46.287831855] [20081217-06:00:46.290468083] System Call Latency statistics in millisecs [20081217-06:00:46.292954978] ===== [20081217-06:00:46.295497377] Min Avg Max Total Calls [20081217-06:00:46.298722087] ======== ======== ======== ============ [20081217-06:00:46.301242781] [ open] 0.013000 0.021526 0.039000 152 [20081217-06:00:46.303755821] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:00:46.306510920] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:00:46.309078921] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:00:46.311839978] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:00:46.314128115] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:00:46.316577489] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:00:46.319000994] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:00:46.321885939] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:00:46.324614202] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:00:46.327297643] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:00:46.329946427] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:00:46.333224293] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:00:46.335647525] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:00:46.338182757] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:00:46.340570522] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:00:46.343108829] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:00:46.345751083] msec_range[16] 0.020000 - 0.050000 : 85 [20081217-06:00:46.348937479] msec_range[17] 0.010000 - 0.020000 : 67 [20081217-06:00:46.351310483] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-06:00:46.354047622] [20081217-06:00:46.356781964] [ read] 0.002000 1.546930 35.584000 194560 [20081217-06:00:46.359284110] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:00:46.361531916] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:00:46.363951614] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:00:46.366425750] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:00:46.369461882] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:00:46.372352876] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:00:46.374969780] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:00:46.377342009] msec_range[7] 20.000000 - 50.000000 : 50 [20081217-06:00:46.380761290] msec_range[8] 10.000000 - 20.000000 : 554 [20081217-06:00:46.383015571] msec_range[9] 5.000000 - 10.000000 : 12193 [20081217-06:00:46.385549581] msec_range[10] 2.000000 - 5.000000 : 43704 [20081217-06:00:46.388291932] msec_range[11] 1.000000 - 2.000000 : 9826 [20081217-06:00:46.390958648] msec_range[12] 0.500000 - 1.000000 : 669 [20081217-06:00:46.394080056] msec_range[13] 0.200000 - 0.500000 : 119774 [20081217-06:00:46.396865795] msec_range[14] 0.100000 - 0.200000 : 1293 [20081217-06:00:46.399587015] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:00:46.401781988] msec_range[16] 0.020000 - 0.050000 : 3 [20081217-06:00:46.403792987] msec_range[17] 0.010000 - 0.020000 : 861 [20081217-06:00:46.406304685] msec_range[18] 0.000000 - 0.010000 : 5633 [20081217-06:00:46.409168137] [20081217-06:00:46.411625914] [ lseek] 0.000000 0.001316 0.022000 194560 [20081217-06:00:46.414912193] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:00:46.417179520] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:00:46.420478631] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:00:46.424822529] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:00:46.427505975] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:00:46.429906698] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:00:46.432317134] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:00:46.435644342] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:00:46.438751153] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:00:46.441086750] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:00:46.444384666] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:00:46.447057936] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:00:46.449500322] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:00:46.453842189] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:00:46.456600664] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:00:46.459329980] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:00:46.462498361] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-06:00:46.465191929] msec_range[17] 0.010000 - 0.020000 : 74 [20081217-06:00:46.467628562] msec_range[18] 0.000000 - 0.010000 : 194485 [20081217-06:00:46.470494099] [20081217-06:00:46.473175855] [ close] 0.002000 0.005382 0.011000 152 [20081217-06:00:46.475857487] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:00:46.478416107] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:00:46.481201847] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:00:46.484214225] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:00:46.486691040] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:00:46.489008967] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:00:46.491224813] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:00:46.496630230] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:00:46.499341170] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:00:46.501870176] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:00:46.504311982] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:00:46.506803455] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:00:46.509196457] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:00:46.511398955] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:00:46.513568413] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:00:46.515660293] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:00:46.518273574] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-06:00:46.520695787] msec_range[17] 0.010000 - 0.020000 : 7 [20081217-06:00:46.522813680] msec_range[18] 0.000000 - 0.010000 : 145 [20081217-06:00:46.525149911] [20081217-06:00:46.527453467] [20081217-06:00:46.529564537] [20081217-06:00:46.531872104] [20081217-06:00:46.534189836] 0.2% User Time [20081217-06:00:46.536251524] 2.3% System Time [20081217-06:00:46.538490992] 2.5% CPU Utilization [20081217-06:00:46.540723546] Profilers reporting [20081217-06:01:00.331876530] Profilers postprocessing [20081217-06:01:01.468090442] Stopping profiling. [20081217-06:01:01.473407321] Killing daemon. [20081217-06:01:02.646241963] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_05.55.30/analysis/oprofile.001 [20081217-06:01:02.648434114] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_05.55.30/analysis/oprofile-brief.001 [20081217-06:01:02.763274126] Processing File : mpstat.001 [20081217-06:01:02.765574984] Discovered mpstat_interval=[5] [20081217-06:01:03.307710745] Processing Directory : sar.breakout.001 [20081217-06:01:03.309801774] Discovered sar_interval=[5] [20081217-06:01:03.475755363] Processing File : iostat.001 [20081217-06:01:03.478045939] Discovered iostat_interval=[5] [20081217-06:01:04.908086209] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-06:01:08.695771171] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-06:01:09.048195829] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-06:01:09.138380405] PROCESSING COMMAND : 'run random_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=16' [20081217-06:01:09.183004645] new log requested [20081217-06:01:09.210349002] Running command ffsb [20081217-06:01:17.944918619] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-06:01:17.959527272] Importing argument : num_threads=16 [20081217-06:01:17.985294688] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-06:01:18.073940686] Checking for sar... [20081217-06:01:18.076030555] found [20081217-06:01:18.132751091] Checking for sar... [20081217-06:01:18.135093490] found [20081217-06:01:18.190826507] Checking for sar... [20081217-06:01:18.193266912] found [20081217-06:01:18.321728727] Checking for binutils-2.18 ... Already installed. [20081217-06:01:18.326203215] mv: cannot stat `lib64/*': No such file or directory [20081217-06:01:18.328867965] rmdir: lib64: No such file or directory [20081217-06:01:18.388844136] Checking for gettext-0.17 ... Already installed. [20081217-06:01:18.429933515] popt32-1.10.4 already installed. [20081217-06:01:18.445802042] popt64-1.10.4 already installed. [20081217-06:01:18.477152676] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-06:01:18.529508574] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-06:01:18.610723974] Daemon not running [20081217-06:01:18.621603816] Unloading oprofile module [20081217-06:01:18.724301534] Daemon not running [20081217-06:01:19.533904465] OPROFILE : using callgraph [5] [20081217-06:01:19.766417181] Daemon not running [20081217-06:01:19.768497586] Separate options: none [20081217-06:01:19.770676336] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-06:01:19.772875774] Image filter: none [20081217-06:01:19.774702821] Call-graph depth: 5 [20081217-06:01:19.833812872] FFSB version 6.0-RC2 started [20081217-06:01:19.836007288] [20081217-06:01:19.895835999] benchmark time = 300 [20081217-06:01:19.897948016] ThreadGroup 0 [20081217-06:01:19.899931320] ================ [20081217-06:01:19.901783792] num_threads = 16 [20081217-06:01:19.903645163] [20081217-06:01:19.905819498] read_random = on [20081217-06:01:19.907935544] read_size = 5242880 (5MB) [20081217-06:01:19.910159532] read_blocksize = 4096 (4KB) [20081217-06:01:19.912058950] read_skip = off [20081217-06:01:19.913925146] read_skipsize = 0 (0B) [20081217-06:01:19.915784339] [20081217-06:01:19.917557621] write_random = off [20081217-06:01:19.919408068] write_size = 0 (0B) [20081217-06:01:19.921244093] fsync_file = 0 [20081217-06:01:19.923000391] write_blocksize = 0 (0B) [20081217-06:01:19.924823874] wait time = 0 [20081217-06:01:19.926604542] [20081217-06:01:19.928454272] op weights [20081217-06:01:19.930220279] read = 1 (100.00%) [20081217-06:01:19.932037879] readall = 0 (0.00%) [20081217-06:01:19.933789089] write = 0 (0.00%) [20081217-06:01:19.935609539] create = 0 (0.00%) [20081217-06:01:19.937381320] append = 0 (0.00%) [20081217-06:01:19.939234928] delete = 0 (0.00%) [20081217-06:01:19.941115743] metaop = 0 (0.00%) [20081217-06:01:19.942879232] createdir = 0 (0.00%) [20081217-06:01:19.944733902] stat = 0 (0.00%) [20081217-06:01:19.946578061] writeall = 0 (0.00%) [20081217-06:01:19.948300371] writeall_fsync = 0 (0.00%) [20081217-06:01:19.950163444] open_close = 0 (0.00%) [20081217-06:01:19.952007283] write_fsync = 0 (0.00%) [20081217-06:01:19.953787430] create_fsync = 0 (0.00%) [20081217-06:01:19.955629627] append_fsync = 0 (0.00%) [20081217-06:01:19.957491534] [20081217-06:01:19.959246351] FileSystem /mnt/ffsb1 [20081217-06:01:19.961090293] ========== [20081217-06:01:19.962846150] num_dirs = 0 [20081217-06:01:19.964704238] starting files = 1024 [20081217-06:01:19.966491338] [20081217-06:01:19.968360930] min file size = 104857600 (100MB) [20081217-06:01:19.970221629] max file size = 104857600 (100MB) [20081217-06:01:19.971954407] directio = off [20081217-06:01:19.973779296] alignedio = on [20081217-06:01:19.975537738] bufferedio = off [20081217-06:01:19.977320232] [20081217-06:01:19.979098684] aging is off [20081217-06:01:19.980960963] current utilization = 4.48% [20081217-06:01:19.982839656] [20081217-06:01:19.984594658] checking existing fs: /mnt/ffsb1 [20081217-06:01:20.003137688] fs setup took 0 secs [20081217-06:01:20.503174117] Syncing()...0 sec [20081217-06:01:20.505450096] Starting Actual Benchmark At: Wed Dec 17 06:01:20 2008 [20081217-06:01:20.518916479] [20081217-06:06:25.440125481] Syncing()...0 sec [20081217-06:06:25.454472229] FFSB benchmark finished at: Wed Dec 17 06:06:25 2008 [20081217-06:06:25.457380730] [20081217-06:06:25.459674892] Results: [20081217-06:06:25.478910671] Benchmark took 304.93 sec [20081217-06:06:25.481625737] [20081217-06:06:25.485938657] Total Results [20081217-06:06:25.501934009] =============== [20081217-06:06:25.504732541] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:06:25.507308761] ======= ============ ========= ======= =========== ========== [20081217-06:06:25.509868938] read : 1438720 4718.14 100.000% 100.000% 18.4MB/sec [20081217-06:06:25.512681312] - [20081217-06:06:25.515648125] 4718.14 Transactions per Second [20081217-06:06:25.518469037] [20081217-06:06:25.521501212] Throughput Results [20081217-06:06:25.537178278] =================== [20081217-06:06:25.539973510] Read Throughput: 18.4MB/sec [20081217-06:06:25.544357188] [20081217-06:06:25.547674093] System Call Latency statistics in millisecs [20081217-06:06:25.550667318] ===== [20081217-06:06:25.554381957] Min Avg Max Total Calls [20081217-06:06:25.558769203] ======== ======== ======== ============ [20081217-06:06:25.561609592] [ open] 0.006000 0.024725 0.103000 1124 [20081217-06:06:25.564250397] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:06:25.566927660] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:06:25.569947092] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:06:25.574372290] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:06:25.577360167] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:06:25.580613655] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:06:25.584404350] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:06:25.589148920] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:06:25.592202417] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:06:25.594980996] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:06:25.597819285] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:06:25.600500865] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:06:25.602766972] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:06:25.605532944] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:06:25.608424702] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-06:06:25.610936271] msec_range[15] 0.050000 - 0.100000 : 46 [20081217-06:06:25.614530456] msec_range[16] 0.020000 - 0.050000 : 721 [20081217-06:06:25.617177608] msec_range[17] 0.010000 - 0.020000 : 331 [20081217-06:06:25.621522798] msec_range[18] 0.000000 - 0.010000 : 25 [20081217-06:06:25.624015860] [20081217-06:06:25.628331370] [ read] 0.001000 3.363185 187.789001 1438720 [20081217-06:06:25.632185188] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:06:25.634503226] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:06:25.637395167] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:06:25.640019230] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:06:25.642729948] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:06:25.645494155] msec_range[5] 100.000000 - 200.000000 : 12 [20081217-06:06:25.648399337] msec_range[6] 50.000000 - 100.000000 : 13 [20081217-06:06:25.651468982] msec_range[7] 20.000000 - 50.000000 : 299 [20081217-06:06:25.655027229] msec_range[8] 10.000000 - 20.000000 : 19647 [20081217-06:06:25.658396486] msec_range[9] 5.000000 - 10.000000 : 362460 [20081217-06:06:25.662166678] msec_range[10] 2.000000 - 5.000000 : 570771 [20081217-06:06:25.665082367] msec_range[11] 1.000000 - 2.000000 : 50851 [20081217-06:06:25.667790175] msec_range[12] 0.500000 - 1.000000 : 9896 [20081217-06:06:25.670477352] msec_range[13] 0.200000 - 0.500000 : 346048 [20081217-06:06:25.673410232] msec_range[14] 0.100000 - 0.200000 : 252 [20081217-06:06:25.682251690] msec_range[15] 0.050000 - 0.100000 : 31 [20081217-06:06:25.686056197] msec_range[16] 0.020000 - 0.050000 : 673 [20081217-06:06:25.691784159] msec_range[17] 0.010000 - 0.020000 : 15512 [20081217-06:06:25.694805057] msec_range[18] 0.000000 - 0.010000 : 62255 [20081217-06:06:25.697434632] [20081217-06:06:25.700138088] [ lseek] 0.000000 0.001318 0.109000 1438720 [20081217-06:06:25.702916702] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:06:25.705681817] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:06:25.708139961] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:06:25.710600202] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:06:25.713120305] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:06:25.715818824] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:06:25.719125381] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:06:25.721928691] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:06:25.724682302] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:06:25.727426631] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:06:25.729888257] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:06:25.732340335] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:06:25.734910326] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:06:25.738332180] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:06:25.740849287] msec_range[14] 0.100000 - 0.200000 : 2 [20081217-06:06:25.743366042] msec_range[15] 0.050000 - 0.100000 : 24 [20081217-06:06:25.745870164] msec_range[16] 0.020000 - 0.050000 : 1221 [20081217-06:06:25.748328469] msec_range[17] 0.010000 - 0.020000 : 1049 [20081217-06:06:25.751269964] msec_range[18] 0.000000 - 0.010000 : 1436424 [20081217-06:06:25.753972308] [20081217-06:06:25.756202906] [ close] 0.002000 0.006185 0.049000 1124 [20081217-06:06:25.758667847] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:06:25.761059941] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:06:25.763757525] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:06:25.766326686] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:06:25.768557485] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:06:25.770923167] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:06:25.773137200] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:06:25.775458229] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:06:25.777670920] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:06:25.781292781] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:06:25.783652285] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:06:25.785881618] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:06:25.788470321] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:06:25.790908763] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:06:25.793576018] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:06:25.796118422] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:06:25.798566412] msec_range[16] 0.020000 - 0.050000 : 8 [20081217-06:06:25.800814408] msec_range[17] 0.010000 - 0.020000 : 117 [20081217-06:06:25.803041885] msec_range[18] 0.000000 - 0.010000 : 999 [20081217-06:06:25.805338464] [20081217-06:06:25.807571457] [20081217-06:06:25.810048665] [20081217-06:06:25.812461571] [20081217-06:06:25.814767303] 1.5% User Time [20081217-06:06:25.817192993] 19.6% System Time [20081217-06:06:25.819414947] 21.1% CPU Utilization [20081217-06:06:25.821636831] Profilers reporting [20081217-06:06:42.922499863] Profilers postprocessing [20081217-06:06:44.059375695] Stopping profiling. [20081217-06:06:44.064061244] Killing daemon. [20081217-06:06:46.271804846] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-12-17_06.01.09/analysis/oprofile.001 [20081217-06:06:46.273969225] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-12-17_06.01.09/analysis/oprofile-brief.001 [20081217-06:06:46.433927083] Processing File : mpstat.001 [20081217-06:06:46.436031305] Discovered mpstat_interval=[5] [20081217-06:06:46.995388010] Processing Directory : sar.breakout.001 [20081217-06:06:46.997694210] Discovered sar_interval=[5] [20081217-06:06:47.164480763] Processing File : iostat.001 [20081217-06:06:47.166838944] Discovered iostat_interval=[5] [20081217-06:06:48.809529876] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-06:06:53.334677636] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-06:06:54.861913132] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-06:06:54.950492480] PROCESSING COMMAND : 'run random_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=128' [20081217-06:06:54.995238614] new log requested [20081217-06:06:55.019686976] Running command ffsb [20081217-06:07:03.644624656] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-06:07:03.659148549] Importing argument : num_threads=128 [20081217-06:07:03.685303564] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-06:07:03.773088497] Checking for sar... [20081217-06:07:03.775173322] found [20081217-06:07:03.831437693] Checking for sar... [20081217-06:07:03.833443261] found [20081217-06:07:03.889330140] Checking for sar... [20081217-06:07:03.891546100] found [20081217-06:07:04.037897430] Checking for binutils-2.18 ... Already installed. [20081217-06:07:04.042494563] mv: cannot stat `lib64/*': No such file or directory [20081217-06:07:04.045260027] rmdir: lib64: No such file or directory [20081217-06:07:04.105285486] Checking for gettext-0.17 ... Already installed. [20081217-06:07:04.146311268] popt32-1.10.4 already installed. [20081217-06:07:04.161485450] popt64-1.10.4 already installed. [20081217-06:07:04.192006292] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-06:07:04.245284093] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-06:07:04.325745559] Daemon not running [20081217-06:07:04.336258275] Unloading oprofile module [20081217-06:07:04.440438522] Daemon not running [20081217-06:07:05.586527824] OPROFILE : using callgraph [5] [20081217-06:07:05.819137074] Daemon not running [20081217-06:07:05.821312576] Separate options: none [20081217-06:07:05.823415644] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-06:07:05.825626560] Image filter: none [20081217-06:07:05.827470663] Call-graph depth: 5 [20081217-06:07:05.886362568] FFSB version 6.0-RC2 started [20081217-06:07:05.888607020] [20081217-06:07:06.380064720] benchmark time = 300 [20081217-06:07:06.382248571] ThreadGroup 0 [20081217-06:07:06.384501051] ================ [20081217-06:07:06.386478863] num_threads = 128 [20081217-06:07:06.388772779] [20081217-06:07:06.390651873] read_random = on [20081217-06:07:06.392424519] read_size = 5242880 (5MB) [20081217-06:07:06.394232900] read_blocksize = 4096 (4KB) [20081217-06:07:06.396082505] read_skip = off [20081217-06:07:06.397874013] read_skipsize = 0 (0B) [20081217-06:07:06.399721273] [20081217-06:07:06.401501998] write_random = off [20081217-06:07:06.403446821] write_size = 0 (0B) [20081217-06:07:06.405480843] fsync_file = 0 [20081217-06:07:06.407274985] write_blocksize = 0 (0B) [20081217-06:07:06.409149868] wait time = 0 [20081217-06:07:06.410943330] [20081217-06:07:06.412801208] op weights [20081217-06:07:06.414558345] read = 1 (100.00%) [20081217-06:07:06.416437263] readall = 0 (0.00%) [20081217-06:07:06.418350868] write = 0 (0.00%) [20081217-06:07:06.420303592] create = 0 (0.00%) [20081217-06:07:06.422072874] append = 0 (0.00%) [20081217-06:07:06.423917729] delete = 0 (0.00%) [20081217-06:07:06.425799444] metaop = 0 (0.00%) [20081217-06:07:06.427590412] createdir = 0 (0.00%) [20081217-06:07:06.429503367] stat = 0 (0.00%) [20081217-06:07:06.431290780] writeall = 0 (0.00%) [20081217-06:07:06.433150423] writeall_fsync = 0 (0.00%) [20081217-06:07:06.434918047] open_close = 0 (0.00%) [20081217-06:07:06.436774512] write_fsync = 0 (0.00%) [20081217-06:07:06.438665267] create_fsync = 0 (0.00%) [20081217-06:07:06.440582601] append_fsync = 0 (0.00%) [20081217-06:07:06.442328782] [20081217-06:07:06.444154133] FileSystem /mnt/ffsb1 [20081217-06:07:06.446021701] ========== [20081217-06:07:06.447792496] num_dirs = 0 [20081217-06:07:06.449641378] starting files = 1024 [20081217-06:07:06.451355056] [20081217-06:07:06.453250818] min file size = 104857600 (100MB) [20081217-06:07:06.455008128] max file size = 104857600 (100MB) [20081217-06:07:06.456868270] directio = off [20081217-06:07:06.458675790] alignedio = on [20081217-06:07:06.460508880] bufferedio = off [20081217-06:07:06.462245874] [20081217-06:07:06.464108871] aging is off [20081217-06:07:06.465994974] current utilization = 4.48% [20081217-06:07:06.467779254] [20081217-06:07:06.469639527] checking existing fs: /mnt/ffsb1 [20081217-06:07:06.478250782] fs setup took 0 secs [20081217-06:07:06.871513315] Syncing()...0 sec [20081217-06:07:06.877179283] Starting Actual Benchmark At: Wed Dec 17 06:07:06 2008 [20081217-06:07:06.892724827] [20081217-06:12:16.688216210] Syncing()...1 sec [20081217-06:12:16.751860776] FFSB benchmark finished at: Wed Dec 17 06:12:16 2008 [20081217-06:12:16.754713738] [20081217-06:12:16.757469379] Results: [20081217-06:12:16.836736301] Benchmark took 309.54 sec [20081217-06:12:16.838853343] [20081217-06:12:16.841825643] Total Results [20081217-06:12:16.857358332] =============== [20081217-06:12:16.859747724] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:12:16.862105054] ======= ============ ========= ======= =========== ========== [20081217-06:12:16.864742559] read : 5888000 19021.62 100.000% 100.000% 74.3MB/sec [20081217-06:12:16.867425248] - [20081217-06:12:16.869943057] 19021.62 Transactions per Second [20081217-06:12:16.872314496] [20081217-06:12:16.874680474] Throughput Results [20081217-06:12:16.889852998] =================== [20081217-06:12:16.892369460] Read Throughput: 74.3MB/sec [20081217-06:12:16.894754748] [20081217-06:12:16.897298455] System Call Latency statistics in millisecs [20081217-06:12:16.899637861] ===== [20081217-06:12:16.902118599] Min Avg Max Total Calls [20081217-06:12:16.904474088] ======== ======== ======== ============ [20081217-06:12:16.906721202] [ open] 0.006000 0.037088 3.052000 4600 [20081217-06:12:16.908934836] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:12:16.911274290] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:12:16.913478467] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:12:16.915805088] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:12:16.917887409] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:12:16.920057791] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:12:16.922195423] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:12:16.924371836] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:12:16.926472129] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:12:16.928636425] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:12:16.930747985] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-06:12:16.932936358] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:12:16.935006748] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:12:16.937144744] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-06:12:16.939205455] msec_range[14] 0.100000 - 0.200000 : 81 [20081217-06:12:16.941390963] msec_range[15] 0.050000 - 0.100000 : 839 [20081217-06:12:16.943714537] msec_range[16] 0.020000 - 0.050000 : 2990 [20081217-06:12:16.945891099] msec_range[17] 0.010000 - 0.020000 : 551 [20081217-06:12:16.948537615] msec_range[18] 0.000000 - 0.010000 : 135 [20081217-06:12:16.950988873] [20081217-06:12:16.953169653] [ read] 0.001000 6.624876 461.667999 5888000 [20081217-06:12:16.955626375] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:12:16.958043004] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:12:16.960195714] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:12:16.962412404] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:12:16.964516244] msec_range[4] 200.000000 - 500.000000 : 830 [20081217-06:12:16.966696071] msec_range[5] 100.000000 - 200.000000 : 3257 [20081217-06:12:16.968797494] msec_range[6] 50.000000 - 100.000000 : 3875 [20081217-06:12:16.971029405] msec_range[7] 20.000000 - 50.000000 : 102355 [20081217-06:12:16.973104386] msec_range[8] 10.000000 - 20.000000 : 774626 [20081217-06:12:16.975287226] msec_range[9] 5.000000 - 10.000000 : 2595683 [20081217-06:12:16.977417403] msec_range[10] 2.000000 - 5.000000 : 1913809 [20081217-06:12:16.979658882] msec_range[11] 1.000000 - 2.000000 : 98361 [20081217-06:12:16.981796113] msec_range[12] 0.500000 - 1.000000 : 16998 [20081217-06:12:16.984062979] msec_range[13] 0.200000 - 0.500000 : 39087 [20081217-06:12:16.986201849] msec_range[14] 0.100000 - 0.200000 : 362 [20081217-06:12:16.988549327] msec_range[15] 0.050000 - 0.100000 : 1512 [20081217-06:12:16.991112782] msec_range[16] 0.020000 - 0.050000 : 9735 [20081217-06:12:16.994617447] msec_range[17] 0.010000 - 0.020000 : 64093 [20081217-06:12:16.997197287] msec_range[18] 0.000000 - 0.010000 : 263417 [20081217-06:12:16.999529134] [20081217-06:12:17.002092332] [ lseek] 0.000000 0.001548 0.345000 5888000 [20081217-06:12:17.004495937] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:12:17.007439425] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:12:17.010294153] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:12:17.013510197] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:12:17.016132956] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:12:17.018493193] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:12:17.021253317] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:12:17.023858323] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:12:17.026339665] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:12:17.028949581] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:12:17.031142337] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:12:17.033456614] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:12:17.035657553] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:12:17.037944287] msec_range[13] 0.200000 - 0.500000 : 35 [20081217-06:12:17.040127595] msec_range[14] 0.100000 - 0.200000 : 284 [20081217-06:12:17.042521325] msec_range[15] 0.050000 - 0.100000 : 2450 [20081217-06:12:17.044950925] msec_range[16] 0.020000 - 0.050000 : 24713 [20081217-06:12:17.349963990] msec_range[17] 0.010000 - 0.020000 : 8585 [20081217-06:12:17.352405015] msec_range[18] 0.000000 - 0.010000 : 5851933 [20081217-06:12:17.354959963] [20081217-06:12:17.357396698] [ close] 0.002000 0.007682 0.126000 4600 [20081217-06:12:17.359824019] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:12:17.362525849] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:12:17.364826326] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:12:17.367004611] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:12:17.369126424] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:12:17.371323439] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:12:17.373440010] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:12:17.375677850] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:12:17.377813758] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:12:17.380093978] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:12:17.382286712] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:12:17.384883133] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:12:17.387027509] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:12:17.390045781] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:12:17.392255275] msec_range[14] 0.100000 - 0.200000 : 2 [20081217-06:12:17.394494421] msec_range[15] 0.050000 - 0.100000 : 16 [20081217-06:12:17.396735513] msec_range[16] 0.020000 - 0.050000 : 99 [20081217-06:12:17.410919280] msec_range[17] 0.010000 - 0.020000 : 549 [20081217-06:12:17.413255715] msec_range[18] 0.000000 - 0.010000 : 3934 [20081217-06:12:17.415447819] [20081217-06:12:17.417796338] [20081217-06:12:17.420279834] [20081217-06:12:17.422763636] [20081217-06:12:17.425071563] 6.7% User Time [20081217-06:12:17.427414665] 95.4% System Time [20081217-06:12:17.429509702] 102.1% CPU Utilization [20081217-06:12:17.431661568] Profilers reporting [20081217-06:12:42.535665409] Profilers postprocessing [20081217-06:12:43.671567971] Stopping profiling. [20081217-06:12:43.676905874] Killing daemon. [20081217-06:12:46.081088277] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-12-17_06.06.54/analysis/oprofile.001 [20081217-06:12:46.083411326] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-12-17_06.06.54/analysis/oprofile-brief.001 [20081217-06:12:46.293518133] Processing File : mpstat.001 [20081217-06:12:46.295715729] Discovered mpstat_interval=[5] [20081217-06:12:46.987270711] Processing Directory : sar.breakout.001 [20081217-06:12:46.989480032] Discovered sar_interval=[5] [20081217-06:12:47.532850006] Processing File : iostat.001 [20081217-06:12:47.534997246] Discovered iostat_interval=[5] [20081217-06:12:49.936257721] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-06:12:55.523472299] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-06:12:57.310276132] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-06:12:57.403005977] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1' [20081217-06:12:57.447888317] new log requested [20081217-06:12:57.475380436] Running command ffsb [20081217-06:13:07.145900595] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-06:13:07.161492342] Importing argument : num_threads=1 [20081217-06:13:07.187566936] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-06:13:07.282868266] Checking for sar... [20081217-06:13:07.285105584] found [20081217-06:13:07.341939086] Checking for sar... [20081217-06:13:07.344062276] found [20081217-06:13:07.399911714] Checking for sar... [20081217-06:13:07.402020854] found [20081217-06:13:07.562677032] Checking for binutils-2.18 ... Already installed. [20081217-06:13:07.567061749] mv: cannot stat `lib64/*': No such file or directory [20081217-06:13:07.573835964] rmdir: lib64: No such file or directory [20081217-06:13:07.645018637] Checking for gettext-0.17 ... Already installed. [20081217-06:13:07.697383283] popt32-1.10.4 already installed. [20081217-06:13:07.712149972] popt64-1.10.4 already installed. [20081217-06:13:07.743661588] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-06:13:07.796112124] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-06:13:07.876683893] Daemon not running [20081217-06:13:07.895832872] Unloading oprofile module [20081217-06:13:08.097348796] Daemon not running [20081217-06:13:09.238830179] OPROFILE : using callgraph [5] [20081217-06:13:09.471423046] Daemon not running [20081217-06:13:09.473384726] Separate options: none [20081217-06:13:09.475511091] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-06:13:09.477648490] Image filter: none [20081217-06:13:09.479495503] Call-graph depth: 5 [20081217-06:13:09.560672550] FFSB version 6.0-RC2 started [20081217-06:13:09.562545366] [20081217-06:13:09.564653063] benchmark time = 300 [20081217-06:13:09.566639139] ThreadGroup 0 [20081217-06:13:09.568525871] ================ [20081217-06:13:09.570247660] num_threads = 1 [20081217-06:13:09.572141612] [20081217-06:13:09.573910769] read_random = off [20081217-06:13:09.575715954] read_size = 0 (0B) [20081217-06:13:09.577404317] read_blocksize = 0 (0B) [20081217-06:13:09.579308908] read_skip = off [20081217-06:13:09.581467819] read_skipsize = 0 (0B) [20081217-06:13:09.583554857] [20081217-06:13:09.585606126] write_random = on [20081217-06:13:09.587477803] write_size = 5242880 (5MB) [20081217-06:13:09.589281471] fsync_file = 0 [20081217-06:13:09.591081461] write_blocksize = 4096 (4KB) [20081217-06:13:09.592925873] wait time = 0 [20081217-06:13:09.594762365] [20081217-06:13:09.596594792] op weights [20081217-06:13:09.598358706] read = 0 (0.00%) [20081217-06:13:09.600193081] readall = 0 (0.00%) [20081217-06:13:09.601945187] write = 1 (100.00%) [20081217-06:13:09.603775709] create = 0 (0.00%) [20081217-06:13:09.605511062] append = 0 (0.00%) [20081217-06:13:09.607397474] delete = 0 (0.00%) [20081217-06:13:09.609286352] metaop = 0 (0.00%) [20081217-06:13:09.611070411] createdir = 0 (0.00%) [20081217-06:13:09.612922625] stat = 0 (0.00%) [20081217-06:13:09.614680735] writeall = 0 (0.00%) [20081217-06:13:09.616505288] writeall_fsync = 0 (0.00%) [20081217-06:13:09.618257889] open_close = 0 (0.00%) [20081217-06:13:09.620280855] write_fsync = 0 (0.00%) [20081217-06:13:09.622140450] create_fsync = 0 (0.00%) [20081217-06:13:09.623957496] append_fsync = 0 (0.00%) [20081217-06:13:09.625689646] [20081217-06:13:09.627496286] FileSystem /mnt/ffsb1 [20081217-06:13:09.629369921] ========== [20081217-06:13:09.631125773] num_dirs = 0 [20081217-06:13:09.632957083] starting files = 1024 [20081217-06:13:09.634752940] [20081217-06:13:09.636560888] min file size = 104857600 (100MB) [20081217-06:13:09.638299431] max file size = 104857600 (100MB) [20081217-06:13:09.640108788] directio = off [20081217-06:13:09.641863347] alignedio = on [20081217-06:13:09.643693558] bufferedio = off [20081217-06:13:09.645421816] [20081217-06:13:09.647274929] aging is off [20081217-06:13:09.649158231] current utilization = 4.48% [20081217-06:13:09.650929010] [20081217-06:13:09.652786566] checking existing fs: /mnt/ffsb1 [20081217-06:13:09.663214419] fs setup took 0 secs [20081217-06:13:10.541307697] Syncing()...0 sec [20081217-06:13:10.543132803] Starting Actual Benchmark At: Wed Dec 17 06:13:10 2008 [20081217-06:13:10.556294181] [20081217-06:18:17.121360525] Syncing()...5 sec [20081217-06:18:17.179224922] FFSB benchmark finished at: Wed Dec 17 06:18:16 2008 [20081217-06:18:17.182150813] [20081217-06:18:17.184926658] Results: [20081217-06:18:17.242426573] Benchmark took 306.21 sec [20081217-06:18:17.245206427] [20081217-06:18:17.247936385] Total Results [20081217-06:18:17.263214081] =============== [20081217-06:18:17.265485936] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:18:17.268049394] ======= ============ ========= ======= =========== ========== [20081217-06:18:17.270341254] write : 10464000 34172.56 100.000% 100.000% 2.61GB/sec [20081217-06:18:17.272632041] - [20081217-06:18:17.275122313] 34172.56 Transactions per Second [20081217-06:18:17.277446784] [20081217-06:18:17.280380190] Throughput Results [20081217-06:18:17.295509298] =================== [20081217-06:18:17.297652712] Write Throughput: 2.61GB/sec [20081217-06:18:17.300090307] [20081217-06:18:17.302891045] System Call Latency statistics in millisecs [20081217-06:18:17.305144269] ===== [20081217-06:18:17.307533266] Min Avg Max Total Calls [20081217-06:18:17.309900877] ======== ======== ======== ============ [20081217-06:18:17.312105099] [ open] 0.006000 0.039272 62.327000 8175 [20081217-06:18:17.314352126] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:18:17.316496241] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:18:17.318657213] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:18:17.321246075] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:18:17.323556307] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:18:17.325707803] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:18:17.327879685] msec_range[6] 50.000000 - 100.000000 : 1 [20081217-06:18:17.330014720] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:18:17.332215924] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:18:17.334340560] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:18:17.336829428] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:18:17.339467384] msec_range[11] 1.000000 - 2.000000 : 4 [20081217-06:18:17.341647840] msec_range[12] 0.500000 - 1.000000 : 40 [20081217-06:18:17.343962711] msec_range[13] 0.200000 - 0.500000 : 43 [20081217-06:18:17.346136802] msec_range[14] 0.100000 - 0.200000 : 38 [20081217-06:18:17.348381352] msec_range[15] 0.050000 - 0.100000 : 561 [20081217-06:18:17.350543774] msec_range[16] 0.020000 - 0.050000 : 4610 [20081217-06:18:17.352844816] msec_range[17] 0.010000 - 0.020000 : 2264 [20081217-06:18:17.355132450] msec_range[18] 0.000000 - 0.010000 : 614 [20081217-06:18:17.357328676] [20081217-06:18:17.359533817] [ write] 0.004000 0.026207 461.941986 10464000 [20081217-06:18:17.361680045] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:18:17.363912968] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:18:17.366132617] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:18:17.368498740] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:18:17.370877509] msec_range[4] 200.000000 - 500.000000 : 31 [20081217-06:18:17.373118421] msec_range[5] 100.000000 - 200.000000 : 75 [20081217-06:18:17.375535573] msec_range[6] 50.000000 - 100.000000 : 449 [20081217-06:18:17.377769414] msec_range[7] 20.000000 - 50.000000 : 2658 [20081217-06:18:17.380016227] msec_range[8] 10.000000 - 20.000000 : 3 [20081217-06:18:17.382174246] msec_range[9] 5.000000 - 10.000000 : 1 [20081217-06:18:17.384486046] msec_range[10] 2.000000 - 5.000000 : 42 [20081217-06:18:17.387472700] msec_range[11] 1.000000 - 2.000000 : 2552 [20081217-06:18:17.389791045] msec_range[12] 0.500000 - 1.000000 : 12583 [20081217-06:18:17.393354492] msec_range[13] 0.200000 - 0.500000 : 15409 [20081217-06:18:17.395765678] msec_range[14] 0.100000 - 0.200000 : 12466 [20081217-06:18:17.398143320] msec_range[15] 0.050000 - 0.100000 : 20716 [20081217-06:18:17.400779598] msec_range[16] 0.020000 - 0.050000 : 661365 [20081217-06:18:17.403163721] msec_range[17] 0.010000 - 0.020000 : 2827848 [20081217-06:18:17.405463514] msec_range[18] 0.000000 - 0.010000 : 6907802 [20081217-06:18:17.407612713] [20081217-06:18:17.409950513] [ lseek] 0.000000 0.001189 2.160000 10464000 [20081217-06:18:17.412323141] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:18:17.414572941] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:18:17.417533511] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:18:17.419928701] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:18:17.422522531] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:18:17.425618393] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:18:17.427960958] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:18:17.430135523] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:18:17.432513819] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:18:17.434766735] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:18:17.436980767] msec_range[10] 2.000000 - 5.000000 : 3 [20081217-06:18:17.439162484] msec_range[11] 1.000000 - 2.000000 : 225 [20081217-06:18:17.441399096] msec_range[12] 0.500000 - 1.000000 : 1226 [20081217-06:18:17.443564126] msec_range[13] 0.200000 - 0.500000 : 1547 [20081217-06:18:17.445795256] msec_range[14] 0.100000 - 0.200000 : 1165 [20081217-06:18:17.447942399] msec_range[15] 0.050000 - 0.100000 : 1471 [20081217-06:18:17.450171157] msec_range[16] 0.020000 - 0.050000 : 4034 [20081217-06:18:17.452279608] msec_range[17] 0.010000 - 0.020000 : 4431 [20081217-06:18:17.454468828] msec_range[18] 0.000000 - 0.010000 : 10449898 [20081217-06:18:17.456533238] [20081217-06:18:17.458677393] [ close] 0.002000 0.006792 1.168000 8175 [20081217-06:18:17.460919091] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:18:17.463096318] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:18:17.465262085] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:18:17.467725055] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:18:17.470158243] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:18:17.472539504] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:18:17.475103297] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:18:17.477551002] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:18:17.479898064] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:18:17.482053124] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:18:17.484300233] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:18:17.486435944] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-06:18:17.488628137] msec_range[12] 0.500000 - 1.000000 : 6 [20081217-06:18:17.490785392] msec_range[13] 0.200000 - 0.500000 : 7 [20081217-06:18:17.492931522] msec_range[14] 0.100000 - 0.200000 : 9 [20081217-06:18:17.495017958] msec_range[15] 0.050000 - 0.100000 : 7 [20081217-06:18:17.497148875] msec_range[16] 0.020000 - 0.050000 : 16 [20081217-06:18:17.499235543] msec_range[17] 0.010000 - 0.020000 : 426 [20081217-06:18:17.501476517] msec_range[18] 0.000000 - 0.010000 : 7703 [20081217-06:18:17.504095234] [20081217-06:18:17.506282577] [20081217-06:18:17.508762232] [20081217-06:18:17.511323653] [20081217-06:18:17.513646269] 6.2% User Time [20081217-06:18:17.515896218] 64.4% System Time [20081217-06:18:17.518252074] 70.6% CPU Utilization [20081217-06:18:17.541337959] Profilers reporting [20081217-06:18:55.467637217] Profilers postprocessing [20081217-06:18:56.604251376] Stopping profiling. [20081217-06:18:56.609171029] Killing daemon. [20081217-06:18:59.000904778] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_06.12.57/analysis/oprofile.001 [20081217-06:18:59.003329150] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_06.12.57/analysis/oprofile-brief.001 [20081217-06:18:59.242176390] Processing File : mpstat.001 [20081217-06:18:59.244256499] Discovered mpstat_interval=[5] [20081217-06:18:59.838099136] Processing Directory : sar.breakout.001 [20081217-06:18:59.840367000] Discovered sar_interval=[5] [20081217-06:19:00.077151168] Processing File : iostat.001 [20081217-06:19:00.079246419] Discovered iostat_interval=[5] [20081217-06:19:02.118305725] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-06:19:07.051961803] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-06:19:08.466092912] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-06:19:08.557697971] PROCESSING COMMAND : 'run random_writes__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16' [20081217-06:19:08.602452331] new log requested [20081217-06:19:08.626344207] Running command ffsb [20081217-06:19:17.919172008] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-06:19:17.935273069] Importing argument : num_threads=16 [20081217-06:19:17.961251624] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-06:19:18.056064419] Checking for sar... [20081217-06:19:18.058161359] found [20081217-06:19:18.114153788] Checking for sar... [20081217-06:19:18.116251398] found [20081217-06:19:18.172004924] Checking for sar... [20081217-06:19:18.174236835] found [20081217-06:19:18.335428623] Checking for binutils-2.18 ... Already installed. [20081217-06:19:18.339867545] mv: cannot stat `lib64/*': No such file or directory [20081217-06:19:18.425014519] rmdir: lib64: No such file or directory [20081217-06:19:18.501489149] Checking for gettext-0.17 ... Already installed. [20081217-06:19:18.548177723] popt32-1.10.4 already installed. [20081217-06:19:18.563185286] popt64-1.10.4 already installed. [20081217-06:19:18.594526325] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-06:19:18.647072065] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-06:19:18.727254024] Daemon not running [20081217-06:19:18.745792811] Unloading oprofile module [20081217-06:19:19.158703831] Daemon not running [20081217-06:19:20.597277120] OPROFILE : using callgraph [5] [20081217-06:19:20.830640736] Daemon not running [20081217-06:19:20.832637760] Separate options: none [20081217-06:19:20.834743098] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-06:19:20.836766501] Image filter: none [20081217-06:19:20.838639200] Call-graph depth: 5 [20081217-06:19:20.912262311] FFSB version 6.0-RC2 started [20081217-06:19:20.914459040] [20081217-06:19:20.970973697] benchmark time = 300 [20081217-06:19:20.973002301] ThreadGroup 0 [20081217-06:19:20.975225910] ================ [20081217-06:19:20.977285580] num_threads = 16 [20081217-06:19:20.979521749] [20081217-06:19:20.981394148] read_random = off [20081217-06:19:20.983243818] read_size = 0 (0B) [20081217-06:19:20.984997076] read_blocksize = 0 (0B) [20081217-06:19:20.986837679] read_skip = off [20081217-06:19:20.988604260] read_skipsize = 0 (0B) [20081217-06:19:20.990417448] [20081217-06:19:20.992152666] write_random = on [20081217-06:19:20.994007894] write_size = 5242880 (5MB) [20081217-06:19:20.995826502] fsync_file = 0 [20081217-06:19:20.997539360] write_blocksize = 4096 (4KB) [20081217-06:19:20.999345508] wait time = 0 [20081217-06:19:21.001123133] [20081217-06:19:21.002978285] op weights [20081217-06:19:21.004695519] read = 0 (0.00%) [20081217-06:19:21.006497090] readall = 0 (0.00%) [20081217-06:19:21.008250447] write = 1 (100.00%) [20081217-06:19:21.010101854] create = 0 (0.00%) [20081217-06:19:21.011851531] append = 0 (0.00%) [20081217-06:19:21.013893282] delete = 0 (0.00%) [20081217-06:19:21.015931043] metaop = 0 (0.00%) [20081217-06:19:21.017733475] createdir = 0 (0.00%) [20081217-06:19:21.019496210] stat = 0 (0.00%) [20081217-06:19:21.021530602] writeall = 0 (0.00%) [20081217-06:19:21.023493163] writeall_fsync = 0 (0.00%) [20081217-06:19:21.025288640] open_close = 0 (0.00%) [20081217-06:19:21.027011841] write_fsync = 0 (0.00%) [20081217-06:19:21.028880508] create_fsync = 0 (0.00%) [20081217-06:19:21.030639148] append_fsync = 0 (0.00%) [20081217-06:19:21.032452914] [20081217-06:19:21.034176507] FileSystem /mnt/ffsb1 [20081217-06:19:21.035979809] ========== [20081217-06:19:21.037868445] num_dirs = 0 [20081217-06:19:21.039618063] starting files = 1024 [20081217-06:19:21.041474174] [20081217-06:19:21.043275999] min file size = 104857600 (100MB) [20081217-06:19:21.045101354] max file size = 104857600 (100MB) [20081217-06:19:21.046825439] directio = off [20081217-06:19:21.048627388] alignedio = on [20081217-06:19:21.050392311] bufferedio = off [20081217-06:19:21.052223375] [20081217-06:19:21.053955417] aging is off [20081217-06:19:21.055756681] current utilization = 4.48% [20081217-06:19:21.057495121] [20081217-06:19:21.059269876] checking existing fs: /mnt/ffsb1 [20081217-06:19:21.150068220] fs setup took 0 secs [20081217-06:19:22.075736002] Syncing()...0 sec [20081217-06:19:22.078288877] Starting Actual Benchmark At: Wed Dec 17 06:19:22 2008 [20081217-06:19:22.091766058] [20081217-06:24:29.619023236] Syncing()...5 sec [20081217-06:24:29.694905003] FFSB benchmark finished at: Wed Dec 17 06:24:29 2008 [20081217-06:24:29.697785112] [20081217-06:24:29.700442584] Results: [20081217-06:24:29.781713751] Benchmark took 307.24 sec [20081217-06:24:29.784611955] [20081217-06:24:29.787297692] Total Results [20081217-06:24:29.802588808] =============== [20081217-06:24:29.804733340] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:24:29.807152051] ======= ============ ========= ======= =========== ========== [20081217-06:24:29.809454824] write : 10272000 33433.18 100.000% 100.000% 2.55GB/sec [20081217-06:24:29.811809839] - [20081217-06:24:29.814502523] 33433.18 Transactions per Second [20081217-06:24:29.817140609] [20081217-06:24:29.819584272] Throughput Results [20081217-06:24:29.834685307] =================== [20081217-06:24:29.836993767] Write Throughput: 2.55GB/sec [20081217-06:24:29.839431346] [20081217-06:24:29.841722729] System Call Latency statistics in millisecs [20081217-06:24:29.844055216] ===== [20081217-06:24:29.846420609] Min Avg Max Total Calls [20081217-06:24:29.848753768] ======== ======== ======== ============ [20081217-06:24:29.851830957] [ open] 0.007000 0.038274 9.097000 8025 [20081217-06:24:29.854703463] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:24:29.857022732] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:24:29.859221209] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:24:29.861768760] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:24:29.864055732] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:24:29.866260010] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:24:29.868349081] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:24:29.870628303] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:24:29.872756382] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:24:29.874977407] msec_range[9] 5.000000 - 10.000000 : 1 [20081217-06:24:29.877084009] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:24:29.879431844] msec_range[11] 1.000000 - 2.000000 : 9 [20081217-06:24:29.881710538] msec_range[12] 0.500000 - 1.000000 : 39 [20081217-06:24:29.884095558] msec_range[13] 0.200000 - 0.500000 : 32 [20081217-06:24:29.886904205] msec_range[14] 0.100000 - 0.200000 : 33 [20081217-06:24:29.889275550] msec_range[15] 0.050000 - 0.100000 : 922 [20081217-06:24:29.891520718] msec_range[16] 0.020000 - 0.050000 : 5253 [20081217-06:24:29.893696873] msec_range[17] 0.010000 - 0.020000 : 1508 [20081217-06:24:29.895903018] msec_range[18] 0.000000 - 0.010000 : 228 [20081217-06:24:29.898025618] [20081217-06:24:29.900230708] [ write] 0.004000 0.460648 2067.964111 10272000 [20081217-06:24:29.902358521] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:24:29.904592073] msec_range[1] 2000.000000 - 5000.000000 : 1 [20081217-06:24:29.906718984] msec_range[2] 1000.000000 - 2000.000000 : 472 [20081217-06:24:29.908962706] msec_range[3] 500.000000 - 1000.000000 : 5095 [20081217-06:24:29.911095972] msec_range[4] 200.000000 - 500.000000 : 866 [20081217-06:24:29.913671423] msec_range[5] 100.000000 - 200.000000 : 65 [20081217-06:24:29.915898528] msec_range[6] 50.000000 - 100.000000 : 159 [20081217-06:24:29.918320698] msec_range[7] 20.000000 - 50.000000 : 210 [20081217-06:24:29.920442617] msec_range[8] 10.000000 - 20.000000 : 103 [20081217-06:24:29.922736796] msec_range[9] 5.000000 - 10.000000 : 165 [20081217-06:24:29.924983876] msec_range[10] 2.000000 - 5.000000 : 855 [20081217-06:24:29.943206632] msec_range[11] 1.000000 - 2.000000 : 5344 [20081217-06:24:29.945445436] msec_range[12] 0.500000 - 1.000000 : 12237 [20081217-06:24:29.947617439] msec_range[13] 0.200000 - 0.500000 : 11028 [20081217-06:24:29.950090658] msec_range[14] 0.100000 - 0.200000 : 9645 [20081217-06:24:29.952488158] msec_range[15] 0.050000 - 0.100000 : 42899 [20081217-06:24:29.954634519] msec_range[16] 0.020000 - 0.050000 : 1446109 [20081217-06:24:29.956930191] msec_range[17] 0.010000 - 0.020000 : 3374100 [20081217-06:24:29.959255586] msec_range[18] 0.000000 - 0.010000 : 5362647 [20081217-06:24:29.961496123] [20081217-06:24:29.963821903] [ lseek] 0.000000 0.007088 1131.637939 10272000 [20081217-06:24:29.966069253] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:24:29.968405931] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:24:29.970748146] msec_range[2] 1000.000000 - 2000.000000 : 3 [20081217-06:24:29.972921688] msec_range[3] 500.000000 - 1000.000000 : 39 [20081217-06:24:29.975242095] msec_range[4] 200.000000 - 500.000000 : 70 [20081217-06:24:29.977454161] msec_range[5] 100.000000 - 200.000000 : 18 [20081217-06:24:29.979708912] msec_range[6] 50.000000 - 100.000000 : 15 [20081217-06:24:29.982048508] msec_range[7] 20.000000 - 50.000000 : 6 [20081217-06:24:29.986038048] msec_range[8] 10.000000 - 20.000000 : 2 [20081217-06:24:29.988731955] msec_range[9] 5.000000 - 10.000000 : 19 [20081217-06:24:29.991301571] msec_range[10] 2.000000 - 5.000000 : 78 [20081217-06:24:29.993668055] msec_range[11] 1.000000 - 2.000000 : 465 [20081217-06:24:29.996167166] msec_range[12] 0.500000 - 1.000000 : 1181 [20081217-06:24:29.998654353] msec_range[13] 0.200000 - 0.500000 : 1363 [20081217-06:24:30.001062642] msec_range[14] 0.100000 - 0.200000 : 1648 [20081217-06:24:30.003447750] msec_range[15] 0.050000 - 0.100000 : 3480 [20081217-06:24:30.005975135] msec_range[16] 0.020000 - 0.050000 : 11474 [20081217-06:24:30.008400069] msec_range[17] 0.010000 - 0.020000 : 17189 [20081217-06:24:30.010805850] msec_range[18] 0.000000 - 0.010000 : 10234950 [20081217-06:24:30.013295091] [20081217-06:24:30.015467837] [ close] 0.002000 0.007674 1.362000 8025 [20081217-06:24:30.017726219] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:24:30.019904525] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:24:30.022128204] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:24:30.024273010] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:24:30.026483652] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:24:30.028627085] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:24:30.030792258] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:24:30.032900944] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:24:30.035062263] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:24:30.037175739] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:24:30.039333883] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:24:30.041446231] msec_range[11] 1.000000 - 2.000000 : 2 [20081217-06:24:30.043644820] msec_range[12] 0.500000 - 1.000000 : 5 [20081217-06:24:30.045848537] msec_range[13] 0.200000 - 0.500000 : 4 [20081217-06:24:30.048947320] msec_range[14] 0.100000 - 0.200000 : 3 [20081217-06:24:30.051432386] msec_range[15] 0.050000 - 0.100000 : 3 [20081217-06:24:30.053745767] msec_range[16] 0.020000 - 0.050000 : 14 [20081217-06:24:30.056238874] msec_range[17] 0.010000 - 0.020000 : 1028 [20081217-06:24:30.058457290] msec_range[18] 0.000000 - 0.010000 : 6966 [20081217-06:24:30.060732352] [20081217-06:24:30.062878941] [20081217-06:24:30.065157323] [20081217-06:24:30.067328538] [20081217-06:24:30.069542479] 7.0% User Time [20081217-06:24:30.071689423] 130.1% System Time [20081217-06:24:30.073968557] 137.0% CPU Utilization [20081217-06:24:30.105860992] Profilers reporting [20081217-06:24:59.640089206] Profilers postprocessing [20081217-06:25:00.777839345] Stopping profiling. [20081217-06:25:00.782771455] Killing daemon. [20081217-06:25:02.384036997] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-12-17_06.19.08/analysis/oprofile.001 [20081217-06:25:02.387668217] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-12-17_06.19.08/analysis/oprofile-brief.001 [20081217-06:25:02.591532924] Processing File : mpstat.001 [20081217-06:25:02.593550485] Discovered mpstat_interval=[5] [20081217-06:25:03.210074726] Processing Directory : sar.breakout.001 [20081217-06:25:03.212350950] Discovered sar_interval=[5] [20081217-06:25:03.506761016] Processing File : iostat.001 [20081217-06:25:03.508910984] Discovered iostat_interval=[5] [20081217-06:25:06.864764342] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-06:25:11.254552578] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-06:25:12.679199070] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-06:25:12.768321140] PROCESSING COMMAND : 'run random_writes__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128' [20081217-06:25:12.812645872] new log requested [20081217-06:25:12.840456652] Running command ffsb [20081217-06:25:22.149354369] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-06:25:22.165009424] Importing argument : num_threads=128 [20081217-06:25:22.191521647] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-06:25:22.287662727] Checking for sar... [20081217-06:25:22.289773995] found [20081217-06:25:22.345630441] Checking for sar... [20081217-06:25:22.347817548] found [20081217-06:25:22.403953398] Checking for sar... [20081217-06:25:22.406328617] found [20081217-06:25:22.567762734] Checking for binutils-2.18 ... Already installed. [20081217-06:25:22.571990827] mv: cannot stat `lib64/*': No such file or directory [20081217-06:25:22.584613771] rmdir: lib64: No such file or directory [20081217-06:25:22.649993856] Checking for gettext-0.17 ... Already installed. [20081217-06:25:22.690799714] popt32-1.10.4 already installed. [20081217-06:25:22.706569790] popt64-1.10.4 already installed. [20081217-06:25:22.737770059] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-06:25:22.791852131] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-06:25:22.871248225] Daemon not running [20081217-06:25:22.890306393] Unloading oprofile module [20081217-06:25:23.123975683] Daemon not running [20081217-06:25:24.578197371] OPROFILE : using callgraph [5] [20081217-06:25:24.809138196] Daemon not running [20081217-06:25:24.811101099] Separate options: none [20081217-06:25:24.813244562] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-06:25:24.815307719] Image filter: none [20081217-06:25:24.817366170] Call-graph depth: 5 [20081217-06:25:24.888882748] FFSB version 6.0-RC2 started [20081217-06:25:24.890999867] [20081217-06:25:25.379190713] benchmark time = 300 [20081217-06:25:25.380990760] ThreadGroup 0 [20081217-06:25:25.382986861] ================ [20081217-06:25:25.384763388] num_threads = 128 [20081217-06:25:25.386606052] [20081217-06:25:25.388332442] read_random = off [20081217-06:25:25.390266799] read_size = 0 (0B) [20081217-06:25:25.392447852] read_blocksize = 0 (0B) [20081217-06:25:25.394469375] read_skip = off [20081217-06:25:25.396702211] read_skipsize = 0 (0B) [20081217-06:25:25.398610148] [20081217-06:25:25.400437348] write_random = on [20081217-06:25:25.402175157] write_size = 5242880 (5MB) [20081217-06:25:25.404006966] fsync_file = 0 [20081217-06:25:25.405743132] write_blocksize = 4096 (4KB) [20081217-06:25:25.407545972] wait time = 0 [20081217-06:25:25.409308930] [20081217-06:25:25.411091890] op weights [20081217-06:25:25.412832962] read = 0 (0.00%) [20081217-06:25:25.414689313] readall = 0 (0.00%) [20081217-06:25:25.416515430] write = 1 (100.00%) [20081217-06:25:25.418263645] create = 0 (0.00%) [20081217-06:25:25.420087768] append = 0 (0.00%) [20081217-06:25:25.421835139] delete = 0 (0.00%) [20081217-06:25:25.423654286] metaop = 0 (0.00%) [20081217-06:25:25.425400133] createdir = 0 (0.00%) [20081217-06:25:25.427231790] stat = 0 (0.00%) [20081217-06:25:25.428925762] writeall = 0 (0.00%) [20081217-06:25:25.430856098] writeall_fsync = 0 (0.00%) [20081217-06:25:25.432672803] open_close = 0 (0.00%) [20081217-06:25:25.434484840] write_fsync = 0 (0.00%) [20081217-06:25:25.436228760] create_fsync = 0 (0.00%) [20081217-06:25:25.438037500] append_fsync = 0 (0.00%) [20081217-06:25:25.439871299] [20081217-06:25:25.441624005] FileSystem /mnt/ffsb1 [20081217-06:25:25.443458434] ========== [20081217-06:25:25.445252249] num_dirs = 0 [20081217-06:25:25.447052275] starting files = 1024 [20081217-06:25:25.448773050] [20081217-06:25:25.450563481] min file size = 104857600 (100MB) [20081217-06:25:25.452294050] max file size = 104857600 (100MB) [20081217-06:25:25.454104117] directio = off [20081217-06:25:25.455818005] alignedio = on [20081217-06:25:25.457611613] bufferedio = off [20081217-06:25:25.459344366] [20081217-06:25:25.461125331] aging is off [20081217-06:25:25.462820795] current utilization = 4.48% [20081217-06:25:25.464617301] [20081217-06:25:25.466344090] checking existing fs: /mnt/ffsb1 [20081217-06:25:25.559952963] fs setup took 0 secs [20081217-06:25:26.492516635] Syncing()...0 sec [20081217-06:25:26.499614878] Starting Actual Benchmark At: Wed Dec 17 06:25:26 2008 [20081217-06:25:26.512831502] [20081217-06:30:33.246036629] Syncing()...3 sec [20081217-06:30:33.269074440] FFSB benchmark finished at: Wed Dec 17 06:30:33 2008 [20081217-06:30:33.271874755] [20081217-06:30:33.274578117] Results: [20081217-06:30:33.353006187] Benchmark took 306.57 sec [20081217-06:30:33.355098235] [20081217-06:30:33.357664520] Total Results [20081217-06:30:33.372497409] =============== [20081217-06:30:33.375045446] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:30:33.377702132] ======= ============ ========= ======= =========== ========== [20081217-06:30:33.380233679] write : 8304640 27089.21 100.000% 100.000% 2.07GB/sec [20081217-06:30:33.382587365] - [20081217-06:30:33.384902463] 27089.21 Transactions per Second [20081217-06:30:33.387472613] [20081217-06:30:33.390021319] Throughput Results [20081217-06:30:33.405258214] =================== [20081217-06:30:33.407695971] Write Throughput: 2.07GB/sec [20081217-06:30:33.410310093] [20081217-06:30:33.413753334] System Call Latency statistics in millisecs [20081217-06:30:33.416209026] ===== [20081217-06:30:33.418408847] Min Avg Max Total Calls [20081217-06:30:33.420853440] ======== ======== ======== ============ [20081217-06:30:33.423286466] [ open] 0.006000 0.050406 58.765999 6488 [20081217-06:30:33.425712395] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:30:33.427814015] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:30:33.429996455] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:30:33.432165445] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:30:33.434466655] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:30:33.436664811] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:30:33.438975478] msec_range[6] 50.000000 - 100.000000 : 1 [20081217-06:30:33.441328324] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:30:33.443590099] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:30:33.446315245] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:30:33.448998103] msec_range[10] 2.000000 - 5.000000 : 2 [20081217-06:30:33.451198533] msec_range[11] 1.000000 - 2.000000 : 8 [20081217-06:30:33.453300182] msec_range[12] 0.500000 - 1.000000 : 15 [20081217-06:30:33.455645334] msec_range[13] 0.200000 - 0.500000 : 52 [20081217-06:30:33.457806871] msec_range[14] 0.100000 - 0.200000 : 77 [20081217-06:30:33.460015000] msec_range[15] 0.050000 - 0.100000 : 1008 [20081217-06:30:33.462108151] msec_range[16] 0.020000 - 0.050000 : 4433 [20081217-06:30:33.464360322] msec_range[17] 0.010000 - 0.020000 : 797 [20081217-06:30:33.466525548] msec_range[18] 0.000000 - 0.010000 : 95 [20081217-06:30:33.468673536] [20081217-06:30:33.470756359] [ write] 0.004000 4.240435 16807.199219 8304640 [20081217-06:30:33.472966299] msec_range[0] 5000.000000 - 10000.000000 : 2464 [20081217-06:30:33.475108475] msec_range[1] 2000.000000 - 5000.000000 : 4170 [20081217-06:30:33.477227788] msec_range[2] 1000.000000 - 2000.000000 : 1547 [20081217-06:30:33.479365822] msec_range[3] 500.000000 - 1000.000000 : 154 [20081217-06:30:33.481601231] msec_range[4] 200.000000 - 500.000000 : 265 [20081217-06:30:33.483894096] msec_range[5] 100.000000 - 200.000000 : 449 [20081217-06:30:33.486557418] msec_range[6] 50.000000 - 100.000000 : 366 [20081217-06:30:33.488890435] msec_range[7] 20.000000 - 50.000000 : 274 [20081217-06:30:33.491119905] msec_range[8] 10.000000 - 20.000000 : 118 [20081217-06:30:33.493571080] msec_range[9] 5.000000 - 10.000000 : 300 [20081217-06:30:33.495774169] msec_range[10] 2.000000 - 5.000000 : 1320 [20081217-06:30:33.498243512] msec_range[11] 1.000000 - 2.000000 : 5024 [20081217-06:30:33.500809022] msec_range[12] 0.500000 - 1.000000 : 13213 [20081217-06:30:33.503575923] msec_range[13] 0.200000 - 0.500000 : 26400 [20081217-06:30:33.506193610] msec_range[14] 0.100000 - 0.200000 : 44936 [20081217-06:30:33.508576715] msec_range[15] 0.050000 - 0.100000 : 122797 [20081217-06:30:33.511103744] msec_range[16] 0.020000 - 0.050000 : 1627736 [20081217-06:30:33.513620616] msec_range[17] 0.010000 - 0.020000 : 2964216 [20081217-06:30:33.516239843] msec_range[18] 0.000000 - 0.010000 : 3488730 [20081217-06:30:33.518813708] [20081217-06:30:33.521087287] [ lseek] 0.000000 0.408919 14013.557617 8304640 [20081217-06:30:33.523759958] msec_range[0] 5000.000000 - 10000.000000 : 199 [20081217-06:30:33.526336025] msec_range[1] 2000.000000 - 5000.000000 : 470 [20081217-06:30:33.528961972] msec_range[2] 1000.000000 - 2000.000000 : 195 [20081217-06:30:33.531368445] msec_range[3] 500.000000 - 1000.000000 : 85 [20081217-06:30:33.533803835] msec_range[4] 200.000000 - 500.000000 : 61 [20081217-06:30:33.536278932] msec_range[5] 100.000000 - 200.000000 : 34 [20081217-06:30:33.538656640] msec_range[6] 50.000000 - 100.000000 : 30 [20081217-06:30:33.541078956] msec_range[7] 20.000000 - 50.000000 : 23 [20081217-06:30:33.543419453] msec_range[8] 10.000000 - 20.000000 : 19 [20081217-06:30:33.545689329] msec_range[9] 5.000000 - 10.000000 : 86 [20081217-06:30:33.547851139] msec_range[10] 2.000000 - 5.000000 : 325 [20081217-06:30:33.550072242] msec_range[11] 1.000000 - 2.000000 : 656 [20081217-06:30:33.552237849] msec_range[12] 0.500000 - 1.000000 : 1864 [20081217-06:30:33.554556570] msec_range[13] 0.200000 - 0.500000 : 5832 [20081217-06:30:33.556714700] msec_range[14] 0.100000 - 0.200000 : 10780 [20081217-06:30:33.559110955] msec_range[15] 0.050000 - 0.100000 : 20691 [20081217-06:30:33.561489624] msec_range[16] 0.020000 - 0.050000 : 48025 [20081217-06:30:33.563647584] msec_range[17] 0.010000 - 0.020000 : 43625 [20081217-06:30:33.565903921] msec_range[18] 0.000000 - 0.010000 : 8171634 [20081217-06:30:33.568283110] [20081217-06:30:33.570476742] [ close] 0.002000 0.007858 0.270000 6488 [20081217-06:30:33.572590261] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:30:33.574885464] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:30:33.577026181] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:30:33.579495817] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:30:33.582120783] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:30:33.584435181] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:30:33.586760355] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:30:33.589009567] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:30:33.591309769] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:30:33.593441936] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:30:33.595653435] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:30:33.597796486] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:30:33.600006785] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:30:33.602091723] msec_range[13] 0.200000 - 0.500000 : 2 [20081217-06:30:33.604420861] msec_range[14] 0.100000 - 0.200000 : 8 [20081217-06:30:33.606900260] msec_range[15] 0.050000 - 0.100000 : 14 [20081217-06:30:33.609076308] msec_range[16] 0.020000 - 0.050000 : 35 [20081217-06:30:33.611606006] msec_range[17] 0.010000 - 0.020000 : 1137 [20081217-06:30:33.615374029] msec_range[18] 0.000000 - 0.010000 : 5292 [20081217-06:30:33.617698702] [20081217-06:30:33.619811616] [20081217-06:30:33.622078469] [20081217-06:30:33.624361866] [20081217-06:30:33.626485939] 5.9% User Time [20081217-06:30:33.628863569] 130.0% System Time [20081217-06:30:33.631198065] 135.9% CPU Utilization [20081217-06:30:33.633351892] Profilers reporting [20081217-06:31:02.375707474] Profilers postprocessing [20081217-06:31:03.512585638] Stopping profiling. [20081217-06:31:03.517367523] Killing daemon. [20081217-06:31:05.897531185] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-12-17_06.25.12/analysis/oprofile.001 [20081217-06:31:05.899680310] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-12-17_06.25.12/analysis/oprofile-brief.001 [20081217-06:31:06.797910064] Processing File : mpstat.001 [20081217-06:31:06.800242416] Discovered mpstat_interval=[5] [20081217-06:31:07.660195682] Processing Directory : sar.breakout.001 [20081217-06:31:07.662481769] Discovered sar_interval=[5] [20081217-06:31:07.905597166] Processing File : iostat.001 [20081217-06:31:07.907721663] Discovered iostat_interval=[5] [20081217-06:31:10.276522052] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline' [20081217-06:31:15.222499633] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-06:31:16.748292054] PROCESSING COMMAND : 'mount -t jfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-06:31:16.838521214] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=1' [20081217-06:31:16.882876452] new log requested [20081217-06:31:16.910689727] Running command ffsb [20081217-06:31:26.273945686] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb [20081217-06:31:26.290416079] Importing argument : num_threads=1 [20081217-06:31:26.316640514] Found a jfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-06:31:26.411398763] Checking for sar... [20081217-06:31:26.413674757] found [20081217-06:31:26.470661762] Checking for sar... [20081217-06:31:26.473145030] found [20081217-06:31:26.529006157] Checking for sar... [20081217-06:31:26.531081736] found [20081217-06:31:26.691207702] Checking for binutils-2.18 ... Already installed. [20081217-06:31:26.695454389] mv: cannot stat `lib64/*': No such file or directory [20081217-06:31:26.708179186] rmdir: lib64: No such file or directory [20081217-06:31:26.773497071] Checking for gettext-0.17 ... Already installed. [20081217-06:31:26.814508188] popt32-1.10.4 already installed. [20081217-06:31:26.830313671] popt64-1.10.4 already installed. [20081217-06:31:26.860510528] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-06:31:26.913542738] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-06:31:26.993245274] Daemon not running [20081217-06:31:27.008309049] Unloading oprofile module [20081217-06:31:27.206858410] Daemon not running [20081217-06:31:28.588500783] OPROFILE : using callgraph [5] [20081217-06:31:28.821728601] Daemon not running [20081217-06:31:28.823800926] Separate options: none [20081217-06:31:28.825848948] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-06:31:28.828048195] Image filter: none [20081217-06:31:28.829854002] Call-graph depth: 5 [20081217-06:31:28.907425424] FFSB version 6.0-RC2 started [20081217-06:31:28.909658409] [20081217-06:31:28.911782581] benchmark time = 300 [20081217-06:31:28.913933021] ThreadGroup 0 [20081217-06:31:28.915828538] ================ [20081217-06:31:28.917663802] num_threads = 1 [20081217-06:31:28.919435470] [20081217-06:31:28.921241921] read_random = off [20081217-06:31:28.922979489] read_size = 0 (0B) [20081217-06:31:28.924764142] read_blocksize = 0 (0B) [20081217-06:31:28.926508958] read_skip = off [20081217-06:31:28.928243896] read_skipsize = 0 (0B) [20081217-06:31:28.930016176] [20081217-06:31:28.931810652] write_random = on [20081217-06:31:28.933528843] write_size = 5242880 (5MB) [20081217-06:31:28.935335418] fsync_file = 0 [20081217-06:31:28.937075555] write_blocksize = 4096 (4KB) [20081217-06:31:28.938919363] wait time = 0 [20081217-06:31:28.940672133] [20081217-06:31:28.942433729] op weights [20081217-06:31:28.944145960] read = 0 (0.00%) [20081217-06:31:28.945937746] readall = 0 (0.00%) [20081217-06:31:28.947679833] write = 1 (100.00%) [20081217-06:31:28.949454540] create = 0 (0.00%) [20081217-06:31:28.951191403] append = 0 (0.00%) [20081217-06:31:28.952984882] delete = 0 (0.00%) [20081217-06:31:28.954733897] metaop = 0 (0.00%) [20081217-06:31:28.956545672] createdir = 0 (0.00%) [20081217-06:31:28.958467391] stat = 0 (0.00%) [20081217-06:31:28.960557840] writeall = 0 (0.00%) [20081217-06:31:28.962459426] writeall_fsync = 0 (0.00%) [20081217-06:31:28.964753535] open_close = 0 (0.00%) [20081217-06:31:28.966837911] write_fsync = 0 (0.00%) [20081217-06:31:28.968668605] create_fsync = 0 (0.00%) [20081217-06:31:28.970405177] append_fsync = 0 (0.00%) [20081217-06:31:28.972237639] [20081217-06:31:28.974117981] FileSystem /mnt/ffsb1 [20081217-06:31:28.975882734] ========== [20081217-06:31:28.977748673] num_dirs = 0 [20081217-06:31:28.979526078] starting files = 1024 [20081217-06:31:28.981290141] [20081217-06:31:28.983047013] min file size = 104857600 (100MB) [20081217-06:31:28.985027289] max file size = 104857600 (100MB) [20081217-06:31:28.986843921] directio = on [20081217-06:31:28.988678853] alignedio = on [20081217-06:31:28.990422649] bufferedio = off [20081217-06:31:28.992258950] [20081217-06:31:28.994109365] aging is off [20081217-06:31:28.995858485] current utilization = 4.48% [20081217-06:31:28.997696388] [20081217-06:31:28.999483832] checking existing fs: /mnt/ffsb1 [20081217-06:31:29.038589119] fs setup took 0 secs [20081217-06:31:29.980620870] Syncing()...0 sec [20081217-06:31:29.982852335] Starting Actual Benchmark At: Wed Dec 17 06:31:29 2008 [20081217-06:31:29.996338140] [20081217-06:36:31.864381005] Syncing()...0 sec [20081217-06:36:31.867272477] FFSB benchmark finished at: Wed Dec 17 06:36:31 2008 [20081217-06:36:31.870076420] [20081217-06:36:31.872418798] Results: [20081217-06:36:31.886401835] Benchmark took 301.88 sec [20081217-06:36:31.889065807] [20081217-06:36:31.891416628] Total Results [20081217-06:36:31.907763617] =============== [20081217-06:36:31.912095743] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-06:36:31.914554043] ======= ============ ========= ======= =========== ========== [20081217-06:36:31.917061142] write : 938240 3107.96 100.000% 100.000% 243MB/sec [20081217-06:36:31.919909554] - [20081217-06:36:31.922606668] 3107.96 Transactions per Second [20081217-06:36:31.925534374] [20081217-06:36:31.928123848] Throughput Results [20081217-06:36:31.943783784] =================== [20081217-06:36:31.946244311] Write Throughput: 243MB/sec [20081217-06:36:31.948520233] [20081217-06:36:31.950691382] System Call Latency statistics in millisecs [20081217-06:36:31.952871607] ===== [20081217-06:36:31.955095594] Min Avg Max Total Calls [20081217-06:36:31.957830243] ======== ======== ======== ============ [20081217-06:36:31.960613686] [ open] 0.007000 0.014041 0.032000 733 [20081217-06:36:31.963026527] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:36:31.967256515] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:36:31.969938941] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:36:31.972421245] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:36:31.974670492] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:36:31.977351485] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:36:31.979628868] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:36:31.981952153] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:36:31.984360998] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:36:31.986937012] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:36:31.989704939] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:36:31.993558238] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:36:31.996437108] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:36:31.999139280] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:36:32.002037897] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:36:32.004745812] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:36:32.007239381] msec_range[16] 0.020000 - 0.050000 : 111 [20081217-06:36:32.009657045] msec_range[17] 0.010000 - 0.020000 : 511 [20081217-06:36:32.012087991] msec_range[18] 0.000000 - 0.010000 : 111 [20081217-06:36:32.014368857] [20081217-06:36:32.017336939] [ write] 0.183000 0.317582 259.726990 938240 [20081217-06:36:32.019857551] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:36:32.022802207] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:36:32.025799695] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:36:32.029234485] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:36:32.031721511] msec_range[4] 200.000000 - 500.000000 : 8 [20081217-06:36:32.033970018] msec_range[5] 100.000000 - 200.000000 : 372 [20081217-06:36:32.036271951] msec_range[6] 50.000000 - 100.000000 : 320 [20081217-06:36:32.038426872] msec_range[7] 20.000000 - 50.000000 : 291 [20081217-06:36:32.040731788] msec_range[8] 10.000000 - 20.000000 : 185 [20081217-06:36:32.043245790] msec_range[9] 5.000000 - 10.000000 : 98 [20081217-06:36:32.045838629] msec_range[10] 2.000000 - 5.000000 : 175 [20081217-06:36:32.048907214] msec_range[11] 1.000000 - 2.000000 : 2959 [20081217-06:36:32.051157625] msec_range[12] 0.500000 - 1.000000 : 1506 [20081217-06:36:32.053859993] msec_range[13] 0.200000 - 0.500000 : 880850 [20081217-06:36:32.056819238] msec_range[14] 0.100000 - 0.200000 : 51476 [20081217-06:36:32.059264929] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:36:32.061947903] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-06:36:32.064579164] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-06:36:32.067179732] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-06:36:32.069784109] [20081217-06:36:32.072007745] [ lseek] 0.000000 0.001345 0.302000 938240 [20081217-06:36:32.074848049] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:36:32.077514813] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:36:32.080024753] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:36:32.083108170] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:36:32.085805213] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:36:32.088215313] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:36:32.090984709] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:36:32.093949391] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:36:32.096972648] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:36:32.100116901] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:36:32.102749175] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:36:32.105817378] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:36:32.108241157] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:36:32.111008493] msec_range[13] 0.200000 - 0.500000 : 11 [20081217-06:36:32.113643042] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-06:36:32.116741000] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:36:32.119416196] msec_range[16] 0.020000 - 0.050000 : 4 [20081217-06:36:32.122187602] msec_range[17] 0.010000 - 0.020000 : 249 [20081217-06:36:32.125250904] msec_range[18] 0.000000 - 0.010000 : 937975 [20081217-06:36:32.128088363] [20081217-06:36:32.130603296] [ close] 0.003000 0.004711 0.013000 733 [20081217-06:36:32.133129700] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-06:36:32.135584214] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-06:36:32.137876524] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-06:36:32.140076624] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-06:36:32.142187759] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-06:36:32.144743260] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-06:36:32.147159374] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-06:36:32.150045174] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-06:36:32.152510958] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-06:36:32.155137126] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-06:36:32.157816119] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-06:36:32.160079122] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-06:36:32.162196278] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-06:36:32.164906013] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-06:36:32.167609397] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-06:36:32.170159090] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-06:36:32.172669044] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-06:36:32.175272231] msec_range[17] 0.010000 - 0.020000 : 11 [20081217-06:36:32.177810599] msec_range[18] 0.000000 - 0.010000 : 722 [20081217-06:36:32.180454572] [20081217-06:36:32.184089008] [20081217-06:36:32.186804357] [20081217-06:36:32.189321937] [20081217-06:36:32.191797361] 1.0% User Time [20081217-06:36:32.194119399] 9.5% System Time [20081217-06:36:32.196552726] 10.5% CPU Utilization [20081217-06:36:32.198892623] Profilers reporting [20081217-06:36:45.533272833] Profilers postprocessing [20081217-06:36:46.672301009] Stopping profiling. [20081217-06:36:46.676659106] Killing daemon. [20081217-06:36:47.845508776] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_06.31.16/analysis/oprofile.001 [20081217-06:36:47.847792358] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_06.31.16/analysis/oprofile-brief.001 [20081217-06:36:47.998116447] Processing File : mpstat.001 [20081217-06:36:48.000466153] Discovered mpstat_interval=[5] [20081217-06:36:48.544972681] Processing Directory : sar.breakout.001 [20081217-06:36:48.547260771] Discovered sar_interval=[5] [20081217-06:36:48.704363288] Processing File : iostat.001 [20081217-06:36:48.706655286] Discovered iostat_interval=[5] [20081217-06:36:50.057953554] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0531/jfs-baseline'