Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1311893 > unrolled thread

[BUG REPORT] ktime_get_ts64 causes Hard Lockup

Started byJeff Merkey <linux.mdb@gmail.com>
First post2016-01-19 03:00 +0100
Last post2016-01-21 18:10 +0100
Articles 9 on this page of 29 — 3 participants

Back to article view | Back to linux.kernel

Contents

  [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-19 03:00 +0100
    Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-19 03:20 +0100
      Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-19 03:40 +0100
    Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Thomas Gleixner <tglx@linutronix.de> - 2016-01-19 11:00 +0100
    Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-19 16:40 +0100
      Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-19 23:10 +0100
        Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 02:00 +0100
        Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Thomas Gleixner <tglx@linutronix.de> - 2016-01-20 10:30 +0100
          Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Thomas Gleixner <tglx@linutronix.de> - 2016-01-20 15:30 +0100
            Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 17:50 +0100
          Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 18:00 +0100
            Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 18:20 +0100
              Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 18:40 +0100
              Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup John Stultz <john.stultz@linaro.org> - 2016-01-20 18:40 +0100
                Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Thomas Gleixner <tglx@linutronix.de> - 2016-01-20 18:50 +0100
                  Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup John Stultz <john.stultz@linaro.org> - 2016-01-20 19:00 +0100
                    Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 19:10 +0100
            Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Thomas Gleixner <tglx@linutronix.de> - 2016-01-20 18:30 +0100
              Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 18:40 +0100
                Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Thomas Gleixner <tglx@linutronix.de> - 2016-01-20 20:40 +0100
                  Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-20 21:10 +0100
                    Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-21 08:20 +0100
                      Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-21 09:20 +0100
                        Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-21 10:10 +0100
                      Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Thomas Gleixner <tglx@linutronix.de> - 2016-01-21 11:20 +0100
                        Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-21 16:50 +0100
                          Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-21 18:00 +0100
                            Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-21 18:10 +0100
                            Re: [BUG REPORT] ktime_get_ts64 causes Hard Lockup Jeff Merkey <linux.mdb@gmail.com> - 2016-01-21 18:10 +0100

Page 2 of 2 — ← Prev page 1 [2]

#1313491

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-20 21:10 +0100
Message-ID<qT7eO-33h-11@gated-at.bofh.it>
In reply to#1313466
On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
> Jeff,
>
> On Wed, 20 Jan 2016, Jeff Merkey wrote:
>> Thomas, so far the only thing I've gotten from you are whining
>> diatribes about email ettiquette and today is the FIRST time you have
>> responded to me with any arguments that have technical merit and
>> actually address the problem.    That's what I am here for, not
>> anything else.  As Linus has said repeatedly, being nice doesn't seem
>> to get results.    Being direct and honest does.
>>
>> I am here to make MDB run as well as I can make it on Linux and to
>> help make it run as well as possible on c86_64 and ia32.  That's my
>> only objective here.   That being said,  I am still wanting to get
>> this fixed.
>>
>> Will you help me?
>
> If you accept, that you are not setting the tone of the conversation as you
> think it fits you.
>
> I started to give you technical answers way before you started your
> completely
> unjustified ranting. And I have done so before.
>
> I'm neither going to cope with random emails in my private inbox nor with
> top-posting and non-trimmed replies simply because that wastes my time. And
> certainly I'm not going to cope with your assumption that not being nice is
> the right way to go.
>
> It's your decision, not mine.
>
> Thanks,
>
> 	tglx
>

Oh good grief -- I guess we all have our days me included.  I am sorry
to have offended you.    Turn the page, next chapter.    I am already
past this.  BTW, I am preparing my report.  Results same as before
with CONFIG_DEBUG_TIMEKEEPING, Hard Lockup again.  I am running a
trace right now to see just how big RAX was this time with the
nanoseconds count.

Jeff

[toc] | [prev] | [next] | [standalone]

#1313970

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-21 08:20 +0100
Message-ID<qThHc-1RP-7@gated-at.bofh.it>
In reply to#1313491
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

[toc] | [prev] | [next] | [standalone]

#1313989

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-21 09:20 +0100
Message-ID<qTiDg-2B3-3@gated-at.bofh.it>
In reply to#1313970
On 1/21/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
> 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
>

s64 = signed 64.    right in the code.  wow.

The iter_div64 functions all assume unsigned values, so this needs to
be patched.  Can't use signed for shifting to a value that will be
interpreted as unsigned by the system math.  Just makes a huge number
that wraps.  This patch is a one-liner after all.

:-)

Jeff

[toc] | [prev] | [next] | [standalone]

#1314016

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-21 10:10 +0100
Message-ID<qTjpF-39M-23@gated-at.bofh.it>
In reply to#1313989
This bug has been fixed as of linux-next-20160121.  I just checked so
looks like its handled.

	delta = timekeeping_get_delta(tkr);

	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
     251:	8b 15 00 00 00 00    	mov    0x0(%rip),%edx        # 257
<ktime_get_ts64+0x77>
     257:	49 0f 45 c4          	cmovne %r12,%rax
     25b:	48 0f af c2          	imul   %rdx,%rax
     25f:	48 03 05 00 00 00 00 	add    0x0(%rip),%rax        # 266
<ktime_get_ts64+0x86>
     266:	48 d3 e8             	shr    %cl,%rax    << correct
	

Jeff

[toc] | [prev] | [next] | [standalone]

#1314074

FromThomas Gleixner <tglx@linutronix.de>
Date2016-01-21 11:20 +0100
Message-ID<qTkvo-3Pq-21@gated-at.bofh.it>
In reply to#1313970
Jeff,

On Thu, 21 Jan 2016, Jeff Merkey wrote:
> 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

That SAR is siomply wrong here. It must be an SHR and it is at least when I'm
looking at the assembly of my machine.

> 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 ?).

There is no macro involved.

timekeeping_get_ns
{
	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
}

> 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

And this is fundamentally wrong. Why is the compiler emitting SAR instead of
SHR here? Here is the assembly output from my kernel:

	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
     27e:	48 0f af c5          	imul   %rbp,%rax
     282:	48 01 d8             	add    %rbx,%rax
     285:	48 d3 e8             	shr    %cl,%rax

	} while (read_seqcount_retry(&tk_core.seq, seq));


So the first thing which needs to be figured out is WHY this results in a SAR
on your compiler.

> 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;
> }

If that value does not change, then the timekeeping update is not
running. That might happen because the timer interrupt is not happening or
whatever got wreckaged.
 
> 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.

Sure. Here you go:

	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;

delta, mult, xtime_nsec and shift are unsigned. The only signed value is nsec.

Does that issue go away if you apply the patch below?

Thanks,

	tglx

8<-----------
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 34b4cedfa80d..d405bcdf9d40 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -301,7 +301,7 @@ static inline u32 arch_gettimeoffset(void) { return 0; }
 static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
 {
 	cycle_t delta;
-	s64 nsec;
+	u64 nsec;
 
 	delta = timekeeping_get_delta(tkr);

[toc] | [prev] | [next] | [standalone]

#1314280

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-21 16:50 +0100
Message-ID<qTpEK-7eF-1@gated-at.bofh.it>
In reply to#1314074
Hi Thomas

That patch works and so does the patch currently in linux-next.  Yeah !

The code on your machine is apparently from the linux-next tree. In
4.4 is busted and that was the build I was using since that's the last
build I have MDB released on.  If you compare v4.4 vs. linux-next you
will see someone already has patched this problem -- its just not in
Linus tree yet.

v4.4

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;  << causes sar to be used

	/* If arch requires, add in get_arch_timeoffset() */
	return nsec + arch_gettimeoffset();
}

linux-next

static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
{
	cycle_t delta;
	u64 nsec;

	delta = timekeeping_get_delta(tkr);

	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift; << shr used here

	/* If arch requires, add in get_arch_timeoffset() */
	return (s64)(nsec + arch_gettimeoffset());
}


This bug goes way back in the linux revs, so I have to retro apply
this patch back to v3.6 in the MDB patch series.  This bug was
introduced in the late linux 3.6 kernels and exists in all of them up
to v4.4.

Jeff


On 1/21/16, Thomas Gleixner <tglx@linutronix.de> wrote:
> Jeff,
>
> On Thu, 21 Jan 2016, Jeff Merkey wrote:
>> 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
>
> That SAR is siomply wrong here. It must be an SHR and it is at least when
> I'm
> looking at the assembly of my machine.
>
>> 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 ?).
>
> There is no macro involved.
>
> timekeeping_get_ns
> {
> 	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
> }
>
>> 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
>
> And this is fundamentally wrong. Why is the compiler emitting SAR instead
> of
> SHR here? Here is the assembly output from my kernel:
>
> 	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
>      27e:	48 0f af c5          	imul   %rbp,%rax
>      282:	48 01 d8             	add    %rbx,%rax
>      285:	48 d3 e8             	shr    %cl,%rax
>
> 	} while (read_seqcount_retry(&tk_core.seq, seq));
>
>
> So the first thing which needs to be figured out is WHY this results in a
> SAR
> on your compiler.
>
>> 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;
>> }
>
> If that value does not change, then the timekeeping update is not
> running. That might happen because the timer interrupt is not happening or
> whatever got wreckaged.
>
>> 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.
>
> Sure. Here you go:
>
> 	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
>
> delta, mult, xtime_nsec and shift are unsigned. The only signed value is
> nsec.
>
> Does that issue go away if you apply the patch below?
>
> Thanks,
>
> 	tglx
>
> 8<-----------
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index 34b4cedfa80d..d405bcdf9d40 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -301,7 +301,7 @@ static inline u32 arch_gettimeoffset(void) { return 0;
> }
>  static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
>  {
>  	cycle_t delta;
> -	s64 nsec;
> +	u64 nsec;
>
>  	delta = timekeeping_get_delta(tkr);
>
>

[toc] | [prev] | [next] | [standalone]

#1314353

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-21 18:00 +0100
Message-ID<qTqKv-7ZR-39@gated-at.bofh.it>
In reply to#1314280
One other item worth mentioning is the effect of this bug on the user
space daemons.  Since this bug is in all kernels from 3.6-v4.4, folks
will see the following behavior of systemd when this bug fires off and
the value wraps:

id 0a0c809bcdc0812145d9c35456e46335650601b7
reason:         systemd-journald killed by SIGABRT
time:           Sun 10 Jan 2016 11:56:16 AM MST
cmdline:        /usr/lib/systemd/systemd-journald
package:        systemd-219-19.el7
uid:            0 (root)
count:          2
Directory:      /var/tmp/abrt/ccpp-2016-01-10-11:56:16-6281

id 38f7bb372d0c14cb912e9d225fb474b931889e77
reason:         __epoll_wait_nocancel(): systemd-logind killed by SIGABRT
time:           Fri 08 Jan 2016 01:33:42 PM MST
cmdline:        /usr/lib/systemd/systemd-logind
package:        systemd-219-19.el7
uid:            0 (root)
count:          39
Directory:      /var/tmp/abrt/ccpp-2016-01-08-13:33:42-630
Reported:
https://retrace.fedoraproject.org/faf/reports/bthash/307b26a77cc6d5005ce2fdf18ff010fe3dc94401

So if folks see aborts in systemd that look like the above, it's this
bug.    I traced the systemd crash as well and its caused by the
system returning garbage via system calls to systemd when that rax
value wraps.

Jeff.



On 1/21/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
> Hi Thomas
>
> That patch works and so does the patch currently in linux-next.  Yeah !
>
> The code on your machine is apparently from the linux-next tree. In
> 4.4 is busted and that was the build I was using since that's the last
> build I have MDB released on.  If you compare v4.4 vs. linux-next you
> will see someone already has patched this problem -- its just not in
> Linus tree yet.
>
> v4.4
>
> 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;  << causes sar to be used
>
> 	/* If arch requires, add in get_arch_timeoffset() */
> 	return nsec + arch_gettimeoffset();
> }
>
> linux-next
>
> static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
> {
> 	cycle_t delta;
> 	u64 nsec;
>
> 	delta = timekeeping_get_delta(tkr);
>
> 	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift; << shr used
> here
>
> 	/* If arch requires, add in get_arch_timeoffset() */
> 	return (s64)(nsec + arch_gettimeoffset());
> }
>
>
> This bug goes way back in the linux revs, so I have to retro apply
> this patch back to v3.6 in the MDB patch series.  This bug was
> introduced in the late linux 3.6 kernels and exists in all of them up
> to v4.4.
>
> Jeff
>
>
> On 1/21/16, Thomas Gleixner <tglx@linutronix.de> wrote:
>> Jeff,
>>
>> On Thu, 21 Jan 2016, Jeff Merkey wrote:
>>> 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
>>
>> That SAR is siomply wrong here. It must be an SHR and it is at least when
>> I'm
>> looking at the assembly of my machine.
>>
>>> 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 ?).
>>
>> There is no macro involved.
>>
>> timekeeping_get_ns
>> {
>> 	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
>> }
>>
>>> 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
>>
>> And this is fundamentally wrong. Why is the compiler emitting SAR instead
>> of
>> SHR here? Here is the assembly output from my kernel:
>>
>> 	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
>>      27e:	48 0f af c5          	imul   %rbp,%rax
>>      282:	48 01 d8             	add    %rbx,%rax
>>      285:	48 d3 e8             	shr    %cl,%rax
>>
>> 	} while (read_seqcount_retry(&tk_core.seq, seq));
>>
>>
>> So the first thing which needs to be figured out is WHY this results in a
>> SAR
>> on your compiler.
>>
>>> 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;
>>> }
>>
>> If that value does not change, then the timekeeping update is not
>> running. That might happen because the timer interrupt is not happening
>> or
>> whatever got wreckaged.
>>
>>> 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.
>>
>> Sure. Here you go:
>>
>> 	nsec = (delta * tkr->mult + tkr->xtime_nsec) >> tkr->shift;
>>
>> delta, mult, xtime_nsec and shift are unsigned. The only signed value is
>> nsec.
>>
>> Does that issue go away if you apply the patch below?
>>
>> Thanks,
>>
>> 	tglx
>>
>> 8<-----------
>> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
>> index 34b4cedfa80d..d405bcdf9d40 100644
>> --- a/kernel/time/timekeeping.c
>> +++ b/kernel/time/timekeeping.c
>> @@ -301,7 +301,7 @@ static inline u32 arch_gettimeoffset(void) { return
>> 0;
>> }
>>  static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
>>  {
>>  	cycle_t delta;
>> -	s64 nsec;
>> +	u64 nsec;
>>
>>  	delta = timekeeping_get_delta(tkr);
>>
>>
>

[toc] | [prev] | [next] | [standalone]

#1314357

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-21 18:10 +0100
Message-ID<qTqUb-8kQ-33@gated-at.bofh.it>
In reply to#1314353
Hi Thomas,

I figured out where the top-posting is coming from -- gmail web client
does it automatically.  Switching email clients.  I will still use
gmail for smtp forwarding but their busted piece of crap web email
client automatically top posts when you use the "reply" window and
it's gone.

I am not intentionally top posting, I am switching clients today so
this problem does not happen again.

Jeff

[toc] | [prev] | [next] | [standalone]

#1314361

FromJeff Merkey <linux.mdb@gmail.com>
Date2016-01-21 18:10 +0100
Message-ID<qTqUb-8kQ-35@gated-at.bofh.it>
In reply to#1314353
I am switching email clients from gmail.  This stupid email client of
theirs constantly top posts and sends multiple emails replies when you
try to send a reply.  I apologize yet again for the top posting.  It's
gmail doing it.  Unless I delete the entire previous message it will
always top post.

Sorry about that I finally figured out that bug too.

:-)

Jeff

[toc] | [prev] | [standalone]

Page 2 of 2 — ← Prev page 1 [2]

Back to top | Article view | linux.kernel

csiph-web