[20090122-22:38:20.399810747] PROCESSING COMMAND : 'clearprofilers' [20090122-22:38:20.667817773] PROCESSING COMMAND : 'useprofiler iostat 5' [20090122-22:38:20.773580317] Checking for sar... [20090122-22:38:20.775722413] found [20090122-22:38:20.918316416] PROCESSING COMMAND : 'useprofiler sar 5' [20090122-22:38:21.025213936] Checking for sar... [20090122-22:38:21.027606992] found [20090122-22:38:21.170547676] PROCESSING COMMAND : 'useprofiler mpstat 5' [20090122-22:38:21.276060084] Checking for sar... [20090122-22:38:21.278114390] found [20090122-22:38:21.451081646] PROCESSING COMMAND : 'useprofiler oprofile' [20090122-22:38:21.680894677] Checking for binutils-2.18 ... [20090122-22:38:21.695726053] Already installed. [20090122-22:38:21.752193338] Checking for oprofile-0.9.4-autobench ... [20090122-22:38:21.766275753] Already installed. [20090122-22:38:21.858406482] opcontrol: oprofile 0.9.4 compiled on Nov 19 2008 09:09:21 [20090122-22:38:22.043089007] Daemon not running [20090122-22:38:24.086443962] OPROFILE : using callgraph [5] [20090122-22:38:24.308812367] Daemon not running [20090122-22:38:24.311080091] Separate options: none [20090122-22:38:24.313288029] vmlinux file: /boot/vmlinux-2.6.29-rc2 [20090122-22:38:24.317061927] Image filter: none [20090122-22:38:24.319202609] Call-graph depth: 5 [20090122-22:38:24.530037519] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20090122-22:38:24.606276170] PROCESSING COMMAND : 'set-sched noop' [20090122-22:38:25.016289667] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2009-01-22_2238 ext3-baseline' [20090122-22:38:25.251452519] Connecting to hks.austin.ibm.com... [20090122-22:38:25.253793729] Remote working directory: /opt [20090122-22:38:25.256104893] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20090122-22:38:25.258157277] Couldn't create directory: Failure [20090122-22:38:25.260418631] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20090122-22:38:25.262588223] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20090122-22:38:25.264570750] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238 [20090122-22:38:25.266508611] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238 [20090122-22:38:25.268452722] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline [20090122-22:38:25.341581052] PROCESSING COMMAND : 'mkfs.ext3 -V 2>&1' [20090122-22:38:25.391852762] mke2fs 1.41.2 (02-Oct-2008) [20090122-22:38:25.394172921] Using EXT2FS Library version 1.41.2 [20090122-22:38:25.491460188] PROCESSING COMMAND : 'mkfs.ext3 -F /dev/ffsbdev1' [20090122-22:38:25.511416391] mke2fs 1.41.2 (02-Oct-2008) [20090122-22:38:25.530870559] Filesystem label= [20090122-22:38:25.532768651] OS type: Linux [20090122-22:38:25.535101325] Block size=4096 (log=2) [20090122-22:38:25.537232648] Fragment size=4096 (log=2) [20090122-22:38:25.539496753] 4481024 inodes, 17921750 blocks [20090122-22:38:25.541677407] 896087 blocks (5.00%) reserved for the super user [20090122-22:38:25.543668779] First data block=0 [20090122-22:38:25.545465212] Maximum filesystem blocks=4294967296 [20090122-22:38:25.547402818] 547 block groups [20090122-22:38:25.549329092] 32768 blocks per group, 32768 fragments per group [20090122-22:38:25.551131424] 8192 inodes per group [20090122-22:38:25.553032106] Superblock backups stored on blocks: [20090122-22:38:25.554859485] 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208, [20090122-22:38:25.556728701] 4096000, 7962624, 11239424 [20090122-22:38:25.558463665] [20090122-22:38:37.438372507] Writing inode tables: 0/547 1/547 2/547 3/547 4/547 5/547 6/547 7/547 8/547 9/547 10/547 11/547 12/547 13/547 14/547 15/547 16/547 17/547 18/547 19/547 20/547 21/547 22/547 23/547 24/547 25/547 26/547 27/547 28/547 29/547 30/547 31/547 32/547 33/547 34/547 35/547 36/547 37/547 38/547 39/547 40/547 41/547 42/547 43/547 44/547 45/547 46/547 47/547 48/547 49/547 50/547 51/547 52/547 53/547 54/547 55/547 56/547 57/547 58/547 59/547 60/547 61/547 62/547 63/547 64/547 65/547 66/547 67/547 68/547 69/547 70/547 71/547 72/547 73/547 74/547 75/547 76/547 77/547 78/547 79/547 80/547 81/547 82/547 83/547 84/547 85/547 86/547 87/547 88/547 89/547 90/547 91/547 92/547 93/547 94/547 95/547 96/547 97/547 98/547 99/547100/547101/547102/547103/547104/547105/547106/547107/547108/547109/547110/547111/547112/547113/547114/547115/547116/547117/547118/547119/547120/547121/547122/547123/547124/547125/547126/547127/547128/547129/547130/547131/547132/547133/547134/547135/547136/547137/547138/547139/547140/547141/547142/547143/547144/547145/547146/547147/547148/547149/547150/547151/547152/547153/547154/547155/547156/547157/547158/547159/547160/547161/547162/547163/547164/547165/547166/547167/547168/547169/547170/547171/547172/547173/547174/547175/547176/547177/547178/547179/547180/547181/547182/547183/547184/547185/547186/547187/547188/547189/547190/547191/547192/547193/547194/547195/547196/547197/547198/547199/547200/547201/547202/547203/547204/547205/547206/547207/547208/547209/547210/547211/547212/547213/547214/547215/547216/547217/547218/547219/547220/547221/547222/547223/547224/547225/547226/547227/547228/547229/547230/547231/547232/547233/547234/547235/547236/547237/547238/547239/547240/547241/547242/547243/547244/547245/547246/547247/547248/547249/547250/547251/547252/547253/547254/547255/547256/547257/547258/547259/547260/547261/547262/547263/547264/547265/547266/547267/547268/547269/547270/547271/547272/547273/547274/547275/547276/547277/547278/547279/547280/547281/547282/547283/547284/547285/547286/547287/547288/547289/547290/547291/547292/547293/547294/547295/547296/547297/547298/547299/547300/547301/547302/547303/547304/547305/547306/547307/547308/547309/547310/547311/547312/547313/547314/547315/547316/547317/547318/547319/547320/547321/547322/547323/547324/547325/547326/547327/547328/547329/547330/547331/547332/547333/547334/547335/547336/547337/547338/547339/547340/547341/547342/547343/547344/547345/547346/547347/547348/547349/547350/547351/547352/547353/547354/547355/547356/547357/547358/547359/547360/547361/547362/547363/547364/547365/547366/547367/547368/547369/547370/547371/547372/547373/547374/547375/547376/547377/547378/547379/547380/547381/547382/547383/547384/547385/547386/547387/547388/547389/547390/547391/547392/547393/547394/547395/547396/547397/547398/547399/547400/547401/547402/547403/547404/547405/547406/547407/547408/547409/547410/547411/547412/547413/547414/547415/547416/547417/547418/547419/547420/547421/547422/547423/547424/547425/547426/547427/547428/547429/547430/547431/547432/547433/547434/547435/547436/547437/547438/547439/547440/547441/547442/547443/547444/547445/547446/547447/547448/547449/547450/547451/547452/547453/547454/547455/547456/547457/547458/547459/547460/547461/547462/547463/547464/547465/547466/547467/547468/547469/547470/547471/547472/547473/547474/547475/547476/547477/547478/547479/547480/547481/547482/547483/547484/547485/547486/547487/547488/547489/547490/547491/547492/547493/547494/547495/547496/547497/547498/547499/547500/547501/547502/547503/547504/547505/547506/547507/547508/547509/547510/547511/547512/547513/547514/547515/547516/547517/547518/547519/547520/547521/547522/547523/547524/547525/547526/547527/547528/547529/547530/547531/547532/547533/547534/547535/547536/547537/547538/547539/547540/547541/547542/547543/547544/547545/547546/547done [20090122-22:38:39.059954227] Creating journal (32768 blocks): done [20090122-22:38:42.875246567] Writing superblocks and filesystem accounting information: done [20090122-22:38:42.877387582] [20090122-22:38:42.879591448] This filesystem will be automatically checked every 26 mounts or [20090122-22:38:42.881898761] 180 days, whichever comes first. Use tune2fs -c or -i to override. [20090122-22:38:43.499929996] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20090122-22:38:43.635296736] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20090122-22:38:43.697161452] new log requested [20090122-22:38:43.732609418] Running command ffsb [20090122-22:38:51.088061166] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20090122-22:38:51.107453234] Importing argument : num_threads=1 [20090122-22:38:51.134176395] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090122-22:38:51.231579623] FFSB version 6.0-RC2 started [20090122-22:38:51.233757581] [20090122-22:38:51.235676649] benchmark time = 300 [20090122-22:38:51.237747575] ThreadGroup 0 [20090122-22:38:51.239824133] ================ [20090122-22:38:51.241977654] num_threads = 1 [20090122-22:38:51.243901989] [20090122-22:38:51.245913491] read_random = off [20090122-22:38:51.247857583] read_size = 0 (0B) [20090122-22:38:51.249923101] read_blocksize = 4096 (4KB) [20090122-22:38:51.251927562] read_skip = off [20090122-22:38:51.253835746] read_skipsize = 0 (0B) [20090122-22:38:51.255640447] [20090122-22:38:51.257580060] write_random = off [20090122-22:38:51.259448999] write_size = 0 (0B) [20090122-22:38:51.261303419] fsync_file = 0 [20090122-22:38:51.263086277] write_blocksize = 0 (0B) [20090122-22:38:51.264956370] wait time = 0 [20090122-22:38:51.266888023] [20090122-22:38:51.268825474] op weights [20090122-22:38:51.270900280] read = 0 (0.00%) [20090122-22:38:51.272701842] readall = 1 (100.00%) [20090122-22:38:51.274557965] write = 0 (0.00%) [20090122-22:38:51.276431601] create = 0 (0.00%) [20090122-22:38:51.278360567] append = 0 (0.00%) [20090122-22:38:51.280280651] delete = 0 (0.00%) [20090122-22:38:51.282118038] metaop = 0 (0.00%) [20090122-22:38:51.284071648] createdir = 0 (0.00%) [20090122-22:38:51.285899425] stat = 0 (0.00%) [20090122-22:38:51.287797012] writeall = 0 (0.00%) [20090122-22:38:51.289613593] writeall_fsync = 0 (0.00%) [20090122-22:38:51.291536834] open_close = 0 (0.00%) [20090122-22:38:51.293472323] write_fsync = 0 (0.00%) [20090122-22:38:51.295316598] create_fsync = 0 (0.00%) [20090122-22:38:51.297236518] append_fsync = 0 (0.00%) [20090122-22:38:51.299066860] [20090122-22:38:51.300947868] FileSystem /mnt/ffsb1 [20090122-22:38:51.302735852] ========== [20090122-22:38:51.304660804] num_dirs = 0 [20090122-22:38:51.306555110] starting files = 1024 [20090122-22:38:51.308372074] [20090122-22:38:51.310277737] min file size = 36700160 (35MB) [20090122-22:38:51.312110724] max file size = 36700160 (35MB) [20090122-22:38:51.313982298] directio = off [20090122-22:38:51.315779137] alignedio = on [20090122-22:38:51.317620831] bufferedio = off [20090122-22:38:51.319554305] [20090122-22:38:51.321350473] aging is off [20090122-22:38:51.323260179] current utilization = 0.26% [20090122-22:38:51.325145675] [20090122-22:38:51.326933164] checking existing fs: /mnt/ffsb1 [20090122-22:38:51.328839868] opendir: No such file or directory [20090122-22:38:51.330655378] recreating new fileset [20090122-22:46:53.749636211] fs setup took 482 secs [20090122-22:46:55.639128262] Syncing()...2 sec [20090122-22:46:55.641560207] Starting Actual Benchmark At: Thu Jan 22 22:46:55 2009 [20090122-22:46:55.725836992] [20090122-22:51:57.238419097] Syncing()...0 sec [20090122-22:51:57.295983300] FFSB benchmark finished at: Thu Jan 22 22:51:56 2009 [20090122-22:51:57.298981010] [20090122-22:51:57.302042629] Results: [20090122-22:51:57.335631001] Benchmark took 301.35 sec [20090122-22:51:57.338521947] [20090122-22:51:57.341411112] Total Results [20090122-22:51:57.356625191] =============== [20090122-22:51:57.359036416] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090122-22:51:57.361839065] ======= ============ ========= ======= =========== ========== [20090122-22:51:57.364543485] readall : 6845440 22716.15 100.000% 100.000% 88.7MB/sec [20090122-22:51:57.367000868] - [20090122-22:51:57.369509417] 22716.15 Transactions per Second [20090122-22:51:57.372262014] [20090122-22:51:57.378985555] Throughput Results [20090122-22:51:57.393976505] =================== [20090122-22:51:57.396312515] Read Throughput: 88.7MB/sec [20090122-22:51:57.398921363] [20090122-22:51:57.401419385] System Call Latency statistics in millisecs [20090122-22:51:57.404068634] ===== [20090122-22:51:57.406520700] Min Avg Max Total Calls [20090122-22:51:57.409243878] ======== ======== ======== ============ [20090122-22:51:57.411768383] [ open] 0.010000 0.098487 8.045000 764 [20090122-22:51:57.414212975] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-22:51:57.416582261] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-22:51:57.419078223] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-22:51:57.421742862] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-22:51:57.424101388] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-22:51:57.426359457] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-22:51:57.428819781] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-22:51:57.431166660] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-22:51:57.433560350] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-22:51:57.435875251] msec_range[9] 5.000000 - 10.000000 : 6 [20090122-22:51:57.438320964] msec_range[10] 2.000000 - 5.000000 : 2 [20090122-22:51:57.440736728] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-22:51:57.443280618] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-22:51:57.445743922] msec_range[13] 0.200000 - 0.500000 : 6 [20090122-22:51:57.448264877] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-22:51:57.450916975] msec_range[15] 0.050000 - 0.100000 : 71 [20090122-22:51:57.453340475] msec_range[16] 0.020000 - 0.050000 : 575 [20090122-22:51:57.455863049] msec_range[17] 0.010000 - 0.020000 : 104 [20090122-22:51:57.458324329] msec_range[18] 0.000000 - 0.010000 : 0 [20090122-22:51:57.460759314] [20090122-22:51:57.463088357] [ read] 0.004000 0.043606 36.858002 6845440 [20090122-22:51:57.465574292] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-22:51:57.467892737] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-22:51:57.470243336] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-22:51:57.472575009] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-22:51:57.475062205] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-22:51:57.477424274] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-22:51:57.479817124] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-22:51:57.482160733] msec_range[7] 20.000000 - 50.000000 : 26 [20090122-22:51:57.484799035] msec_range[8] 10.000000 - 20.000000 : 5082 [20090122-22:51:57.487166412] msec_range[9] 5.000000 - 10.000000 : 15610 [20090122-22:51:57.489555897] msec_range[10] 2.000000 - 5.000000 : 26172 [20090122-22:51:57.491871748] msec_range[11] 1.000000 - 2.000000 : 568 [20090122-22:51:57.494217974] msec_range[12] 0.500000 - 1.000000 : 2581 [20090122-22:51:57.496561673] msec_range[13] 0.200000 - 0.500000 : 3375 [20090122-22:51:57.498926715] msec_range[14] 0.100000 - 0.200000 : 690 [20090122-22:51:57.501178747] msec_range[15] 0.050000 - 0.100000 : 897 [20090122-22:51:57.503524667] msec_range[16] 0.020000 - 0.050000 : 949 [20090122-22:51:57.505811265] msec_range[17] 0.010000 - 0.020000 : 75485 [20090122-22:51:57.508177422] msec_range[18] 0.000000 - 0.010000 : 6714005 [20090122-22:51:57.510519409] [20090122-22:51:57.513073587] [ close] 0.003000 0.006975 0.014000 764 [20090122-22:51:57.515632106] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-22:51:57.518317015] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-22:51:57.521091360] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-22:51:57.523872132] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-22:51:57.526739948] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-22:51:57.529281941] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-22:51:57.532185860] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-22:51:57.534613639] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-22:51:57.537228302] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-22:51:57.539827352] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-22:51:57.542390193] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-22:51:57.544722003] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-22:51:57.547143049] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-22:51:57.550346446] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-22:51:57.553024130] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-22:51:57.555729336] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-22:51:57.558270433] msec_range[16] 0.020000 - 0.050000 : 0 [20090122-22:51:57.560752082] msec_range[17] 0.010000 - 0.020000 : 69 [20090122-22:51:57.563092902] msec_range[18] 0.000000 - 0.010000 : 695 [20090122-22:51:57.565608796] [20090122-22:51:57.568150916] [20090122-22:51:57.570635874] [20090122-22:51:57.573106629] [20090122-22:51:57.575823336] 1.5% User Time [20090122-22:51:57.578341769] 14.5% System Time [20090122-22:51:57.580744771] 16.0% CPU Utilization [20090122-22:51:57.673882317] Profilers reporting [20090122-22:52:06.994441116] Profilers postprocessing [20090122-22:52:07.288209145] Processing File : iostat.001 [20090122-22:52:07.293226860] Discovered iostat_interval=[5] [20090122-22:52:07.834587125] Processing Directory : sar.breakout.001 [20090122-22:52:07.836478149] Discovered sar_interval=[5] [20090122-22:52:08.006388393] Processing File : mpstat.001 [20090122-22:52:08.008710003] Discovered mpstat_interval=[5] [20090122-22:52:09.141936058] Stopping profiling. [20090122-22:52:09.146293878] Killing daemon. [20090122-22:52:10.367341933] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.09-01-22_22.38.43/analysis/oprofile.001 [20090122-22:52:10.369531026] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.09-01-22_22.38.43/analysis/oprofile-brief.001 [20090122-22:52:11.391176497] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline' [20090122-22:52:13.287261962] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090122-22:52:13.922922179] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20090122-22:52:14.031204160] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20090122-22:52:14.074050360] new log requested [20090122-22:52:14.095442052] Running command ffsb [20090122-22:52:22.111411249] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20090122-22:52:22.124596697] Importing argument : num_threads=8 [20090122-22:52:22.149962202] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090122-22:52:22.222169999] FFSB version 6.0-RC2 started [20090122-22:52:22.224246422] [20090122-22:52:22.248475302] benchmark time = 300 [20090122-22:52:22.250479351] ThreadGroup 0 [20090122-22:52:22.252454053] ================ [20090122-22:52:22.254234834] num_threads = 8 [20090122-22:52:22.256137280] [20090122-22:52:22.257922501] read_random = off [20090122-22:52:22.259786106] read_size = 0 (0B) [20090122-22:52:22.261548333] read_blocksize = 4096 (4KB) [20090122-22:52:22.263544567] read_skip = off [20090122-22:52:22.265361121] read_skipsize = 0 (0B) [20090122-22:52:22.267245857] [20090122-22:52:22.268975038] write_random = off [20090122-22:52:22.270904723] write_size = 0 (0B) [20090122-22:52:22.272720540] fsync_file = 0 [20090122-22:52:22.274584064] write_blocksize = 0 (0B) [20090122-22:52:22.276340169] wait time = 0 [20090122-22:52:22.278245832] [20090122-22:52:22.280049736] op weights [20090122-22:52:22.281914882] read = 0 (0.00%) [20090122-22:52:22.283679717] readall = 1 (100.00%) [20090122-22:52:22.285819509] write = 0 (0.00%) [20090122-22:52:22.287935188] create = 0 (0.00%) [20090122-22:52:22.289891362] append = 0 (0.00%) [20090122-22:52:22.291938034] delete = 0 (0.00%) [20090122-22:52:22.293844837] metaop = 0 (0.00%) [20090122-22:52:22.295719566] createdir = 0 (0.00%) [20090122-22:52:22.297517697] stat = 0 (0.00%) [20090122-22:52:22.299387470] writeall = 0 (0.00%) [20090122-22:52:22.301233101] writeall_fsync = 0 (0.00%) [20090122-22:52:22.303091053] open_close = 0 (0.00%) [20090122-22:52:22.304878420] write_fsync = 0 (0.00%) [20090122-22:52:22.306739313] create_fsync = 0 (0.00%) [20090122-22:52:22.308550322] append_fsync = 0 (0.00%) [20090122-22:52:22.310426856] [20090122-22:52:22.312160102] FileSystem /mnt/ffsb1 [20090122-22:52:22.314133875] ========== [20090122-22:52:22.315974756] num_dirs = 0 [20090122-22:52:22.317842308] starting files = 1024 [20090122-22:52:22.319660500] [20090122-22:52:22.321537664] min file size = 36700160 (35MB) [20090122-22:52:22.323455612] max file size = 36700160 (35MB) [20090122-22:52:22.325206499] directio = off [20090122-22:52:22.327164474] alignedio = on [20090122-22:52:22.329005565] bufferedio = off [20090122-22:52:22.330868073] [20090122-22:52:22.332647443] aging is off [20090122-22:52:22.334518596] current utilization = 52.33% [20090122-22:52:22.336329480] [20090122-22:52:22.338277095] checking existing fs: /mnt/ffsb1 [20090122-22:52:22.388428958] fs setup took 0 secs [20090122-22:52:23.451652036] Syncing()...1 sec [20090122-22:52:23.453570956] Starting Actual Benchmark At: Thu Jan 22 22:52:23 2009 [20090122-22:52:23.467216801] [20090122-22:57:27.183444026] Syncing()...0 sec [20090122-22:57:27.222844862] FFSB benchmark finished at: Thu Jan 22 22:57:26 2009 [20090122-22:57:27.225982666] [20090122-22:57:27.228982104] Results: [20090122-22:57:27.289922112] Benchmark took 303.27 sec [20090122-22:57:27.292268494] [20090122-22:57:27.295038547] Total Results [20090122-22:57:27.310184346] =============== [20090122-22:57:27.312656526] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090122-22:57:27.315340979] ======= ============ ========= ======= =========== ========== [20090122-22:57:27.317771647] readall : 5850880 19292.63 100.000% 100.000% 75.4MB/sec [20090122-22:57:27.320416012] - [20090122-22:57:27.322865309] 19292.63 Transactions per Second [20090122-22:57:27.325321044] [20090122-22:57:27.328166488] Throughput Results [20090122-22:57:27.343884867] =================== [20090122-22:57:27.346523843] Read Throughput: 75.4MB/sec [20090122-22:57:27.349237941] [20090122-22:57:27.351785505] System Call Latency statistics in millisecs [20090122-22:57:27.354172103] ===== [20090122-22:57:27.356589878] Min Avg Max Total Calls [20090122-22:57:27.358971920] ======== ======== ======== ============ [20090122-22:57:27.361612944] [ open] 0.006000 6.924519 1264.296997 653 [20090122-22:57:27.363966616] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-22:57:27.366436138] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-22:57:27.368766645] msec_range[2] 1000.000000 - 2000.000000 : 1 [20090122-22:57:27.371330197] msec_range[3] 500.000000 - 1000.000000 : 1 [20090122-22:57:27.374137554] msec_range[4] 200.000000 - 500.000000 : 5 [20090122-22:57:27.377493276] msec_range[5] 100.000000 - 200.000000 : 3 [20090122-22:57:27.380225963] msec_range[6] 50.000000 - 100.000000 : 6 [20090122-22:57:27.382862884] msec_range[7] 20.000000 - 50.000000 : 2 [20090122-22:57:27.395795465] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-22:57:27.398545614] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-22:57:27.401206566] msec_range[10] 2.000000 - 5.000000 : 1 [20090122-22:57:27.404069050] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-22:57:27.406904895] msec_range[12] 0.500000 - 1.000000 : 5 [20090122-22:57:27.410186997] msec_range[13] 0.200000 - 0.500000 : 7 [20090122-22:57:27.413107114] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-22:57:27.416043257] msec_range[15] 0.050000 - 0.100000 : 110 [20090122-22:57:27.418762684] msec_range[16] 0.020000 - 0.050000 : 442 [20090122-22:57:27.421572180] msec_range[17] 0.010000 - 0.020000 : 60 [20090122-22:57:27.424167383] msec_range[18] 0.000000 - 0.010000 : 10 [20090122-22:57:27.426588072] [20090122-22:57:27.429134902] [ read] 0.001000 0.412070 3545.430908 5850880 [20090122-22:57:27.431868101] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-22:57:27.434473504] msec_range[1] 2000.000000 - 5000.000000 : 245 [20090122-22:57:27.436963824] msec_range[2] 1000.000000 - 2000.000000 : 377 [20090122-22:57:27.439343999] msec_range[3] 500.000000 - 1000.000000 : 528 [20090122-22:57:27.441794594] msec_range[4] 200.000000 - 500.000000 : 1120 [20090122-22:57:27.444512292] msec_range[5] 100.000000 - 200.000000 : 1384 [20090122-22:57:27.447082638] msec_range[6] 50.000000 - 100.000000 : 2617 [20090122-22:57:27.449507221] msec_range[7] 20.000000 - 50.000000 : 708 [20090122-22:57:27.452146199] msec_range[8] 10.000000 - 20.000000 : 4130 [20090122-22:57:27.454449867] msec_range[9] 5.000000 - 10.000000 : 12871 [20090122-22:57:27.456837955] msec_range[10] 2.000000 - 5.000000 : 16511 [20090122-22:57:27.459178685] msec_range[11] 1.000000 - 2.000000 : 402 [20090122-22:57:27.461652554] msec_range[12] 0.500000 - 1.000000 : 2494 [20090122-22:57:27.463986758] msec_range[13] 0.200000 - 0.500000 : 2785 [20090122-22:57:27.466449493] msec_range[14] 0.100000 - 0.200000 : 461 [20090122-22:57:27.468778457] msec_range[15] 0.050000 - 0.100000 : 743 [20090122-22:57:27.471207077] msec_range[16] 0.020000 - 0.050000 : 1093 [20090122-22:57:27.473527383] msec_range[17] 0.010000 - 0.020000 : 88869 [20090122-22:57:27.475956628] msec_range[18] 0.000000 - 0.010000 : 5713542 [20090122-22:57:27.478465193] [20090122-22:57:27.481161475] [ close] 0.002000 0.006911 0.014000 653 [20090122-22:57:27.483666259] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-22:57:27.486077832] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-22:57:27.488406146] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-22:57:27.490840164] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-22:57:27.493193739] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-22:57:27.495681894] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-22:57:27.497990039] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-22:57:27.500418827] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-22:57:27.502731415] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-22:57:27.505162482] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-22:57:27.507497522] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-22:57:27.509905875] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-22:57:27.512485752] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-22:57:27.514891024] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-22:57:27.517209918] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-22:57:27.519658133] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-22:57:27.522002768] msec_range[16] 0.020000 - 0.050000 : 0 [20090122-22:57:27.524369502] msec_range[17] 0.010000 - 0.020000 : 45 [20090122-22:57:27.526738861] msec_range[18] 0.000000 - 0.010000 : 608 [20090122-22:57:27.529209057] [20090122-22:57:27.531564712] [20090122-22:57:27.533850500] [20090122-22:57:27.536116092] [20090122-22:57:27.538501294] 1.4% User Time [20090122-22:57:27.541101619] 12.2% System Time [20090122-22:57:27.543528367] 13.6% CPU Utilization [20090122-22:57:27.545904298] Profilers reporting [20090122-22:57:37.718321460] Profilers postprocessing [20090122-22:57:37.959361316] Processing File : iostat.001 [20090122-22:57:37.961678340] Discovered iostat_interval=[5] [20090122-22:57:38.514568891] Processing Directory : sar.breakout.001 [20090122-22:57:38.516512916] Discovered sar_interval=[5] [20090122-22:57:38.679221039] Processing File : mpstat.001 [20090122-22:57:38.681485464] Discovered mpstat_interval=[5] [20090122-22:57:39.809516532] Stopping profiling. [20090122-22:57:39.813260525] Killing daemon. [20090122-22:57:42.196193183] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.09-01-22_22.52.14/analysis/oprofile.001 [20090122-22:57:42.198451866] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.09-01-22_22.52.14/analysis/oprofile-brief.001 [20090122-22:57:43.253564316] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline' [20090122-22:57:45.221336982] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090122-22:57:45.802496782] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20090122-22:57:45.916325867] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20090122-22:57:45.958623233] new log requested [20090122-22:57:45.988804769] Running command ffsb [20090122-22:57:53.741617975] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20090122-22:57:53.754747856] Importing argument : num_threads=32 [20090122-22:57:53.780183116] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090122-22:57:53.852444956] FFSB version 6.0-RC2 started [20090122-22:57:53.854374433] [20090122-22:57:53.979706622] benchmark time = 300 [20090122-22:57:53.981643134] ThreadGroup 0 [20090122-22:57:53.983772922] ================ [20090122-22:57:53.985892021] num_threads = 32 [20090122-22:57:53.987710395] [20090122-22:57:53.989584132] read_random = off [20090122-22:57:53.991405353] read_size = 0 (0B) [20090122-22:57:53.993272698] read_blocksize = 4096 (4KB) [20090122-22:57:53.995051965] read_skip = off [20090122-22:57:53.996891874] read_skipsize = 0 (0B) [20090122-22:57:53.998884702] [20090122-22:57:54.001059415] write_random = off [20090122-22:57:54.003201521] write_size = 0 (0B) [20090122-22:57:54.005505092] fsync_file = 0 [20090122-22:57:54.007511397] write_blocksize = 0 (0B) [20090122-22:57:54.009385409] wait time = 0 [20090122-22:57:54.011206244] [20090122-22:57:54.013350532] op weights [20090122-22:57:54.015275833] read = 0 (0.00%) [20090122-22:57:54.017102135] readall = 1 (100.00%) [20090122-22:57:54.018901459] write = 0 (0.00%) [20090122-22:57:54.020811994] create = 0 (0.00%) [20090122-22:57:54.022629442] append = 0 (0.00%) [20090122-22:57:54.024399818] delete = 0 (0.00%) [20090122-22:57:54.026268197] metaop = 0 (0.00%) [20090122-22:57:54.028199173] createdir = 0 (0.00%) [20090122-22:57:54.030021087] stat = 0 (0.00%) [20090122-22:57:54.031870824] writeall = 0 (0.00%) [20090122-22:57:54.033656848] writeall_fsync = 0 (0.00%) [20090122-22:57:54.035561586] open_close = 0 (0.00%) [20090122-22:57:54.037368125] write_fsync = 0 (0.00%) [20090122-22:57:54.039198429] create_fsync = 0 (0.00%) [20090122-22:57:54.040964093] append_fsync = 0 (0.00%) [20090122-22:57:54.043043054] [20090122-22:57:54.045074764] FileSystem /mnt/ffsb1 [20090122-22:57:54.046918803] ========== [20090122-22:57:54.048678682] num_dirs = 0 [20090122-22:57:54.050583048] starting files = 1024 [20090122-22:57:54.052407569] [20090122-22:57:54.054246031] min file size = 36700160 (35MB) [20090122-22:57:54.056016278] max file size = 36700160 (35MB) [20090122-22:57:54.057830739] directio = off [20090122-22:57:54.059809847] alignedio = on [20090122-22:57:54.061644247] bufferedio = off [20090122-22:57:54.063599445] [20090122-22:57:54.065448769] aging is off [20090122-22:57:54.067326388] current utilization = 52.33% [20090122-22:57:54.069127334] [20090122-22:57:54.071162997] checking existing fs: /mnt/ffsb1 [20090122-22:57:54.114874845] fs setup took 0 secs [20090122-22:57:55.082407047] Syncing()...0 sec [20090122-22:57:55.084893397] Starting Actual Benchmark At: Thu Jan 22 22:57:55 2009 [20090122-22:57:55.097899120] [20090122-23:03:04.641386114] Syncing()...0 sec [20090122-23:03:04.686348924] FFSB benchmark finished at: Thu Jan 22 23:03:04 2009 [20090122-23:03:04.689478763] [20090122-23:03:04.692473725] Results: [20090122-23:03:04.759133842] Benchmark took 309.25 sec [20090122-23:03:04.761442462] [20090122-23:03:04.764335753] Total Results [20090122-23:03:04.779554411] =============== [20090122-23:03:04.782621342] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090122-23:03:04.785386408] ======= ============ ========= ======= =========== ========== [20090122-23:03:04.787907045] readall : 6012160 19441.36 100.000% 100.000% 75.9MB/sec [20090122-23:03:04.790426431] - [20090122-23:03:04.793225457] 19441.36 Transactions per Second [20090122-23:03:04.796287383] [20090122-23:03:04.798986900] Throughput Results [20090122-23:03:04.813939045] =================== [20090122-23:03:04.816471252] Read Throughput: 75.9MB/sec [20090122-23:03:04.819106865] [20090122-23:03:04.821532854] System Call Latency statistics in millisecs [20090122-23:03:04.824002227] ===== [20090122-23:03:04.826628541] Min Avg Max Total Calls [20090122-23:03:04.829178713] ======== ======== ======== ============ [20090122-23:03:04.831631034] [ open] 0.005000 16.563100 812.791016 671 [20090122-23:03:04.834232461] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:03:04.836744115] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:03:04.839200828] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:03:04.841495056] msec_range[3] 500.000000 - 1000.000000 : 5 [20090122-23:03:04.843894291] msec_range[4] 200.000000 - 500.000000 : 21 [20090122-23:03:04.846219131] msec_range[5] 100.000000 - 200.000000 : 5 [20090122-23:03:04.848721174] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:03:04.851114986] msec_range[7] 20.000000 - 50.000000 : 3 [20090122-23:03:04.853624070] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:03:04.856791424] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:03:04.859261266] msec_range[10] 2.000000 - 5.000000 : 1 [20090122-23:03:04.861675447] msec_range[11] 1.000000 - 2.000000 : 1 [20090122-23:03:04.864222827] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:03:04.866701968] msec_range[13] 0.200000 - 0.500000 : 1 [20090122-23:03:04.869063302] msec_range[14] 0.100000 - 0.200000 : 2 [20090122-23:03:04.871531033] msec_range[15] 0.050000 - 0.100000 : 112 [20090122-23:03:04.873938419] msec_range[16] 0.020000 - 0.050000 : 417 [20090122-23:03:04.876439022] msec_range[17] 0.010000 - 0.020000 : 70 [20090122-23:03:04.878785203] msec_range[18] 0.000000 - 0.010000 : 33 [20090122-23:03:04.881266817] [20090122-23:03:04.883653836] [ read] 0.001000 1.624177 3358.583984 6012160 [20090122-23:03:04.886094167] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:03:04.888420845] msec_range[1] 2000.000000 - 5000.000000 : 112 [20090122-23:03:04.900916922] msec_range[2] 1000.000000 - 2000.000000 : 1236 [20090122-23:03:04.903581547] msec_range[3] 500.000000 - 1000.000000 : 6056 [20090122-23:03:04.905981393] msec_range[4] 200.000000 - 500.000000 : 9485 [20090122-23:03:04.908364758] msec_range[5] 100.000000 - 200.000000 : 619 [20090122-23:03:04.910805485] msec_range[6] 50.000000 - 100.000000 : 393 [20090122-23:03:04.913163165] msec_range[7] 20.000000 - 50.000000 : 358 [20090122-23:03:04.915615054] msec_range[8] 10.000000 - 20.000000 : 206 [20090122-23:03:04.918262788] msec_range[9] 5.000000 - 10.000000 : 9075 [20090122-23:03:04.920668666] msec_range[10] 2.000000 - 5.000000 : 12429 [20090122-23:03:04.923127031] msec_range[11] 1.000000 - 2.000000 : 281 [20090122-23:03:04.925493181] msec_range[12] 0.500000 - 1.000000 : 687 [20090122-23:03:04.927924174] msec_range[13] 0.200000 - 0.500000 : 4706 [20090122-23:03:04.930285105] msec_range[14] 0.100000 - 0.200000 : 467 [20090122-23:03:04.932842921] msec_range[15] 0.050000 - 0.100000 : 1148 [20090122-23:03:04.935366019] msec_range[16] 0.020000 - 0.050000 : 5809 [20090122-23:03:04.937779726] msec_range[17] 0.010000 - 0.020000 : 164356 [20090122-23:03:04.940247155] msec_range[18] 0.000000 - 0.010000 : 5794737 [20090122-23:03:04.942676414] [20090122-23:03:04.945113156] [ close] 0.002000 0.007058 0.021000 671 [20090122-23:03:04.947482697] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:03:04.950018507] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:03:04.952558116] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:03:04.954993762] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:03:04.957453977] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:03:04.959867521] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:03:04.962365031] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:03:04.964818013] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:03:04.967431879] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:03:04.969734410] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:03:04.972417563] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:03:04.974861084] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:03:04.977360845] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:03:04.979798892] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:03:04.982446043] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:03:04.986165455] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:03:04.988827077] msec_range[16] 0.020000 - 0.050000 : 1 [20090122-23:03:04.991465848] msec_range[17] 0.010000 - 0.020000 : 65 [20090122-23:03:04.993924480] msec_range[18] 0.000000 - 0.010000 : 605 [20090122-23:03:04.996423178] [20090122-23:03:04.999296657] [20090122-23:03:05.001604210] [20090122-23:03:05.004113279] [20090122-23:03:05.006941990] 1.4% User Time [20090122-23:03:05.009244100] 12.3% System Time [20090122-23:03:05.011833354] 13.7% CPU Utilization [20090122-23:03:05.156621211] Profilers reporting [20090122-23:03:16.055034420] Profilers postprocessing [20090122-23:03:16.295893064] Processing File : iostat.001 [20090122-23:03:16.298137254] Discovered iostat_interval=[5] [20090122-23:03:16.855567702] Processing Directory : sar.breakout.001 [20090122-23:03:16.857630829] Discovered sar_interval=[5] [20090122-23:03:17.021839545] Processing File : mpstat.001 [20090122-23:03:17.024100796] Discovered mpstat_interval=[5] [20090122-23:03:18.157687058] Stopping profiling. [20090122-23:03:18.163878297] Killing daemon. [20090122-23:03:19.400126884] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.09-01-22_22.57.45/analysis/oprofile.001 [20090122-23:03:19.402407655] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.09-01-22_22.57.45/analysis/oprofile-brief.001 [20090122-23:03:20.620713137] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline' [20090122-23:03:22.551197518] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090122-23:03:23.234409254] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20090122-23:03:23.395696435] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=1' [20090122-23:03:23.438716895] new log requested [20090122-23:03:23.461008561] Running command ffsb [20090122-23:03:31.163025206] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20090122-23:03:31.181009286] Importing argument : num_threads=1 [20090122-23:03:31.206960727] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090122-23:03:31.271396458] FFSB version 6.0-RC2 started [20090122-23:03:31.273577385] [20090122-23:03:31.275756022] benchmark time = 300 [20090122-23:03:31.277860212] ThreadGroup 0 [20090122-23:03:31.279764969] ================ [20090122-23:03:31.281666257] num_threads = 1 [20090122-23:03:31.283528944] [20090122-23:03:31.285399777] read_random = on [20090122-23:03:31.287187483] read_size = 1048576 (1MB) [20090122-23:03:31.289249296] read_blocksize = 4096 (4KB) [20090122-23:03:31.291227974] read_skip = off [20090122-23:03:31.292980111] read_skipsize = 0 (0B) [20090122-23:03:31.294925917] [20090122-23:03:31.296827707] write_random = off [20090122-23:03:31.298684781] write_size = 0 (0B) [20090122-23:03:31.300457593] fsync_file = 0 [20090122-23:03:31.302439094] write_blocksize = 0 (0B) [20090122-23:03:31.304383207] wait time = 0 [20090122-23:03:31.306215796] [20090122-23:03:31.307956864] op weights [20090122-23:03:31.309887629] read = 1 (100.00%) [20090122-23:03:31.311771013] readall = 0 (0.00%) [20090122-23:03:31.313629969] write = 0 (0.00%) [20090122-23:03:31.315391393] create = 0 (0.00%) [20090122-23:03:31.317487160] append = 0 (0.00%) [20090122-23:03:31.319461868] delete = 0 (0.00%) [20090122-23:03:31.321294422] metaop = 0 (0.00%) [20090122-23:03:31.323064896] createdir = 0 (0.00%) [20090122-23:03:31.325001979] stat = 0 (0.00%) [20090122-23:03:31.327012773] writeall = 0 (0.00%) [20090122-23:03:31.328978911] writeall_fsync = 0 (0.00%) [20090122-23:03:31.331090898] open_close = 0 (0.00%) [20090122-23:03:31.333006092] write_fsync = 0 (0.00%) [20090122-23:03:31.334896895] create_fsync = 0 (0.00%) [20090122-23:03:31.336737603] append_fsync = 0 (0.00%) [20090122-23:03:31.338672192] [20090122-23:03:31.340554365] FileSystem /mnt/ffsb1 [20090122-23:03:31.342322722] ========== [20090122-23:03:31.344303558] num_dirs = 0 [20090122-23:03:31.346237085] starting files = 1024 [20090122-23:03:31.348046261] [20090122-23:03:31.349865513] min file size = 36700160 (35MB) [20090122-23:03:31.351790398] max file size = 36700160 (35MB) [20090122-23:03:31.353677691] directio = off [20090122-23:03:31.355478908] alignedio = on [20090122-23:03:31.357468800] bufferedio = off [20090122-23:03:31.359389423] [20090122-23:03:31.361240648] aging is off [20090122-23:03:31.362974999] current utilization = 52.33% [20090122-23:03:31.364898425] [20090122-23:03:31.366785352] checking existing fs: /mnt/ffsb1 [20090122-23:03:31.423056644] fs setup took 0 secs [20090122-23:03:32.575231659] Syncing()...1 sec [20090122-23:03:32.577314718] Starting Actual Benchmark At: Thu Jan 22 23:03:32 2009 [20090122-23:03:32.590170444] [20090122-23:08:34.415613405] Syncing()...0 sec [20090122-23:08:34.418779730] FFSB benchmark finished at: Thu Jan 22 23:08:34 2009 [20090122-23:08:34.421862426] [20090122-23:08:34.424431560] Results: [20090122-23:08:34.439511537] Benchmark took 301.84 sec [20090122-23:08:34.442070892] [20090122-23:08:34.444636674] Total Results [20090122-23:08:34.458581733] =============== [20090122-23:08:34.461543929] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090122-23:08:34.464398864] ======= ============ ========= ======= =========== ========== [20090122-23:08:34.467519615] read : 99328 329.08 100.000% 100.000% 1.29MB/sec [20090122-23:08:34.470490846] - [20090122-23:08:34.473387970] 329.08 Transactions per Second [20090122-23:08:34.476043203] [20090122-23:08:34.478930817] Throughput Results [20090122-23:08:34.496398302] =================== [20090122-23:08:34.499221356] Read Throughput: 1.29MB/sec [20090122-23:08:34.502179247] [20090122-23:08:34.504932706] System Call Latency statistics in millisecs [20090122-23:08:34.507858337] ===== [20090122-23:08:34.511678950] Min Avg Max Total Calls [20090122-23:08:34.514387412] ======== ======== ======== ============ [20090122-23:08:34.517472526] [ open] 0.009000 0.015531 0.025000 388 [20090122-23:08:34.521002394] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:08:34.523885007] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:08:34.526985623] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:08:34.529701428] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:08:34.533578812] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:08:34.536548619] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:08:34.539844534] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:08:34.543379836] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:08:34.546457055] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:08:34.549919912] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:08:34.552845570] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:08:34.556271376] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:08:34.559445777] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:08:34.562329847] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:08:34.564971247] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:08:34.567521138] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:08:34.570124523] msec_range[16] 0.020000 - 0.050000 : 65 [20090122-23:08:34.572863947] msec_range[17] 0.010000 - 0.020000 : 322 [20090122-23:08:34.575519845] msec_range[18] 0.000000 - 0.010000 : 1 [20090122-23:08:34.578444829] [20090122-23:08:34.581695033] [ read] 0.001000 3.032179 45.881001 99328 [20090122-23:08:34.585098307] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:08:34.588579398] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:08:34.592181484] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:08:34.595210633] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:08:34.598227763] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:08:34.602234014] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:08:34.605054805] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:08:34.608158184] msec_range[7] 20.000000 - 50.000000 : 49 [20090122-23:08:34.610862110] msec_range[8] 10.000000 - 20.000000 : 2412 [20090122-23:08:34.613763254] msec_range[9] 5.000000 - 10.000000 : 2518 [20090122-23:08:34.616278883] msec_range[10] 2.000000 - 5.000000 : 61271 [20090122-23:08:34.619170855] msec_range[11] 1.000000 - 2.000000 : 19644 [20090122-23:08:34.621808911] msec_range[12] 0.500000 - 1.000000 : 410 [20090122-23:08:34.624582346] msec_range[13] 0.200000 - 0.500000 : 10100 [20090122-23:08:34.627547990] msec_range[14] 0.100000 - 0.200000 : 282 [20090122-23:08:34.630578785] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:08:34.633432474] msec_range[16] 0.020000 - 0.050000 : 3 [20090122-23:08:34.636259170] msec_range[17] 0.010000 - 0.020000 : 180 [20090122-23:08:34.640357650] msec_range[18] 0.000000 - 0.010000 : 2459 [20090122-23:08:34.643321540] [20090122-23:08:34.646124279] [ lseek] 0.000000 0.001164 0.177000 99328 [20090122-23:08:34.649019065] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:08:34.651754942] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:08:34.654586809] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:08:34.657371421] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:08:34.660297028] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:08:34.663826096] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:08:34.666775438] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:08:34.669348906] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:08:34.672041142] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:08:34.674997840] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:08:34.677780381] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:08:34.680718290] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:08:34.683209651] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:08:34.685739445] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:08:34.688621611] msec_range[14] 0.100000 - 0.200000 : 1 [20090122-23:08:34.691307854] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:08:34.693989074] msec_range[16] 0.020000 - 0.050000 : 1 [20090122-23:08:34.696504425] msec_range[17] 0.010000 - 0.020000 : 29 [20090122-23:08:34.699346540] msec_range[18] 0.000000 - 0.010000 : 99297 [20090122-23:08:34.701996453] [20090122-23:08:34.704463419] [ close] 0.003000 0.004817 0.011000 388 [20090122-23:08:34.707338382] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:08:34.710217566] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:08:34.713013012] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:08:34.716027249] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:08:34.719182273] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:08:34.722133615] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:08:34.725007376] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:08:34.727678212] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:08:34.730153598] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:08:34.732608982] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:08:34.735383358] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:08:34.738208543] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:08:34.741040554] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:08:34.743971500] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:08:34.746853411] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:08:34.749363380] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:08:34.751984769] msec_range[16] 0.020000 - 0.050000 : 0 [20090122-23:08:34.754624843] msec_range[17] 0.010000 - 0.020000 : 18 [20090122-23:08:34.757150664] msec_range[18] 0.000000 - 0.010000 : 370 [20090122-23:08:34.759702314] [20090122-23:08:34.762245083] [20090122-23:08:34.764579382] [20090122-23:08:34.767068255] [20090122-23:08:34.769510315] 0.1% User Time [20090122-23:08:34.771800693] 0.8% System Time [20090122-23:08:34.774252559] 0.9% CPU Utilization [20090122-23:08:34.776629690] Profilers reporting [20090122-23:08:34.778921370] /autobench/scripts/doprofilers: line 33: 2977 Terminated ${CMDS[$i]} [20090122-23:08:34.781341889] /autobench/scripts/doprofilers: line 33: 2986 Terminated ${CMDS[$i]} [20090122-23:08:34.783799311] /autobench/scripts/doprofilers: line 33: 2996 Terminated ${CMDS[$i]} [20090122-23:08:41.714467297] Profilers postprocessing [20090122-23:08:41.799570310] Processing File : iostat.001 [20090122-23:08:41.801940056] Discovered iostat_interval=[5] [20090122-23:08:42.327795064] Processing Directory : sar.breakout.001 [20090122-23:08:42.329911507] Discovered sar_interval=[5] [20090122-23:08:42.492041089] Processing File : mpstat.001 [20090122-23:08:42.494443308] Discovered mpstat_interval=[5] [20090122-23:08:43.625410687] Stopping profiling. [20090122-23:08:43.629312259] Killing daemon. [20090122-23:08:44.790695192] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.09-01-22_23.03.23/analysis/oprofile.001 [20090122-23:08:44.793289657] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.09-01-22_23.03.23/analysis/oprofile-brief.001 [20090122-23:08:45.234352859] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline' [20090122-23:08:46.466855991] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090122-23:08:46.754188063] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20090122-23:08:46.852657882] PROCESSING COMMAND : 'run random_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=8' [20090122-23:08:46.895784902] new log requested [20090122-23:08:46.918382741] Running command ffsb [20090122-23:08:53.788191194] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20090122-23:08:53.801018222] Importing argument : num_threads=8 [20090122-23:08:53.826965946] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090122-23:08:53.890412238] FFSB version 6.0-RC2 started [20090122-23:08:53.892646290] [20090122-23:08:53.924660437] benchmark time = 300 [20090122-23:08:53.926887118] ThreadGroup 0 [20090122-23:08:53.928980933] ================ [20090122-23:08:53.931005399] num_threads = 8 [20090122-23:08:53.932903643] [20090122-23:08:53.934785717] read_random = on [20090122-23:08:53.936667060] read_size = 1048576 (1MB) [20090122-23:08:53.938470314] read_blocksize = 4096 (4KB) [20090122-23:08:53.940284207] read_skip = off [20090122-23:08:53.942189987] read_skipsize = 0 (0B) [20090122-23:08:53.944025619] [20090122-23:08:53.945856792] write_random = off [20090122-23:08:53.947644694] write_size = 0 (0B) [20090122-23:08:53.949542362] fsync_file = 0 [20090122-23:08:53.951350870] write_blocksize = 0 (0B) [20090122-23:08:53.953170141] wait time = 0 [20090122-23:08:53.954929635] [20090122-23:08:53.956843053] op weights [20090122-23:08:53.958648928] read = 1 (100.00%) [20090122-23:08:53.960398641] readall = 0 (0.00%) [20090122-23:08:53.962186740] write = 0 (0.00%) [20090122-23:08:53.964143156] create = 0 (0.00%) [20090122-23:08:53.965965173] append = 0 (0.00%) [20090122-23:08:53.967746187] delete = 0 (0.00%) [20090122-23:08:53.969538655] metaop = 0 (0.00%) [20090122-23:08:53.971406622] createdir = 0 (0.00%) [20090122-23:08:53.973197336] stat = 0 (0.00%) [20090122-23:08:53.975012534] writeall = 0 (0.00%) [20090122-23:08:53.976796078] writeall_fsync = 0 (0.00%) [20090122-23:08:53.978956943] open_close = 0 (0.00%) [20090122-23:08:53.980821385] write_fsync = 0 (0.00%) [20090122-23:08:53.982650654] create_fsync = 0 (0.00%) [20090122-23:08:53.984409888] append_fsync = 0 (0.00%) [20090122-23:08:53.986376030] [20090122-23:08:53.988613541] FileSystem /mnt/ffsb1 [20090122-23:08:53.990563241] ========== [20090122-23:08:53.992522275] num_dirs = 0 [20090122-23:08:53.994371386] starting files = 1024 [20090122-23:08:53.996250879] [20090122-23:08:53.998041223] min file size = 36700160 (35MB) [20090122-23:08:53.999998713] max file size = 36700160 (35MB) [20090122-23:08:54.001956368] directio = off [20090122-23:08:54.003876269] alignedio = on [20090122-23:08:54.005724627] bufferedio = off [20090122-23:08:54.007567759] [20090122-23:08:54.009376528] aging is off [20090122-23:08:54.011394549] current utilization = 52.33% [20090122-23:08:54.013337687] [20090122-23:08:54.015221579] checking existing fs: /mnt/ffsb1 [20090122-23:08:54.084934638] fs setup took 0 secs [20090122-23:08:55.118413545] Syncing()...1 sec [20090122-23:08:55.120388653] Starting Actual Benchmark At: Thu Jan 22 23:08:55 2009 [20090122-23:08:55.133480568] [20090122-23:13:59.680280819] Syncing()...0 sec [20090122-23:13:59.683379428] FFSB benchmark finished at: Thu Jan 22 23:13:59 2009 [20090122-23:13:59.686438096] [20090122-23:13:59.689346508] Results: [20090122-23:13:59.704956974] Benchmark took 304.56 sec [20090122-23:13:59.707435035] [20090122-23:13:59.710211930] Total Results [20090122-23:13:59.729069484] =============== [20090122-23:13:59.732675436] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090122-23:13:59.735729926] ======= ============ ========= ======= =========== ========== [20090122-23:13:59.738461266] read : 116736 383.29 100.000% 100.000% 1.5MB/sec [20090122-23:13:59.741285490] - [20090122-23:13:59.743913534] 383.29 Transactions per Second [20090122-23:13:59.746721466] [20090122-23:13:59.749744085] Throughput Results [20090122-23:13:59.765197809] =================== [20090122-23:13:59.768028484] Read Throughput: 1.5MB/sec [20090122-23:13:59.770696468] [20090122-23:13:59.773848563] System Call Latency statistics in millisecs [20090122-23:13:59.776460565] ===== [20090122-23:13:59.781344589] Min Avg Max Total Calls [20090122-23:13:59.784092082] ======== ======== ======== ============ [20090122-23:13:59.787111725] [ open] 0.006000 0.013971 0.029000 456 [20090122-23:13:59.789992339] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:13:59.792783991] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:13:59.795860454] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:13:59.798785436] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:13:59.802360809] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:13:59.805568482] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:13:59.810131411] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:13:59.813073080] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:13:59.816720000] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:13:59.819702945] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:13:59.823751437] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:13:59.826754123] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:13:59.829543286] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:13:59.832128854] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:13:59.835540747] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:13:59.838967350] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:13:59.841522744] msec_range[16] 0.020000 - 0.050000 : 71 [20090122-23:13:59.844245825] msec_range[17] 0.010000 - 0.020000 : 278 [20090122-23:13:59.847184713] msec_range[18] 0.000000 - 0.010000 : 107 [20090122-23:13:59.849921849] [20090122-23:13:59.852651848] [ read] 0.001000 20.750786 2010.297974 116736 [20090122-23:13:59.856779169] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:13:59.859469550] msec_range[1] 2000.000000 - 5000.000000 : 5 [20090122-23:13:59.862206085] msec_range[2] 1000.000000 - 2000.000000 : 54 [20090122-23:13:59.864896980] msec_range[3] 500.000000 - 1000.000000 : 282 [20090122-23:13:59.867584276] msec_range[4] 200.000000 - 500.000000 : 1434 [20090122-23:13:59.870458590] msec_range[5] 100.000000 - 200.000000 : 2869 [20090122-23:13:59.874387542] msec_range[6] 50.000000 - 100.000000 : 5077 [20090122-23:13:59.877353953] msec_range[7] 20.000000 - 50.000000 : 14127 [20090122-23:13:59.883821542] msec_range[8] 10.000000 - 20.000000 : 17500 [20090122-23:13:59.888784631] msec_range[9] 5.000000 - 10.000000 : 18836 [20090122-23:13:59.891825144] msec_range[10] 2.000000 - 5.000000 : 38115 [20090122-23:13:59.895225817] msec_range[11] 1.000000 - 2.000000 : 15219 [20090122-23:13:59.898078911] msec_range[12] 0.500000 - 1.000000 : 435 [20090122-23:13:59.901686902] msec_range[13] 0.200000 - 0.500000 : 585 [20090122-23:13:59.904703937] msec_range[14] 0.100000 - 0.200000 : 26 [20090122-23:13:59.907272854] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:13:59.910233913] msec_range[16] 0.020000 - 0.050000 : 4 [20090122-23:13:59.913138524] msec_range[17] 0.010000 - 0.020000 : 205 [20090122-23:13:59.915962288] msec_range[18] 0.000000 - 0.010000 : 1963 [20090122-23:13:59.918729753] [20090122-23:13:59.922465803] [ lseek] 0.000000 0.001153 0.058000 116736 [20090122-23:13:59.925196676] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:13:59.930284073] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:13:59.932938765] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:13:59.935828427] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:13:59.938607605] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:13:59.941705750] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:13:59.944893894] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:13:59.948639164] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:13:59.953013403] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:13:59.955748709] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:13:59.958449675] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:13:59.961333761] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:13:59.964432444] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:13:59.967119831] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:13:59.969856261] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:13:59.972848378] msec_range[15] 0.050000 - 0.100000 : 1 [20090122-23:13:59.975546558] msec_range[16] 0.020000 - 0.050000 : 0 [20090122-23:13:59.978695356] msec_range[17] 0.010000 - 0.020000 : 21 [20090122-23:13:59.981459034] msec_range[18] 0.000000 - 0.010000 : 116714 [20090122-23:13:59.984895199] [20090122-23:13:59.987360644] [ close] 0.002000 0.004879 0.014000 456 [20090122-23:13:59.990146867] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:13:59.992827135] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:13:59.995292507] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:13:59.997848941] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:14:00.000320923] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:14:00.002854596] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:14:00.005375118] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:14:00.008177547] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:14:00.010886975] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:14:00.013488624] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:14:00.015994657] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:14:00.018508116] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:14:00.020986472] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:14:00.023554914] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:14:00.026128541] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:14:00.028501897] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:14:00.030982722] msec_range[16] 0.020000 - 0.050000 : 0 [20090122-23:14:00.033539824] msec_range[17] 0.010000 - 0.020000 : 21 [20090122-23:14:00.035903108] msec_range[18] 0.000000 - 0.010000 : 435 [20090122-23:14:00.038440357] [20090122-23:14:00.040876306] [20090122-23:14:00.043191879] [20090122-23:14:00.045664503] [20090122-23:14:00.048130646] 0.1% User Time [20090122-23:14:00.050429038] 1.1% System Time [20090122-23:14:00.052935055] 1.2% CPU Utilization [20090122-23:14:00.055330077] Profilers reporting [20090122-23:14:00.057624677] /autobench/scripts/doprofilers: line 33: 8829 Terminated ${CMDS[$i]} [20090122-23:14:00.060077391] /autobench/scripts/doprofilers: line 33: 8837 Terminated ${CMDS[$i]} [20090122-23:14:00.062480341] /autobench/scripts/doprofilers: line 33: 8880 Terminated ${CMDS[$i]} [20090122-23:14:07.594081752] Profilers postprocessing [20090122-23:14:07.679498720] Processing File : iostat.001 [20090122-23:14:07.681853235] Discovered iostat_interval=[5] [20090122-23:14:08.203887511] Processing Directory : sar.breakout.001 [20090122-23:14:08.206090196] Discovered sar_interval=[5] [20090122-23:14:08.367795175] Processing File : mpstat.001 [20090122-23:14:08.370114270] Discovered mpstat_interval=[5] [20090122-23:14:09.500482658] Stopping profiling. [20090122-23:14:09.504553540] Killing daemon. [20090122-23:14:10.670205954] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.09-01-22_23.08.46/analysis/oprofile.001 [20090122-23:14:10.672409777] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.09-01-22_23.08.46/analysis/oprofile-brief.001 [20090122-23:14:11.092953057] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline' [20090122-23:14:12.476377728] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090122-23:14:12.818730926] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20090122-23:14:12.918716583] PROCESSING COMMAND : 'run random_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=32' [20090122-23:14:12.971004631] new log requested [20090122-23:14:12.993523584] Running command ffsb [20090122-23:14:19.944848353] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20090122-23:14:19.957794575] Importing argument : num_threads=32 [20090122-23:14:19.983550813] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090122-23:14:20.047039554] FFSB version 6.0-RC2 started [20090122-23:14:20.049410860] [20090122-23:14:20.181973174] benchmark time = 300 [20090122-23:14:20.183997210] ThreadGroup 0 [20090122-23:14:20.186116207] ================ [20090122-23:14:20.188183031] num_threads = 32 [20090122-23:14:20.190131658] [20090122-23:14:20.192014219] read_random = on [20090122-23:14:20.193878076] read_size = 1048576 (1MB) [20090122-23:14:20.195744859] read_blocksize = 4096 (4KB) [20090122-23:14:20.197659799] read_skip = off [20090122-23:14:20.199444889] read_skipsize = 0 (0B) [20090122-23:14:20.201337233] [20090122-23:14:20.203214266] write_random = off [20090122-23:14:20.205024070] write_size = 0 (0B) [20090122-23:14:20.206890615] fsync_file = 0 [20090122-23:14:20.208766265] write_blocksize = 0 (0B) [20090122-23:14:20.210539810] wait time = 0 [20090122-23:14:20.212372236] [20090122-23:14:20.214244379] op weights [20090122-23:14:20.216012994] read = 1 (100.00%) [20090122-23:14:20.217865321] readall = 0 (0.00%) [20090122-23:14:20.219674530] write = 0 (0.00%) [20090122-23:14:20.221656132] create = 0 (0.00%) [20090122-23:14:20.223529622] append = 0 (0.00%) [20090122-23:14:20.225349973] delete = 0 (0.00%) [20090122-23:14:20.227252103] metaop = 0 (0.00%) [20090122-23:14:20.229006259] createdir = 0 (0.00%) [20090122-23:14:20.230865398] stat = 0 (0.00%) [20090122-23:14:20.232648272] writeall = 0 (0.00%) [20090122-23:14:20.234732428] writeall_fsync = 0 (0.00%) [20090122-23:14:20.236568077] open_close = 0 (0.00%) [20090122-23:14:20.238354918] write_fsync = 0 (0.00%) [20090122-23:14:20.240269013] create_fsync = 0 (0.00%) [20090122-23:14:20.242072685] append_fsync = 0 (0.00%) [20090122-23:14:20.243932430] [20090122-23:14:20.245791579] FileSystem /mnt/ffsb1 [20090122-23:14:20.247541626] ========== [20090122-23:14:20.249354798] num_dirs = 0 [20090122-23:14:20.251251034] starting files = 1024 [20090122-23:14:20.253024810] [20090122-23:14:20.254877956] min file size = 36700160 (35MB) [20090122-23:14:20.256643584] max file size = 36700160 (35MB) [20090122-23:14:20.258647196] directio = off [20090122-23:14:20.260550137] alignedio = on [20090122-23:14:20.262400976] bufferedio = off [20090122-23:14:20.264201548] [20090122-23:14:20.266362454] aging is off [20090122-23:14:20.268656847] current utilization = 52.33% [20090122-23:14:20.270679411] [20090122-23:14:20.272600573] checking existing fs: /mnt/ffsb1 [20090122-23:14:20.348642246] fs setup took 0 secs [20090122-23:14:21.373085984] Syncing()...1 sec [20090122-23:14:21.375105825] Starting Actual Benchmark At: Thu Jan 22 23:14:21 2009 [20090122-23:14:21.387968358] [20090122-23:19:31.102719507] Syncing()...0 sec [20090122-23:19:31.105854787] FFSB benchmark finished at: Thu Jan 22 23:19:31 2009 [20090122-23:19:31.108705673] [20090122-23:19:31.111208415] Results: [20090122-23:19:31.126793017] Benchmark took 309.73 sec [20090122-23:19:31.129319162] [20090122-23:19:31.131902767] Total Results [20090122-23:19:31.148610930] =============== [20090122-23:19:31.151336903] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090122-23:19:31.155965297] ======= ============ ========= ======= =========== ========== [20090122-23:19:31.159393395] read : 146432 472.78 100.000% 100.000% 1.85MB/sec [20090122-23:19:31.163093244] - [20090122-23:19:31.166092235] 472.78 Transactions per Second [20090122-23:19:31.169532631] [20090122-23:19:31.172636081] Throughput Results [20090122-23:19:31.188458743] =================== [20090122-23:19:31.191905718] Read Throughput: 1.85MB/sec [20090122-23:19:31.195718629] [20090122-23:19:31.198590641] System Call Latency statistics in millisecs [20090122-23:19:31.201476849] ===== [20090122-23:19:31.204206661] Min Avg Max Total Calls [20090122-23:19:31.207036042] ======== ======== ======== ============ [20090122-23:19:31.209883223] [ open] 0.005000 0.014094 0.028000 572 [20090122-23:19:31.212794430] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:19:31.215806748] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:19:31.218941367] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:19:31.223426015] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:19:31.226436614] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:19:31.229221534] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:19:31.232115363] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:19:31.235837700] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:19:31.238442119] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:19:31.240950931] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:19:31.243455691] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:19:31.246302648] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:19:31.249119706] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:19:31.253287806] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:19:31.256031862] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:19:31.258853024] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:19:31.261646598] msec_range[16] 0.020000 - 0.050000 : 100 [20090122-23:19:31.264656059] msec_range[17] 0.010000 - 0.020000 : 321 [20090122-23:19:31.268558263] msec_range[18] 0.000000 - 0.010000 : 151 [20090122-23:19:31.271114875] [20090122-23:19:31.273494980] [ read] 0.001000 66.870264 3406.294922 146432 [20090122-23:19:31.275958251] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:19:31.278331328] msec_range[1] 2000.000000 - 5000.000000 : 455 [20090122-23:19:31.280915954] msec_range[2] 1000.000000 - 2000.000000 : 2013 [20090122-23:19:31.284007932] msec_range[3] 500.000000 - 1000.000000 : 1475 [20090122-23:19:31.287253587] msec_range[4] 200.000000 - 500.000000 : 3258 [20090122-23:19:31.291232917] msec_range[5] 100.000000 - 200.000000 : 7708 [20090122-23:19:31.293968062] msec_range[6] 50.000000 - 100.000000 : 15171 [20090122-23:19:31.296441114] msec_range[7] 20.000000 - 50.000000 : 30447 [20090122-23:19:31.299491173] msec_range[8] 10.000000 - 20.000000 : 26828 [20090122-23:19:31.302563176] msec_range[9] 5.000000 - 10.000000 : 25359 [20090122-23:19:31.305482013] msec_range[10] 2.000000 - 5.000000 : 23271 [20090122-23:19:31.308284658] msec_range[11] 1.000000 - 2.000000 : 6919 [20090122-23:19:31.311023463] msec_range[12] 0.500000 - 1.000000 : 100 [20090122-23:19:31.313531176] msec_range[13] 0.200000 - 0.500000 : 69 [20090122-23:19:31.316333580] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:19:31.319232910] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:19:31.322234687] msec_range[16] 0.020000 - 0.050000 : 2 [20090122-23:19:31.325149137] msec_range[17] 0.010000 - 0.020000 : 363 [20090122-23:19:31.327714873] msec_range[18] 0.000000 - 0.010000 : 2994 [20090122-23:19:31.330773749] [20090122-23:19:31.334910934] [ lseek] 0.000000 0.001149 0.018000 146432 [20090122-23:19:31.337885164] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:19:31.340614099] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:19:31.343960457] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:19:31.346607313] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:19:31.349657393] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:19:31.352716029] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:19:31.355136652] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:19:31.358037465] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:19:31.361372998] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:19:31.364247569] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:19:31.367231211] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:19:31.369991276] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:19:31.372472481] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:19:31.375079326] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:19:31.381934352] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:19:31.385120488] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:19:31.387678565] msec_range[16] 0.020000 - 0.050000 : 0 [20090122-23:19:31.390332788] msec_range[17] 0.010000 - 0.020000 : 61 [20090122-23:19:31.393012244] msec_range[18] 0.000000 - 0.010000 : 146371 [20090122-23:19:31.395736043] [20090122-23:19:31.398127871] [ close] 0.002000 0.004650 0.015000 572 [20090122-23:19:31.400466808] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:19:31.403748401] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:19:31.406562180] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:19:31.409290177] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:19:31.411870262] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:19:31.414251290] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:19:31.417019771] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:19:31.419675927] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:19:31.422217914] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:19:31.424624559] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:19:31.427195120] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:19:31.430139759] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:19:31.432483828] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:19:31.435033066] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:19:31.437568341] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:19:31.439712488] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:19:31.442328330] msec_range[16] 0.020000 - 0.050000 : 0 [20090122-23:19:31.444805739] msec_range[17] 0.010000 - 0.020000 : 16 [20090122-23:19:31.447233485] msec_range[18] 0.000000 - 0.010000 : 556 [20090122-23:19:31.449631669] [20090122-23:19:31.452440278] [20090122-23:19:31.455086825] [20090122-23:19:31.457627672] [20090122-23:19:31.460236984] 0.1% User Time [20090122-23:19:31.462596670] 1.2% System Time [20090122-23:19:31.464774711] 1.4% CPU Utilization [20090122-23:19:31.467159624] Profilers reporting [20090122-23:19:31.469611338] /autobench/scripts/doprofilers: line 33: 14753 Terminated ${CMDS[$i]} [20090122-23:19:31.472103149] /autobench/scripts/doprofilers: line 33: 14767 Terminated ${CMDS[$i]} [20090122-23:19:31.474774574] /autobench/scripts/doprofilers: line 33: 14803 Terminated ${CMDS[$i]} [20090122-23:19:38.472454489] Profilers postprocessing [20090122-23:19:38.556835709] Processing File : iostat.001 [20090122-23:19:38.559258154] Discovered iostat_interval=[5] [20090122-23:19:39.083318315] Processing Directory : sar.breakout.001 [20090122-23:19:39.085222122] Discovered sar_interval=[5] [20090122-23:19:39.248981814] Processing File : mpstat.001 [20090122-23:19:39.251183041] Discovered mpstat_interval=[5] [20090122-23:19:40.381267405] Stopping profiling. [20090122-23:19:40.385325107] Killing daemon. [20090122-23:19:41.545403369] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.09-01-22_23.14.12/analysis/oprofile.001 [20090122-23:19:41.548770188] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.09-01-22_23.14.12/analysis/oprofile-brief.001 [20090122-23:19:41.969387816] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline' [20090122-23:19:43.275282070] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090122-23:19:43.739078762] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20090122-23:19:43.849079638] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=1' [20090122-23:19:43.907917930] new log requested [20090122-23:19:43.930361613] Running command ffsb [20090122-23:19:50.770065339] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20090122-23:19:50.791512177] Importing argument : num_threads=1 [20090122-23:19:50.817811725] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090122-23:19:50.880659646] FFSB version 6.0-RC2 started [20090122-23:19:50.882928607] [20090122-23:19:50.885162568] benchmark time = 300 [20090122-23:19:50.887162308] ThreadGroup 0 [20090122-23:19:50.889110045] ================ [20090122-23:19:50.891045950] num_threads = 1 [20090122-23:19:50.892992695] [20090122-23:19:50.894922944] read_random = off [20090122-23:19:50.896808991] read_size = 0 (0B) [20090122-23:19:50.898617367] read_blocksize = 0 (0B) [20090122-23:19:50.900537187] read_skip = off [20090122-23:19:50.902364130] read_skipsize = 0 (0B) [20090122-23:19:50.904190147] [20090122-23:19:50.906118516] write_random = on [20090122-23:19:50.907953397] write_size = 1048576 (1MB) [20090122-23:19:50.909812034] fsync_file = 0 [20090122-23:19:50.911683713] write_blocksize = 4096 (4KB) [20090122-23:19:50.913606996] wait time = 0 [20090122-23:19:50.915442853] [20090122-23:19:50.917290588] op weights [20090122-23:19:50.919085799] read = 0 (0.00%) [20090122-23:19:50.920975838] readall = 0 (0.00%) [20090122-23:19:50.923278657] write = 1 (100.00%) [20090122-23:19:50.925269520] create = 0 (0.00%) [20090122-23:19:50.927293954] append = 0 (0.00%) [20090122-23:19:50.929170287] delete = 0 (0.00%) [20090122-23:19:50.931067944] metaop = 0 (0.00%) [20090122-23:19:50.932877819] createdir = 0 (0.00%) [20090122-23:19:50.934821584] stat = 0 (0.00%) [20090122-23:19:50.936770037] writeall = 0 (0.00%) [20090122-23:19:50.938619556] writeall_fsync = 0 (0.00%) [20090122-23:19:50.940398884] open_close = 0 (0.00%) [20090122-23:19:50.942236442] write_fsync = 0 (0.00%) [20090122-23:19:50.944134959] create_fsync = 0 (0.00%) [20090122-23:19:50.945973377] append_fsync = 0 (0.00%) [20090122-23:19:50.947773491] [20090122-23:19:50.949638822] FileSystem /mnt/ffsb1 [20090122-23:19:50.951542557] ========== [20090122-23:19:50.953353597] num_dirs = 0 [20090122-23:19:50.955354257] starting files = 1024 [20090122-23:19:50.957206710] [20090122-23:19:50.959080343] min file size = 36700160 (35MB) [20090122-23:19:50.960942152] max file size = 36700160 (35MB) [20090122-23:19:50.962926591] directio = off [20090122-23:19:50.964790447] alignedio = on [20090122-23:19:50.966646511] bufferedio = off [20090122-23:19:50.968465636] [20090122-23:19:50.970341647] aging is off [20090122-23:19:50.972261021] current utilization = 52.33% [20090122-23:19:50.974062443] [20090122-23:19:50.976069019] checking existing fs: /mnt/ffsb1 [20090122-23:19:51.050573043] fs setup took 0 secs [20090122-23:19:52.147844520] Syncing()...1 sec [20090122-23:19:52.149813154] Starting Actual Benchmark At: Thu Jan 22 23:19:52 2009 [20090122-23:19:52.162495797] [20090122-23:24:55.864345123] Syncing()...0 sec [20090122-23:24:55.867342301] FFSB benchmark finished at: Thu Jan 22 23:24:55 2009 [20090122-23:24:55.870402551] [20090122-23:24:55.873240684] Results: [20090122-23:24:55.888796972] Benchmark took 303.71 sec [20090122-23:24:55.891193642] [20090122-23:24:55.893916386] Total Results [20090122-23:24:55.909728917] =============== [20090122-23:24:55.913035216] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090122-23:24:55.915943330] ======= ============ ========= ======= =========== ========== [20090122-23:24:55.918800546] write : 180736 595.09 100.000% 100.000% 2.32MB/sec [20090122-23:24:55.921353752] - [20090122-23:24:55.924036389] 595.09 Transactions per Second [20090122-23:24:55.926708802] [20090122-23:24:55.930758520] Throughput Results [20090122-23:24:55.946603002] =================== [20090122-23:24:55.950904554] Write Throughput: 2.32MB/sec [20090122-23:24:55.953673086] [20090122-23:24:55.956600118] System Call Latency statistics in millisecs [20090122-23:24:55.959932246] ===== [20090122-23:24:55.963046957] Min Avg Max Total Calls [20090122-23:24:55.967133507] ======== ======== ======== ============ [20090122-23:24:55.972818030] [ open] 0.005000 0.008551 0.033000 706 [20090122-23:24:55.975816552] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:24:55.978705507] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:24:55.981602979] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:24:55.984337761] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:24:55.989222684] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:24:55.991878262] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:24:55.995148781] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:24:55.998322702] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:24:56.001480423] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:24:56.004491962] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:24:56.007223648] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:24:56.009764112] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:24:56.012637127] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:24:56.015431825] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:24:56.018062822] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:24:56.021144215] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:24:56.025024111] msec_range[16] 0.020000 - 0.050000 : 37 [20090122-23:24:56.027867681] msec_range[17] 0.010000 - 0.020000 : 152 [20090122-23:24:56.031547925] msec_range[18] 0.000000 - 0.010000 : 517 [20090122-23:24:56.034956898] [20090122-23:24:56.037573189] [ write] 0.005000 1.675678 3182.584961 180736 [20090122-23:24:56.040188800] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:24:56.042755326] msec_range[1] 2000.000000 - 5000.000000 : 33 [20090122-23:24:56.047715361] msec_range[2] 1000.000000 - 2000.000000 : 69 [20090122-23:24:56.050381208] msec_range[3] 500.000000 - 1000.000000 : 96 [20090122-23:24:56.053566345] msec_range[4] 200.000000 - 500.000000 : 130 [20090122-23:24:56.057953989] msec_range[5] 100.000000 - 200.000000 : 26 [20090122-23:24:56.060891336] msec_range[6] 50.000000 - 100.000000 : 5 [20090122-23:24:56.064166725] msec_range[7] 20.000000 - 50.000000 : 6 [20090122-23:24:56.068917319] msec_range[8] 10.000000 - 20.000000 : 109 [20090122-23:24:56.071840901] msec_range[9] 5.000000 - 10.000000 : 405 [20090122-23:24:56.074660625] msec_range[10] 2.000000 - 5.000000 : 2770 [20090122-23:24:56.077793847] msec_range[11] 1.000000 - 2.000000 : 923 [20090122-23:24:56.081392901] msec_range[12] 0.500000 - 1.000000 : 22 [20090122-23:24:56.084271871] msec_range[13] 0.200000 - 0.500000 : 6 [20090122-23:24:56.087141556] msec_range[14] 0.100000 - 0.200000 : 15 [20090122-23:24:56.090592285] msec_range[15] 0.050000 - 0.100000 : 6 [20090122-23:24:56.093602567] msec_range[16] 0.020000 - 0.050000 : 5910 [20090122-23:24:56.097365339] msec_range[17] 0.010000 - 0.020000 : 87600 [20090122-23:24:56.100927651] msec_range[18] 0.000000 - 0.010000 : 82605 [20090122-23:24:56.104092336] [20090122-23:24:56.108534414] [ lseek] 0.000000 0.000943 0.177000 180736 [20090122-23:24:56.111331341] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:24:56.114324051] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:24:56.116968881] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:24:56.120941856] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:24:56.123772480] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:24:56.126908220] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:24:56.129625170] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:24:56.133095756] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:24:56.135897361] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:24:56.138673967] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:24:56.141494059] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:24:56.144279561] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:24:56.147983964] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:24:56.150705455] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:24:56.153644178] msec_range[14] 0.100000 - 0.200000 : 1 [20090122-23:24:56.156368710] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:24:56.158912115] msec_range[16] 0.020000 - 0.050000 : 9 [20090122-23:24:56.161379758] msec_range[17] 0.010000 - 0.020000 : 20 [20090122-23:24:56.163799139] msec_range[18] 0.000000 - 0.010000 : 180706 [20090122-23:24:56.166150963] [20090122-23:24:56.168716451] [ close] 0.002000 0.002997 0.028000 706 [20090122-23:24:56.171325754] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090122-23:24:56.173897637] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090122-23:24:56.176397914] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090122-23:24:56.179294548] msec_range[3] 500.000000 - 1000.000000 : 0 [20090122-23:24:56.181868786] msec_range[4] 200.000000 - 500.000000 : 0 [20090122-23:24:56.184485258] msec_range[5] 100.000000 - 200.000000 : 0 [20090122-23:24:56.187047745] msec_range[6] 50.000000 - 100.000000 : 0 [20090122-23:24:56.189592033] msec_range[7] 20.000000 - 50.000000 : 0 [20090122-23:24:56.192049493] msec_range[8] 10.000000 - 20.000000 : 0 [20090122-23:24:56.194491270] msec_range[9] 5.000000 - 10.000000 : 0 [20090122-23:24:56.196777284] msec_range[10] 2.000000 - 5.000000 : 0 [20090122-23:24:56.199093022] msec_range[11] 1.000000 - 2.000000 : 0 [20090122-23:24:56.201552766] msec_range[12] 0.500000 - 1.000000 : 0 [20090122-23:24:56.203887933] msec_range[13] 0.200000 - 0.500000 : 0 [20090122-23:24:56.206439342] msec_range[14] 0.100000 - 0.200000 : 0 [20090122-23:24:56.209135498] msec_range[15] 0.050000 - 0.100000 : 0 [20090122-23:24:56.211531289] msec_range[16] 0.020000 - 0.050000 : 1 [20090122-23:24:56.213947917] msec_range[17] 0.010000 - 0.020000 : 5 [20090122-23:24:56.216435798] msec_range[18] 0.000000 - 0.010000 : 700 [20090122-23:24:56.218731503] [20090122-23:24:56.221112286] [20090122-23:24:56.223558237] [20090122-23:24:56.225885584] [20090122-23:24:56.228239908] 0.1% User Time [20090122-23:24:56.231633020] 0.7% System Time [20090122-23:24:56.234549507] 0.8% CPU Utilization [20090122-23:24:56.237076119] Profilers reporting [20090122-23:24:56.239694084] /autobench/scripts/doprofilers: line 33: 20609 Terminated ${CMDS[$i]} [20090122-23:24:56.242258941] /autobench/scripts/doprofilers: line 33: 20632 Terminated ${CMDS[$i]} [20090122-23:24:56.244642872] /autobench/scripts/doprofilers: line 33: 20664 Terminated ${CMDS[$i]} [20090122-23:25:03.787620683] Profilers postprocessing [20090122-23:25:03.874340693] Processing File : iostat.001 [20090122-23:25:03.876720319] Discovered iostat_interval=[5] [20090122-23:25:04.383365652] Processing Directory : sar.breakout.001 [20090122-23:25:04.389665163] Discovered sar_interval=[5] [20090122-23:25:04.547972956] Processing File : mpstat.001 [20090122-23:25:04.550242252] Discovered mpstat_interval=[5] [20090122-23:25:05.680615114] Stopping profiling. [20090122-23:25:05.685012079] Killing daemon. [20090122-23:25:06.843802727] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.09-01-22_23.19.43/analysis/oprofile.001 [20090122-23:25:06.846618221] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.09-01-22_23.19.43/analysis/oprofile-brief.001 [20090122-23:25:07.261490461] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-01-22_2238/ext3-baseline'