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

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 1 of 2  [1] 2  Next page →

#1311893 — [BUG REPORT] ktime_get_ts64 causes Hard Lockup

If I suspend all processors in the NMI handler while in the debugger
console at an active breakpoint, and then I leave the system in the
console for about 20 minutes with the processors spinning, then exit
and release the processors, ktime_get_ts64 enters an infinite loop and
triggers the Hard Lockup detector.   Nice having a debugger to just
step into the NMI handlers and find this stuff now.

The offending code is:

(2)> u ktime_get_ts64+9d
<<<  this section gets stuck in an infinite loop.
0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
0xffffffff810ede23 83C201          add    edx,0x1
0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
(0xffffffff810ede1d) (up)
<<<
0xffffffff810ede2e 4801CA          add    rdx,rcx
0xffffffff810ede31 48894308        mov    QWORD PTR
[rbx+8]=0xFFFFFFFFA0774E01,rax
0xffffffff810ede35 488913          mov    QWORD PTR [rbx]=0xFFFFFFFFA0742000,rdx
0xffffffff810ede38 5B              pop    rbx
0xffffffff810ede39 415C            pop    r12
0xffffffff810ede3b 415D            pop    r13
0xffffffff810ede3d 5D              pop    rbp
0xffffffff810ede3e C3              ret
0xffffffff810ede3f 31D2            xor    edx,edx
0xffffffff810ede41 EBEB            jmp    ktime_get_ts64+0xae
(0xffffffff810ede2e) (up)
0xffffffff810ede43 BE11030000      mov    esi,0x311
0xffffffff810ede48 48C7C751C38D81  mov    rdi,0xffffffff818dc351
0xffffffff810ede4f E82C12F9FF      call   warn_slowpath_null
0xffffffff810ede54 E946FFFFFF      jmp    ktime_get_ts64+0x1f
(0xffffffff810edd9f) (up)
0xffffffff810ede59 F390            pause
0xffffffff810ede5b E942FFFFFF      jmp    ktime_get_ts64+0x22
(0xffffffff810edda2) (up)

Same code in GDB format

(2)> id ktime_get_ts64+9d
<<<
0xffffffff810ede1d ktime_get_ts64+0x9d:    sub    $0x3b9aca00,%rax
0xffffffff810ede23 ktime_get_ts64+0xa3:    add    $0x1,%edx
0xffffffff810ede26 ktime_get_ts64+0xa6:    cmp    $0x3b9ac9ff,%rax
0xffffffff810ede2c ktime_get_ts64+0xac:    ja     0xffffffff810ede1d
ktime_get_ts64+0x9d (up)
<<<
0xffffffff810ede2e ktime_get_ts64+0xae:    add    %rcx,%rdx
0xffffffff810ede31 ktime_get_ts64+0xb1:    mov    %rax,0x8(%rbx)
0xffffffff810ede35 ktime_get_ts64+0xb5:    mov    %rdx,(%rbx)
0xffffffff810ede38 ktime_get_ts64+0xb8:    pop    %rbx
0xffffffff810ede39 ktime_get_ts64+0xb9:    pop    %r12
0xffffffff810ede3b ktime_get_ts64+0xbb:    pop    %r13
0xffffffff810ede3d ktime_get_ts64+0xbd:    pop    %rbp
0xffffffff810ede3e ktime_get_ts64+0xbe:    retq
0xffffffff810ede3f ktime_get_ts64+0xbf:    xor    %edx,%edx
0xffffffff810ede41 ktime_get_ts64+0xc1:    jmp    0xffffffff810ede2e
ktime_get_ts64+0xae (up)
0xffffffff810ede43 ktime_get_ts64+0xc3:    mov    $0x311,%esi
0xffffffff810ede48 ktime_get_ts64+0xc8:    mov    $0xffffffff818dc351,%rdi
0xffffffff810ede4f ktime_get_ts64+0xcf:    callq  0xffffffff8107f080
warn_slowpath_null
0xffffffff810ede54 ktime_get_ts64+0xd4:    jmpq   0xffffffff810edd9f
ktime_get_ts64+0x1f (up)
0xffffffff810ede59 ktime_get_ts64+0xd9:    pause
0xffffffff810ede5b ktime_get_ts64+0xdb:    jmpq   0xffffffff810edda2
ktime_get_ts64+0x22 (up)
(2)> g


What is strange is the math its doing.  It is subtracting a fixed
value from rax then comparing the value.  It looks like this is case
where the value may have wrapped and the code just wasn;t setup to
handle it.

0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
0xffffffff810ede23 83C201          add    edx,0x1
0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
(0xffffffff810ede1d) (up)

The C code is:


/**
 * ktime_get_ts64 - get the monotonic clock in timespec64 format
 * @ts:		pointer to timespec variable
 *
 * The function calculates the monotonic clock from the realtime
 * clock and the wall_to_monotonic offset and stores the result
 * in normalized timespec64 format in the variable pointed to by @ts.
 */
void ktime_get_ts64(struct timespec64 *ts)
{
	struct timekeeper *tk = &tk_core.timekeeper;
	struct timespec64 tomono;
	s64 nsec;
	unsigned int seq;

	WARN_ON(timekeeping_suspended);

	do {
		seq = read_seqcount_begin(&tk_core.seq);
		ts->tv_sec = tk->xtime_sec;
		nsec = timekeeping_get_ns(&tk->tkr_mono);
		tomono = tk->wall_to_monotonic;
<<<
	} while (read_seqcount_retry(&tk_core.seq, seq));
<<<
	ts->tv_sec += tomono.tv_sec;
	ts->tv_nsec = 0;
	timespec64_add_ns(ts, nsec + tomono.tv_nsec);
}
EXPORT_SYMBOL_GPL(ktime_get_ts64);

Any ideas how to fix this problem?  That do {} while gets stuck there.

Jeff

[toc] | [next] | [standalone]

#1311896

On 1/18/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
> If I suspend all processors in the NMI handler while in the debugger
> console at an active breakpoint, and then I leave the system in the
> console for about 20 minutes with the processors spinning, then exit
> and release the processors, ktime_get_ts64 enters an infinite loop and
> triggers the Hard Lockup detector.   Nice having a debugger to just
> step into the NMI handlers and find this stuff now.
>
> The offending code is:
>
> (2)> u ktime_get_ts64+9d
> <<<  this section gets stuck in an infinite loop.
> 0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
> 0xffffffff810ede23 83C201          add    edx,0x1
> 0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
> 0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
> (0xffffffff810ede1d) (up)
> <<<
> 0xffffffff810ede2e 4801CA          add    rdx,rcx
> 0xffffffff810ede31 48894308        mov    QWORD PTR
> [rbx+8]=0xFFFFFFFFA0774E01,rax
> 0xffffffff810ede35 488913          mov    QWORD PTR
> [rbx]=0xFFFFFFFFA0742000,rdx
> 0xffffffff810ede38 5B              pop    rbx
> 0xffffffff810ede39 415C            pop    r12
> 0xffffffff810ede3b 415D            pop    r13
> 0xffffffff810ede3d 5D              pop    rbp
> 0xffffffff810ede3e C3              ret
> 0xffffffff810ede3f 31D2            xor    edx,edx
> 0xffffffff810ede41 EBEB            jmp    ktime_get_ts64+0xae
> (0xffffffff810ede2e) (up)
> 0xffffffff810ede43 BE11030000      mov    esi,0x311
> 0xffffffff810ede48 48C7C751C38D81  mov    rdi,0xffffffff818dc351
> 0xffffffff810ede4f E82C12F9FF      call   warn_slowpath_null
> 0xffffffff810ede54 E946FFFFFF      jmp    ktime_get_ts64+0x1f
> (0xffffffff810edd9f) (up)
> 0xffffffff810ede59 F390            pause
> 0xffffffff810ede5b E942FFFFFF      jmp    ktime_get_ts64+0x22
> (0xffffffff810edda2) (up)
>
> Same code in GDB format
>
> (2)> id ktime_get_ts64+9d
> <<<
> 0xffffffff810ede1d ktime_get_ts64+0x9d:    sub    $0x3b9aca00,%rax
> 0xffffffff810ede23 ktime_get_ts64+0xa3:    add    $0x1,%edx
> 0xffffffff810ede26 ktime_get_ts64+0xa6:    cmp    $0x3b9ac9ff,%rax
> 0xffffffff810ede2c ktime_get_ts64+0xac:    ja     0xffffffff810ede1d
> ktime_get_ts64+0x9d (up)
> <<<
> 0xffffffff810ede2e ktime_get_ts64+0xae:    add    %rcx,%rdx
> 0xffffffff810ede31 ktime_get_ts64+0xb1:    mov    %rax,0x8(%rbx)
> 0xffffffff810ede35 ktime_get_ts64+0xb5:    mov    %rdx,(%rbx)
> 0xffffffff810ede38 ktime_get_ts64+0xb8:    pop    %rbx
> 0xffffffff810ede39 ktime_get_ts64+0xb9:    pop    %r12
> 0xffffffff810ede3b ktime_get_ts64+0xbb:    pop    %r13
> 0xffffffff810ede3d ktime_get_ts64+0xbd:    pop    %rbp
> 0xffffffff810ede3e ktime_get_ts64+0xbe:    retq
> 0xffffffff810ede3f ktime_get_ts64+0xbf:    xor    %edx,%edx
> 0xffffffff810ede41 ktime_get_ts64+0xc1:    jmp    0xffffffff810ede2e
> ktime_get_ts64+0xae (up)
> 0xffffffff810ede43 ktime_get_ts64+0xc3:    mov    $0x311,%esi
> 0xffffffff810ede48 ktime_get_ts64+0xc8:    mov    $0xffffffff818dc351,%rdi
> 0xffffffff810ede4f ktime_get_ts64+0xcf:    callq  0xffffffff8107f080
> warn_slowpath_null
> 0xffffffff810ede54 ktime_get_ts64+0xd4:    jmpq   0xffffffff810edd9f
> ktime_get_ts64+0x1f (up)
> 0xffffffff810ede59 ktime_get_ts64+0xd9:    pause
> 0xffffffff810ede5b ktime_get_ts64+0xdb:    jmpq   0xffffffff810edda2
> ktime_get_ts64+0x22 (up)
> (2)> g
>
>
> What is strange is the math its doing.  It is subtracting a fixed
> value from rax then comparing the value.  It looks like this is case
> where the value may have wrapped and the code just wasn;t setup to
> handle it.
>
> 0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
> 0xffffffff810ede23 83C201          add    edx,0x1
> 0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
> 0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
> (0xffffffff810ede1d) (up)
>
> The C code is:
>
>
> /**
>  * ktime_get_ts64 - get the monotonic clock in timespec64 format
>  * @ts:		pointer to timespec variable
>  *
>  * The function calculates the monotonic clock from the realtime
>  * clock and the wall_to_monotonic offset and stores the result
>  * in normalized timespec64 format in the variable pointed to by @ts.
>  */
> void ktime_get_ts64(struct timespec64 *ts)
> {
> 	struct timekeeper *tk = &tk_core.timekeeper;
> 	struct timespec64 tomono;
> 	s64 nsec;
> 	unsigned int seq;
>
> 	WARN_ON(timekeeping_suspended);
>
> 	do {
> 		seq = read_seqcount_begin(&tk_core.seq);
> 		ts->tv_sec = tk->xtime_sec;
> 		nsec = timekeeping_get_ns(&tk->tkr_mono);
> 		tomono = tk->wall_to_monotonic;
> <<<
> 	} while (read_seqcount_retry(&tk_core.seq, seq));
> <<<
> 	ts->tv_sec += tomono.tv_sec;
> 	ts->tv_nsec = 0;
> 	timespec64_add_ns(ts, nsec + tomono.tv_nsec);
> }
> EXPORT_SYMBOL_GPL(ktime_get_ts64);
>
> Any ideas how to fix this problem?  That do {} while gets stuck there.
>
> Jeff
>

I just verified that both kgdb and kdb trigger this bug as well if you
hold the processors suspended for about 20-45 minutes.

Jeff

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

#1311899

output from objdump provided:

static __always_inline u32
__iter_div_u64_rem(u64 dividend, u32 divisor, u64 *remainder)
{
	u32 ret = 0;
     27b:	31 d2                	xor    %edx,%edx
	while (dividend >= divisor) {
		/* The following asm() prevents the compiler from
		   optimising this loop into a modulo operation.  */
		asm("" : "+rm"(dividend));

		dividend -= divisor;
     27d:	48 2d 00 ca 9a 3b    	sub    $0x3b9aca00,%rax
		ret++;
     283:	83 c2 01             	add    $0x1,%edx
static __always_inline u32
__iter_div_u64_rem(u64 dividend, u32 divisor, u64 *remainder)
{
	u32 ret = 0;

	while (dividend >= divisor) {
     286:	48 3d ff c9 9a 3b    	cmp    $0x3b9ac9ff,%rax
     28c:	77 ef                	ja     27d <ktime_get_ts64+0x9d>
 * This must always be inlined because its used from the x86-64 vdso,
 * which cannot call other kernel functions.
 */

I guess is dividend and divsor get out of whack this function loops
forever.  So I sent this to the maintainers, so which is the list of
"engineers" who actually wrote and understand this section of code.  I
would like to get this fixed.

Thanks

Jeff

On 1/18/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
> On 1/18/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
>> If I suspend all processors in the NMI handler while in the debugger
>> console at an active breakpoint, and then I leave the system in the
>> console for about 20 minutes with the processors spinning, then exit
>> and release the processors, ktime_get_ts64 enters an infinite loop and
>> triggers the Hard Lockup detector.   Nice having a debugger to just
>> step into the NMI handlers and find this stuff now.
>>
>> The offending code is:
>>
>> (2)> u ktime_get_ts64+9d
>> <<<  this section gets stuck in an infinite loop.
>> 0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
>> 0xffffffff810ede23 83C201          add    edx,0x1
>> 0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
>> 0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
>> (0xffffffff810ede1d) (up)
>> <<<
>> 0xffffffff810ede2e 4801CA          add    rdx,rcx
>> 0xffffffff810ede31 48894308        mov    QWORD PTR
>> [rbx+8]=0xFFFFFFFFA0774E01,rax
>> 0xffffffff810ede35 488913          mov    QWORD PTR
>> [rbx]=0xFFFFFFFFA0742000,rdx
>> 0xffffffff810ede38 5B              pop    rbx
>> 0xffffffff810ede39 415C            pop    r12
>> 0xffffffff810ede3b 415D            pop    r13
>> 0xffffffff810ede3d 5D              pop    rbp
>> 0xffffffff810ede3e C3              ret
>> 0xffffffff810ede3f 31D2            xor    edx,edx
>> 0xffffffff810ede41 EBEB            jmp    ktime_get_ts64+0xae
>> (0xffffffff810ede2e) (up)
>> 0xffffffff810ede43 BE11030000      mov    esi,0x311
>> 0xffffffff810ede48 48C7C751C38D81  mov    rdi,0xffffffff818dc351
>> 0xffffffff810ede4f E82C12F9FF      call   warn_slowpath_null
>> 0xffffffff810ede54 E946FFFFFF      jmp    ktime_get_ts64+0x1f
>> (0xffffffff810edd9f) (up)
>> 0xffffffff810ede59 F390            pause
>> 0xffffffff810ede5b E942FFFFFF      jmp    ktime_get_ts64+0x22
>> (0xffffffff810edda2) (up)
>>
>> Same code in GDB format
>>
>> (2)> id ktime_get_ts64+9d
>> <<<
>> 0xffffffff810ede1d ktime_get_ts64+0x9d:    sub    $0x3b9aca00,%rax
>> 0xffffffff810ede23 ktime_get_ts64+0xa3:    add    $0x1,%edx
>> 0xffffffff810ede26 ktime_get_ts64+0xa6:    cmp    $0x3b9ac9ff,%rax
>> 0xffffffff810ede2c ktime_get_ts64+0xac:    ja     0xffffffff810ede1d
>> ktime_get_ts64+0x9d (up)
>> <<<
>> 0xffffffff810ede2e ktime_get_ts64+0xae:    add    %rcx,%rdx
>> 0xffffffff810ede31 ktime_get_ts64+0xb1:    mov    %rax,0x8(%rbx)
>> 0xffffffff810ede35 ktime_get_ts64+0xb5:    mov    %rdx,(%rbx)
>> 0xffffffff810ede38 ktime_get_ts64+0xb8:    pop    %rbx
>> 0xffffffff810ede39 ktime_get_ts64+0xb9:    pop    %r12
>> 0xffffffff810ede3b ktime_get_ts64+0xbb:    pop    %r13
>> 0xffffffff810ede3d ktime_get_ts64+0xbd:    pop    %rbp
>> 0xffffffff810ede3e ktime_get_ts64+0xbe:    retq
>> 0xffffffff810ede3f ktime_get_ts64+0xbf:    xor    %edx,%edx
>> 0xffffffff810ede41 ktime_get_ts64+0xc1:    jmp    0xffffffff810ede2e
>> ktime_get_ts64+0xae (up)
>> 0xffffffff810ede43 ktime_get_ts64+0xc3:    mov    $0x311,%esi
>> 0xffffffff810ede48 ktime_get_ts64+0xc8:    mov
>> $0xffffffff818dc351,%rdi
>> 0xffffffff810ede4f ktime_get_ts64+0xcf:    callq  0xffffffff8107f080
>> warn_slowpath_null
>> 0xffffffff810ede54 ktime_get_ts64+0xd4:    jmpq   0xffffffff810edd9f
>> ktime_get_ts64+0x1f (up)
>> 0xffffffff810ede59 ktime_get_ts64+0xd9:    pause
>> 0xffffffff810ede5b ktime_get_ts64+0xdb:    jmpq   0xffffffff810edda2
>> ktime_get_ts64+0x22 (up)
>> (2)> g
>>
>>
>> What is strange is the math its doing.  It is subtracting a fixed
>> value from rax then comparing the value.  It looks like this is case
>> where the value may have wrapped and the code just wasn;t setup to
>> handle it.
>>
>> 0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
>> 0xffffffff810ede23 83C201          add    edx,0x1
>> 0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
>> 0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
>> (0xffffffff810ede1d) (up)
>>
>> The C code is:
>>
>>
>> /**
>>  * ktime_get_ts64 - get the monotonic clock in timespec64 format
>>  * @ts:		pointer to timespec variable
>>  *
>>  * The function calculates the monotonic clock from the realtime
>>  * clock and the wall_to_monotonic offset and stores the result
>>  * in normalized timespec64 format in the variable pointed to by @ts.
>>  */
>> void ktime_get_ts64(struct timespec64 *ts)
>> {
>> 	struct timekeeper *tk = &tk_core.timekeeper;
>> 	struct timespec64 tomono;
>> 	s64 nsec;
>> 	unsigned int seq;
>>
>> 	WARN_ON(timekeeping_suspended);
>>
>> 	do {
>> 		seq = read_seqcount_begin(&tk_core.seq);
>> 		ts->tv_sec = tk->xtime_sec;
>> 		nsec = timekeeping_get_ns(&tk->tkr_mono);
>> 		tomono = tk->wall_to_monotonic;
>> <<<
>> 	} while (read_seqcount_retry(&tk_core.seq, seq));
>> <<<
>> 	ts->tv_sec += tomono.tv_sec;
>> 	ts->tv_nsec = 0;
>> 	timespec64_add_ns(ts, nsec + tomono.tv_nsec);
>> }
>> EXPORT_SYMBOL_GPL(ktime_get_ts64);
>>
>> Any ideas how to fix this problem?  That do {} while gets stuck there.
>>
>> Jeff
>>
>
> I just verified that both kgdb and kdb trigger this bug as well if you
> hold the processors suspended for about 20-45 minutes.
>
> Jeff
>

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

#1312057

On Mon, 18 Jan 2016, Jeff Merkey wrote:
> What is strange is the math its doing.  It is subtracting a fixed
> value from rax then comparing the value.  It looks like this is case
> where the value may have wrapped and the code just wasn;t setup to
> handle it.

Well, the worst case what would happen is that it loops another full round.
If you subtract 1e9 from rax often enough then it will become smaller than 1e9
no matter whether it wrapped or not. It just takes more iterations.

> 0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
> 0xffffffff810ede23 83C201          add    edx,0x1
> 0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
> 0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
> (0xffffffff810ede1d) (up)
> 
> The C code is:
> 
> 
> /**
>  * ktime_get_ts64 - get the monotonic clock in timespec64 format
>  * @ts:		pointer to timespec variable
>  *
>  * The function calculates the monotonic clock from the realtime
>  * clock and the wall_to_monotonic offset and stores the result
>  * in normalized timespec64 format in the variable pointed to by @ts.
>  */
> void ktime_get_ts64(struct timespec64 *ts)
> {
> 	struct timekeeper *tk = &tk_core.timekeeper;
> 	struct timespec64 tomono;
> 	s64 nsec;
> 	unsigned int seq;
> 
> 	WARN_ON(timekeeping_suspended);
> 
> 	do {
> 		seq = read_seqcount_begin(&tk_core.seq);
> 		ts->tv_sec = tk->xtime_sec;
> 		nsec = timekeeping_get_ns(&tk->tkr_mono);
> 		tomono = tk->wall_to_monotonic;
> <<<
> 	} while (read_seqcount_retry(&tk_core.seq, seq));
> <<<
> 	ts->tv_sec += tomono.tv_sec;
> 	ts->tv_nsec = 0;
> 	timespec64_add_ns(ts, nsec + tomono.tv_nsec);
> }
> EXPORT_SYMBOL_GPL(ktime_get_ts64);
> 
> Any ideas how to fix this problem?  That do {} while gets stuck there.

So now you are pointing to that do { } while. That has absolutely nothing to
do with timespec64_add_ns() to which you are referring above.

That do {} while loop gets stuck when the time keeper sequence counter has
changed while we were reading the time and the offset.

So where exactly is it stuck? Please provide backtraces from the
hardlockup detector.

Thanks,

	tglx

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

#1312330

On 1/18/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
> If I suspend all processors in the NMI handler while in the debugger
> console at an active breakpoint, and then I leave the system in the
> console for about 20 minutes with the processors spinning, then exit
> and release the processors, ktime_get_ts64 enters an infinite loop and
> triggers the Hard Lockup detector.   Nice having a debugger to just
> step into the NMI handlers and find this stuff now.
>
> The offending code is:
>
> (2)> u ktime_get_ts64+9d
> <<<  this section gets stuck in an infinite loop.
> 0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
> 0xffffffff810ede23 83C201          add    edx,0x1
> 0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
> 0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
> (0xffffffff810ede1d) (up)
> <<<
> 0xffffffff810ede2e 4801CA          add    rdx,rcx
> 0xffffffff810ede31 48894308        mov    QWORD PTR
> [rbx+8]=0xFFFFFFFFA0774E01,rax
> 0xffffffff810ede35 488913          mov    QWORD PTR
> [rbx]=0xFFFFFFFFA0742000,rdx
> 0xffffffff810ede38 5B              pop    rbx
> 0xffffffff810ede39 415C            pop    r12
> 0xffffffff810ede3b 415D            pop    r13
> 0xffffffff810ede3d 5D              pop    rbp
> 0xffffffff810ede3e C3              ret
> 0xffffffff810ede3f 31D2            xor    edx,edx
> 0xffffffff810ede41 EBEB            jmp    ktime_get_ts64+0xae
> (0xffffffff810ede2e) (up)
> 0xffffffff810ede43 BE11030000      mov    esi,0x311
> 0xffffffff810ede48 48C7C751C38D81  mov    rdi,0xffffffff818dc351
> 0xffffffff810ede4f E82C12F9FF      call   warn_slowpath_null
> 0xffffffff810ede54 E946FFFFFF      jmp    ktime_get_ts64+0x1f
> (0xffffffff810edd9f) (up)
> 0xffffffff810ede59 F390            pause
> 0xffffffff810ede5b E942FFFFFF      jmp    ktime_get_ts64+0x22
> (0xffffffff810edda2) (up)
>
> Same code in GDB format
>
> (2)> id ktime_get_ts64+9d
> <<<
> 0xffffffff810ede1d ktime_get_ts64+0x9d:    sub    $0x3b9aca00,%rax
> 0xffffffff810ede23 ktime_get_ts64+0xa3:    add    $0x1,%edx
> 0xffffffff810ede26 ktime_get_ts64+0xa6:    cmp    $0x3b9ac9ff,%rax
> 0xffffffff810ede2c ktime_get_ts64+0xac:    ja     0xffffffff810ede1d
> ktime_get_ts64+0x9d (up)
> <<<
> 0xffffffff810ede2e ktime_get_ts64+0xae:    add    %rcx,%rdx
> 0xffffffff810ede31 ktime_get_ts64+0xb1:    mov    %rax,0x8(%rbx)
> 0xffffffff810ede35 ktime_get_ts64+0xb5:    mov    %rdx,(%rbx)
> 0xffffffff810ede38 ktime_get_ts64+0xb8:    pop    %rbx
> 0xffffffff810ede39 ktime_get_ts64+0xb9:    pop    %r12
> 0xffffffff810ede3b ktime_get_ts64+0xbb:    pop    %r13
> 0xffffffff810ede3d ktime_get_ts64+0xbd:    pop    %rbp
> 0xffffffff810ede3e ktime_get_ts64+0xbe:    retq
> 0xffffffff810ede3f ktime_get_ts64+0xbf:    xor    %edx,%edx
> 0xffffffff810ede41 ktime_get_ts64+0xc1:    jmp    0xffffffff810ede2e
> ktime_get_ts64+0xae (up)
> 0xffffffff810ede43 ktime_get_ts64+0xc3:    mov    $0x311,%esi
> 0xffffffff810ede48 ktime_get_ts64+0xc8:    mov    $0xffffffff818dc351,%rdi
> 0xffffffff810ede4f ktime_get_ts64+0xcf:    callq  0xffffffff8107f080
> warn_slowpath_null
> 0xffffffff810ede54 ktime_get_ts64+0xd4:    jmpq   0xffffffff810edd9f
> ktime_get_ts64+0x1f (up)
> 0xffffffff810ede59 ktime_get_ts64+0xd9:    pause
> 0xffffffff810ede5b ktime_get_ts64+0xdb:    jmpq   0xffffffff810edda2
> ktime_get_ts64+0x22 (up)
> (2)> g
>
>
> What is strange is the math its doing.  It is subtracting a fixed
> value from rax then comparing the value.  It looks like this is case
> where the value may have wrapped and the code just wasn;t setup to
> handle it.
>
> 0xffffffff810ede1d 482D00CA9A3B    sub    rax,0x3b9aca00
> 0xffffffff810ede23 83C201          add    edx,0x1
> 0xffffffff810ede26 483DFFC99A3B    cmp    rax,0x3b9ac9ff
> 0xffffffff810ede2c 77EF            ja     ktime_get_ts64+0x9d
> (0xffffffff810ede1d) (up)
>
> The C code is:
>
>
> /**
>  * ktime_get_ts64 - get the monotonic clock in timespec64 format
>  * @ts:		pointer to timespec variable
>  *
>  * The function calculates the monotonic clock from the realtime
>  * clock and the wall_to_monotonic offset and stores the result
>  * in normalized timespec64 format in the variable pointed to by @ts.
>  */
> void ktime_get_ts64(struct timespec64 *ts)
> {
> 	struct timekeeper *tk = &tk_core.timekeeper;
> 	struct timespec64 tomono;
> 	s64 nsec;
> 	unsigned int seq;
>
> 	WARN_ON(timekeeping_suspended);
>
> 	do {
> 		seq = read_seqcount_begin(&tk_core.seq);
> 		ts->tv_sec = tk->xtime_sec;
> 		nsec = timekeeping_get_ns(&tk->tkr_mono);
> 		tomono = tk->wall_to_monotonic;
> <<<
> 	} while (read_seqcount_retry(&tk_core.seq, seq));
> <<<
> 	ts->tv_sec += tomono.tv_sec;
> 	ts->tv_nsec = 0;
> 	timespec64_add_ns(ts, nsec + tomono.tv_nsec);
> }
> EXPORT_SYMBOL_GPL(ktime_get_ts64);
>
> Any ideas how to fix this problem?  That do {} while gets stuck there.
>
> Jeff
>

I'll try to get a better trace of this problem today and post it.  I
have a target system setup to catch this now.

Jeff

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

#1312549

Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
a bunch of macros to __iter_div_u64_rem().  It doesn't loop infinitely
with a number that big, just for about 4 minutes but long enough for
the hard lockup detector to fire off.  Setting RAX=0 when this bug
occurs clears the problem from the debugger console when this function
gets stuck in this loop and the system recovers fine.

The problem code is in:

include/linux/math64.h:117
static __always_inline u32
__iter_div_u64_rem(u64 dividend, u32 divisor, u64 *remainder)
{
	u32 ret = 0;

	while (dividend >= divisor) {
		/* The following asm() prevents the compiler from
		   optimising this loop into a modulo operation.  */
		asm("" : "+rm"(dividend));

		dividend -= divisor;
		ret++;
	}
	*remainder = dividend;

	return ret;
}

which is called by
include/linux/time.h:233
static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)
{
	a->tv_sec += __iter_div_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
	a->tv_nsec = ns;
}

it's defined so that timespec64_add_ns just points to this function
which is called by ktime_get_ts64.  tv_nsec + ns gets passed as a huge
number (RAX = 0x17AE7F57C671EA7D) with a very small divisor and just
sits there and loops.

Submitting a patch to fix this after I regress and test it.   Since it
makes no sense to loop on a simple calculation, fix should be:

static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)
{
	a->tv_sec += div64_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
	a->tv_nsec = ns;
}

Jeff

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

#1312626

I have done some more research on this and due to the way vdso works
any fix must also be on inline macro are rely only on inline macros.

Jeff

On 1/19/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
> a bunch of macros to __iter_div_u64_rem().  It doesn't loop infinitely
> with a number that big, just for about 4 minutes but long enough for
> the hard lockup detector to fire off.  Setting RAX=0 when this bug
> occurs clears the problem from the debugger console when this function
> gets stuck in this loop and the system recovers fine.
>
> The problem code is in:
>
> include/linux/math64.h:117
> static __always_inline u32
> __iter_div_u64_rem(u64 dividend, u32 divisor, u64 *remainder)
> {
> 	u32 ret = 0;
>
> 	while (dividend >= divisor) {
> 		/* The following asm() prevents the compiler from
> 		   optimising this loop into a modulo operation.  */
> 		asm("" : "+rm"(dividend));
>
> 		dividend -= divisor;
> 		ret++;
> 	}
> 	*remainder = dividend;
>
> 	return ret;
> }
>
> which is called by
> include/linux/time.h:233
> static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)
> {
> 	a->tv_sec += __iter_div_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
> 	a->tv_nsec = ns;
> }
>
> it's defined so that timespec64_add_ns just points to this function
> which is called by ktime_get_ts64.  tv_nsec + ns gets passed as a huge
> number (RAX = 0x17AE7F57C671EA7D) with a very small divisor and just
> sits there and loops.
>
> Submitting a patch to fix this after I regress and test it.   Since it
> makes no sense to loop on a simple calculation, fix should be:
>
> static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)
> {
> 	a->tv_sec += div64_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
> 	a->tv_nsec = ns;
> }
>
> Jeff
>

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

#1313029

On Tue, 19 Jan 2016, Jeff Merkey wrote:
> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through

And how exactly does that happen?

0x17AE7F57C671EA7D = 1.70644e+18  nsec
		   = 1.70644e+09  sec
		   = 2.84407e+07  min
		   = 474011	  hrs
		   = 19750.5	  days
		   = 54.1109	  years

That's the real issue, not what you are trying to 'fix' in timespec_add_ns()

> Submitting a patch to fix this after I regress and test it.   Since it
> makes no sense to loop on a simple calculation, fix should be:
> 
> static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)
> {
> 	a->tv_sec += div64_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
> 	a->tv_nsec = ns;
> }

No. It's not that simple, because div64_u64_rem() is expensive on 32bit
architectures which have no hardware 64/32 division. And that's going to hurt
for the normal tick case where we have at max one iteration.

Thanks,

	tglx

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

#1313244

Jeff,

On Wed, 20 Jan 2016, Thomas Gleixner wrote:
> On Tue, 19 Jan 2016, Jeff Merkey wrote:
> > Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
> > gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
> 
> And how exactly does that happen?
> 
> 0x17AE7F57C671EA7D = 1.70644e+18  nsec
> 		   = 1.70644e+09  sec
> 		   = 2.84407e+07  min
> 		   = 474011	  hrs
> 		   = 19750.5	  days
> 		   = 54.1109	  years
> 
> That's the real issue, not what you are trying to 'fix' in timespec_add_ns()

And that's caused by stopping the whole machine for 20 minutes. It violates
the assumption of the timekeeping core, that the maximum time which is between
two updates of the core is < 5-10min. So that insane large number is caused by a
mult overrun when converting the time delta to nanoseconds.

You can find that limit via:

# dmesg | grep tsc | grep max_idle_ns
[    5.242683] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x21139a22526, max_idle_ns: 440795252169 ns

So on that machine the limit is:

   440795252169 nsec
   440.795	sec
   7.34659	min

And before you ask or come up with patches: No, we are not going to add
anything to the core timekeeping code to work around this limitation simply
because its going to add overhead to a performance sensitive code path for a
very limited value.

Keeping a machine stopped for 20 minutes will make a lot of other things
unhappy, so introducing a 'fix' for that particular issue is just silly.

Thanks,

	tglx

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

#1313358

On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
> Jeff,
>
> On Wed, 20 Jan 2016, Thomas Gleixner wrote:
>> On Tue, 19 Jan 2016, Jeff Merkey wrote:
>> > Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
>> > gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
>>
>> And how exactly does that happen?
>>
>> 0x17AE7F57C671EA7D = 1.70644e+18  nsec
>> 		   = 1.70644e+09  sec
>> 		   = 2.84407e+07  min
>> 		   = 474011	  hrs
>> 		   = 19750.5	  days
>> 		   = 54.1109	  years
>>
>> That's the real issue, not what you are trying to 'fix' in
>> timespec_add_ns()
>
> And that's caused by stopping the whole machine for 20 minutes. It violates
> the assumption of the timekeeping core, that the maximum time which is
> between
> two updates of the core is < 5-10min. So that insane large number is caused
> by a
> mult overrun when converting the time delta to nanoseconds.
>
> You can find that limit via:
>
> # dmesg | grep tsc | grep max_idle_ns
> [    5.242683] clocksource tsc: mask: 0xffffffffffffffff max_cycles:
> 0x21139a22526, max_idle_ns: 440795252169 ns
>
> So on that machine the limit is:
>
>    440795252169 nsec
>    440.795	sec
>    7.34659	min
>
> And before you ask or come up with patches: No, we are not going to add
> anything to the core timekeeping code to work around this limitation simply
> because its going to add overhead to a performance sensitive code path for
> a
> very limited value.

Given how fragile that code appears to be, this is reasonable.

>
> Keeping a machine stopped for 20 minutes will make a lot of other things
> unhappy, so introducing a 'fix' for that particular issue is just silly.
>

You know what's needed here is some form of touch function to keep this
system updated while spinning in the debugger.  That would solve it.
I can maintain
a fix for that locally.  I debugged the soft hang in systemd last
night, and I discovered
that its all related to this function returning bogus time (systemd
was doing a system call that eventually made its way to ktime_get_ts64
and got returned garbage).   When this wraps it causes all sorts of
bad stuff.

Do you have any suggestions on how a touch function could be coded to keep this
subsystem updated while the debugger is active?  There are already a
few of them I
have to call as well as kgdb and kdb to get around some of this.

void mdb_watchdogs(void)
{
    touch_softlockup_watchdog_sync();
    clocksource_touch_watchdog();

#if defined(CONFIG_TREE_RCU)
    rcu_cpu_stall_reset();
#endif

    touch_nmi_watchdog();
#ifdef CONFIG_HARDLOCKUP_DETECTOR
    touch_hardlockup_watchdog();
#endif
    return;
}

As you can see, there are already quite a few subsystems that manage
this problem of
debuggers holding the system in stasis.

Jeff

> Thanks,
>
> 	tglx
>

Well, that explains it.

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

#1313371

On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Tue, 19 Jan 2016, Jeff Merkey wrote:
>> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
>> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
>
> And how exactly does that happen?
>
> 0x17AE7F57C671EA7D = 1.70644e+18  nsec
> 		   = 1.70644e+09  sec
> 		   = 2.84407e+07  min
> 		   = 474011	  hrs
> 		   = 19750.5	  days
> 		   = 54.1109	  years
>
> That's the real issue, not what you are trying to 'fix' in
> timespec_add_ns()
>
>> Submitting a patch to fix this after I regress and test it.   Since it
>> makes no sense to loop on a simple calculation, fix should be:
>>
>> static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)
>> {
>> 	a->tv_sec += div64_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
>> 	a->tv_nsec = ns;
>> }
>
> No. It's not that simple, because div64_u64_rem() is expensive on 32bit
> architectures which have no hardware 64/32 division. And that's going to
> hurt
> for the normal tick case where we have at max one iteration.
>

It's less expensive than a hard coded loop that subtracts in a looping
function as a substitute for dividing which is what is there.  What a
busted piece of shit .... LOL



> Thanks,
>
> 	tglx
>
>
>

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

#1313387

On 1/20/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
> On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
>> On Tue, 19 Jan 2016, Jeff Merkey wrote:
>>> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
>>> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
>>
>> And how exactly does that happen?
>>
>> 0x17AE7F57C671EA7D = 1.70644e+18  nsec
>> 		   = 1.70644e+09  sec
>> 		   = 2.84407e+07  min
>> 		   = 474011	  hrs
>> 		   = 19750.5	  days
>> 		   = 54.1109	  years
>>
>> That's the real issue, not what you are trying to 'fix' in
>> timespec_add_ns()
>>

I guess I am going to have to become an expert on the timekeeper and
learn this subsystem backwards and forwards to code a touch function
to keep it from crashing the system.

On the 2.6 series kernels (and 2.2) this problem did not exist.  I
noticed a lot of these changes came in in the late 2.6 cycles.  Before
that time, I could leave the debugger spinning for days and linux
worked fine.

For people who have to pay developers to develop code on Linux a
debugger is almost
an essential tool since it saves hundreds of thousands of dollars in
development costs.  Not everyone wants to spend money for their
employees and engineers to sit around and code review every problem -
customers just want their problems fixed -- and fast.  That being
said, I am having no lack of people who download and use this debugger
and I'm certain kgdb is heavily used by folks doing development.   If
kernel development is too hard, people move to something else based on
simple economics.

That being said, I need to get this fixed.  There is no good reason a
debugger shouldn't be able to stop the system and leave it suspended
for days if necessary to run down a bug.  I wrote a debugger on SMP
Netware that worked that way.  The earliest versions of MDB worked
that way.

kgdb is broken right now because of this.  I am not certain it affects
all systems out there, but it needs to be fixed.

If you have any ideas on how to code a touch function please send me a
patch or suggest how it could be done non-obstrusively, otherwise I'll
have to dive into the timekeeper and fix it myself and learn yet
another subsystem of Linux and fix it bugs.  A code subsystem that
crashes because the timer tick is skewed or returns garbage is poorly
designed IMHO.

It should have either a touch function to keep it updated, or have the
ability to recover.

Jeff

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

#1313406

On 1/20/16, John Stultz <john.stultz@linaro.org> wrote:
> On Wed, Jan 20, 2016 at 9:16 AM, Jeff Merkey <linux.mdb@gmail.com> wrote:
>> On 1/20/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
>>> On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
>>>> On Tue, 19 Jan 2016, Jeff Merkey wrote:
>>>>> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
>>>>> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
>>>>
>>>> And how exactly does that happen?
>>>>
>>>> 0x17AE7F57C671EA7D = 1.70644e+18  nsec
>>>>                 = 1.70644e+09  sec
>>>>                 = 2.84407e+07  min
>>>>                 = 474011       hrs
>>>>                 = 19750.5      days
>>>>                 = 54.1109      years
>>>>
>>>> That's the real issue, not what you are trying to 'fix' in
>>>> timespec_add_ns()
>>>>
>>
>> I guess I am going to have to become an expert on the timekeeper and
>> learn this subsystem backwards and forwards to code a touch function
>> to keep it from crashing the system.
>>
>> On the 2.6 series kernels (and 2.2) this problem did not exist.  I
>> noticed a lot of these changes came in in the late 2.6 cycles.  Before
>> that time, I could leave the debugger spinning for days and linux
>> worked fine.
>>
>> For people who have to pay developers to develop code on Linux a
>> debugger is almost
>> an essential tool since it saves hundreds of thousands of dollars in
>> development costs.  Not everyone wants to spend money for their
>> employees and engineers to sit around and code review every problem -
>> customers just want their problems fixed -- and fast.  That being
>> said, I am having no lack of people who download and use this debugger
>> and I'm certain kgdb is heavily used by folks doing development.   If
>> kernel development is too hard, people move to something else based on
>> simple economics.
>>
>> That being said, I need to get this fixed.  There is no good reason a
>> debugger shouldn't be able to stop the system and leave it suspended
>> for days if necessary to run down a bug.  I wrote a debugger on SMP
>> Netware that worked that way.  The earliest versions of MDB worked
>> that way.
>>
>> kgdb is broken right now because of this.  I am not certain it affects
>> all systems out there, but it needs to be fixed.
>>
>> If you have any ideas on how to code a touch function please send me a
>> patch or suggest how it could be done non-obstrusively, otherwise I'll
>> have to dive into the timekeeper and fix it myself and learn yet
>> another subsystem of Linux and fix it bugs.  A code subsystem that
>> crashes because the timer tick is skewed or returns garbage is poorly
>> designed IMHO.
>
> Ehrm.  A more productive route in solving this might be to cap the
> cycle delta we return from timekeeping_get_delta().
>
> We already do this in the CONFIG_DEBUG_TIMEKEEPING, but adding a
> simple check it to the non-debug case should be doable w/o adding too
> much overhead to this very hot path.
>
> Something like:
> if (delta > tkr->clock->max_cycles)
>     delta = tkr->clock->max_cycles;
>
> return delta;
>
> thanks
> -john
>


Thank you John.  This is helpful.  Can you send me a patch for this
and I'll test it.  Then I am not touching this code and you guys can
put it in.

Jeff

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

#1313407

On Wed, Jan 20, 2016 at 9:16 AM, Jeff Merkey <linux.mdb@gmail.com> wrote:
> On 1/20/16, Jeff Merkey <linux.mdb@gmail.com> wrote:
>> On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
>>> On Tue, 19 Jan 2016, Jeff Merkey wrote:
>>>> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
>>>> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
>>>
>>> And how exactly does that happen?
>>>
>>> 0x17AE7F57C671EA7D = 1.70644e+18  nsec
>>>                 = 1.70644e+09  sec
>>>                 = 2.84407e+07  min
>>>                 = 474011       hrs
>>>                 = 19750.5      days
>>>                 = 54.1109      years
>>>
>>> That's the real issue, not what you are trying to 'fix' in
>>> timespec_add_ns()
>>>
>
> I guess I am going to have to become an expert on the timekeeper and
> learn this subsystem backwards and forwards to code a touch function
> to keep it from crashing the system.
>
> On the 2.6 series kernels (and 2.2) this problem did not exist.  I
> noticed a lot of these changes came in in the late 2.6 cycles.  Before
> that time, I could leave the debugger spinning for days and linux
> worked fine.
>
> For people who have to pay developers to develop code on Linux a
> debugger is almost
> an essential tool since it saves hundreds of thousands of dollars in
> development costs.  Not everyone wants to spend money for their
> employees and engineers to sit around and code review every problem -
> customers just want their problems fixed -- and fast.  That being
> said, I am having no lack of people who download and use this debugger
> and I'm certain kgdb is heavily used by folks doing development.   If
> kernel development is too hard, people move to something else based on
> simple economics.
>
> That being said, I need to get this fixed.  There is no good reason a
> debugger shouldn't be able to stop the system and leave it suspended
> for days if necessary to run down a bug.  I wrote a debugger on SMP
> Netware that worked that way.  The earliest versions of MDB worked
> that way.
>
> kgdb is broken right now because of this.  I am not certain it affects
> all systems out there, but it needs to be fixed.
>
> If you have any ideas on how to code a touch function please send me a
> patch or suggest how it could be done non-obstrusively, otherwise I'll
> have to dive into the timekeeper and fix it myself and learn yet
> another subsystem of Linux and fix it bugs.  A code subsystem that
> crashes because the timer tick is skewed or returns garbage is poorly
> designed IMHO.

Ehrm.  A more productive route in solving this might be to cap the
cycle delta we return from timekeeping_get_delta().

We already do this in the CONFIG_DEBUG_TIMEKEEPING, but adding a
simple check it to the non-debug case should be doable w/o adding too
much overhead to this very hot path.

Something like:
if (delta > tkr->clock->max_cycles)
    delta = tkr->clock->max_cycles;

return delta;

thanks
-john

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

#1313411

On Wed, 20 Jan 2016, John Stultz wrote:
> Ehrm.  A more productive route in solving this might be to cap the
> cycle delta we return from timekeeping_get_delta().
> 
> We already do this in the CONFIG_DEBUG_TIMEKEEPING, but adding a
> simple check it to the non-debug case should be doable w/o adding too
> much overhead to this very hot path.
> 
> Something like:
> if (delta > tkr->clock->max_cycles)
>     delta = tkr->clock->max_cycles;
> 
> return delta;

Well, you can make CONFIG_KDB select CONFIG_DEBUG_TIMEKEEPING.

Thanks,

	tglx

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

#1313415

On Wed, Jan 20, 2016 at 9:42 AM, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Wed, 20 Jan 2016, John Stultz wrote:
>> Ehrm.  A more productive route in solving this might be to cap the
>> cycle delta we return from timekeeping_get_delta().
>>
>> We already do this in the CONFIG_DEBUG_TIMEKEEPING, but adding a
>> simple check it to the non-debug case should be doable w/o adding too
>> much overhead to this very hot path.
>>
>> Something like:
>> if (delta > tkr->clock->max_cycles)
>>     delta = tkr->clock->max_cycles;
>>
>> return delta;
>
> Well, you can make CONFIG_KDB select CONFIG_DEBUG_TIMEKEEPING.

True.  And turning on DEBUG_TIMEKEEPING is probably the easiest thing
for Jeff to try.

Though, there's still the same issue w/ paused VMs. Most of the design
for the timekeeping code has been that it can't properly function if
you block update_wall_time() calls, but it shouldn't kill the box.
With most clocksources, the issue is the counter wraps and we lose
time. But in this case with the TSC its the *very* large cycle delta
turning into a unexpectedly large nanosecond value.

Hrm.. I do also wonder: the logarithmic accumulation chews through
large cycle deltas efficiently, but it does have some design limits,
so it  might also hit the rails and take awhile to spin accumulating
time with such large offsets.

Jeff: Can you try the config option above to let me know if that
avoids the issue? And if not, can you provide some analysis of what
else is going on?

thanks
-john

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

#1313423

On 1/20/16, John Stultz <john.stultz@linaro.org> wrote:
> On Wed, Jan 20, 2016 at 9:42 AM, Thomas Gleixner <tglx@linutronix.de>
> wrote:
>> On Wed, 20 Jan 2016, John Stultz wrote:
>>> Ehrm.  A more productive route in solving this might be to cap the
>>> cycle delta we return from timekeeping_get_delta().
>>>
>>> We already do this in the CONFIG_DEBUG_TIMEKEEPING, but adding a
>>> simple check it to the non-debug case should be doable w/o adding too
>>> much overhead to this very hot path.
>>>
>>> Something like:
>>> if (delta > tkr->clock->max_cycles)
>>>     delta = tkr->clock->max_cycles;
>>>
>>> return delta;
>>
>> Well, you can make CONFIG_KDB select CONFIG_DEBUG_TIMEKEEPING.
>
> True.  And turning on DEBUG_TIMEKEEPING is probably the easiest thing
> for Jeff to try.
>
> Though, there's still the same issue w/ paused VMs. Most of the design
> for the timekeeping code has been that it can't properly function if
> you block update_wall_time() calls, but it shouldn't kill the box.
> With most clocksources, the issue is the counter wraps and we lose
> time. But in this case with the TSC its the *very* large cycle delta
> turning into a unexpectedly large nanosecond value.
>
> Hrm.. I do also wonder: the logarithmic accumulation chews through
> large cycle deltas efficiently, but it does have some design limits,
> so it  might also hit the rails and take awhile to spin accumulating
> time with such large offsets.
>
> Jeff: Can you try the config option above to let me know if that
> avoids the issue? And if not, can you provide some analysis of what
> else is going on?
>
> thanks
> -john
>

Yes sir.  I am changing the code and preparing to test this right now.
It will be about 4 hours before I have the results.

Thanks to you and Thomas for the help.  I appreciate it.

Jeff

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

#1313400

On Wed, 20 Jan 2016, Jeff Merkey wrote:
> On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
> > On Tue, 19 Jan 2016, Jeff Merkey wrote:
> >> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
> >> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
> >
> > And how exactly does that happen?
> >
> > 0x17AE7F57C671EA7D = 1.70644e+18  nsec
> > 		   = 1.70644e+09  sec
> > 		   = 2.84407e+07  min
> > 		   = 474011	  hrs
> > 		   = 19750.5	  days
> > 		   = 54.1109	  years
> >
> > That's the real issue, not what you are trying to 'fix' in
> > timespec_add_ns()
> >
> >> Submitting a patch to fix this after I regress and test it.   Since it
> >> makes no sense to loop on a simple calculation, fix should be:
> >>
> >> static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)
> >> {
> >> 	a->tv_sec += div64_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
> >> 	a->tv_nsec = ns;
> >> }
> >
> > No. It's not that simple, because div64_u64_rem() is expensive on 32bit
> > architectures which have no hardware 64/32 division. And that's going to
> > hurt
> > for the normal tick case where we have at max one iteration.
> >
> 
> It's less expensive than a hard coded loop that subtracts in a looping
> function as a substitute for dividing which is what is there.  What a
> busted piece of shit .... LOL

Let's talk about shit.

timespec[64]_add_ns() is used for timekeeping and in all normal use cases the
nsec part is less than 1e9 nsec. Even on 64 bit a divide is more expensive
than the sinlge iteration while loop and its insane expensive on 32bit
machines which do not have a 64/32 divison in hardware.

The while loop is there for a few corner cases which are a bit larger than 1e9
nsecs, but that's not the case we optimize for.

The case you are creating with your debugger is something completely different
and we never thought about it nor cared about it. Why? Because so far nobody
complained and I never cared about kernel debuggers at all.

What's worse is that your 'fix' does not resolve the underlying issue at
all. Why? Simply because you tried to fix the symptom and not the root cause.

I explained you the root cause and I explained you why that while() loop is
more efficient than a divide for the case it was written and optimized for.

Instead of reading and understanding what I wrote you teach me that your
divide is more efficient and call it a busted piece of shit.

Sure you are free to call that a busted piece of shit, but you don't have to
expect that the people who wrote, maintain and understand that code are going
to put up with your attitude.

Thanks,

	tglx

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

#1313408

On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Wed, 20 Jan 2016, Jeff Merkey wrote:
>> On 1/20/16, Thomas Gleixner <tglx@linutronix.de> wrote:
>> > On Tue, 19 Jan 2016, Jeff Merkey wrote:
>> >> Nasty bug but trivial fix for this.  What happens here is RAX (nsecs)
>> >> gets set to a huge value (RAX = 0x17AE7F57C671EA7D) and passed through
>> >
>> > And how exactly does that happen?
>> >
>> > 0x17AE7F57C671EA7D = 1.70644e+18  nsec
>> > 		   = 1.70644e+09  sec
>> > 		   = 2.84407e+07  min
>> > 		   = 474011	  hrs
>> > 		   = 19750.5	  days
>> > 		   = 54.1109	  years
>> >
>> > That's the real issue, not what you are trying to 'fix' in
>> > timespec_add_ns()
>> >
>> >> Submitting a patch to fix this after I regress and test it.   Since it
>> >> makes no sense to loop on a simple calculation, fix should be:
>> >>
>> >> static __always_inline void timespec_add_ns(struct timespec *a, u64
>> >> ns)
>> >> {
>> >> 	a->tv_sec += div64_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
>> >> 	a->tv_nsec = ns;
>> >> }
>> >
>> > No. It's not that simple, because div64_u64_rem() is expensive on 32bit
>> > architectures which have no hardware 64/32 division. And that's going
>> > to
>> > hurt
>> > for the normal tick case where we have at max one iteration.
>> >
>>
>> It's less expensive than a hard coded loop that subtracts in a looping
>> function as a substitute for dividing which is what is there.  What a
>> busted piece of shit .... LOL
>
> Let's talk about shit.
>
> timespec[64]_add_ns() is used for timekeeping and in all normal use cases
> the
> nsec part is less than 1e9 nsec. Even on 64 bit a divide is more expensive
> than the sinlge iteration while loop and its insane expensive on 32bit
> machines which do not have a 64/32 divison in hardware.
>
> The while loop is there for a few corner cases which are a bit larger than
> 1e9
> nsecs, but that's not the case we optimize for.
>
> The case you are creating with your debugger is something completely
> different
> and we never thought about it nor cared about it. Why? Because so far
> nobody
> complained and I never cared about kernel debuggers at all.
>
> What's worse is that your 'fix' does not resolve the underlying issue at
> all. Why? Simply because you tried to fix the symptom and not the root
> cause.
>
> I explained you the root cause and I explained you why that while() loop is
> more efficient than a divide for the case it was written and optimized for.
>
> Instead of reading and understanding what I wrote you teach me that your
> divide is more efficient and call it a busted piece of shit.
>
> Sure you are free to call that a busted piece of shit, but you don't have
> to
> expect that the people who wrote, maintain and understand that code are
> going
> to put up with your attitude.
>
> Thanks,
>
> 	tglx
>
>
>
>

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?

Jeff

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

#1313466

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

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

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web