From patchwork Tue Apr 24 14:54:58 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Thomas Gleixner X-Patchwork-Id: 10360169 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id D3D6C601BE for ; Tue, 24 Apr 2018 14:55:06 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id C1A5427F81 for ; Tue, 24 Apr 2018 14:55:06 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id B22E628E08; Tue, 24 Apr 2018 14:55:06 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-7.9 required=2.0 tests=BAYES_00, MAILING_LIST_MULTI, RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id DE5E027F81 for ; Tue, 24 Apr 2018 14:55:05 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1750749AbeDXOzE (ORCPT ); Tue, 24 Apr 2018 10:55:04 -0400 Received: from Galois.linutronix.de ([146.0.238.70]:36195 "EHLO Galois.linutronix.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750739AbeDXOzD (ORCPT ); Tue, 24 Apr 2018 10:55:03 -0400 Received: from hsi-kbw-5-158-153-52.hsi19.kabel-badenwuerttemberg.de ([5.158.153.52] helo=nanos.tec.linutronix.de) by Galois.linutronix.de with esmtpsa (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1fAzLO-0004zI-Js; Tue, 24 Apr 2018 16:54:58 +0200 Date: Tue, 24 Apr 2018 16:54:58 +0200 (CEST) From: Thomas Gleixner To: "Wan, Kaike" cc: "Marciniszyn, Mike" , "Dalessandro, Dennis" , "Weiny, Ira" , "Fleck, John" , "linux-kernel@vger.kernel.org" , "linux-rdma@vger.kernel.org" , Peter Zijlstra , Anna-Maria Gleixner , Frederic Weisbecker , Ingo Molnar Subject: RE: hrtimer (rdmavt RNR timer) was lost In-Reply-To: Message-ID: References: <3F128C9216C9B84BB6ED23EF16290AFB634C8C87@CRSMSX101.amr.corp.intel.com> <3F128C9216C9B84BB6ED23EF16290AFB634C9420@CRSMSX101.amr.corp.intel.com> User-Agent: Alpine 2.21 (DEB 202 2017-01-01) MIME-Version: 1.0 Sender: linux-rdma-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-rdma@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP On Mon, 23 Apr 2018, Thomas Gleixner wrote: > On Mon, 23 Apr 2018, Wan, Kaike wrote: > > > Can you apply the following debug patch and enable the hrtimer_start trace > > > point and send me the full trace or upload it somewhere? > > > > The original trace was about 29GB and I filtered it with > > "0000000066dda1ea" (the offending base) to generate a 1.4GB file that I > > could open and investigate. I am not sure how I can send them to you. Do > > you have somewhere I can upload to? > > > > I can try your debug patch and again I am anticipating a big trace file. > > Well, you can find the spot where the fail happens and then extract the > full thing from 2s before that point to 1s after. That should be reasonably > small and good enough. Let me know when you have it and how big it is > (compressed) and we'll figure something out how to transport it. Thanks for the more complete data which actually let me decode the wreckage. So you have NO_HZ enabled and looking at the trace then this is related: -0 [003] dN.. 3598605307236: hrtimer_start: hrtimer=0000000004346740 function=tick_sched_timer expires=712171000000 softexpires=712171000000mode=ABS|PINNED base=0000000066dda1ea next=00000000708914d7 -0 [003] dN.. 3598605307601: hrtimer_post_add: hrtimer=0000000004346740 function=tick_sched_timer base=0000000066dda1ea next=0000000004346740 -0 [002] d.h. 3598605313255: hrtimer_start: hrtimer=00000000662d2dd8 function=rvt_rc_rnr_retry [rdmavt] expires=712172915662 softexpires=712172915662mode=REL base=0000000066dda1ea next=0000000004346740 -0 [002] d.h. 3599538740786: hrtimer_post_add: hrtimer=00000000662d2dd8 function=rvt_rc_rnr_retry [rdmavt] base=0000000066dda1ea next=00000000662d2dd8 -0 [003] dn.. 3599538742242: hrtimer_pre_remove: hrtimer=0000000004346740 function=tick_sched_timer base=0000000066dda1ea next=00000000662d2dd8 -0 [003] dn.. 3599538743084: hrtimer_post_remove: hrtimer=0000000004346740 function=tick_sched_timer base=0000000066dda1ea next=00000000662d2dd8 -0 [003] dn.. 3599538743830: hrtimer_start: hrtimer=0000000004346740 function=tick_sched_timer expires=716767000000 softexpires=716767000000mode=ABS|PINNED base=0000000066dda1ea next=00000000662d2dd8 -0 [003] dn.. 3599538744560: hrtimer_post_add: hrtimer=0000000004346740 function=tick_sched_timer base=0000000066dda1ea next=00000000662d2dd8 And staring at the NOHZ code I'm pretty sure, I know what happens. CPU 3 CPU 2 idle start tick_sched_timer 712171000000 start rdmavt timer 712172915662 lock(base) tick_nohz_stop_tick() tick = 716767000000 timerqueue_add(tmr) hrtimer_set_expires(&ts->sched_timer, tick); <---- FAIL if (tmr->exp < queue->next->exp) hrtimer_start(sched_timer) queue->next = tmr; lock(base) unlock(base) timerqueue_remove() timerqueue_add() .... So ts->sched_timer is still queued and queue->next is pointing to it, but then expires is modified. So the other side sees the new expiry time and makes the rdmavt timer the new queue->next. All f*cked from there. The problem was introduced with: d4af6d933ccf ("nohz: Fix spurious warning when hrtimer and clockevent get out of sync") The changelog is not really helpful, but I can't see why the expiry time of ts->sched_timer should be updated before the timer is [re]started in case of HIGHRES + NOHZ. hrtimer_start() sets the expiry time, so that should be sufficient. Of course the tick needs to be stored in ts->sched_timer for the !HIGHRES + HOHZ case, but that's trivial enough to do. Patch against Linus tree below. It's easy to backport in case you want to run it against the kernel which made the observation simpler. I need to come up with integration of hrtimer_set_expires() into debug objects to catch this kind of horrors. Groan.... Thanks, tglx 8<----------- --- To unsubscribe from this list: send the line "unsubscribe linux-rdma" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html --- a/kernel/time/tick-sched.c +++ b/kernel/time/tick-sched.c @@ -804,12 +804,12 @@ static void tick_nohz_stop_tick(struct t return; } - hrtimer_set_expires(&ts->sched_timer, tick); - - if (ts->nohz_mode == NOHZ_MODE_HIGHRES) - hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED); - else + if (ts->nohz_mode == NOHZ_MODE_HIGHRES) { + hrtimer_start(&ts->sched_timer, tick, HRTIMER_MODE_ABS_PINNED); + } else { + hrtimer_set_expires(&ts->sched_timer, tick); tick_program_event(tick, 1); + } } static void tick_nohz_retain_tick(struct tick_sched *ts)