Ok, here's what I found after several hours of debugging and reviewing
this subsystem:
This subsystem plays is pretty loose in doing its math on 64 bit
registers. I traced through ktime_get_ts64 hundreds of times and
sampled data running through it and from what I saw, just normal
operations comes dangerously close to causing the RAX register to
wrap. If the delta gets too big it does wrap and I observed it
happening with the debugger tracing through the code. It wraps
because of a sar instruction generated from the inline macros.
The wrap happens in this inline function.
static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
{
cycle_t delta;
s64 nsec;
delta = timekeeping_get_delta(tkr);
nsec = delta * tkr->mult + tkr->xtime_nsec;
nsec >>= tkr->shift; << wrap caused here
/* If arch requires, add in get_arch_timeoffset() */
return nsec + arch_gettimeoffset();
}
You only have 64 bits of register and the numbers being calculated
here are big. By way of example, I observed the following during
normal operations:
delta (RAX) | tkr->mult (RDX)
0x157876 0x65ee27
0xf1855 0x65f158
0x16cf05 0x65f408
303bc3 0x65f154
When this bug occurs different story.
delta (RAX) | tkr->mult (RDX)
0x243283994b8 0x65233
So it goes like this:
nsec = delta * tkr->mult + tkr->xtime_nsec;
0x243283994b8 * 0x65233
imul rax,rdx = 0xE6A2Ce1f1ea690a8
nsec >>= tkr->shift; << wrap caused here
sar rax,cl = 0xFFFFFFE6BFB3B7C3
the sar instruction doesn't just shift, it backfills the signedness of
the value, so this instruction is not doing what the C code is asking
it to do. I am guessing that somewhere in this mass of macros,
something may have gotten declared wrong or incomplete (declared
signed ?).
The assembler output for this section that calls the macro to
calculate nsecs shows the sar instruction:
delta = timekeeping_get_delta(tkr);
nsec = delta * tkr->mult + tkr->xtime_nsec;
29b: 48 0f af c2 imul %rdx,%rax
29f: 48 03 05 00 00 00 00 add 0x0(%rip),%rax # 2a6
<ktime_get_ts64+0xc6>
nsec >>= tkr->shift;
2a6: 48 d3 f8 sar %cl,%rax
There is another problem with the tkr->read returning an unchanging,
unclearable number when this bug occurs for the delta value. I
appears for whatever reason the clock has gone to sleep or gone away
and is no longer updating its counters.
static inline cycle_t timekeeping_get_delta(struct tk_read_base *tkr)
{
cycle_t cycle_now, delta;
/* read clocksource */
cycle_now = tkr->read(tkr->clock); << returns the same value after
this bug happens
/* calculate the delta since the last update_wall_time */
delta = clocksource_delta(cycle_now, tkr->cycle_last, tkr->mask); <<
cycle last is also the same value.
return delta;
}
This problem appears to have several things happening at once.
Probably the most concerning is that the assembler output is making
some assumptions about the SIGNEDNESS of the values being shifted and
using sar instead of shl instructions.
I am also concerned about the thr->read function returning an
unchanging value when this problem shows up.
This subsystem plays it fast and loose with its math, and if the clock
gets delayed or out of sync, it will wrap in the above function and it
will trigger the Hard Lockup detector if the value is large enough in
RAX. The sanity check for CONFIG_DEBUG_TIMEKEEPER does not catch the
code path where this delta value gets set because the function to
update the delta is called in more then just in that function that
checks for an overflow and the wrap case happens underneath it.
I would check how these structs are defined and the vars in them to
see if somewhere they are declared as signed values to the compiler,
because that's what it thinks it was given to compile.
I am still debugging the thr->read issue. I have determined the cause
of the wrap in the assembler. As to why the gcc compiler is outputing
this instruction here is something to be determined.
Jeff
