| 1 | #!/usr/bin/env python |
| 2 | |
| 3 | # module to parse fio histogram log files, not using pandas |
| 4 | # runs in python v2 or v3 |
| 5 | # to get help with the CLI: $ python fio-histo-log-pctiles.py -h |
| 6 | # this can be run standalone as a script but is callable |
| 7 | # assumes all threads run for same time duration |
| 8 | # assumes all threads are doing the same thing for the entire run |
| 9 | |
| 10 | # percentiles: |
| 11 | # 0 - min latency |
| 12 | # 50 - median |
| 13 | # 100 - max latency |
| 14 | |
| 15 | # TO-DO: |
| 16 | # separate read and write stats for randrw mixed workload |
| 17 | # report average latency if needed |
| 18 | # prove that it works (partially done with unit tests) |
| 19 | |
| 20 | # to run unit tests, set UNITTEST environment variable to anything |
| 21 | # if you do this, don't pass normal CLI parameters to it |
| 22 | # otherwise it runs the CLI |
| 23 | |
| 24 | import sys, os, math, copy |
| 25 | from copy import deepcopy |
| 26 | import argparse |
| 27 | import unittest2 |
| 28 | |
| 29 | msec_per_sec = 1000 |
| 30 | nsec_per_usec = 1000 |
| 31 | |
| 32 | class FioHistoLogExc(Exception): |
| 33 | pass |
| 34 | |
| 35 | # if there is an error, print message, and exit with error status |
| 36 | |
| 37 | def myabort(msg): |
| 38 | print('ERROR: ' + msg) |
| 39 | sys.exit(1) |
| 40 | |
| 41 | # convert histogram log file into a list of |
| 42 | # (time_ms, direction, bsz, buckets) tuples where |
| 43 | # - time_ms is the time in msec at which the log record was written |
| 44 | # - direction is 0 (read) or 1 (write) |
| 45 | # - bsz is block size (not used) |
| 46 | # - buckets is a CSV list of counters that make up the histogram |
| 47 | # caller decides if the expected number of counters are present |
| 48 | |
| 49 | |
| 50 | def exception_suffix( record_num, pathname ): |
| 51 | return 'in histogram record %d file %s' % (record_num+1, pathname) |
| 52 | |
| 53 | # log file parser raises FioHistoLogExc exceptions |
| 54 | # it returns histogram buckets in whatever unit fio uses |
| 55 | |
| 56 | def parse_hist_file(logfn, buckets_per_interval): |
| 57 | max_timestamp_ms = 0.0 |
| 58 | |
| 59 | with open(logfn, 'r') as f: |
| 60 | records = [ l.strip() for l in f.readlines() ] |
| 61 | intervals = [] |
| 62 | for k, r in enumerate(records): |
| 63 | if r == '': |
| 64 | continue |
| 65 | tokens = r.split(',') |
| 66 | try: |
| 67 | int_tokens = [ int(t) for t in tokens ] |
| 68 | except ValueError as e: |
| 69 | raise FioHistoLogExc('non-integer value %s' % exception_suffix(k+1, logfn)) |
| 70 | |
| 71 | neg_ints = list(filter( lambda tk : tk < 0, int_tokens )) |
| 72 | if len(neg_ints) > 0: |
| 73 | raise FioHistoLogExc('negative integer value %s' % exception_suffix(k+1, logfn)) |
| 74 | |
| 75 | if len(int_tokens) < 3: |
| 76 | raise FioHistoLogExc('too few numbers %s' % exception_suffix(k+1, logfn)) |
| 77 | |
| 78 | time_ms = int_tokens[0] |
| 79 | if time_ms > max_timestamp_ms: |
| 80 | max_timestamp_ms = time_ms |
| 81 | |
| 82 | direction = int_tokens[1] |
| 83 | if direction != 0 and direction != 1: |
| 84 | raise FioHistoLogExc('invalid I/O direction %s' % exception_suffix(k+1, logfn)) |
| 85 | |
| 86 | bsz = int_tokens[2] |
| 87 | if bsz > (1 << 24): |
| 88 | raise FioHistoLogExc('block size too large %s' % exception_suffix(k+1, logfn)) |
| 89 | |
| 90 | buckets = int_tokens[3:] |
| 91 | if len(buckets) != buckets_per_interval: |
| 92 | raise FioHistoLogExc('%d buckets per interval but %d expected in %s' % |
| 93 | (len(buckets), buckets_per_interval, exception_suffix(k+1, logfn))) |
| 94 | intervals.append((time_ms, direction, bsz, buckets)) |
| 95 | if len(intervals) == 0: |
| 96 | raise FioHistoLogExc('no records in %s' % logfn) |
| 97 | return (intervals, max_timestamp_ms) |
| 98 | |
| 99 | |
| 100 | # compute time range for each bucket index in histogram record |
| 101 | # see comments in https://github.com/axboe/fio/blob/master/stat.h |
| 102 | # for description of bucket groups and buckets |
| 103 | # fio v3 bucket ranges are in nanosec (since response times are measured in nanosec) |
| 104 | # but we convert fio v3 nanosecs to floating-point microseconds |
| 105 | |
| 106 | def time_ranges(groups, counters_per_group, fio_version=3): |
| 107 | bucket_width = 1 |
| 108 | bucket_base = 0 |
| 109 | bucket_intervals = [] |
| 110 | for g in range(0, groups): |
| 111 | for b in range(0, counters_per_group): |
| 112 | rmin = float(bucket_base) |
| 113 | rmax = rmin + bucket_width |
| 114 | if fio_version == 3: |
| 115 | rmin /= nsec_per_usec |
| 116 | rmax /= nsec_per_usec |
| 117 | bucket_intervals.append( [rmin, rmax] ) |
| 118 | bucket_base += bucket_width |
| 119 | if g != 0: |
| 120 | bucket_width *= 2 |
| 121 | return bucket_intervals |
| 122 | |
| 123 | |
| 124 | # compute number of time quantum intervals in the test |
| 125 | |
| 126 | def get_time_intervals(time_quantum, max_timestamp_ms): |
| 127 | # round down to nearest second |
| 128 | max_timestamp = max_timestamp_ms // msec_per_sec |
| 129 | # round up to nearest whole multiple of time_quantum |
| 130 | time_interval_count = (max_timestamp + time_quantum) // time_quantum |
| 131 | end_time = time_interval_count * time_quantum |
| 132 | return (end_time, time_interval_count) |
| 133 | |
| 134 | # align raw histogram log data to time quantum so |
| 135 | # we can then combine histograms from different threads with addition |
| 136 | # for randrw workload we count both reads and writes in same output bucket |
| 137 | # but we separate reads and writes for purposes of calculating |
| 138 | # end time for histogram record. |
| 139 | # this requires us to weight a raw histogram bucket by the |
| 140 | # fraction of time quantum that the bucket overlaps the current |
| 141 | # time quantum interval |
| 142 | # for example, if we have a bucket with 515 samples for time interval |
| 143 | # [ 1010, 2014 ] msec since start of test, and time quantum is 1 sec, then |
| 144 | # for time quantum interval [ 1000, 2000 ] msec, the overlap is |
| 145 | # (2000 - 1010) / (2000 - 1000) = 0.99 |
| 146 | # so the contribution of this bucket to this time quantum is |
| 147 | # 515 x 0.99 = 509.85 |
| 148 | |
| 149 | def align_histo_log(raw_histogram_log, time_quantum, bucket_count, max_timestamp_ms): |
| 150 | |
| 151 | # slice up test time int intervals of time_quantum seconds |
| 152 | |
| 153 | (end_time, time_interval_count) = get_time_intervals(time_quantum, max_timestamp_ms) |
| 154 | time_qtm_ms = time_quantum * msec_per_sec |
| 155 | end_time_ms = end_time * msec_per_sec |
| 156 | aligned_intervals = [] |
| 157 | for j in range(0, time_interval_count): |
| 158 | aligned_intervals.append(( |
| 159 | j * time_qtm_ms, |
| 160 | [ 0.0 for j in range(0, bucket_count) ] )) |
| 161 | |
| 162 | log_record_count = len(raw_histogram_log) |
| 163 | for k, record in enumerate(raw_histogram_log): |
| 164 | |
| 165 | # find next record with same direction to get end-time |
| 166 | # have to avoid going past end of array |
| 167 | # for fio randrw workload, |
| 168 | # we have read and write records on same time interval |
| 169 | # sometimes read and write records are in opposite order |
| 170 | # assertion checks that next read/write record |
| 171 | # can be separated by at most 2 other records |
| 172 | |
| 173 | (time_msec, direction, sz, interval_buckets) = record |
| 174 | if k+1 < log_record_count: |
| 175 | (time_msec_end, direction2, _, _) = raw_histogram_log[k+1] |
| 176 | if direction2 != direction: |
| 177 | if k+2 < log_record_count: |
| 178 | (time_msec_end, direction2, _, _) = raw_histogram_log[k+2] |
| 179 | if direction2 != direction: |
| 180 | if k+3 < log_record_count: |
| 181 | (time_msec_end, direction2, _, _) = raw_histogram_log[k+3] |
| 182 | assert direction2 == direction |
| 183 | else: |
| 184 | time_msec_end = end_time_ms |
| 185 | else: |
| 186 | time_msec_end = end_time_ms |
| 187 | else: |
| 188 | time_msec_end = end_time_ms |
| 189 | |
| 190 | # calculate first quantum that overlaps this histogram record |
| 191 | |
| 192 | qtm_start_ms = (time_msec // time_qtm_ms) * time_qtm_ms |
| 193 | qtm_end_ms = ((time_msec + time_qtm_ms) // time_qtm_ms) * time_qtm_ms |
| 194 | qtm_index = qtm_start_ms // time_qtm_ms |
| 195 | |
| 196 | # for each quantum that overlaps this histogram record's time interval |
| 197 | |
| 198 | while qtm_start_ms < time_msec_end: # while quantum overlaps record |
| 199 | |
| 200 | # calculate fraction of time that this quantum |
| 201 | # overlaps histogram record's time interval |
| 202 | |
| 203 | overlap_start = max(qtm_start_ms, time_msec) |
| 204 | overlap_end = min(qtm_end_ms, time_msec_end) |
| 205 | weight = float(overlap_end - overlap_start) |
| 206 | weight /= (time_msec_end - time_msec) |
| 207 | (_,aligned_histogram) = aligned_intervals[qtm_index] |
| 208 | for bx, b in enumerate(interval_buckets): |
| 209 | weighted_bucket = weight * b |
| 210 | aligned_histogram[bx] += weighted_bucket |
| 211 | |
| 212 | # advance to the next time quantum |
| 213 | |
| 214 | qtm_start_ms += time_qtm_ms |
| 215 | qtm_end_ms += time_qtm_ms |
| 216 | qtm_index += 1 |
| 217 | |
| 218 | return aligned_intervals |
| 219 | |
| 220 | # add histogram in "source" to histogram in "target" |
| 221 | # it is assumed that the 2 histograms are precisely time-aligned |
| 222 | |
| 223 | def add_to_histo_from( target, source ): |
| 224 | for b in range(0, len(source)): |
| 225 | target[b] += source[b] |
| 226 | |
| 227 | # compute percentiles |
| 228 | # inputs: |
| 229 | # buckets: histogram bucket array |
| 230 | # wanted: list of floating-pt percentiles to calculate |
| 231 | # time_ranges: [tmin,tmax) time interval for each bucket |
| 232 | # returns None if no I/O reported. |
| 233 | # otherwise we would be dividing by zero |
| 234 | # think of buckets as probability distribution function |
| 235 | # and this loop is integrating to get cumulative distribution function |
| 236 | |
| 237 | def get_pctiles(buckets, wanted, time_ranges): |
| 238 | |
| 239 | # get total of IO requests done |
| 240 | total_ios = 0 |
| 241 | for io_count in buckets: |
| 242 | total_ios += io_count |
| 243 | |
| 244 | # don't return percentiles if no I/O was done during interval |
| 245 | if total_ios == 0.0: |
| 246 | return None |
| 247 | |
| 248 | pctile_count = len(wanted) |
| 249 | |
| 250 | # results returned as dictionary keyed by percentile |
| 251 | pctile_result = {} |
| 252 | |
| 253 | # index of next percentile in list |
| 254 | pctile_index = 0 |
| 255 | |
| 256 | # next percentile |
| 257 | next_pctile = wanted[pctile_index] |
| 258 | |
| 259 | # no one is interested in percentiles bigger than this but not 100.0 |
| 260 | # this prevents floating-point error from preventing loop exit |
| 261 | almost_100 = 99.9999 |
| 262 | |
| 263 | # pct is the percentile corresponding to |
| 264 | # all I/O requests up through bucket b |
| 265 | pct = 0.0 |
| 266 | total_so_far = 0 |
| 267 | for b, io_count in enumerate(buckets): |
| 268 | if io_count == 0: |
| 269 | continue |
| 270 | total_so_far += io_count |
| 271 | # last_pct_lt is the percentile corresponding to |
| 272 | # all I/O requests up to, but not including, bucket b |
| 273 | last_pct = pct |
| 274 | pct = 100.0 * float(total_so_far) / total_ios |
| 275 | # a single bucket could satisfy multiple pctiles |
| 276 | # so this must be a while loop |
| 277 | # for 100-percentile (max latency) case, no bucket exceeds it |
| 278 | # so we must stop there. |
| 279 | while ((next_pctile == 100.0 and pct >= almost_100) or |
| 280 | (next_pctile < 100.0 and pct > next_pctile)): |
| 281 | # interpolate between min and max time for bucket time interval |
| 282 | # we keep the time_ranges access inside this loop, |
| 283 | # even though it could be above the loop, |
| 284 | # because in many cases we will not be even entering |
| 285 | # the loop so we optimize out these accesses |
| 286 | range_max_time = time_ranges[b][1] |
| 287 | range_min_time = time_ranges[b][0] |
| 288 | offset_frac = (next_pctile - last_pct)/(pct - last_pct) |
| 289 | interpolation = range_min_time + (offset_frac*(range_max_time - range_min_time)) |
| 290 | pctile_result[next_pctile] = interpolation |
| 291 | pctile_index += 1 |
| 292 | if pctile_index == pctile_count: |
| 293 | break |
| 294 | next_pctile = wanted[pctile_index] |
| 295 | if pctile_index == pctile_count: |
| 296 | break |
| 297 | assert pctile_index == pctile_count |
| 298 | return pctile_result |
| 299 | |
| 300 | |
| 301 | # this is really the main program |
| 302 | |
| 303 | def compute_percentiles_from_logs(): |
| 304 | parser = argparse.ArgumentParser() |
| 305 | parser.add_argument("--fio-version", dest="fio_version", |
| 306 | default="3", choices=[2,3], type=int, |
| 307 | help="fio version (default=3)") |
| 308 | parser.add_argument("--bucket-groups", dest="bucket_groups", default="29", type=int, |
| 309 | help="fio histogram bucket groups (default=29)") |
| 310 | parser.add_argument("--bucket-bits", dest="bucket_bits", |
| 311 | default="6", type=int, |
| 312 | help="fio histogram buckets-per-group bits (default=6 means 64 buckets/group)") |
| 313 | parser.add_argument("--percentiles", dest="pctiles_wanted", |
| 314 | default="0 50 95 99 100", type=float, nargs='+', |
| 315 | help="fio histogram buckets-per-group bits (default=6 means 64 buckets/group)") |
| 316 | parser.add_argument("--time-quantum", dest="time_quantum", |
| 317 | default="1", type=int, |
| 318 | help="time quantum in seconds (default=1)") |
| 319 | parser.add_argument("--output-unit", dest="output_unit", |
| 320 | default="usec", type=str, |
| 321 | help="Latency percentile output unit: msec|usec|nsec (default usec)") |
| 322 | parser.add_argument("file_list", nargs='+') |
| 323 | args = parser.parse_args() |
| 324 | print(args) |
| 325 | |
| 326 | if not args.bucket_groups: |
| 327 | # default changes based on fio version |
| 328 | if fio_version == 2: |
| 329 | args.bucket_groups = 19 |
| 330 | else: |
| 331 | # default in fio 3.x |
| 332 | args.bucket_groups = 29 |
| 333 | |
| 334 | # print parameters |
| 335 | |
| 336 | print('bucket groups = %d' % args.bucket_groups) |
| 337 | print('bucket bits = %d' % args.bucket_bits) |
| 338 | print('time quantum = %d sec' % args.time_quantum) |
| 339 | print('percentiles = %s' % ','.join([ str(p) for p in args.pctiles_wanted ])) |
| 340 | buckets_per_group = 1 << args.bucket_bits |
| 341 | print('buckets per group = %d' % buckets_per_group) |
| 342 | buckets_per_interval = buckets_per_group * args.bucket_groups |
| 343 | print('buckets per interval = %d ' % buckets_per_interval) |
| 344 | bucket_index_range = range(0, buckets_per_interval) |
| 345 | if args.time_quantum == 0: |
| 346 | print('ERROR: time-quantum must be a positive number of seconds') |
| 347 | print('output unit = ' + args.output_unit) |
| 348 | if args.output_unit == 'msec': |
| 349 | time_divisor = 1000.0 |
| 350 | elif args.output_unit == 'usec': |
| 351 | time_divisor = 1.0 |
| 352 | |
| 353 | # calculate response time interval associated with each histogram bucket |
| 354 | |
| 355 | bucket_times = time_ranges(args.bucket_groups, buckets_per_group, fio_version=args.fio_version) |
| 356 | |
| 357 | # construct template for each histogram bucket array with buckets all zeroes |
| 358 | # we just copy this for each new histogram |
| 359 | |
| 360 | zeroed_buckets = [ 0.0 for r in bucket_index_range ] |
| 361 | |
| 362 | # print CSV header just like fiologparser_hist does |
| 363 | |
| 364 | header = 'msec, ' |
| 365 | for p in args.pctiles_wanted: |
| 366 | header += '%3.1f, ' % p |
| 367 | print('time (millisec), percentiles in increasing order with values in ' + args.output_unit) |
| 368 | print(header) |
| 369 | |
| 370 | # parse the histogram logs |
| 371 | # assumption: each bucket has a monotonically increasing time |
| 372 | # assumption: time ranges do not overlap for a single thread's records |
| 373 | # (exception: if randrw workload, then there is a read and a write |
| 374 | # record for the same time interval) |
| 375 | |
| 376 | max_timestamp_all_logs = 0 |
| 377 | hist_files = {} |
| 378 | for fn in args.file_list: |
| 379 | try: |
| 380 | (hist_files[fn], max_timestamp_ms) = parse_hist_file(fn, buckets_per_interval) |
| 381 | except FioHistoLogExc as e: |
| 382 | myabort(str(e)) |
| 383 | max_timestamp_all_logs = max(max_timestamp_all_logs, max_timestamp_ms) |
| 384 | |
| 385 | (end_time, time_interval_count) = get_time_intervals(args.time_quantum, max_timestamp_all_logs) |
| 386 | all_threads_histograms = [ ((j*args.time_quantum*msec_per_sec), deepcopy(zeroed_buckets)) |
| 387 | for j in range(0, time_interval_count) ] |
| 388 | |
| 389 | for logfn in hist_files.keys(): |
| 390 | aligned_per_thread = align_histo_log(hist_files[logfn], |
| 391 | args.time_quantum, |
| 392 | buckets_per_interval, |
| 393 | max_timestamp_all_logs) |
| 394 | for t in range(0, time_interval_count): |
| 395 | (_, all_threads_histo_t) = all_threads_histograms[t] |
| 396 | (_, log_histo_t) = aligned_per_thread[t] |
| 397 | add_to_histo_from( all_threads_histo_t, log_histo_t ) |
| 398 | |
| 399 | # calculate percentiles across aggregate histogram for all threads |
| 400 | |
| 401 | for (t_msec, all_threads_histo_t) in all_threads_histograms: |
| 402 | record = '%d, ' % t_msec |
| 403 | pct = get_pctiles(all_threads_histo_t, args.pctiles_wanted, bucket_times) |
| 404 | if not pct: |
| 405 | for w in args.pctiles_wanted: |
| 406 | record += ', ' |
| 407 | else: |
| 408 | pct_keys = [ k for k in pct.keys() ] |
| 409 | pct_values = [ str(pct[wanted]/time_divisor) for wanted in sorted(pct_keys) ] |
| 410 | record += ', '.join(pct_values) |
| 411 | print(record) |
| 412 | |
| 413 | |
| 414 | |
| 415 | #end of MAIN PROGRAM |
| 416 | |
| 417 | |
| 418 | |
| 419 | ##### below are unit tests ############## |
| 420 | |
| 421 | import tempfile, shutil |
| 422 | from os.path import join |
| 423 | should_not_get_here = False |
| 424 | |
| 425 | class Test(unittest2.TestCase): |
| 426 | tempdir = None |
| 427 | |
| 428 | # a little less typing please |
| 429 | def A(self, boolean_val): |
| 430 | self.assertTrue(boolean_val) |
| 431 | |
| 432 | # initialize unit test environment |
| 433 | |
| 434 | @classmethod |
| 435 | def setUpClass(cls): |
| 436 | d = tempfile.mkdtemp() |
| 437 | Test.tempdir = d |
| 438 | |
| 439 | # remove anything left by unit test environment |
| 440 | # unless user sets UNITTEST_LEAVE_FILES environment variable |
| 441 | |
| 442 | @classmethod |
| 443 | def tearDownClass(cls): |
| 444 | if not os.getenv("UNITTEST_LEAVE_FILES"): |
| 445 | shutil.rmtree(cls.tempdir) |
| 446 | |
| 447 | def setUp(self): |
| 448 | self.fn = join(Test.tempdir, self.id()) |
| 449 | |
| 450 | def test_a_add_histos(self): |
| 451 | a = [ 1.0, 2.0 ] |
| 452 | b = [ 1.5, 2.5 ] |
| 453 | add_to_histo_from( a, b ) |
| 454 | self.A(a == [2.5, 4.5]) |
| 455 | self.A(b == [1.5, 2.5]) |
| 456 | |
| 457 | def test_b1_parse_log(self): |
| 458 | with open(self.fn, 'w') as f: |
| 459 | f.write('1234, 0, 4096, 1, 2, 3, 4\n') |
| 460 | f.write('5678,1,16384,5,6,7,8 \n') |
| 461 | (raw_histo_log, max_timestamp) = parse_hist_file(self.fn, 4) # 4 buckets per interval |
| 462 | self.A(len(raw_histo_log) == 2 and max_timestamp == 5678) |
| 463 | (time_ms, direction, bsz, histo) = raw_histo_log[0] |
| 464 | self.A(time_ms == 1234 and direction == 0 and bsz == 4096 and histo == [ 1, 2, 3, 4 ]) |
| 465 | (time_ms, direction, bsz, histo) = raw_histo_log[1] |
| 466 | self.A(time_ms == 5678 and direction == 1 and bsz == 16384 and histo == [ 5, 6, 7, 8 ]) |
| 467 | |
| 468 | def test_b2_parse_empty_log(self): |
| 469 | with open(self.fn, 'w') as f: |
| 470 | pass |
| 471 | try: |
| 472 | (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4) |
| 473 | self.A(should_not_get_here) |
| 474 | except FioHistoLogExc as e: |
| 475 | self.A(str(e).startswith('no records')) |
| 476 | |
| 477 | def test_b3_parse_empty_records(self): |
| 478 | with open(self.fn, 'w') as f: |
| 479 | f.write('\n') |
| 480 | f.write('1234, 0, 4096, 1, 2, 3, 4\n') |
| 481 | f.write('5678,1,16384,5,6,7,8 \n') |
| 482 | f.write('\n') |
| 483 | (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4) |
| 484 | self.A(len(raw_histo_log) == 2 and max_timestamp_ms == 5678) |
| 485 | (time_ms, direction, bsz, histo) = raw_histo_log[0] |
| 486 | self.A(time_ms == 1234 and direction == 0 and bsz == 4096 and histo == [ 1, 2, 3, 4 ]) |
| 487 | (time_ms, direction, bsz, histo) = raw_histo_log[1] |
| 488 | self.A(time_ms == 5678 and direction == 1 and bsz == 16384 and histo == [ 5, 6, 7, 8 ]) |
| 489 | |
| 490 | def test_b4_parse_non_int(self): |
| 491 | with open(self.fn, 'w') as f: |
| 492 | f.write('12, 0, 4096, 1a, 2, 3, 4\n') |
| 493 | try: |
| 494 | (raw_histo_log, _) = parse_hist_file(self.fn, 4) |
| 495 | self.A(False) |
| 496 | except FioHistoLogExc as e: |
| 497 | self.A(str(e).startswith('non-integer')) |
| 498 | |
| 499 | def test_b5_parse_neg_int(self): |
| 500 | with open(self.fn, 'w') as f: |
| 501 | f.write('-12, 0, 4096, 1, 2, 3, 4\n') |
| 502 | try: |
| 503 | (raw_histo_log, _) = parse_hist_file(self.fn, 4) |
| 504 | self.A(False) |
| 505 | except FioHistoLogExc as e: |
| 506 | self.A(str(e).startswith('negative integer')) |
| 507 | |
| 508 | def test_b6_parse_too_few_int(self): |
| 509 | with open(self.fn, 'w') as f: |
| 510 | f.write('0, 0\n') |
| 511 | try: |
| 512 | (raw_histo_log, _) = parse_hist_file(self.fn, 4) |
| 513 | self.A(False) |
| 514 | except FioHistoLogExc as e: |
| 515 | self.A(str(e).startswith('too few numbers')) |
| 516 | |
| 517 | def test_b7_parse_invalid_direction(self): |
| 518 | with open(self.fn, 'w') as f: |
| 519 | f.write('100, 2, 4096, 1, 2, 3, 4\n') |
| 520 | try: |
| 521 | (raw_histo_log, _) = parse_hist_file(self.fn, 4) |
| 522 | self.A(False) |
| 523 | except FioHistoLogExc as e: |
| 524 | self.A(str(e).startswith('invalid I/O direction')) |
| 525 | |
| 526 | def test_b8_parse_bsz_too_big(self): |
| 527 | with open(self.fn+'_good', 'w') as f: |
| 528 | f.write('100, 1, %d, 1, 2, 3, 4\n' % (1<<24)) |
| 529 | (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn+'_good', 4) |
| 530 | with open(self.fn+'_bad', 'w') as f: |
| 531 | f.write('100, 1, 20000000, 1, 2, 3, 4\n') |
| 532 | try: |
| 533 | (raw_histo_log, _) = parse_hist_file(self.fn+'_bad', 4) |
| 534 | self.A(False) |
| 535 | except FioHistoLogExc as e: |
| 536 | self.A(str(e).startswith('block size too large')) |
| 537 | |
| 538 | def test_b9_parse_wrong_bucket_count(self): |
| 539 | with open(self.fn, 'w') as f: |
| 540 | f.write('100, 1, %d, 1, 2, 3, 4, 5\n' % (1<<24)) |
| 541 | try: |
| 542 | (raw_histo_log, _) = parse_hist_file(self.fn, 4) |
| 543 | self.A(False) |
| 544 | except FioHistoLogExc as e: |
| 545 | self.A(str(e).__contains__('buckets per interval')) |
| 546 | |
| 547 | def test_c1_time_ranges(self): |
| 548 | ranges = time_ranges(3, 2) # fio_version defaults to 3 |
| 549 | expected_ranges = [ # fio_version 3 is in nanoseconds |
| 550 | [0.000, 0.001], [0.001, 0.002], # first group |
| 551 | [0.002, 0.003], [0.003, 0.004], # second group same width |
| 552 | [0.004, 0.006], [0.006, 0.008]] # subsequent groups double width |
| 553 | self.A(ranges == expected_ranges) |
| 554 | ranges = time_ranges(3, 2, fio_version=3) |
| 555 | self.A(ranges == expected_ranges) |
| 556 | ranges = time_ranges(3, 2, fio_version=2) |
| 557 | expected_ranges_v2 = [ [ 1000.0 * min_or_max for min_or_max in time_range ] |
| 558 | for time_range in expected_ranges ] |
| 559 | self.A(ranges == expected_ranges_v2) |
| 560 | # see fio V3 stat.h for why 29 groups and 2^6 buckets/group |
| 561 | normal_ranges_v3 = time_ranges(29, 64) |
| 562 | # for v3, bucket time intervals are measured in nanoseconds |
| 563 | self.A(len(normal_ranges_v3) == 29 * 64 and normal_ranges_v3[-1][1] == 64*(1<<(29-1))/1000.0) |
| 564 | normal_ranges_v2 = time_ranges(19, 64, fio_version=2) |
| 565 | # for v2, bucket time intervals are measured in microseconds so we have fewer buckets |
| 566 | self.A(len(normal_ranges_v2) == 19 * 64 and normal_ranges_v2[-1][1] == 64*(1<<(19-1))) |
| 567 | |
| 568 | def test_d1_align_histo_log_1_quantum(self): |
| 569 | with open(self.fn, 'w') as f: |
| 570 | f.write('100, 1, 4096, 1, 2, 3, 4') |
| 571 | (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4) |
| 572 | self.A(max_timestamp_ms == 100) |
| 573 | aligned_log = align_histo_log(raw_histo_log, 5, 4, max_timestamp_ms) |
| 574 | self.A(len(aligned_log) == 1) |
| 575 | (time_ms0, h) = aligned_log[0] |
| 576 | self.A(time_ms0 == 0 and h == [1.0, 2.0, 3.0, 4.0]) |
| 577 | |
| 578 | # we need this to compare 2 lists of floating point numbers for equality |
| 579 | # because of floating-point imprecision |
| 580 | |
| 581 | def compare_2_floats(self, x, y): |
| 582 | if x == 0.0 or y == 0.0: |
| 583 | return (x+y) < 0.0000001 |
| 584 | else: |
| 585 | return (math.fabs(x-y)/x) < 0.00001 |
| 586 | |
| 587 | def is_close(self, buckets, buckets_expected): |
| 588 | if len(buckets) != len(buckets_expected): |
| 589 | return False |
| 590 | compare_buckets = lambda k: self.compare_2_floats(buckets[k], buckets_expected[k]) |
| 591 | indices_close = list(filter(compare_buckets, range(0, len(buckets)))) |
| 592 | return len(indices_close) == len(buckets) |
| 593 | |
| 594 | def test_d2_align_histo_log_2_quantum(self): |
| 595 | with open(self.fn, 'w') as f: |
| 596 | f.write('2000, 1, 4096, 1, 2, 3, 4\n') |
| 597 | f.write('7000, 1, 4096, 1, 2, 3, 4\n') |
| 598 | (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4) |
| 599 | self.A(max_timestamp_ms == 7000) |
| 600 | (_, _, _, raw_buckets1) = raw_histo_log[0] |
| 601 | (_, _, _, raw_buckets2) = raw_histo_log[1] |
| 602 | aligned_log = align_histo_log(raw_histo_log, 5, 4, max_timestamp_ms) |
| 603 | self.A(len(aligned_log) == 2) |
| 604 | (time_ms1, h1) = aligned_log[0] |
| 605 | (time_ms2, h2) = aligned_log[1] |
| 606 | # because first record is from time interval [2000, 7000] |
| 607 | # we weight it according |
| 608 | expect1 = [float(b) * 0.6 for b in raw_buckets1] |
| 609 | expect2 = [float(b) * 0.4 for b in raw_buckets1] |
| 610 | for e in range(0, len(expect2)): |
| 611 | expect2[e] += raw_buckets2[e] |
| 612 | self.A(time_ms1 == 0 and self.is_close(h1, expect1)) |
| 613 | self.A(time_ms2 == 5000 and self.is_close(h2, expect2)) |
| 614 | |
| 615 | # what to expect if histogram buckets are all equal |
| 616 | def test_e1_get_pctiles_flat_histo(self): |
| 617 | with open(self.fn, 'w') as f: |
| 618 | buckets = [ 100 for j in range(0, 128) ] |
| 619 | f.write('9000, 1, 4096, %s\n' % ', '.join([str(b) for b in buckets])) |
| 620 | (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 128) |
| 621 | self.A(max_timestamp_ms == 9000) |
| 622 | aligned_log = align_histo_log(raw_histo_log, 5, 128, max_timestamp_ms) |
| 623 | time_intervals = time_ranges(4, 32) |
| 624 | # since buckets are all equal, then median is halfway through time_intervals |
| 625 | # and max latency interval is at end of time_intervals |
| 626 | self.A(time_intervals[64][1] == 0.066 and time_intervals[127][1] == 0.256) |
| 627 | pctiles_wanted = [ 0, 50, 100 ] |
| 628 | pct_vs_time = [] |
| 629 | for (time_ms, histo) in aligned_log: |
| 630 | pct_vs_time.append(get_pctiles(histo, pctiles_wanted, time_intervals)) |
| 631 | self.A(pct_vs_time[0] == None) # no I/O in this time interval |
| 632 | expected_pctiles = { 0:0.000, 50:0.064, 100:0.256 } |
| 633 | self.A(pct_vs_time[1] == expected_pctiles) |
| 634 | |
| 635 | # what to expect if just the highest histogram bucket is used |
| 636 | def test_e2_get_pctiles_highest_pct(self): |
| 637 | fio_v3_bucket_count = 29 * 64 |
| 638 | with open(self.fn, 'w') as f: |
| 639 | # make a empty fio v3 histogram |
| 640 | buckets = [ 0 for j in range(0, fio_v3_bucket_count) ] |
| 641 | # add one I/O request to last bucket |
| 642 | buckets[-1] = 1 |
| 643 | f.write('9000, 1, 4096, %s\n' % ', '.join([str(b) for b in buckets])) |
| 644 | (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, fio_v3_bucket_count) |
| 645 | self.A(max_timestamp_ms == 9000) |
| 646 | aligned_log = align_histo_log(raw_histo_log, 5, fio_v3_bucket_count, max_timestamp_ms) |
| 647 | (time_ms, histo) = aligned_log[1] |
| 648 | time_intervals = time_ranges(29, 64) |
| 649 | expected_pctiles = { 100.0:(64*(1<<28))/1000.0 } |
| 650 | pct = get_pctiles( histo, [ 100.0 ], time_intervals ) |
| 651 | self.A(pct == expected_pctiles) |
| 652 | |
| 653 | # we are using this module as a standalone program |
| 654 | |
| 655 | if __name__ == '__main__': |
| 656 | if os.getenv('UNITTEST'): |
| 657 | sys.exit(unittest2.main()) |
| 658 | else: |
| 659 | compute_percentiles_from_logs() |
| 660 | |