[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'