Repeated timestamps in latency log files

[pzoxiuv]

This seems to be the same as #947, but I'm using the latest from master and still seeing the issue.

Config file:

[global]
directory=/var/data/
size=64m

[test]
rw=write
time_based
runtime=1m
write_lat_log=/host/fio_out_lat
log_avg_msec=50

And here's a segment of the log file:

3250, 2407, 1, 0, 0
3300, 2467, 1, 0, 0
3350, 2459, 1, 0, 0
3400, 2502, 1, 0, 0
3450, 2493, 1, 0, 0
3500, 2497, 1, 0, 0
3550, 2471, 1, 0, 0
5471, 194581, 1, 0, 0
5475, 4039507, 1, 0, 0
5475, 13797, 1, 0, 0
5475, 6633, 1, 0, 0
5475, 6187, 1, 0, 0
5475, 5457, 1, 0, 0
...
5475, 5063, 1, 0, 0
5475, 5510, 1, 0, 0
5475, 5537, 1, 0, 0
5500, 5902, 1, 0, 0
5553, 5831, 1, 0, 0
5600, 6004, 1, 0, 0

The first several lines are as expected, but then there's 38 lines with the same timestamp. It seems like maybe the timestamp just isn't being updated? I think there's the correct number of lines: (5500-3550)/50 = 39

[pzoxiuv]

I think the issue is that when add_log_sample saves a log entry it always sets the last log time (iolog->avg_last) to iolog->avg_last plus the sampling window duration (iolog->avg_msec), even if more than one sampling window has elapsed. E.g. if iolog->avg_last is 600ms, iolog->avg_msec is 50ms, and add_log_sample is called at t=800ms, iolog->avg_last will be set to 650ms. So next time add_log_sample gets called (probably with t=800ms again) a new log entry will be saved with the same t=800ms timestamp.

One fix would be to change line https://github.com/axboe/fio/blob/master/stat.c#L2754 from
iolog->avg_last[ddir] = elapsed - (this_window - iolog->avg_msec);
to
iolog->avg_last[ddir] = elapsed - (elapsed % iolog->avg_msec);

[sitsofe]

@pzoxiuv Do you know if #973 also fixes this?

[pzoxiuv]

@sitsofe just tried, it does not.

[sitsofe]

@vincentkfu does the fix suggested a bit above look correct?

[vincentkfu]

I took a brief look and the fix appears reasonable, although I do not know the logging code well. The result will be missing log entries but that is better than having these repeated timestamps. I have to say, though, that 50ms seems like an awfully short logging interval.

[pzoxiuv]

@vincentkfu thanks for looking, I'll submit a pull request soon for this. 50ms is short but I was just using that to speed up reproducing the issue - I originally ran into the problem with 500ms, but it happens more often with shorter intervals.