ring-buffer: Do not trigger a WARN if clock going backwards is detected
After tweaking the ring buffer to be a bit faster, a warning is triggering on one of my machines, and causing my tests to fail. This warning is caused when the delta (current time stamp minus previous time stamp), is larger than the max time held by the ring buffer (59 bits). If the clock were to go backwards slightly, this would then easily trigger this warning. The machine that it triggered on, the clock did go backwards by around 450 nanoseconds, and this happened after a recalibration of the TSC clock. Now that the ring buffer is faster, it detects this, and the delta that is used larger than the max, the warning is triggered and my test fails. To handle the clock going backwards, look at the saved before and after time stamps. If they are the same, it means that the current event did not interrupt another event, and that those timestamp are of a previous event that was recorded. If the max delta is triggered, look at those time stamps, make sure they are the same, then use them to compare with the current timestamp. If the current timestamp is less than the before/after time stamps, then that means the clock being used went backward. Print out a message that this has happened, but do not warn about it (and only print the message once). Still do the warning if the delta is indeed larger than what can be used. Also remove the unneeded KERN_WARNING from the WARN_ONCE() print. Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
This commit is contained in:
parent
bbeba3e58f
commit
29ce24519c
|
@ -2642,8 +2642,7 @@ rb_check_timestamp(struct ring_buffer_per_cpu *cpu_buffer,
|
|||
{
|
||||
u64 write_stamp;
|
||||
|
||||
WARN_ONCE(info->delta > (1ULL << 59),
|
||||
KERN_WARNING "Delta way too big! %llu ts=%llu before=%llu after=%llu write stamp=%llu\n%s",
|
||||
WARN_ONCE(1, "Delta way too big! %llu ts=%llu before=%llu after=%llu write stamp=%llu\n%s",
|
||||
(unsigned long long)info->delta,
|
||||
(unsigned long long)info->ts,
|
||||
(unsigned long long)info->before,
|
||||
|
@ -2665,7 +2664,26 @@ static void rb_add_timestamp(struct ring_buffer_per_cpu *cpu_buffer,
|
|||
bool abs = info->add_timestamp &
|
||||
(RB_ADD_STAMP_FORCE | RB_ADD_STAMP_ABSOLUTE);
|
||||
|
||||
rb_check_timestamp(cpu_buffer, info);
|
||||
if (unlikely(info->delta > (1ULL << 59))) {
|
||||
/* did the clock go backwards */
|
||||
if (info->before == info->after && info->before > info->ts) {
|
||||
/* not interrupted */
|
||||
static int once;
|
||||
|
||||
/*
|
||||
* This is possible with a recalibrating of the TSC.
|
||||
* Do not produce a call stack, but just report it.
|
||||
*/
|
||||
if (!once) {
|
||||
once++;
|
||||
pr_warn("Ring buffer clock went backwards: %llu -> %llu\n",
|
||||
info->before, info->ts);
|
||||
}
|
||||
} else
|
||||
rb_check_timestamp(cpu_buffer, info);
|
||||
if (!abs)
|
||||
info->delta = 0;
|
||||
}
|
||||
*event = rb_add_time_stamp(*event, info->delta, abs);
|
||||
*length -= RB_LEN_TIME_EXTEND;
|
||||
*delta = 0;
|
||||
|
|
Loading…
Reference in New Issue