# if you do this, don't pass normal CLI parameters to it
# otherwise it runs the CLI
- import sys, os, math, copy
+ import sys, os, math, copy, time
from copy import deepcopy
import argparse
-import unittest2
+
+unittest2_imported = True
+try:
+ import unittest2
+except ImportError:
+ unittest2_imported = False
msec_per_sec = 1000
nsec_per_usec = 1000
+ direction_read = 0
+ direction_write = 1
class FioHistoLogExc(Exception):
pass
# log file parser raises FioHistoLogExc exceptions
# it returns histogram buckets in whatever unit fio uses
-
- def parse_hist_file(logfn, buckets_per_interval):
- max_timestamp_ms = 0.0
-
+ # inputs:
+ # logfn: pathname to histogram log file
+ # buckets_per_interval - how many histogram buckets to expect
+ # log_hist_msec - if not None, expected time interval between histogram records
+
+ def parse_hist_file(logfn, buckets_per_interval, log_hist_msec):
+ previous_ts_ms_read = -1
+ previous_ts_ms_write = -1
+
with open(logfn, 'r') as f:
records = [ l.strip() for l in f.readlines() ]
intervals = []
+ last_time_ms = -1
+ last_direction = -1
for k, r in enumerate(records):
if r == '':
continue
if len(int_tokens) < 3:
raise FioHistoLogExc('too few numbers %s' % exception_suffix(k+1, logfn))
- time_ms = int_tokens[0]
- if time_ms > max_timestamp_ms:
- max_timestamp_ms = time_ms
-
direction = int_tokens[1]
- if direction != 0 and direction != 1:
+ if direction != direction_read and direction != direction_write:
raise FioHistoLogExc('invalid I/O direction %s' % exception_suffix(k+1, logfn))
+ time_ms = int_tokens[0]
+ if direction == direction_read:
+ if time_ms < previous_ts_ms_read:
+ raise FioHistoLogExc('read timestamp in column 1 decreased %s' % exception_suffix(k+1, logfn))
+ previous_ts_ms_read = time_ms
+ elif direction == direction_write:
+ if time_ms < previous_ts_ms_write:
+ raise FioHistoLogExc('write timestamp in column 1 decreased %s' % exception_suffix(k+1, logfn))
+ previous_ts_ms_write = time_ms
+
bsz = int_tokens[2]
if bsz > (1 << 24):
raise FioHistoLogExc('block size too large %s' % exception_suffix(k+1, logfn))
if len(buckets) != buckets_per_interval:
raise FioHistoLogExc('%d buckets per interval but %d expected in %s' %
(len(buckets), buckets_per_interval, exception_suffix(k+1, logfn)))
+
+ # hack to filter out records with the same timestamp
+ # we should not have to do this if fio logs histogram records correctly
+
+ if time_ms == last_time_ms and direction == last_direction:
+ continue
+ last_time_ms = time_ms
+ last_direction = direction
+
intervals.append((time_ms, direction, bsz, buckets))
if len(intervals) == 0:
raise FioHistoLogExc('no records in %s' % logfn)
- return (intervals, max_timestamp_ms)
+ (first_timestamp, _, _, _) = intervals[0]
+ if first_timestamp < 1000000:
+ start_time = 0 # assume log_unix_epoch = 0
+ elif log_hist_msec != None:
+ start_time = first_timestamp - log_hist_msec
+ elif len(intervals) > 1:
+ (second_timestamp, _, _, _) = intervals[1]
+ start_time = first_timestamp - (second_timestamp - first_timestamp)
+ else:
+ raise FioHistoLogExc('no way to estimate test start time')
+ (end_timestamp, _, _, _) = intervals[-1]
+
+ return (intervals, start_time, end_timestamp)
# compute time range for each bucket index in histogram record
# compute number of time quantum intervals in the test
- def get_time_intervals(time_quantum, max_timestamp_ms):
+ def get_time_intervals(time_quantum, min_timestamp_ms, max_timestamp_ms):
# round down to nearest second
max_timestamp = max_timestamp_ms // msec_per_sec
+ min_timestamp = min_timestamp_ms // msec_per_sec
# round up to nearest whole multiple of time_quantum
- time_interval_count = (max_timestamp + time_quantum) // time_quantum
- end_time = time_interval_count * time_quantum
+ time_interval_count = ((max_timestamp - min_timestamp) + time_quantum) // time_quantum
+ end_time = min_timestamp + (time_interval_count * time_quantum)
return (end_time, time_interval_count)
# align raw histogram log data to time quantum so
# so the contribution of this bucket to this time quantum is
# 515 x 0.99 = 509.85
- def align_histo_log(raw_histogram_log, time_quantum, bucket_count, max_timestamp_ms):
+ def align_histo_log(raw_histogram_log, time_quantum, bucket_count, min_timestamp_ms, max_timestamp_ms):
# slice up test time int intervals of time_quantum seconds
- (end_time, time_interval_count) = get_time_intervals(time_quantum, max_timestamp_ms)
+ (end_time, time_interval_count) = get_time_intervals(time_quantum, min_timestamp_ms, max_timestamp_ms)
time_qtm_ms = time_quantum * msec_per_sec
end_time_ms = end_time * msec_per_sec
aligned_intervals = []
for j in range(0, time_interval_count):
aligned_intervals.append((
- j * time_qtm_ms,
+ min_timestamp_ms + (j * time_qtm_ms),
[ 0.0 for j in range(0, bucket_count) ] ))
log_record_count = len(raw_histogram_log)
# calculate first quantum that overlaps this histogram record
- qtm_start_ms = (time_msec // time_qtm_ms) * time_qtm_ms
- qtm_end_ms = ((time_msec + time_qtm_ms) // time_qtm_ms) * time_qtm_ms
- qtm_index = qtm_start_ms // time_qtm_ms
+ offset_from_min_ts = time_msec - min_timestamp_ms
+ qtm_start_ms = min_timestamp_ms + (offset_from_min_ts // time_qtm_ms) * time_qtm_ms
+ qtm_end_ms = min_timestamp_ms + ((offset_from_min_ts + time_qtm_ms) // time_qtm_ms) * time_qtm_ms
+ qtm_index = offset_from_min_ts // time_qtm_ms
# for each quantum that overlaps this histogram record's time interval
while qtm_start_ms < time_msec_end: # while quantum overlaps record
+ # some histogram logs may be longer than others
+
+ if len(aligned_intervals) <= qtm_index:
+ break
+
# calculate fraction of time that this quantum
# overlaps histogram record's time interval
parser.add_argument("--time-quantum", dest="time_quantum",
default="1", type=int,
help="time quantum in seconds (default=1)")
+ parser.add_argument("--log-hist-msec", dest="log_hist_msec",
+ type=int, default=None,
+ help="log_hist_msec value in fio job file")
parser.add_argument("--output-unit", dest="output_unit",
default="usec", type=str,
help="Latency percentile output unit: msec|usec|nsec (default usec)")
buckets_per_interval = buckets_per_group * args.bucket_groups
print('buckets per interval = %d ' % buckets_per_interval)
bucket_index_range = range(0, buckets_per_interval)
+ if args.log_hist_msec != None:
+ print('log_hist_msec = %d' % args.log_hist_msec)
if args.time_quantum == 0:
print('ERROR: time-quantum must be a positive number of seconds')
print('output unit = ' + args.output_unit)
if args.output_unit == 'msec':
- time_divisor = 1000.0
+ time_divisor = float(msec_per_sec)
elif args.output_unit == 'usec':
time_divisor = 1.0
- # calculate response time interval associated with each histogram bucket
-
- bucket_times = time_ranges(args.bucket_groups, buckets_per_group, fio_version=args.fio_version)
-
# construct template for each histogram bucket array with buckets all zeroes
# we just copy this for each new histogram
zeroed_buckets = [ 0.0 for r in bucket_index_range ]
- # print CSV header just like fiologparser_hist does
+ # calculate response time interval associated with each histogram bucket
- header = 'msec, '
- for p in args.pctiles_wanted:
- header += '%3.1f, ' % p
- print('time (millisec), percentiles in increasing order with values in ' + args.output_unit)
- print(header)
+ bucket_times = time_ranges(args.bucket_groups, buckets_per_group, fio_version=args.fio_version)
# parse the histogram logs
# assumption: each bucket has a monotonically increasing time
# (exception: if randrw workload, then there is a read and a write
# record for the same time interval)
- max_timestamp_all_logs = 0
+ test_start_time = 0
+ test_end_time = 1.0e18
hist_files = {}
for fn in args.file_list:
try:
- (hist_files[fn], max_timestamp_ms) = parse_hist_file(fn, buckets_per_interval)
+ (hist_files[fn], log_start_time, log_end_time) = parse_hist_file(fn, buckets_per_interval, args.log_hist_msec)
except FioHistoLogExc as e:
myabort(str(e))
- max_timestamp_all_logs = max(max_timestamp_all_logs, max_timestamp_ms)
-
- (end_time, time_interval_count) = get_time_intervals(args.time_quantum, max_timestamp_all_logs)
+ # we consider the test started when all threads have started logging
+ test_start_time = max(test_start_time, log_start_time)
+ # we consider the test over when one of the logs has ended
+ test_end_time = min(test_end_time, log_end_time)
+
+ if test_start_time >= test_end_time:
+ raise FioHistoLogExc('no time interval when all threads logs overlapped')
+ if test_start_time > 0:
+ print('all threads running as of unix epoch time %d = %s' % (
+ test_start_time/float(msec_per_sec),
+ time.ctime(test_start_time/1000.0)))
+
+ (end_time, time_interval_count) = get_time_intervals(args.time_quantum, test_start_time, test_end_time)
all_threads_histograms = [ ((j*args.time_quantum*msec_per_sec), deepcopy(zeroed_buckets))
- for j in range(0, time_interval_count) ]
+ for j in range(0, time_interval_count) ]
for logfn in hist_files.keys():
aligned_per_thread = align_histo_log(hist_files[logfn],
args.time_quantum,
buckets_per_interval,
- max_timestamp_all_logs)
+ test_start_time,
+ test_end_time)
for t in range(0, time_interval_count):
(_, all_threads_histo_t) = all_threads_histograms[t]
(_, log_histo_t) = aligned_per_thread[t]
add_to_histo_from( all_threads_histo_t, log_histo_t )
# calculate percentiles across aggregate histogram for all threads
+ # print CSV header just like fiologparser_hist does
+
+ header = 'msec-since-start, '
+ for p in args.pctiles_wanted:
+ header += '%3.1f, ' % p
+ print('time (millisec), percentiles in increasing order with values in ' + args.output_unit)
+ print(header)
for (t_msec, all_threads_histo_t) in all_threads_histograms:
- record = '%d, ' % t_msec
+ record = '%8d, ' % t_msec
pct = get_pctiles(all_threads_histo_t, args.pctiles_wanted, bucket_times)
if not pct:
for w in args.pctiles_wanted:
#end of MAIN PROGRAM
-
##### below are unit tests ##############
-import tempfile, shutil
-from os.path import join
-should_not_get_here = False
+if unittest2_imported:
+ import tempfile, shutil
+ from os.path import join
+ should_not_get_here = False
-class Test(unittest2.TestCase):
+ class Test(unittest2.TestCase):
tempdir = None
# a little less typing please
with open(self.fn, 'w') as f:
f.write('1234, 0, 4096, 1, 2, 3, 4\n')
f.write('5678,1,16384,5,6,7,8 \n')
- (raw_histo_log, max_timestamp) = parse_hist_file(self.fn, 4) # 4 buckets per interval
- self.A(len(raw_histo_log) == 2 and max_timestamp == 5678)
+ (raw_histo_log, min_timestamp, max_timestamp) = parse_hist_file(self.fn, 4, None) # 4 buckets per interval
+ # if not log_unix_epoch=1, then min_timestamp will always be set to zero
+ self.A(len(raw_histo_log) == 2 and min_timestamp == 0 and max_timestamp == 5678)
(time_ms, direction, bsz, histo) = raw_histo_log[0]
self.A(time_ms == 1234 and direction == 0 and bsz == 4096 and histo == [ 1, 2, 3, 4 ])
(time_ms, direction, bsz, histo) = raw_histo_log[1]
with open(self.fn, 'w') as f:
pass
try:
- (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
self.A(should_not_get_here)
except FioHistoLogExc as e:
self.A(str(e).startswith('no records'))
f.write('1234, 0, 4096, 1, 2, 3, 4\n')
f.write('5678,1,16384,5,6,7,8 \n')
f.write('\n')
- (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4)
+ (raw_histo_log, _, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
self.A(len(raw_histo_log) == 2 and max_timestamp_ms == 5678)
(time_ms, direction, bsz, histo) = raw_histo_log[0]
self.A(time_ms == 1234 and direction == 0 and bsz == 4096 and histo == [ 1, 2, 3, 4 ])
with open(self.fn, 'w') as f:
f.write('12, 0, 4096, 1a, 2, 3, 4\n')
try:
- (raw_histo_log, _) = parse_hist_file(self.fn, 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
self.A(False)
except FioHistoLogExc as e:
self.A(str(e).startswith('non-integer'))
with open(self.fn, 'w') as f:
f.write('-12, 0, 4096, 1, 2, 3, 4\n')
try:
- (raw_histo_log, _) = parse_hist_file(self.fn, 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
self.A(False)
except FioHistoLogExc as e:
self.A(str(e).startswith('negative integer'))
with open(self.fn, 'w') as f:
f.write('0, 0\n')
try:
- (raw_histo_log, _) = parse_hist_file(self.fn, 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
self.A(False)
except FioHistoLogExc as e:
self.A(str(e).startswith('too few numbers'))
with open(self.fn, 'w') as f:
f.write('100, 2, 4096, 1, 2, 3, 4\n')
try:
- (raw_histo_log, _) = parse_hist_file(self.fn, 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
self.A(False)
except FioHistoLogExc as e:
self.A(str(e).startswith('invalid I/O direction'))
def test_b8_parse_bsz_too_big(self):
with open(self.fn+'_good', 'w') as f:
f.write('100, 1, %d, 1, 2, 3, 4\n' % (1<<24))
- (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn+'_good', 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn+'_good', 4, None)
with open(self.fn+'_bad', 'w') as f:
f.write('100, 1, 20000000, 1, 2, 3, 4\n')
try:
- (raw_histo_log, _) = parse_hist_file(self.fn+'_bad', 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn+'_bad', 4, None)
self.A(False)
except FioHistoLogExc as e:
self.A(str(e).startswith('block size too large'))
with open(self.fn, 'w') as f:
f.write('100, 1, %d, 1, 2, 3, 4, 5\n' % (1<<24))
try:
- (raw_histo_log, _) = parse_hist_file(self.fn, 4)
+ (raw_histo_log, _, _) = parse_hist_file(self.fn, 4, None)
self.A(False)
except FioHistoLogExc as e:
self.A(str(e).__contains__('buckets per interval'))
def test_d1_align_histo_log_1_quantum(self):
with open(self.fn, 'w') as f:
f.write('100, 1, 4096, 1, 2, 3, 4')
- (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4)
- self.A(max_timestamp_ms == 100)
- aligned_log = align_histo_log(raw_histo_log, 5, 4, max_timestamp_ms)
+ (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
+ self.A(min_timestamp_ms == 0 and max_timestamp_ms == 100)
+ aligned_log = align_histo_log(raw_histo_log, 5, 4, min_timestamp_ms, max_timestamp_ms)
+ self.A(len(aligned_log) == 1)
+ (time_ms0, h) = aligned_log[0]
+ self.A(time_ms0 == 0 and h == [1., 2., 3., 4.])
+
+ # handle case with log_unix_epoch=1 timestamps, 1-second time quantum
+ # here both records will be separated into 2 aligned intervals
+
+ def test_d1a_align_2rec_histo_log_epoch_1_quantum_1sec(self):
+ with open(self.fn, 'w') as f:
+ f.write('1536504002123, 1, 4096, 1, 2, 3, 4\n')
+ f.write('1536504003123, 1, 4096, 4, 3, 2, 1\n')
+ (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
+ self.A(min_timestamp_ms == 1536504001123 and max_timestamp_ms == 1536504003123)
+ aligned_log = align_histo_log(raw_histo_log, 1, 4, min_timestamp_ms, max_timestamp_ms)
+ self.A(len(aligned_log) == 3)
+ (time_ms0, h) = aligned_log[0]
+ self.A(time_ms0 == 1536504001123 and h == [0., 0., 0., 0.])
+ (time_ms1, h) = aligned_log[1]
+ self.A(time_ms1 == 1536504002123 and h == [1., 2., 3., 4.])
+ (time_ms2, h) = aligned_log[2]
+ self.A(time_ms2 == 1536504003123 and h == [4., 3., 2., 1.])
+
+ # handle case with log_unix_epoch=1 timestamps, 5-second time quantum
+ # here both records will be merged into a single aligned time interval
+
+ def test_d1b_align_2rec_histo_log_epoch_1_quantum_5sec(self):
+ with open(self.fn, 'w') as f:
+ f.write('1536504002123, 1, 4096, 1, 2, 3, 4\n')
+ f.write('1536504003123, 1, 4096, 4, 3, 2, 1\n')
+ (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
+ self.A(min_timestamp_ms == 1536504001123 and max_timestamp_ms == 1536504003123)
+ aligned_log = align_histo_log(raw_histo_log, 5, 4, min_timestamp_ms, max_timestamp_ms)
self.A(len(aligned_log) == 1)
(time_ms0, h) = aligned_log[0]
- self.A(time_ms0 == 0 and h == [1.0, 2.0, 3.0, 4.0])
+ self.A(time_ms0 == 1536504001123 and h == [5., 5., 5., 5.])
# we need this to compare 2 lists of floating point numbers for equality
# because of floating-point imprecision
with open(self.fn, 'w') as f:
f.write('2000, 1, 4096, 1, 2, 3, 4\n')
f.write('7000, 1, 4096, 1, 2, 3, 4\n')
- (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 4)
- self.A(max_timestamp_ms == 7000)
+ (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 4, None)
+ self.A(min_timestamp_ms == 0 and max_timestamp_ms == 7000)
(_, _, _, raw_buckets1) = raw_histo_log[0]
(_, _, _, raw_buckets2) = raw_histo_log[1]
- aligned_log = align_histo_log(raw_histo_log, 5, 4, max_timestamp_ms)
+ aligned_log = align_histo_log(raw_histo_log, 5, 4, min_timestamp_ms, max_timestamp_ms)
self.A(len(aligned_log) == 2)
(time_ms1, h1) = aligned_log[0]
(time_ms2, h2) = aligned_log[1]
with open(self.fn, 'w') as f:
buckets = [ 100 for j in range(0, 128) ]
f.write('9000, 1, 4096, %s\n' % ', '.join([str(b) for b in buckets]))
- (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, 128)
- self.A(max_timestamp_ms == 9000)
- aligned_log = align_histo_log(raw_histo_log, 5, 128, max_timestamp_ms)
+ (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, 128, None)
+ self.A(min_timestamp_ms == 0 and max_timestamp_ms == 9000)
+ aligned_log = align_histo_log(raw_histo_log, 5, 128, min_timestamp_ms, max_timestamp_ms)
time_intervals = time_ranges(4, 32)
# since buckets are all equal, then median is halfway through time_intervals
# and max latency interval is at end of time_intervals
# add one I/O request to last bucket
buckets[-1] = 1
f.write('9000, 1, 4096, %s\n' % ', '.join([str(b) for b in buckets]))
- (raw_histo_log, max_timestamp_ms) = parse_hist_file(self.fn, fio_v3_bucket_count)
- self.A(max_timestamp_ms == 9000)
- aligned_log = align_histo_log(raw_histo_log, 5, fio_v3_bucket_count, max_timestamp_ms)
+ (raw_histo_log, min_timestamp_ms, max_timestamp_ms) = parse_hist_file(self.fn, fio_v3_bucket_count, None)
+ self.A(min_timestamp_ms == 0 and max_timestamp_ms == 9000)
+ aligned_log = align_histo_log(raw_histo_log, 5, fio_v3_bucket_count, min_timestamp_ms, max_timestamp_ms)
(time_ms, histo) = aligned_log[1]
time_intervals = time_ranges(29, 64)
expected_pctiles = { 100.0:(64*(1<<28))/1000.0 }
if __name__ == '__main__':
if os.getenv('UNITTEST'):
- sys.exit(unittest2.main())
+ if unittest2_imported:
+ sys.exit(unittest2.main())
+ else:
+ raise Exception('you must install unittest2 module to run unit test')
else:
compute_percentiles_from_logs()
projects / fio.git / commitdiff