[20081217-03:00:00.982727817] PROCESSING COMMAND : 'clearprofilers' [20081217-03:00:01.236675276] PROCESSING COMMAND : 'useprofiler iostat 5' [20081217-03:00:01.343010277] Checking for sar... [20081217-03:00:01.345192357] found [20081217-03:00:01.480326692] PROCESSING COMMAND : 'useprofiler sar 5' [20081217-03:00:01.586394624] Checking for sar... [20081217-03:00:01.588563797] found [20081217-03:00:01.724570450] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081217-03:00:01.830974135] Checking for sar... [20081217-03:00:01.833314181] found [20081217-03:00:02.000243948] PROCESSING COMMAND : 'useprofiler oprofile' [20081217-03:00:02.281942028] Checking for binutils-2.18 ... Already installed. [20081217-03:00:02.286285771] mv: cannot stat `lib64/*': No such file or directory [20081217-03:00:02.308807885] rmdir: lib64: No such file or directory [20081217-03:00:02.398696062] Checking for gettext-0.17 ... Already installed. [20081217-03:00:02.450737378] popt32-1.10.4 already installed. [20081217-03:00:02.465432986] popt64-1.10.4 already installed. [20081217-03:00:02.496019491] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:00:02.548661651] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:00:02.628220629] Daemon not running [20081217-03:00:02.649618857] Unloading oprofile module [20081217-03:00:02.847460983] Daemon not running [20081217-03:00:05.074501285] OPROFILE : using callgraph [5] [20081217-03:00:05.304455353] Daemon not running [20081217-03:00:05.306766632] Separate options: none [20081217-03:00:05.308970964] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:00:05.311133949] Image filter: none [20081217-03:00:05.313191426] Call-graph depth: 5 [20081217-03:00:05.514914277] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081217-03:00:05.590617910] PROCESSING COMMAND : 'set-sched noop' [20081217-03:00:05.989802035] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2008-12-17_0300 xfs-baseline' [20081217-03:00:06.208858361] Connecting to hks.austin.ibm.com... [20081217-03:00:06.211047650] Remote working directory: /opt [20081217-03:00:06.212925479] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081217-03:00:06.214993931] Couldn't create directory: Failure [20081217-03:00:06.217303159] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-03:00:06.219372548] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-03:00:06.221319675] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300 [20081217-03:00:06.223088670] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300 [20081217-03:00:06.225052896] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline [20081217-03:00:06.297312136] PROCESSING COMMAND : 'mkfs.xfs -V 2>&1' [20081217-03:00:06.335800430] mkfs.xfs version 2.10.1 [20081217-03:00:06.431882543] PROCESSING COMMAND : 'mkfs.xfs -f /dev/ffsbdev1' [20081217-03:00:07.890083046] meta-data=/dev/ffsbdev1 isize=256 agcount=32, agsize=18327808 blks [20081217-03:00:07.893697409] = sectsz=512 attr=2 [20081217-03:00:07.895905686] data = bsize=4096 blocks=586489856, imaxpct=5 [20081217-03:00:07.898189621] = sunit=64 swidth=512 blks [20081217-03:00:07.900311794] naming =version 2 bsize=4096 ascii-ci=0 [20081217-03:00:07.902089156] log =internal log bsize=4096 blocks=32768, version=2 [20081217-03:00:07.904381775] = sectsz=512 sunit=64 blks, lazy-count=0 [20081217-03:00:07.906541310] realtime =none extsz=2097152 blocks=0, rtextents=0 [20081217-03:00:08.089100449] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:00:08.500794436] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=1' [20081217-03:00:08.545700161] new log requested [20081217-03:00:08.569936438] Running command ffsb [20081217-03:00:18.259185324] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-03:00:18.286090516] Importing argument : num_threads=1 [20081217-03:00:18.312534869] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:00:18.400775804] Checking for sar... [20081217-03:00:18.402845863] found [20081217-03:00:18.459583000] Checking for sar... [20081217-03:00:18.462035457] found [20081217-03:00:18.517478312] Checking for sar... [20081217-03:00:18.527222457] found [20081217-03:00:18.659724139] Checking for binutils-2.18 ... Already installed. [20081217-03:00:18.663876293] mv: cannot stat `lib64/*': No such file or directory [20081217-03:00:18.666844444] rmdir: lib64: No such file or directory [20081217-03:00:18.726288968] Checking for gettext-0.17 ... Already installed. [20081217-03:00:18.767605866] popt32-1.10.4 already installed. [20081217-03:00:18.783107923] popt64-1.10.4 already installed. [20081217-03:00:18.813774418] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:00:18.866170157] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:00:18.947637349] Daemon not running [20081217-03:00:18.958136117] Unloading oprofile module [20081217-03:00:19.086380913] Daemon not running [20081217-03:00:19.319983284] OPROFILE : using callgraph [5] [20081217-03:00:19.553178445] Daemon not running [20081217-03:00:19.555281326] Separate options: none [20081217-03:00:19.557335068] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:00:19.559583245] Image filter: none [20081217-03:00:19.561739894] Call-graph depth: 5 [20081217-03:00:19.641297487] FFSB version 6.0-RC2 started [20081217-03:00:19.643470970] [20081217-03:00:19.645641585] benchmark time = 300 [20081217-03:00:19.647642420] ThreadGroup 0 [20081217-03:00:19.649876757] ================ [20081217-03:00:19.652089571] num_threads = 1 [20081217-03:00:19.654123675] [20081217-03:00:19.655991208] read_random = off [20081217-03:00:19.657883992] read_size = 0 (0B) [20081217-03:00:19.659702127] read_blocksize = 4096 (4KB) [20081217-03:00:19.661759291] read_skip = off [20081217-03:00:19.663737164] read_skipsize = 0 (0B) [20081217-03:00:19.665523722] [20081217-03:00:19.667415885] write_random = off [20081217-03:00:19.669294246] write_size = 0 (0B) [20081217-03:00:19.671058742] fsync_file = 0 [20081217-03:00:19.672936142] write_blocksize = 0 (0B) [20081217-03:00:19.674783401] wait time = 0 [20081217-03:00:19.676530529] [20081217-03:00:19.678394928] op weights [20081217-03:00:19.680229961] read = 0 (0.00%) [20081217-03:00:19.681983163] readall = 1 (100.00%) [20081217-03:00:19.683850485] write = 0 (0.00%) [20081217-03:00:19.685828124] create = 0 (0.00%) [20081217-03:00:19.687794528] append = 0 (0.00%) [20081217-03:00:19.689651677] delete = 0 (0.00%) [20081217-03:00:19.691542890] metaop = 0 (0.00%) [20081217-03:00:19.693363719] createdir = 0 (0.00%) [20081217-03:00:19.695254375] stat = 0 (0.00%) [20081217-03:00:19.697101776] writeall = 0 (0.00%) [20081217-03:00:19.698862093] writeall_fsync = 0 (0.00%) [20081217-03:00:19.700717413] open_close = 0 (0.00%) [20081217-03:00:19.702589621] write_fsync = 0 (0.00%) [20081217-03:00:19.704342175] create_fsync = 0 (0.00%) [20081217-03:00:19.706190355] append_fsync = 0 (0.00%) [20081217-03:00:19.708020414] [20081217-03:00:19.709918983] FileSystem /mnt/ffsb1 [20081217-03:00:19.711792133] ========== [20081217-03:00:19.713587942] num_dirs = 0 [20081217-03:00:19.715481448] starting files = 1024 [20081217-03:00:19.717267776] [20081217-03:00:19.719110491] min file size = 104857600 (100MB) [20081217-03:00:19.720926305] max file size = 104857600 (100MB) [20081217-03:00:19.722760655] directio = off [20081217-03:00:19.724604350] alignedio = on [20081217-03:00:19.726467781] bufferedio = off [20081217-03:00:19.728213072] [20081217-03:00:19.729939751] aging is off [20081217-03:00:19.731624071] current utilization = 0.00% [20081217-03:00:19.733481081] [20081217-03:00:19.735317028] checking existing fs: /mnt/ffsb1 [20081217-03:00:19.737032172] opendir: No such file or directory [20081217-03:00:19.738888718] recreating new fileset [20081217-03:06:02.636310669] fs setup took 342 secs [20081217-03:06:03.224226910] Syncing()...0 sec [20081217-03:06:03.226694891] Starting Actual Benchmark At: Wed Dec 17 03:06:03 2008 [20081217-03:06:03.304368400] [20081217-03:11:04.943109948] Syncing()...0 sec [20081217-03:11:05.041988837] FFSB benchmark finished at: Wed Dec 17 03:11:04 2008 [20081217-03:11:05.044835268] [20081217-03:11:05.047682659] Results: [20081217-03:11:05.108918310] Benchmark took 301.50 sec [20081217-03:11:05.111721397] [20081217-03:11:05.114301869] Total Results [20081217-03:11:05.129759817] =============== [20081217-03:11:05.132006253] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:11:05.134453778] ======= ============ ========= ======= =========== ========== [20081217-03:11:05.136896178] readall : 11980800 39736.67 100.000% 100.000% 155MB/sec [20081217-03:11:05.139200003] - [20081217-03:11:05.141315049] 39736.67 Transactions per Second [20081217-03:11:05.143578576] [20081217-03:11:05.145817233] Throughput Results [20081217-03:11:05.162229006] =================== [20081217-03:11:05.164761855] Read Throughput: 155MB/sec [20081217-03:11:05.167254988] [20081217-03:11:05.169920705] System Call Latency statistics in millisecs [20081217-03:11:05.172118565] ===== [20081217-03:11:05.174648204] Min Avg Max Total Calls [20081217-03:11:05.177163825] ======== ======== ======== ============ [20081217-03:11:05.179646770] [ open] 0.017000 0.163154 9.812000 468 [20081217-03:11:05.182245943] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:11:05.184471148] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:11:05.186682512] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:11:05.188906073] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:11:05.191014841] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:11:05.193212039] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:11:05.195339393] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:11:05.197523932] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:11:05.199625269] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:11:05.201874355] msec_range[9] 5.000000 - 10.000000 : 5 [20081217-03:11:05.204407132] msec_range[10] 2.000000 - 5.000000 : 2 [20081217-03:11:05.206997442] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:11:05.209749351] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:11:05.212385070] msec_range[13] 0.200000 - 0.500000 : 2 [20081217-03:11:05.214841846] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-03:11:05.217476604] msec_range[15] 0.050000 - 0.100000 : 355 [20081217-03:11:05.220092813] msec_range[16] 0.020000 - 0.050000 : 100 [20081217-03:11:05.223241837] msec_range[17] 0.010000 - 0.020000 : 2 [20081217-03:11:05.225920870] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-03:11:05.228377712] [20081217-03:11:05.230956451] [ read] 0.004000 0.024784 312.401001 11980800 [20081217-03:11:05.233304160] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:11:05.235617181] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:11:05.237840646] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:11:05.240348270] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:11:05.243141879] msec_range[4] 200.000000 - 500.000000 : 76 [20081217-03:11:05.245516344] msec_range[5] 100.000000 - 200.000000 : 18 [20081217-03:11:05.248084843] msec_range[6] 50.000000 - 100.000000 : 6 [20081217-03:11:05.250469348] msec_range[7] 20.000000 - 50.000000 : 15 [20081217-03:11:05.252733793] msec_range[8] 10.000000 - 20.000000 : 597 [20081217-03:11:05.254876123] msec_range[9] 5.000000 - 10.000000 : 4395 [20081217-03:11:05.257116491] msec_range[10] 2.000000 - 5.000000 : 20785 [20081217-03:11:05.259239400] msec_range[11] 1.000000 - 2.000000 : 56906 [20081217-03:11:05.261405360] msec_range[12] 0.500000 - 1.000000 : 13119 [20081217-03:11:05.263527750] msec_range[13] 0.200000 - 0.500000 : 53838 [20081217-03:11:05.265799461] msec_range[14] 0.100000 - 0.200000 : 14917 [20081217-03:11:05.267973034] msec_range[15] 0.050000 - 0.100000 : 1366 [20081217-03:11:05.270170912] msec_range[16] 0.020000 - 0.050000 : 3446 [20081217-03:11:05.272243477] msec_range[17] 0.010000 - 0.020000 : 426053 [20081217-03:11:05.274467086] msec_range[18] 0.000000 - 0.010000 : 11385263 [20081217-03:11:05.276592018] [20081217-03:11:05.278868484] [ close] 0.007000 0.011731 0.022000 468 [20081217-03:11:05.281431137] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:11:05.283884508] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:11:05.286480474] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:11:05.288779335] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:11:05.290967200] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:11:05.293103511] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:11:05.295606783] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:11:05.297774859] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:11:05.299971130] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:11:05.302120917] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:11:05.304470887] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:11:05.306775158] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:11:05.309334461] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:11:05.311743707] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:11:05.314078646] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:11:05.316290317] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:11:05.318873237] msec_range[16] 0.020000 - 0.050000 : 6 [20081217-03:11:05.321265145] msec_range[17] 0.010000 - 0.020000 : 382 [20081217-03:11:05.323611970] msec_range[18] 0.000000 - 0.010000 : 80 [20081217-03:11:05.325910404] [20081217-03:11:05.327990256] [20081217-03:11:05.330810189] [20081217-03:11:05.333295134] [20081217-03:11:05.335515975] 2.6% User Time [20081217-03:11:05.337632694] 28.4% System Time [20081217-03:11:05.339837983] 31.0% CPU Utilization [20081217-03:11:05.342149655] Profilers reporting [20081217-03:11:25.001942035] Profilers postprocessing [20081217-03:11:26.139698111] Stopping profiling. [20081217-03:11:26.145156644] Killing daemon. [20081217-03:11:28.607502525] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_03.00.08/analysis/oprofile.001 [20081217-03:11:28.609701089] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_03.00.08/analysis/oprofile-brief.001 [20081217-03:11:28.814980330] Processing File : mpstat.001 [20081217-03:11:28.817058242] Discovered mpstat_interval=[5] [20081217-03:11:29.458161803] Processing Directory : sar.breakout.001 [20081217-03:11:29.460473546] Discovered sar_interval=[5] [20081217-03:11:29.676534828] Processing File : iostat.001 [20081217-03:11:29.678688270] Discovered iostat_interval=[5] [20081217-03:11:32.194036982] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:11:36.684326049] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:11:37.663641988] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:11:37.938912800] PROCESSING COMMAND : 'run sequential_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=16' [20081217-03:11:37.984299550] new log requested [20081217-03:11:38.008464441] Running command ffsb [20081217-03:11:46.989747799] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-03:11:47.014884946] Importing argument : num_threads=16 [20081217-03:11:47.041542143] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:11:47.137141693] Checking for sar... [20081217-03:11:47.139247731] found [20081217-03:11:47.195501320] Checking for sar... [20081217-03:11:47.197822659] found [20081217-03:11:47.253159492] Checking for sar... [20081217-03:11:47.255238867] found [20081217-03:11:47.416340304] Checking for binutils-2.18 ... Already installed. [20081217-03:11:47.420805658] mv: cannot stat `lib64/*': No such file or directory [20081217-03:11:47.427642086] rmdir: lib64: No such file or directory [20081217-03:11:47.498766125] Checking for gettext-0.17 ... Already installed. [20081217-03:11:47.545219310] popt32-1.10.4 already installed. [20081217-03:11:47.560858158] popt64-1.10.4 already installed. [20081217-03:11:47.591742905] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:11:47.644384962] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:11:47.725624609] Daemon not running [20081217-03:11:47.743773272] Unloading oprofile module [20081217-03:11:47.994133670] Daemon not running [20081217-03:11:48.907295566] OPROFILE : using callgraph [5] [20081217-03:11:49.141307461] Daemon not running [20081217-03:11:49.143302192] Separate options: none [20081217-03:11:49.145437672] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:11:49.147599137] Image filter: none [20081217-03:11:49.149471557] Call-graph depth: 5 [20081217-03:11:49.229339839] FFSB version 6.0-RC2 started [20081217-03:11:49.231654929] [20081217-03:11:49.286546675] benchmark time = 300 [20081217-03:11:49.288455768] ThreadGroup 0 [20081217-03:11:49.290305428] ================ [20081217-03:11:49.292009576] num_threads = 16 [20081217-03:11:49.294155425] [20081217-03:11:49.296036647] read_random = off [20081217-03:11:49.297972363] read_size = 0 (0B) [20081217-03:11:49.299728844] read_blocksize = 4096 (4KB) [20081217-03:11:49.301549183] read_skip = off [20081217-03:11:49.303303853] read_skipsize = 0 (0B) [20081217-03:11:49.305069819] [20081217-03:11:49.306827090] write_random = off [20081217-03:11:49.308619945] write_size = 0 (0B) [20081217-03:11:49.310358072] fsync_file = 0 [20081217-03:11:49.312184792] write_blocksize = 0 (0B) [20081217-03:11:49.313934471] wait time = 0 [20081217-03:11:49.315733683] [20081217-03:11:49.317818027] op weights [20081217-03:11:49.319662440] read = 0 (0.00%) [20081217-03:11:49.321498558] readall = 1 (100.00%) [20081217-03:11:49.323352891] write = 0 (0.00%) [20081217-03:11:49.325124338] create = 0 (0.00%) [20081217-03:11:49.327085509] append = 0 (0.00%) [20081217-03:11:49.329077686] delete = 0 (0.00%) [20081217-03:11:49.330821846] metaop = 0 (0.00%) [20081217-03:11:49.332679102] createdir = 0 (0.00%) [20081217-03:11:49.334546340] stat = 0 (0.00%) [20081217-03:11:49.336262290] writeall = 0 (0.00%) [20081217-03:11:49.338105918] writeall_fsync = 0 (0.00%) [20081217-03:11:49.339928004] open_close = 0 (0.00%) [20081217-03:11:49.341671496] write_fsync = 0 (0.00%) [20081217-03:11:49.343507855] create_fsync = 0 (0.00%) [20081217-03:11:49.345303038] append_fsync = 0 (0.00%) [20081217-03:11:49.347012047] [20081217-03:11:49.348866614] FileSystem /mnt/ffsb1 [20081217-03:11:49.351177486] ========== [20081217-03:11:49.353376600] num_dirs = 0 [20081217-03:11:49.355143392] starting files = 1024 [20081217-03:11:49.356951126] [20081217-03:11:49.358797571] min file size = 104857600 (100MB) [20081217-03:11:49.360542996] max file size = 104857600 (100MB) [20081217-03:11:49.362377184] directio = off [20081217-03:11:49.364177738] alignedio = on [20081217-03:11:49.365906072] bufferedio = off [20081217-03:11:49.367715110] [20081217-03:11:49.369587049] aging is off [20081217-03:11:49.371545222] current utilization = 4.47% [20081217-03:11:49.373297413] [20081217-03:11:49.375055342] checking existing fs: /mnt/ffsb1 [20081217-03:11:49.394302022] fs setup took 0 secs [20081217-03:11:49.918406997] Syncing()...0 sec [20081217-03:11:49.920227589] Starting Actual Benchmark At: Wed Dec 17 03:11:49 2008 [20081217-03:11:49.933252923] [20081217-03:16:53.525476701] Syncing()...1 sec [20081217-03:16:53.582526663] FFSB benchmark finished at: Wed Dec 17 03:16:53 2008 [20081217-03:16:53.585373290] [20081217-03:16:53.588020581] Results: [20081217-03:16:53.702967278] Benchmark took 303.31 sec [20081217-03:16:53.705176359] [20081217-03:16:53.707816797] Total Results [20081217-03:16:53.722887043] =============== [20081217-03:16:53.725420650] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:16:53.728309151] ======= ============ ========= ======= =========== ========== [20081217-03:16:53.730634604] readall : 50176000 165428.70 100.000% 100.000% 646MB/sec [20081217-03:16:53.732963559] - [20081217-03:16:53.735193252] 165428.70 Transactions per Second [20081217-03:16:53.737588102] [20081217-03:16:53.739966969] Throughput Results [20081217-03:16:53.755091239] =================== [20081217-03:16:53.757202121] Read Throughput: 646MB/sec [20081217-03:16:53.759559107] [20081217-03:16:53.761825058] System Call Latency statistics in millisecs [20081217-03:16:53.764314088] ===== [20081217-03:16:53.766947279] Min Avg Max Total Calls [20081217-03:16:53.769137983] ======== ======== ======== ============ [20081217-03:16:53.771421068] [ open] 0.007000 1.223164 44.543999 1960 [20081217-03:16:53.773604712] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:16:53.775921705] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:16:53.778380036] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:16:53.781937520] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:16:53.784224473] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:16:53.787058529] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:16:53.789952113] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:16:53.792256953] msec_range[7] 20.000000 - 50.000000 : 21 [20081217-03:16:53.794400126] msec_range[8] 10.000000 - 20.000000 : 104 [20081217-03:16:53.796624965] msec_range[9] 5.000000 - 10.000000 : 38 [20081217-03:16:53.798739667] msec_range[10] 2.000000 - 5.000000 : 6 [20081217-03:16:53.800907572] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:16:53.803066167] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:16:53.805249516] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-03:16:53.807305386] msec_range[14] 0.100000 - 0.200000 : 89 [20081217-03:16:53.809431536] msec_range[15] 0.050000 - 0.100000 : 1026 [20081217-03:16:53.811534074] msec_range[16] 0.020000 - 0.050000 : 637 [20081217-03:16:53.814609123] msec_range[17] 0.010000 - 0.020000 : 16 [20081217-03:16:53.817297297] msec_range[18] 0.000000 - 0.010000 : 19 [20081217-03:16:53.820722778] [20081217-03:16:53.823209783] [ read] 0.002000 0.095723 175.686996 50176000 [20081217-03:16:53.825787343] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:16:53.828393284] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:16:53.849646655] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:16:53.852150489] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:16:53.854647200] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:16:53.857139506] msec_range[5] 100.000000 - 200.000000 : 27 [20081217-03:16:53.859344961] msec_range[6] 50.000000 - 100.000000 : 166 [20081217-03:16:53.861615373] msec_range[7] 20.000000 - 50.000000 : 26603 [20081217-03:16:53.863765657] msec_range[8] 10.000000 - 20.000000 : 148785 [20081217-03:16:53.866019447] msec_range[9] 5.000000 - 10.000000 : 160538 [20081217-03:16:53.868106273] msec_range[10] 2.000000 - 5.000000 : 127113 [20081217-03:16:53.870320464] msec_range[11] 1.000000 - 2.000000 : 50074 [20081217-03:16:53.872443151] msec_range[12] 0.500000 - 1.000000 : 29943 [20081217-03:16:53.874617836] msec_range[13] 0.200000 - 0.500000 : 199109 [20081217-03:16:53.876706825] msec_range[14] 0.100000 - 0.200000 : 10382 [20081217-03:16:53.878883988] msec_range[15] 0.050000 - 0.100000 : 73835 [20081217-03:16:53.880991792] msec_range[16] 0.020000 - 0.050000 : 173201 [20081217-03:16:53.883194618] msec_range[17] 0.010000 - 0.020000 : 3787251 [20081217-03:16:53.885264336] msec_range[18] 0.000000 - 0.010000 : 45388973 [20081217-03:16:53.887438633] [20081217-03:16:53.889590782] [ close] 0.003000 0.011264 0.058000 1960 [20081217-03:16:53.891947880] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:16:53.894199057] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:16:53.896619397] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:16:53.899075379] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:16:53.901499174] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:16:53.903937880] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:16:53.907677352] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:16:53.910096548] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:16:53.912824706] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:16:53.915339564] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:16:53.917667328] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:16:53.919837000] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:16:53.922099886] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:16:53.924336590] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:16:53.926817870] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:16:53.929155974] msec_range[15] 0.050000 - 0.100000 : 2 [20081217-03:16:53.931513148] msec_range[16] 0.020000 - 0.050000 : 21 [20081217-03:16:53.933825880] msec_range[17] 0.010000 - 0.020000 : 1489 [20081217-03:16:53.935991091] msec_range[18] 0.000000 - 0.010000 : 448 [20081217-03:16:53.938854685] [20081217-03:16:53.942423801] [20081217-03:16:53.944672344] [20081217-03:16:53.946892820] [20081217-03:16:53.949248746] 13.1% User Time [20081217-03:16:53.951579528] 140.9% System Time [20081217-03:16:53.953683095] 154.0% CPU Utilization [20081217-03:16:53.955964229] Profilers reporting [20081217-03:17:17.022260380] Profilers postprocessing [20081217-03:17:18.160180089] Stopping profiling. [20081217-03:17:18.165605535] Killing daemon. [20081217-03:17:20.652108947] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_03.11.37/analysis/oprofile.001 [20081217-03:17:20.654301189] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_03.11.37/analysis/oprofile-brief.001 [20081217-03:17:20.871574769] Processing File : mpstat.001 [20081217-03:17:20.873762594] Discovered mpstat_interval=[5] [20081217-03:17:21.521919660] Processing Directory : sar.breakout.001 [20081217-03:17:21.524184675] Discovered sar_interval=[5] [20081217-03:17:21.870608139] Processing File : iostat.001 [20081217-03:17:21.872817987] Discovered iostat_interval=[5] [20081217-03:17:24.152040068] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:17:30.352351592] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:17:31.441700913] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:17:31.712012138] PROCESSING COMMAND : 'run sequential_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=128' [20081217-03:17:31.756671420] new log requested [20081217-03:17:31.780838653] Running command ffsb [20081217-03:17:41.267931029] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-03:17:41.284201223] Importing argument : num_threads=128 [20081217-03:17:41.309776914] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:17:41.405499570] Checking for sar... [20081217-03:17:41.407738392] found [20081217-03:17:41.463588683] Checking for sar... [20081217-03:17:41.465730624] found [20081217-03:17:41.521457181] Checking for sar... [20081217-03:17:41.523546603] found [20081217-03:17:41.685460542] Checking for binutils-2.18 ... Already installed. [20081217-03:17:41.689873460] mv: cannot stat `lib64/*': No such file or directory [20081217-03:17:41.767405257] rmdir: lib64: No such file or directory [20081217-03:17:41.857362157] Checking for gettext-0.17 ... Already installed. [20081217-03:17:41.903751999] popt32-1.10.4 already installed. [20081217-03:17:41.918620674] popt64-1.10.4 already installed. [20081217-03:17:41.949799814] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:17:42.001936378] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:17:42.083809564] Daemon not running [20081217-03:17:42.101612364] Unloading oprofile module [20081217-03:17:42.334780676] Daemon not running [20081217-03:17:43.397511848] OPROFILE : using callgraph [5] [20081217-03:17:43.629915189] Daemon not running [20081217-03:17:43.632092491] Separate options: none [20081217-03:17:43.634103611] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:17:43.636296058] Image filter: none [20081217-03:17:43.638340592] Call-graph depth: 5 [20081217-03:17:43.711786532] FFSB version 6.0-RC2 started [20081217-03:17:43.713716921] [20081217-03:17:44.204176093] benchmark time = 300 [20081217-03:17:44.206347008] ThreadGroup 0 [20081217-03:17:44.208480605] ================ [20081217-03:17:44.210780932] num_threads = 128 [20081217-03:17:44.212889023] [20081217-03:17:44.214769355] read_random = off [20081217-03:17:44.216645959] read_size = 0 (0B) [20081217-03:17:44.218411517] read_blocksize = 4096 (4KB) [20081217-03:17:44.220296920] read_skip = off [20081217-03:17:44.222159014] read_skipsize = 0 (0B) [20081217-03:17:44.224014011] [20081217-03:17:44.225726338] write_random = off [20081217-03:17:44.227579302] write_size = 0 (0B) [20081217-03:17:44.229389800] fsync_file = 0 [20081217-03:17:44.231128659] write_blocksize = 0 (0B) [20081217-03:17:44.232953438] wait time = 0 [20081217-03:17:44.234768265] [20081217-03:17:44.236504854] op weights [20081217-03:17:44.238315141] read = 0 (0.00%) [20081217-03:17:44.240139722] readall = 1 (100.00%) [20081217-03:17:44.241856174] write = 0 (0.00%) [20081217-03:17:44.243686407] create = 0 (0.00%) [20081217-03:17:44.245486640] append = 0 (0.00%) [20081217-03:17:44.247199731] delete = 0 (0.00%) [20081217-03:17:44.249026728] metaop = 0 (0.00%) [20081217-03:17:44.250820666] createdir = 0 (0.00%) [20081217-03:17:44.252554822] stat = 0 (0.00%) [20081217-03:17:44.254377990] writeall = 0 (0.00%) [20081217-03:17:44.256226760] writeall_fsync = 0 (0.00%) [20081217-03:17:44.257964533] open_close = 0 (0.00%) [20081217-03:17:44.259840633] write_fsync = 0 (0.00%) [20081217-03:17:44.261663456] create_fsync = 0 (0.00%) [20081217-03:17:44.263389638] append_fsync = 0 (0.00%) [20081217-03:17:44.265247761] [20081217-03:17:44.267077309] FileSystem /mnt/ffsb1 [20081217-03:17:44.268910365] ========== [20081217-03:17:44.270603459] num_dirs = 0 [20081217-03:17:44.272478654] starting files = 1024 [20081217-03:17:44.274314924] [20081217-03:17:44.276064044] min file size = 104857600 (100MB) [20081217-03:17:44.277897158] max file size = 104857600 (100MB) [20081217-03:17:44.279686657] directio = off [20081217-03:17:44.281452053] alignedio = on [20081217-03:17:44.283280671] bufferedio = off [20081217-03:17:44.285095602] [20081217-03:17:44.286927229] aging is off [20081217-03:17:44.288666564] current utilization = 4.47% [20081217-03:17:44.290518338] [20081217-03:17:44.292350175] checking existing fs: /mnt/ffsb1 [20081217-03:17:44.312785518] fs setup took 0 secs [20081217-03:17:44.894462934] Syncing()...0 sec [20081217-03:17:44.901032965] Starting Actual Benchmark At: Wed Dec 17 03:17:44 2008 [20081217-03:17:44.914506040] [20081217-03:22:53.274134278] Syncing()...1 sec [20081217-03:22:53.324826432] FFSB benchmark finished at: Wed Dec 17 03:22:52 2008 [20081217-03:22:53.327676123] [20081217-03:22:53.330348809] Results: [20081217-03:22:53.379741304] Benchmark took 308.08 sec [20081217-03:22:53.382209502] [20081217-03:22:53.384946600] Total Results [20081217-03:22:53.399791487] =============== [20081217-03:22:53.401788515] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:22:53.404197039] ======= ============ ========= ======= =========== ========== [20081217-03:22:53.406612349] readall : 52454400 170262.53 100.000% 100.000% 665MB/sec [20081217-03:22:53.408750576] - [20081217-03:22:53.411242525] 170262.53 Transactions per Second [20081217-03:22:53.413601030] [20081217-03:22:53.415917555] Throughput Results [20081217-03:22:53.430784018] =================== [20081217-03:22:53.432889220] Read Throughput: 665MB/sec [20081217-03:22:53.435361284] [20081217-03:22:53.437623985] System Call Latency statistics in millisecs [20081217-03:22:53.439740245] ===== [20081217-03:22:53.442315053] Min Avg Max Total Calls [20081217-03:22:53.444674462] ======== ======== ======== ============ [20081217-03:22:53.446951935] [ open] 0.006000 73.854661 1147.068970 2049 [20081217-03:22:53.449062122] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:22:53.451331876] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:22:53.453501289] msec_range[2] 1000.000000 - 2000.000000 : 4 [20081217-03:22:53.455681772] msec_range[3] 500.000000 - 1000.000000 : 81 [20081217-03:22:53.457722859] msec_range[4] 200.000000 - 500.000000 : 199 [20081217-03:22:53.460406082] msec_range[5] 100.000000 - 200.000000 : 113 [20081217-03:22:53.463215958] msec_range[6] 50.000000 - 100.000000 : 72 [20081217-03:22:53.465393120] msec_range[7] 20.000000 - 50.000000 : 86 [20081217-03:22:53.467468447] msec_range[8] 10.000000 - 20.000000 : 60 [20081217-03:22:53.469687394] msec_range[9] 5.000000 - 10.000000 : 19 [20081217-03:22:53.471965573] msec_range[10] 2.000000 - 5.000000 : 7 [20081217-03:22:53.474468159] msec_range[11] 1.000000 - 2.000000 : 3 [20081217-03:22:53.476520193] msec_range[12] 0.500000 - 1.000000 : 3 [20081217-03:22:53.478813703] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-03:22:53.480980921] msec_range[14] 0.100000 - 0.200000 : 112 [20081217-03:22:53.483043771] msec_range[15] 0.050000 - 0.100000 : 432 [20081217-03:22:53.485051803] msec_range[16] 0.020000 - 0.050000 : 678 [20081217-03:22:53.487294161] msec_range[17] 0.010000 - 0.020000 : 115 [20081217-03:22:53.489475707] msec_range[18] 0.000000 - 0.010000 : 60 [20081217-03:22:53.491593671] [20081217-03:22:53.493627246] [ read] 0.002000 0.740256 452.691010 52454400 [20081217-03:22:53.495849150] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:22:53.497960806] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:22:53.499966511] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:22:53.501956367] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:22:53.504141742] msec_range[4] 200.000000 - 500.000000 : 21283 [20081217-03:22:53.506226263] msec_range[5] 100.000000 - 200.000000 : 135787 [20081217-03:22:53.508182117] msec_range[6] 50.000000 - 100.000000 : 128247 [20081217-03:22:53.510168024] msec_range[7] 20.000000 - 50.000000 : 118175 [20081217-03:22:53.512377464] msec_range[8] 10.000000 - 20.000000 : 41332 [20081217-03:22:53.514451131] msec_range[9] 5.000000 - 10.000000 : 20696 [20081217-03:22:53.516390959] msec_range[10] 2.000000 - 5.000000 : 13289 [20081217-03:22:53.518349765] msec_range[11] 1.000000 - 2.000000 : 5503 [20081217-03:22:53.520669843] msec_range[12] 0.500000 - 1.000000 : 17604 [20081217-03:22:53.522955838] msec_range[13] 0.200000 - 0.500000 : 193074 [20081217-03:22:53.525079682] msec_range[14] 0.100000 - 0.200000 : 22639 [20081217-03:22:53.527404372] msec_range[15] 0.050000 - 0.100000 : 110714 [20081217-03:22:53.529550848] msec_range[16] 0.020000 - 0.050000 : 212188 [20081217-03:22:53.531560502] msec_range[17] 0.010000 - 0.020000 : 5297710 [20081217-03:22:53.533561954] msec_range[18] 0.000000 - 0.010000 : 46116159 [20081217-03:22:53.535779560] [20081217-03:22:53.537867396] [ close] 0.003000 0.011871 1.838000 2049 [20081217-03:22:53.539859232] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:22:53.541830812] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:22:53.544030338] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:22:53.546115006] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:22:53.548102829] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:22:53.550207791] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:22:53.552620491] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:22:53.556432243] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:22:53.558978431] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:22:53.561638677] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:22:53.564022684] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:22:53.566621172] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:22:53.570192383] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:22:53.574295593] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:22:53.576906777] msec_range[14] 0.100000 - 0.200000 : 2 [20081217-03:22:53.579301412] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-03:22:53.581606737] msec_range[16] 0.020000 - 0.050000 : 46 [20081217-03:22:53.583951353] msec_range[17] 0.010000 - 0.020000 : 1261 [20081217-03:22:53.586402845] msec_range[18] 0.000000 - 0.010000 : 738 [20081217-03:22:53.588607998] [20081217-03:22:53.590660095] [20081217-03:22:53.592704428] [20081217-03:22:53.594935304] [20081217-03:22:53.597012489] 14.2% User Time [20081217-03:22:53.599074643] 150.0% System Time [20081217-03:22:53.601037361] 164.3% CPU Utilization [20081217-03:22:53.664217779] Profilers reporting [20081217-03:23:27.967299816] Profilers postprocessing [20081217-03:23:29.104329847] Stopping profiling. [20081217-03:23:29.108554966] Killing daemon. [20081217-03:23:31.517963797] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_03.17.31/analysis/oprofile.001 [20081217-03:23:31.520132449] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_03.17.31/analysis/oprofile-brief.001 [20081217-03:23:31.703089482] Processing File : mpstat.001 [20081217-03:23:31.705318352] Discovered mpstat_interval=[5] [20081217-03:23:32.813344640] Processing Directory : sar.breakout.001 [20081217-03:23:32.815544224] Discovered sar_interval=[5] [20081217-03:23:33.136099914] Processing File : iostat.001 [20081217-03:23:33.138274932] Discovered iostat_interval=[5] [20081217-03:23:40.145284657] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:23:44.306460882] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:23:45.455436688] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:23:45.729185180] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=1' [20081217-03:23:45.774050062] new log requested [20081217-03:23:45.798467544] Running command ffsb [20081217-03:23:55.182921858] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-03:23:55.203007956] Importing argument : num_threads=1 [20081217-03:23:55.228479649] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:23:55.327328440] Checking for sar... [20081217-03:23:55.329495114] found [20081217-03:23:55.385501727] Checking for sar... [20081217-03:23:55.387632537] found [20081217-03:23:55.443849550] Checking for sar... [20081217-03:23:55.446282122] found [20081217-03:23:55.606987412] Checking for binutils-2.18 ... Already installed. [20081217-03:23:55.611273775] mv: cannot stat `lib64/*': No such file or directory [20081217-03:23:55.624050093] rmdir: lib64: No such file or directory [20081217-03:23:55.695199207] Checking for gettext-0.17 ... Already installed. [20081217-03:23:55.753668327] popt32-1.10.4 already installed. [20081217-03:23:55.800602654] popt64-1.10.4 already installed. [20081217-03:23:55.831482788] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:23:55.884133313] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:23:55.964141179] Daemon not running [20081217-03:23:55.981479706] Unloading oprofile module [20081217-03:23:56.191691972] Daemon not running [20081217-03:23:57.772313969] OPROFILE : using callgraph [5] [20081217-03:23:58.006735749] Daemon not running [20081217-03:23:58.008858822] Separate options: none [20081217-03:23:58.010881771] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:23:58.013045251] Image filter: none [20081217-03:23:58.014871151] Call-graph depth: 5 [20081217-03:23:58.094605709] FFSB version 6.0-RC2 started [20081217-03:23:58.096891092] [20081217-03:23:58.098675784] benchmark time = 300 [20081217-03:23:58.100770161] ThreadGroup 0 [20081217-03:23:58.102607166] ================ [20081217-03:23:58.104430386] num_threads = 1 [20081217-03:23:58.106448960] [20081217-03:23:58.108439109] read_random = on [20081217-03:23:58.110626484] read_size = 5242880 (5MB) [20081217-03:23:58.112639624] read_blocksize = 4096 (4KB) [20081217-03:23:58.114556526] read_skip = off [20081217-03:23:58.116292867] read_skipsize = 0 (0B) [20081217-03:23:58.118168312] [20081217-03:23:58.119970663] write_random = off [20081217-03:23:58.121815828] write_size = 0 (0B) [20081217-03:23:58.123534606] fsync_file = 0 [20081217-03:23:58.125338499] write_blocksize = 0 (0B) [20081217-03:23:58.127197090] wait time = 0 [20081217-03:23:58.128924320] [20081217-03:23:58.130765721] op weights [20081217-03:23:58.132590630] read = 1 (100.00%) [20081217-03:23:58.134462902] readall = 0 (0.00%) [20081217-03:23:58.136474915] write = 0 (0.00%) [20081217-03:23:58.138276315] create = 0 (0.00%) [20081217-03:23:58.140103626] append = 0 (0.00%) [20081217-03:23:58.141850696] delete = 0 (0.00%) [20081217-03:23:58.143716852] metaop = 0 (0.00%) [20081217-03:23:58.145521135] createdir = 0 (0.00%) [20081217-03:23:58.147216561] stat = 0 (0.00%) [20081217-03:23:58.149112199] writeall = 0 (0.00%) [20081217-03:23:58.150921408] writeall_fsync = 0 (0.00%) [20081217-03:23:58.152821716] open_close = 0 (0.00%) [20081217-03:23:58.154733418] write_fsync = 0 (0.00%) [20081217-03:23:58.156533823] create_fsync = 0 (0.00%) [20081217-03:23:58.158304049] append_fsync = 0 (0.00%) [20081217-03:23:58.160092819] [20081217-03:23:58.161961454] FileSystem /mnt/ffsb1 [20081217-03:23:58.163765119] ========== [20081217-03:23:58.165479591] num_dirs = 0 [20081217-03:23:58.167324105] starting files = 1024 [20081217-03:23:58.169108974] [20081217-03:23:58.170966062] min file size = 104857600 (100MB) [20081217-03:23:58.172892447] max file size = 104857600 (100MB) [20081217-03:23:58.174698097] directio = off [20081217-03:23:58.176516322] alignedio = on [20081217-03:23:58.178222163] bufferedio = off [20081217-03:23:58.180104071] [20081217-03:23:58.181900237] aging is off [20081217-03:23:58.183646610] current utilization = 4.47% [20081217-03:23:58.185471715] [20081217-03:23:58.187259737] checking existing fs: /mnt/ffsb1 [20081217-03:23:58.198006704] fs setup took 0 secs [20081217-03:23:59.129248835] Syncing()...0 sec [20081217-03:23:59.131093000] Starting Actual Benchmark At: Wed Dec 17 03:23:59 2008 [20081217-03:23:59.144395380] [20081217-03:29:01.136443886] Syncing()...0 sec [20081217-03:29:01.139433228] FFSB benchmark finished at: Wed Dec 17 03:29:01 2008 [20081217-03:29:01.142224126] [20081217-03:29:01.145055172] Results: [20081217-03:29:01.160353611] Benchmark took 302.01 sec [20081217-03:29:01.162758181] [20081217-03:29:01.165063195] Total Results [20081217-03:29:01.180538318] =============== [20081217-03:29:01.184637568] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:29:01.187243202] ======= ============ ========= ======= =========== ========== [20081217-03:29:01.189796790] read : 162560 538.27 100.000% 100.000% 2.1MB/sec [20081217-03:29:01.192697051] - [20081217-03:29:01.196003175] 538.27 Transactions per Second [20081217-03:29:01.199420123] [20081217-03:29:01.202787421] Throughput Results [20081217-03:29:01.219448992] =================== [20081217-03:29:01.222146102] Read Throughput: 2.1MB/sec [20081217-03:29:01.224590093] [20081217-03:29:01.227301877] System Call Latency statistics in millisecs [20081217-03:29:01.231190274] ===== [20081217-03:29:01.233905784] Min Avg Max Total Calls [20081217-03:29:01.236849509] ======== ======== ======== ============ [20081217-03:29:01.240318619] [ open] 0.013000 0.023276 0.282000 127 [20081217-03:29:01.243072052] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.246142012] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.248731319] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.251334409] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.253662742] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.256334876] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.260859052] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.264367818] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:29:01.267257721] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:29:01.270255491] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:29:01.273442035] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:29:01.276102902] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:29:01.278636806] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:29:01.281125536] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-03:29:01.283561596] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:29:01.286074430] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:29:01.288641680] msec_range[16] 0.020000 - 0.050000 : 71 [20081217-03:29:01.291266227] msec_range[17] 0.010000 - 0.020000 : 55 [20081217-03:29:01.293644468] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-03:29:01.296314548] [20081217-03:29:01.299504911] [ read] 0.002000 1.850123 29.485001 162560 [20081217-03:29:01.302229346] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.305445435] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.308491712] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.311194087] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.313808685] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.316238382] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.318884680] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.325891058] msec_range[7] 20.000000 - 50.000000 : 73 [20081217-03:29:01.329033761] msec_range[8] 10.000000 - 20.000000 : 583 [20081217-03:29:01.332443118] msec_range[9] 5.000000 - 10.000000 : 20692 [20081217-03:29:01.335352569] msec_range[10] 2.000000 - 5.000000 : 27665 [20081217-03:29:01.338654090] msec_range[11] 1.000000 - 2.000000 : 7042 [20081217-03:29:01.341427723] msec_range[12] 0.500000 - 1.000000 : 480 [20081217-03:29:01.344496754] msec_range[13] 0.200000 - 0.500000 : 99428 [20081217-03:29:01.347120254] msec_range[14] 0.100000 - 0.200000 : 775 [20081217-03:29:01.349359160] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:29:01.351881439] msec_range[16] 0.020000 - 0.050000 : 12 [20081217-03:29:01.354635180] msec_range[17] 0.010000 - 0.020000 : 910 [20081217-03:29:01.356956936] msec_range[18] 0.000000 - 0.010000 : 4900 [20081217-03:29:01.359387729] [20081217-03:29:01.363037003] [ lseek] 0.000000 0.001314 0.060000 162560 [20081217-03:29:01.365794545] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.368400790] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.372300500] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.374637751] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.377068948] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.379302237] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.382024086] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.384621000] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:29:01.387350190] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:29:01.389966015] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:29:01.392357286] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:29:01.394924286] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:29:01.397105923] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:29:01.399439936] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:29:01.402277993] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:29:01.404985528] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-03:29:01.407745930] msec_range[16] 0.020000 - 0.050000 : 3 [20081217-03:29:01.410257232] msec_range[17] 0.010000 - 0.020000 : 85 [20081217-03:29:01.412590526] msec_range[18] 0.000000 - 0.010000 : 162471 [20081217-03:29:01.415133792] [20081217-03:29:01.417715244] [ close] 0.005000 0.008165 0.016000 127 [20081217-03:29:01.420638851] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.423239224] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.425866793] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.429120794] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.431638500] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.434327318] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.436994129] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.439400148] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:29:01.441813286] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:29:01.444370579] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:29:01.446984612] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:29:01.454236781] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:29:01.456533844] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:29:01.459023221] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:29:01.461469513] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:29:01.464095952] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:29:01.466471322] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-03:29:01.468932598] msec_range[17] 0.010000 - 0.020000 : 30 [20081217-03:29:01.471460471] msec_range[18] 0.000000 - 0.010000 : 97 [20081217-03:29:01.474511455] [20081217-03:29:01.477061241] [20081217-03:29:01.479210974] [20081217-03:29:01.481407506] [20081217-03:29:01.483598098] 0.2% User Time [20081217-03:29:01.485685484] 2.0% System Time [20081217-03:29:01.487871219] 2.2% CPU Utilization [20081217-03:29:01.490043189] Profilers reporting [20081217-03:29:15.343149536] Profilers postprocessing [20081217-03:29:16.479971587] Stopping profiling. [20081217-03:29:16.484364045] Killing daemon. [20081217-03:29:17.659795479] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_03.23.45/analysis/oprofile.001 [20081217-03:29:17.661956471] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_03.23.45/analysis/oprofile-brief.001 [20081217-03:29:17.777705109] Processing File : mpstat.001 [20081217-03:29:17.779646349] Discovered mpstat_interval=[5] [20081217-03:29:18.322523841] Processing Directory : sar.breakout.001 [20081217-03:29:18.324967163] Discovered sar_interval=[5] [20081217-03:29:18.484277461] Processing File : iostat.001 [20081217-03:29:18.486629378] Discovered iostat_interval=[5] [20081217-03:29:20.109375502] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline'