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
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)
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
24 import sys, os, math, copy, time
25 from copy import deepcopy
28 unittest2_imported = True
32 unittest2_imported = False
39 class FioHistoLogExc(Exception):
42 # if there is an error, print message, and exit with error status
45 print('ERROR: ' + msg)
48 # convert histogram log file into a list of
49 # (time_ms, direction, bsz, buckets) tuples where
50 # - time_ms is the time in msec at which the log record was written
51 # - direction is 0 (read) or 1 (write)
52 # - bsz is block size (not used)
53 # - buckets is a CSV list of counters that make up the histogram
54 # caller decides if the expected number of counters are present
57 def exception_suffix( record_num, pathname ):
58 return 'in histogram record %d file %s' % (record_num+1, pathname)
60 # log file parser raises FioHistoLogExc exceptions
61 # it returns histogram buckets in whatever unit fio uses
63 # logfn: pathname to histogram log file
64 # buckets_per_interval - how many histogram buckets to expect
65 # log_hist_msec - if not None, expected time interval between histogram records
67 def parse_hist_file(logfn, buckets_per_interval, log_hist_msec):
68 previous_ts_ms_read = -1
69 previous_ts_ms_write = -1
71 with open(logfn, 'r') as f:
72 records = [ l.strip() for l in f.readlines() ]
76 for k, r in enumerate(records):
81 int_tokens = [ int(t) for t in tokens ]
82 except ValueError as e:
83 raise FioHistoLogExc('non-integer value %s' % exception_suffix(k+1, logfn))
85 neg_ints = list(filter( lambda tk : tk < 0, int_tokens ))
87 raise FioHistoLogExc('negative integer value %s' % exception_suffix(k+1, logfn))
89 if len(int_tokens) < 3:
90 raise FioHistoLogExc('too few numbers %s' % exception_suffix(k+1, logfn))
92 direction = int_tokens[1]
93 if direction != direction_read and direction != direction_write:
94 raise FioHistoLogExc('invalid I/O direction %s' % exception_suffix(k+1, logfn))
96 time_ms = int_tokens[0]
97 if direction == direction_read:
98 if time_ms < previous_ts_ms_read:
99 raise FioHistoLogExc('read timestamp in column 1 decreased %s' % exception_suffix(k+1, logfn))
100 previous_ts_ms_read = time_ms
101 elif direction == direction_write:
102 if time_ms < previous_ts_ms_write:
103 raise FioHistoLogExc('write timestamp in column 1 decreased %s' % exception_suffix(k+1, logfn))
104 previous_ts_ms_write = time_ms
108 raise FioHistoLogExc('block size too large %s' % exception_suffix(k+1, logfn))
110 buckets = int_tokens[3:]
111 if len(buckets) != buckets_per_interval:
112 raise FioHistoLogExc('%d buckets per interval but %d expected in %s' %
113 (len(buckets), buckets_per_interval, exception_suffix(k+1, logfn)))
115 # hack to filter out records with the same timestamp
116 # we should not have to do this if fio logs histogram records correctly
118 if time_ms == last_time_ms and direction == last_direction:
120 last_time_ms = time_ms
121 last_direction = direction
123 intervals.append((time_ms, direction, bsz, buckets))
124 if len(intervals) == 0:
125 raise FioHistoLogExc('no records in %s' % logfn)
126 (first_timestamp, _, _, _) = intervals[0]
127 if first_timestamp < 1000000:
128 start_time = 0 # assume log_unix_epoch = 0
129 elif log_hist_msec != None:
130 start_time = first_timestamp - log_hist_msec
131 elif len(intervals) > 1:
132 (second_timestamp, _, _, _) = intervals[1]
133 start_time = first_timestamp - (second_timestamp - first_timestamp)
135 raise FioHistoLogExc('no way to estimate test start time')
136 (end_timestamp, _, _, _) = intervals[-1]
138 return (intervals, start_time, end_timestamp)
141 # compute time range for each bucket index in histogram record
142 # see comments in https://github.com/axboe/fio/blob/master/stat.h
143 # for description of bucket groups and buckets
144 # fio v3 bucket ranges are in nanosec (since response times are measured in nanosec)
145 # but we convert fio v3 nanosecs to floating-point microseconds
147 def time_ranges(groups, counters_per_group, fio_version=3):
150 bucket_intervals = []
151 for g in range(0, groups):
152 for b in range(0, counters_per_group):
153 rmin = float(bucket_base)
154 rmax = rmin + bucket_width
156 rmin /= nsec_per_usec
157 rmax /= nsec_per_usec
158 bucket_intervals.append( [rmin, rmax] )
159 bucket_base += bucket_width
162 return bucket_intervals
165 # compute number of time quantum intervals in the test
167 def get_time_intervals(time_quantum, min_timestamp_ms, max_timestamp_ms):
168 # round down to nearest second
169 max_timestamp = max_timestamp_ms // msec_per_sec
170 min_timestamp = min_timestamp_ms // msec_per_sec
171 # round up to nearest whole multiple of time_quantum
172 time_interval_count = ((max_timestamp - min_timestamp) + time_quantum) // time_quantum
173 end_time = min_timestamp + (time_interval_count * time_quantum)
174 return (end_time, time_interval_count)
176 # align raw histogram log data to time quantum so
177 # we can then combine histograms from different threads with addition
178 # for randrw workload we count both reads and writes in same output bucket
179 # but we separate reads and writes for purposes of calculating
180 # end time for histogram record.
181 # this requires us to weight a raw histogram bucket by the
182 # fraction of time quantum that the bucket overlaps the current
183 # time quantum interval
184 # for example, if we have a bucket with 515 samples for time interval
185 # [ 1010, 2014 ] msec since start of test, and time quantum is 1 sec, then
186 # for time quantum interval [ 1000, 2000 ] msec, the overlap is
187 # (2000 - 1010) / (2000 - 1000) = 0.99
188 # so the contribution of this bucket to this time quantum is
189 # 515 x 0.99 = 509.85
191 def align_histo_log(raw_histogram_log, time_quantum, bucket_count, min_timestamp_ms, max_timestamp_ms):
193 # slice up test time int intervals of time_quantum seconds
195 (end_time, time_interval_count) = get_time_intervals(time_quantum, min_timestamp_ms, max_timestamp_ms)
196 time_qtm_ms = time_quantum * msec_per_sec
197 end_time_ms = end_time * msec_per_sec
198 aligned_intervals = []
199 for j in range(0, time_interval_count):
200 aligned_intervals.append((
201 min_timestamp_ms + (j * time_qtm_ms),
202 [ 0.0 for j in range(0, bucket_count) ] ))
204 log_record_count = len(raw_histogram_log)
205 for k, record in enumerate(raw_histogram_log):
207 # find next record with same direction to get end-time
208 # have to avoid going past end of array
209 # for fio randrw workload,
210 # we have read and write records on same time interval
211 # sometimes read and write records are in opposite order
212 # assertion checks that next read/write record
213 # can be separated by at most 2 other records
215 (time_msec, direction, sz, interval_buckets) = record
216 if k+1 < log_record_count:
217 (time_msec_end, direction2, _, _) = raw_histogram_log[k+1]
218 if direction2 != direction:
219 if k+2 < log_record_count:
220 (time_msec_end, direction2, _, _) = raw_histogram_log[k+2]
221 if direction2 != direction:
222 if k+3 < log_record_count:
223 (time_msec_end, direction2, _, _) = raw_histogram_log[k+3]
224 assert direction2 == direction
226 time_msec_end = end_time_ms
228 time_msec_end = end_time_ms
230 time_msec_end = end_time_ms
232 # calculate first quantum that overlaps this histogram record
234 offset_from_min_ts = time_msec - min_timestamp_ms
235 qtm_start_ms = min_timestamp_ms + (offset_from_min_ts // time_qtm_ms) * time_qtm_ms
236 qtm_end_ms = min_timestamp_ms + ((offset_from_min_ts + time_qtm_ms) // time_qtm_ms) * time_qtm_ms
237 qtm_index = offset_from_min_ts // time_qtm_ms
239 # for each quantum that overlaps this histogram record's time interval
241 while qtm_start_ms < time_msec_end: # while quantum overlaps record
243 # some histogram logs may be longer than others
245 if len(aligned_intervals) <= qtm_index:
248 # calculate fraction of time that this quantum
249 # overlaps histogram record's time interval
251 overlap_start = max(qtm_start_ms, time_msec)
252 overlap_end = min(qtm_end_ms, time_msec_end)
253 weight = float(overlap_end - overlap_start)
254 weight /= (time_msec_end - time_msec)
255 (_,aligned_histogram) = aligned_intervals[qtm_index]
256 for bx, b in enumerate(interval_buckets):
257 weighted_bucket = weight * b
258 aligned_histogram[bx] += weighted_bucket
260 # advance to the next time quantum
262 qtm_start_ms += time_qtm_ms
263 qtm_end_ms += time_qtm_ms
266 return aligned_intervals
268 # add histogram in "source" to histogram in "target"
269 # it is assumed that the 2 histograms are precisely time-aligned
271 def add_to_histo_from( target, source ):
272 for b in range(0, len(source)):
273 target[b] += source[b]
276 # calculate total samples in the histogram buckets
278 def get_samples(buckets):
279 return reduce( lambda x,y: x + y, buckets)
282 # compute percentiles
284 # buckets: histogram bucket array
285 # wanted: list of floating-pt percentiles to calculate
286 # time_ranges: [tmin,tmax) time interval for each bucket
287 # returns None if no I/O reported.
288 # otherwise we would be dividing by zero
289 # think of buckets as probability distribution function
290 # and this loop is integrating to get cumulative distribution function
292 def get_pctiles(buckets, wanted, time_ranges):
294 # get total of IO requests done
296 for io_count in buckets:
297 total_ios += io_count
299 # don't return percentiles if no I/O was done during interval
303 pctile_count = len(wanted)
305 # results returned as dictionary keyed by percentile
308 # index of next percentile in list
312 next_pctile = wanted[pctile_index]
314 # no one is interested in percentiles bigger than this but not 100.0
315 # this prevents floating-point error from preventing loop exit
318 # pct is the percentile corresponding to
319 # all I/O requests up through bucket b
322 for b, io_count in enumerate(buckets):
325 total_so_far += io_count
326 # last_pct_lt is the percentile corresponding to
327 # all I/O requests up to, but not including, bucket b
329 pct = 100.0 * float(total_so_far) / total_ios
330 # a single bucket could satisfy multiple pctiles
331 # so this must be a while loop
332 # for 100-percentile (max latency) case, no bucket exceeds it
333 # so we must stop there.
334 while ((next_pctile == 100.0 and pct >= almost_100) or
335 (next_pctile < 100.0 and pct > next_pctile)):
336 # interpolate between min and max time for bucket time interval
337 # we keep the time_ranges access inside this loop,
338 # even though it could be above the loop,
339 # because in many cases we will not be even entering
340 # the loop so we optimize out these accesses
341 range_max_time = time_ranges[b][1]
342 range_min_time = time_ranges[b][0]
343 offset_frac = (next_pctile - last_pct)/(pct - last_pct)
344 interpolation = range_min_time + (offset_frac*(range_max_time - range_min_time))
345 pctile_result[next_pctile] = interpolation
347 if pctile_index == pctile_count:
349 next_pctile = wanted[pctile_index]
350 if pctile_index == pctile_count:
352 assert pctile_index == pctile_count
356 # this is really the main program
358 def compute_percentiles_from_logs():
359 parser = argparse.ArgumentParser()
360 parser.add_argument("--fio-version", dest="fio_version",
361 default="3", choices=[2,3], type=int,
362 help="fio version (default=3)")
363 parser.add_argument("--bucket-groups", dest="bucket_groups", default="29", type=int,
364 help="fio histogram bucket groups (default=29)")
365 parser.add_argument("--bucket-bits", dest="bucket_bits",
366 default="6", type=int,
367 help="fio histogram buckets-per-group bits (default=6 means 64 buckets/group)")
368 parser.add_argument("--percentiles", dest="pctiles_wanted",
369 default=[ 0., 50., 95., 99., 100.], type=float, nargs='+',
370 help="fio histogram buckets-per-group bits (default=6 means 64 buckets/group)")
371 parser.add_argument("--time-quantum", dest="time_quantum",
372 default="1", type=int,
373 help="time quantum in seconds (default=1)")
374 parser.add_argument("--log-hist-msec", dest="log_hist_msec",
375 type=int, default=None,
376 help="log_hist_msec value in fio job file")
377 parser.add_argument("--output-unit", dest="output_unit",
378 default="usec", type=str,
379 help="Latency percentile output unit: msec|usec|nsec (default usec)")
380 parser.add_argument("file_list", nargs='+',
381 help='list of files, preceded by " -- " if necessary')
382 args = parser.parse_args()
384 # default changes based on fio version
385 if args.fio_version == 2:
386 args.bucket_groups = 19
390 print('fio version = %d' % args.fio_version)
391 print('bucket groups = %d' % args.bucket_groups)
392 print('bucket bits = %d' % args.bucket_bits)
393 print('time quantum = %d sec' % args.time_quantum)
394 print('percentiles = %s' % ','.join([ str(p) for p in args.pctiles_wanted ]))
395 buckets_per_group = 1 << args.bucket_bits
396 print('buckets per group = %d' % buckets_per_group)
397 buckets_per_interval = buckets_per_group * args.bucket_groups
398 print('buckets per interval = %d ' % buckets_per_interval)
399 bucket_index_range = range(0, buckets_per_interval)
400 if args.log_hist_msec != None:
401 print('log_hist_msec = %d' % args.log_hist_msec)
402 if args.time_quantum == 0:
403 print('ERROR: time-quantum must be a positive number of seconds')
404 print('output unit = ' + args.output_unit)
405 if args.output_unit == 'msec':
406 time_divisor = float(msec_per_sec)
407 elif args.output_unit == 'usec':
410 # construct template for each histogram bucket array with buckets all zeroes
411 # we just copy this for each new histogram
413 zeroed_buckets = [ 0.0 for r in bucket_index_range ]
415 # calculate response time interval associated with each histogram bucket
417 bucket_times = time_ranges(args.bucket_groups, buckets_per_group, fio_version=args.fio_version)
419 # parse the histogram logs
420 # assumption: each bucket has a monotonically increasing time
421 # assumption: time ranges do not overlap for a single thread's records
422 # (exception: if randrw workload, then there is a read and a write
423 # record for the same time interval)
426 test_end_time = 1.0e18
428 for fn in args.file_list:
430 (hist_files[fn], log_start_time, log_end_time) = parse_hist_file(fn, buckets_per_interval, args.log_hist_msec)
431 except FioHistoLogExc as e:
433 # we consider the test started when all threads have started logging
434 test_start_time = max(test_start_time, log_start_time)
435 # we consider the test over when one of the logs has ended
436 test_end_time = min(test_end_time, log_end_time)
438 if test_start_time >= test_end_time:
439 raise FioHistoLogExc('no time interval when all threads logs overlapped')
440 if test_start_time > 0:
441 print('all threads running as of unix epoch time %d = %s' % (
442 test_start_time/float(msec_per_sec),
443 time.ctime(test_start_time/1000.0)))
445 (end_time, time_interval_count) = get_time_intervals(args.time_quantum, test_start_time, test_end_time)
446 all_threads_histograms = [ ((j*args.time_quantum*msec_per_sec), deepcopy(zeroed_buckets))
447 for j in range(0, time_interval_count) ]
449 for logfn in hist_files.keys():
450 aligned_per_thread = align_histo_log(hist_files[logfn],
452 buckets_per_interval,
455 for t in range(0, time_interval_count):
456 (_, all_threads_histo_t) = all_threads_histograms[t]
457 (_, log_histo_t) = aligned_per_thread[t]
458 add_to_histo_from( all_threads_histo_t, log_histo_t )
460 # calculate percentiles across aggregate histogram for all threads
461 # print CSV header just like fiologparser_hist does
463 header = 'msec-since-start, samples, '
464 for p in args.pctiles_wanted:
466 next_pctile_header = 'min'
468 next_pctile_header = 'max'
470 next_pctile_header = 'median'
472 next_pctile_header = '%3.1f' % p
473 header += '%s, ' % next_pctile_header
475 print('time (millisec), percentiles in increasing order with values in ' + args.output_unit)
478 for (t_msec, all_threads_histo_t) in all_threads_histograms:
479 samples = get_samples(all_threads_histo_t)
480 record = '%8d, %8d, ' % (t_msec, samples)
481 pct = get_pctiles(all_threads_histo_t, args.pctiles_wanted, bucket_times)
483 for w in args.pctiles_wanted:
486 pct_keys = [ k for k in pct.keys() ]
487 pct_values = [ str(pct[wanted]/time_divisor) for wanted in sorted(pct_keys) ]
488 record += ', '.join(pct_values)
496 ##### below are unit tests ##############
498 if unittest2_imported:
499 import tempfile, shutil
500 from os.path import join
501 should_not_get_here = False
503 class Test(unittest2.TestCase):
506 # a little less typing please
507 def A(self, boolean_val):
508 self.assertTrue(boolean_val)
510 # initialize unit test environment
514 d = tempfile.mkdtemp()
517 # remove anything left by unit test environment
518 # unless user sets UNITTEST_LEAVE_FILES environment variable
521 def tearDownClass(cls):
522 if not os.getenv("UNITTEST_LEAVE_FILES"):
523 shutil.rmtree(cls.tempdir)
526 self.fn = join(Test.tempdir, self.id())
528 def test_a_add_histos(self):
531 add_to_histo_from( a, b )
532 self.A(a == [2.5, 4.5])
533 self.A(b == [1.5, 2.5])
535 def test_b1_parse_log(self):
536 with open(self.fn, 'w') as f:
537 f.write('1234, 0, 4096, 1, 2, 3, 4\n')
538 f.write('5678,1,16384,5,6,7,8 \n')
539 (raw_histo_log, min_timestamp, max_timestamp) = parse_hist_file(self.fn, 4, None) # 4 buckets per interval
540 # if not log_unix_epoch=1, then min_timestamp will always be set to zero
541 self.A(len(raw_histo_log) == 2 and min_timestamp == 0 and max_timestamp == 5678)
542 (time_ms, direction, bsz, histo) = raw_histo_log[0]
543 self.A(time_ms == 1234 and direction == 0 and bsz == 4096 and histo == [ 1, 2, 3, 4 ])
544 (time_ms, direction, bsz, histo) = raw_histo_log[1]
545 self.A(time_ms == 5678 and direction == 1 and bsz == 16384 and histo == [ 5, 6, 7, 8 ])
547 def test_b2_parse_empty_log(self):
548 with open(self.fn, 'w') as f:
551 (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
552 self.A(should_not_get_here)
553 except FioHistoLogExc as e:
554 self.A(str(e).startswith('no records'))
556 def test_b3_parse_empty_records(self):
557 with open(self.fn, 'w') as f:
559 f.write('1234, 0, 4096, 1, 2, 3, 4\n')
560 f.write('5678,1,16384,5,6,7,8 \n')
562 (raw_histo_log, _, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
563 self.A(len(raw_histo_log) == 2 and max_timestamp_ms == 5678)
564 (time_ms, direction, bsz, histo) = raw_histo_log[0]
565 self.A(time_ms == 1234 and direction == 0 and bsz == 4096 and histo == [ 1, 2, 3, 4 ])
566 (time_ms, direction, bsz, histo) = raw_histo_log[1]
567 self.A(time_ms == 5678 and direction == 1 and bsz == 16384 and histo == [ 5, 6, 7, 8 ])
569 def test_b4_parse_non_int(self):
570 with open(self.fn, 'w') as f:
571 f.write('12, 0, 4096, 1a, 2, 3, 4\n')
573 (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
575 except FioHistoLogExc as e:
576 self.A(str(e).startswith('non-integer'))
578 def test_b5_parse_neg_int(self):
579 with open(self.fn, 'w') as f:
580 f.write('-12, 0, 4096, 1, 2, 3, 4\n')
582 (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
584 except FioHistoLogExc as e:
585 self.A(str(e).startswith('negative integer'))
587 def test_b6_parse_too_few_int(self):
588 with open(self.fn, 'w') as f:
591 (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
593 except FioHistoLogExc as e:
594 self.A(str(e).startswith('too few numbers'))
596 def test_b7_parse_invalid_direction(self):
597 with open(self.fn, 'w') as f:
598 f.write('100, 2, 4096, 1, 2, 3, 4\n')
600 (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
602 except FioHistoLogExc as e:
603 self.A(str(e).startswith('invalid I/O direction'))
605 def test_b8_parse_bsz_too_big(self):
606 with open(self.fn+'_good', 'w') as f:
607 f.write('100, 1, %d, 1, 2, 3, 4\n' % (1<<24))
608 (raw_histo_log, _, _) = parse_hist_file(self.fn+'_good', 4, None)
609 with open(self.fn+'_bad', 'w') as f:
610 f.write('100, 1, 20000000, 1, 2, 3, 4\n')
612 (raw_histo_log, _, _) = parse_hist_file(self.fn+'_bad', 4, None)
614 except FioHistoLogExc as e:
615 self.A(str(e).startswith('block size too large'))
617 def test_b9_parse_wrong_bucket_count(self):
618 with open(self.fn, 'w') as f:
619 f.write('100, 1, %d, 1, 2, 3, 4, 5\n' % (1<<24))
621 (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
623 except FioHistoLogExc as e:
624 self.A(str(e).__contains__('buckets per interval'))
626 def test_c1_time_ranges(self):
627 ranges = time_ranges(3, 2) # fio_version defaults to 3
628 expected_ranges = [ # fio_version 3 is in nanoseconds
629 [0.000, 0.001], [0.001, 0.002], # first group
630 [0.002, 0.003], [0.003, 0.004], # second group same width
631 [0.004, 0.006], [0.006, 0.008]] # subsequent groups double width
632 self.A(ranges == expected_ranges)
633 ranges = time_ranges(3, 2, fio_version=3)
634 self.A(ranges == expected_ranges)
635 ranges = time_ranges(3, 2, fio_version=2)
636 expected_ranges_v2 = [ [ 1000.0 * min_or_max for min_or_max in time_range ]
637 for time_range in expected_ranges ]
638 self.A(ranges == expected_ranges_v2)
639 # see fio V3 stat.h for why 29 groups and 2^6 buckets/group
640 normal_ranges_v3 = time_ranges(29, 64)
641 # for v3, bucket time intervals are measured in nanoseconds
642 self.A(len(normal_ranges_v3) == 29 * 64 and normal_ranges_v3[-1][1] == 64*(1<<(29-1))/1000.0)
643 normal_ranges_v2 = time_ranges(19, 64, fio_version=2)
644 # for v2, bucket time intervals are measured in microseconds so we have fewer buckets
645 self.A(len(normal_ranges_v2) == 19 * 64 and normal_ranges_v2[-1][1] == 64*(1<<(19-1)))
647 def test_d1_align_histo_log_1_quantum(self):
648 with open(self.fn, 'w') as f:
649 f.write('100, 1, 4096, 1, 2, 3, 4')
650 (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
651 self.A(min_timestamp_ms == 0 and max_timestamp_ms == 100)
652 aligned_log = align_histo_log(raw_histo_log, 5, 4, min_timestamp_ms, max_timestamp_ms)
653 self.A(len(aligned_log) == 1)
654 (time_ms0, h) = aligned_log[0]
655 self.A(time_ms0 == 0 and h == [1., 2., 3., 4.])
657 # handle case with log_unix_epoch=1 timestamps, 1-second time quantum
658 # here both records will be separated into 2 aligned intervals
660 def test_d1a_align_2rec_histo_log_epoch_1_quantum_1sec(self):
661 with open(self.fn, 'w') as f:
662 f.write('1536504002123, 1, 4096, 1, 2, 3, 4\n')
663 f.write('1536504003123, 1, 4096, 4, 3, 2, 1\n')
664 (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
665 self.A(min_timestamp_ms == 1536504001123 and max_timestamp_ms == 1536504003123)
666 aligned_log = align_histo_log(raw_histo_log, 1, 4, min_timestamp_ms, max_timestamp_ms)
667 self.A(len(aligned_log) == 3)
668 (time_ms0, h) = aligned_log[0]
669 self.A(time_ms0 == 1536504001123 and h == [0., 0., 0., 0.])
670 (time_ms1, h) = aligned_log[1]
671 self.A(time_ms1 == 1536504002123 and h == [1., 2., 3., 4.])
672 (time_ms2, h) = aligned_log[2]
673 self.A(time_ms2 == 1536504003123 and h == [4., 3., 2., 1.])
675 # handle case with log_unix_epoch=1 timestamps, 5-second time quantum
676 # here both records will be merged into a single aligned time interval
678 def test_d1b_align_2rec_histo_log_epoch_1_quantum_5sec(self):
679 with open(self.fn, 'w') as f:
680 f.write('1536504002123, 1, 4096, 1, 2, 3, 4\n')
681 f.write('1536504003123, 1, 4096, 4, 3, 2, 1\n')
682 (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
683 self.A(min_timestamp_ms == 1536504001123 and max_timestamp_ms == 1536504003123)
684 aligned_log = align_histo_log(raw_histo_log, 5, 4, min_timestamp_ms, max_timestamp_ms)
685 self.A(len(aligned_log) == 1)
686 (time_ms0, h) = aligned_log[0]
687 self.A(time_ms0 == 1536504001123 and h == [5., 5., 5., 5.])
689 # we need this to compare 2 lists of floating point numbers for equality
690 # because of floating-point imprecision
692 def compare_2_floats(self, x, y):
693 if x == 0.0 or y == 0.0:
694 return (x+y) < 0.0000001
696 return (math.fabs(x-y)/x) < 0.00001
698 def is_close(self, buckets, buckets_expected):
699 if len(buckets) != len(buckets_expected):
701 compare_buckets = lambda k: self.compare_2_floats(buckets[k], buckets_expected[k])
702 indices_close = list(filter(compare_buckets, range(0, len(buckets))))
703 return len(indices_close) == len(buckets)
705 def test_d2_align_histo_log_2_quantum(self):
706 with open(self.fn, 'w') as f:
707 f.write('2000, 1, 4096, 1, 2, 3, 4\n')
708 f.write('7000, 1, 4096, 1, 2, 3, 4\n')
709 (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
710 self.A(min_timestamp_ms == 0 and max_timestamp_ms == 7000)
711 (_, _, _, raw_buckets1) = raw_histo_log[0]
712 (_, _, _, raw_buckets2) = raw_histo_log[1]
713 aligned_log = align_histo_log(raw_histo_log, 5, 4, min_timestamp_ms, max_timestamp_ms)
714 self.A(len(aligned_log) == 2)
715 (time_ms1, h1) = aligned_log[0]
716 (time_ms2, h2) = aligned_log[1]
717 # because first record is from time interval [2000, 7000]
718 # we weight it according
719 expect1 = [float(b) * 0.6 for b in raw_buckets1]
720 expect2 = [float(b) * 0.4 for b in raw_buckets1]
721 for e in range(0, len(expect2)):
722 expect2[e] += raw_buckets2[e]
723 self.A(time_ms1 == 0 and self.is_close(h1, expect1))
724 self.A(time_ms2 == 5000 and self.is_close(h2, expect2))
726 # what to expect if histogram buckets are all equal
727 def test_e1_get_pctiles_flat_histo(self):
728 with open(self.fn, 'w') as f:
729 buckets = [ 100 for j in range(0, 128) ]
730 f.write('9000, 1, 4096, %s\n' % ', '.join([str(b) for b in buckets]))
731 (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 128, None)
732 self.A(min_timestamp_ms == 0 and max_timestamp_ms == 9000)
733 aligned_log = align_histo_log(raw_histo_log, 5, 128, min_timestamp_ms, max_timestamp_ms)
734 time_intervals = time_ranges(4, 32)
735 # since buckets are all equal, then median is halfway through time_intervals
736 # and max latency interval is at end of time_intervals
737 self.A(time_intervals[64][1] == 0.066 and time_intervals[127][1] == 0.256)
738 pctiles_wanted = [ 0, 50, 100 ]
740 for (time_ms, histo) in aligned_log:
741 pct_vs_time.append(get_pctiles(histo, pctiles_wanted, time_intervals))
742 self.A(pct_vs_time[0] == None) # no I/O in this time interval
743 expected_pctiles = { 0:0.000, 50:0.064, 100:0.256 }
744 self.A(pct_vs_time[1] == expected_pctiles)
746 # what to expect if just the highest histogram bucket is used
747 def test_e2_get_pctiles_highest_pct(self):
748 fio_v3_bucket_count = 29 * 64
749 with open(self.fn, 'w') as f:
750 # make a empty fio v3 histogram
751 buckets = [ 0 for j in range(0, fio_v3_bucket_count) ]
752 # add one I/O request to last bucket
754 f.write('9000, 1, 4096, %s\n' % ', '.join([str(b) for b in buckets]))
755 (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, fio_v3_bucket_count, None)
756 self.A(min_timestamp_ms == 0 and max_timestamp_ms == 9000)
757 aligned_log = align_histo_log(raw_histo_log, 5, fio_v3_bucket_count, min_timestamp_ms, max_timestamp_ms)
758 (time_ms, histo) = aligned_log[1]
759 time_intervals = time_ranges(29, 64)
760 expected_pctiles = { 100.0:(64*(1<<28))/1000.0 }
761 pct = get_pctiles( histo, [ 100.0 ], time_intervals )
762 self.A(pct == expected_pctiles)
764 # we are using this module as a standalone program
766 if __name__ == '__main__':
767 if os.getenv('UNITTEST'):
768 if unittest2_imported:
769 sys.exit(unittest2.main())
771 raise Exception('you must install unittest2 module to run unit test')
773 compute_percentiles_from_logs()