Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Subject: Re: [PATCH v2] watchdog: Fix possible soft lockup warning at bootup
To:     Thomas Gleixner <tglx@linutronix.de>,
        Andrew Morton <akpm@linux-foundation.org>,
        Ingo Molnar <mingo@kernel.org>
Cc:     linux-kernel@vger.kernel.org, Mike Rapoport <rppt@linux.ibm.com>,
        Kees Cook <keescook@chromium.org>,
        Catalin Marinas <catalin.marinas@arm.com>,
        Will Deacon <will@kernel.org>,
        Robert Richter <rrichter@marvell.com>,
        Peter Zijlstra <peterz@infradead.org>
References: <20200103151032.19590-1-longman@redhat.com>
 <87sgkgw3xq.fsf@nanos.tec.linutronix.de>
 <87blr3wrqw.fsf@nanos.tec.linutronix.de>
From:   Waiman Long <longman@redhat.com>
Organization: Red Hat
Message-ID: <bf71e29f-ae5a-aad0-758d-53293e2105b4@redhat.com>
Date:   Thu, 16 Jan 2020 10:34:20 -0500
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101
 Thunderbird/60.7.2
MIME-Version: 1.0
In-Reply-To: <87blr3wrqw.fsf@nanos.tec.linutronix.de>
Content-Type: text/plain; charset=windows-1252
Content-Transfer-Encoding: 7bit
Content-Language: en-US
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On 1/16/20 6:44 AM, Thomas Gleixner wrote:
> Thomas Gleixner <tglx@linutronix.de> writes:
>
> Added ARM64 and ThunderX folks 
>
>> Waiman Long <longman@redhat.com> writes:
>>> By adding some instrumentation code, it was found that for cpu 14,
>>> watchdog_enable() was called early with a timestamp of 1. That activates
>>> the watchdog time checking logic. It was also found that the monotonic
>>> time measured during the smp_init() phase runs much slower than the
>>> real elapsed time as shown by the below debug printf output:
>>>
>>>   [    1.138522] run_queues, watchdog_timer_fn: now =  170000000
>>>   [   25.519391] run_queues, watchdog_timer_fn: now = 4170000000
>>>
>>> In this particular case, it took about 24.4s of elapsed time for the
>>> clock to advance 4s which is the soft expiration time that is required
>>> to trigger the calling of watchdog_timer_fn(). That clock slowdown
>>> stopped once the smp_init() call was done and the clock time ran at
>>> the same rate as the elapsed time afterward.
> And looking at this with a more awake brain, the root cause is pretty
> obvious.
>
> sched_clock() advances by 24 seconds, but clock MONOTONIC on which the
> watchdog timer is based does not. As the timestamps you printed have 7
> trailing zeros, it's pretty clear that timekeeping is still jiffies
> based at this point and HZ is set to 100.
>
> So while bringing up the non-boot CPUs the boot CPU loses ~2000 timer
> interrupts. That needs to be fixed and not papered over.
>
You are right that the root-causing effort wasn't complete and I took
the easy way out. As I have limited knowledge on how the timer code
work, I was not sure how to start further investigation at that time.
Your insight gives me a hint on where to start now. So I will dig
further in to see what causes this.

Thanks,
Longman