Hi Sitsofe, Yes, that is correct. -----Original Message----- From: Sitsofe Wheeler [mailto:sitsofe@xxxxxxxxx] Sent: Friday, March 31, 2017 12:35 AM To: Chris Taylor <ctaylor@xxxxxxxxxx> Cc: fio@xxxxxxxxxxxxxxx Subject: Re: FIO log averaging issue with --write_bw_log and --write_iops_log using > 1000 log_avg_msec values Hi Chris, Sorry for the slow reply. So this change is to deal with the case where the time being added is two more seconds in size? On 2 March 2017 at 21:52, Chris Taylor <ctaylor@xxxxxxxxxx> wrote: > Hi, > I am less concerned about any possible timing issues as they are probably miniscule and I can't think of the scenario where it would be a problem and cause less accurate results to really be concerned about. > Tests pretty much prove we are getting close to what we expect: > fio --eta=never --ioengine=libaio --readwrite=write --time_based=1 > --runtime=60 --filename=/tmp/fio --size=1M --direct=1 --name=test > --write_iops_log=/tmp/test --log_avg_msec=5500 --log_unix_epoch=1 > 1488489137632, 6413, 1, 0 1488489143131, 5503, 1, 0 1488489148631, > 5585, 1, 0 1488489154131, 5883, 1, 0 1488489159631, 5726, 1, 0 > 1488489165131, 5331, 1, 0 1488489170631, 5772, 1, 0 1488489176131, > 5661, 1, 0 1488489181631, 5970, 1, 0 1488489187131, 5776, 1, 0 [5499, > 5500, 5500, 5500, 5500, 5500, 5500, 5500, 5500] > > However, the problem still exists where in timeval_add_msec gets a > value greater than 1000 msecs the tv->tv_usec it will grow beyond > usecs (1000000) and causes unexpected behavior. Possibly this is the > better fix to avoid other callers having to adjust for the overflow > in timeval_add_msecs?\ diff --git a/time.c b/time.c index > f5dc049..a318ad5 100644 > --- a/time.c > +++ b/time.c > @@ -9,10 +9,9 @@ static unsigned long ns_granularity; void > timeval_add_msec(struct timeval *tv, unsigned int msec) { > tv->tv_usec += 1000 * msec; > - if (tv->tv_usec >= 1000000) { > - tv->tv_usec -= 1000000; > - tv->tv_sec++; > - } > + tv->tv_sec += tv->tv_usec / 1000000; > + tv->tv_usec %= 1000000; > + > } > > /* > Running the same job as above with the change: > 1488489763099, 5773, 1, 0 > 1488489768599, 5852, 1, 0 > 1488489774099, 5654, 1, 0 > 1488489779599, 5482, 1, 0 > 1488489785099, 5650, 1, 0 > 1488489790599, 5752, 1, 0 > 1488489796099, 5390, 1, 0 > 1488489801599, 5746, 1, 0 > 1488489807099, 5610, 1, 0 > 1488489812599, 5361, 1, 0 > [5500, 5500, 5500, 5500, 5500, 5500, 5500, 5500, 5500] > > Thanks, > Chris > > -----Original Message----- > From: Sitsofe Wheeler [mailto:sitsofe@xxxxxxxxx] > Sent: Tuesday, February 28, 2017 11:50 AM > To: Chris Taylor <ctaylor@xxxxxxxxxx> > Cc: fio@xxxxxxxxxxxxxxx > Subject: Re: FIO log averaging issue with --write_bw_log and > --write_iops_log using > 1000 log_avg_msec values > > Hi, > > Re timing issues: do you mean because of usec /= 1000; on line 428? As mtime_since() returns milliseconds it would mean all fractional millisecond amounts would be pushed downward so potentially things could be be under by a millisecond. If that's what you're thinking of I guess how bad that is depends on how much accuracy you need and how much jitter there is within the system already. Perhaps you can demonstrate a problem scenario so folks numerate than I will see the problem too... > > Re rounding problem - fair enough. > > On 28 February 2017 at 00:47, Chris Taylor <ctaylor@xxxxxxxxxx> wrote: >> Hi Sitsofe, >> Looks like this is handled in commit be6bb2b72608d7efbec13d06c67446e229136afa. >> I am no longer able to reproduce the issue with latest version of FIO 2.17, with that change as usecs will now be 0. Could this potentially cause some timing issues? >> >> Prior to that commit... >> The job below would result in bw_logs and iops_log that have skewed >> results both the add_iops_samples and add_bw_samples makes a call to >> mtime_since with start time as the _sample_time >> ./stat.c:2435: spent = mtime_since(&td->bw_sample_time, t) >> ./stat.c:2510: spent = mtime_since(&td->iops_sample_time, t); >> >> ./stat.c:2473: timeval_add_msec(&td->bw_sample_time, >> td->o.bw_avg_time); >> ./stat.c:2548: timeval_add_msec(&td->iops_sample_time, >> td->o.iops_avg_time); >> >> stat.c:2480:27: runtime error: unsigned integer overflow: 2000 - 18446744073708449 cannot be represented in type 'unsigned long' >> stat.c:2555:29: runtime error: unsigned integer overflow: 2000 - 18446744073708449 cannot be represented in type 'unsigned long' >> >> The overflow at stat.c:2265 is a different issue possibly a rounding problem with msec and usecs. > > -- > Sitsofe | http://sucs.org/~sits/ > > On 28 February 2017 at 00:47, Chris Taylor <ctaylor@xxxxxxxxxx> wrote: >> Hi Sitsofe, >> Looks like this is handled in commit be6bb2b72608d7efbec13d06c67446e229136afa. >> I am no longer able to reproduce the issue with latest version of FIO 2.17, with that change as usecs will now be 0. Could this potentially cause some timing issues? >> >> Prior to that commit... >> The job below would result in bw_logs and iops_log that have skewed >> results both the add_iops_samples and add_bw_samples makes a call to >> mtime_since with start time as the _sample_time >> ./stat.c:2435: spent = mtime_since(&td->bw_sample_time, t) >> ./stat.c:2510: spent = mtime_since(&td->iops_sample_time, t); >> >> ./stat.c:2473: timeval_add_msec(&td->bw_sample_time, >> td->o.bw_avg_time); >> ./stat.c:2548: timeval_add_msec(&td->iops_sample_time, >> td->o.iops_avg_time); >> >> stat.c:2480:27: runtime error: unsigned integer overflow: 2000 - 18446744073708449 cannot be represented in type 'unsigned long' >> stat.c:2555:29: runtime error: unsigned integer overflow: 2000 - 18446744073708449 cannot be represented in type 'unsigned long' >> >> The overflow at stat.c:2265 is a different issue possibly a rounding problem with msec and usecs. >> >> >> Thanks, >> Chris >> >> On 23 February 2017 at 20:55, Chris Taylor <ctaylor@xxxxxxxxxx> wrote: >>> There is an issue in FIO when using the detailed bandwidth and iops logging with averaging over a period of time > 1 second. >>> It seems that usecs overflows which later causes negative time diff values resulting in skewed toward 0 results. >>> I have attached a potential fix that should prevent usecs from going beyond 1000000. >> >> Is this problem shown by the following job: >> >> ./fio --ioengine=null --write_bw_log=/dev/null --log_avg_msec=2000 >> --size=100M --runtime=10s --time_based --name=overflow >> >> Among Clang's undefined behaviour sanitizer output was this for the above: >> stat.c:2265:43: runtime error: unsigned integer overflow: 1999 - 2000 cannot be represented in type 'unsigned long' >> stat.c:2265:28: runtime error: unsigned integer overflow: 3999 - >> 4294967295 cannot be represented in type 'unsigned long' >> >>> diff --git a/time.c b/time.c >>> index f5dc049..c748bee 100644 >>> --- a/time.c >>> +++ b/time.c >>> @@ -8,11 +8,18 @@ static unsigned long ns_granularity; >>> >>> void timeval_add_msec(struct timeval *tv, unsigned int msec) { >>> - tv->tv_usec += 1000 * msec; >>> - if (tv->tv_usec >= 1000000) { >>> - tv->tv_usec -= 1000000; >>> - tv->tv_sec++; >>> - } >>> + int adj_usec = 1000 * msec; >>> + int adj_sec = 0; >>> + tv->tv_usec += adj_usec; >>> + if (adj_usec >= 1000000) { >>> + adj_sec = adj_usec / 1000000; >>> + tv->tv_usec -= adj_sec * 1000000; >>> + tv->tv_sec += adj_sec; >>> + } >>> + if (tv->tv_usec >= 1000000){ >>> + tv->tv_usec -= 1000000; >>> + tv->tv_sec++; >>> + } >>> } >> >> Is it still safe to use int if you're targeting a 32 bit platform? >> -- >> Sitsofe | http://sucs.org/~sits/ > > > > -- > Sitsofe | http://sucs.org/~sits/ -- Sitsofe | http://sucs.org/~sits/ ��.n��������+%������w��{.n�������^n�r������&��z�ޗ�zf���h���~����������_��+v���)ߣ�
