From patchwork Mon Apr 23 12:53:08 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Thomas Gleixner X-Patchwork-Id: 10356947 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 EAA6A601D3 for ; Mon, 23 Apr 2018 12:53:15 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id DA21828AAF for ; Mon, 23 Apr 2018 12:53:15 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id CE92828AB6; Mon, 23 Apr 2018 12:53:15 +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 400FF28AAF for ; Mon, 23 Apr 2018 12:53:15 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754825AbeDWMxN (ORCPT ); Mon, 23 Apr 2018 08:53:13 -0400 Received: from Galois.linutronix.de ([146.0.238.70]:55501 "EHLO Galois.linutronix.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754786AbeDWMxN (ORCPT ); Mon, 23 Apr 2018 08:53:13 -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 1fAaxw-0008Lq-Ol; Mon, 23 Apr 2018 14:53:08 +0200 Date: Mon, 23 Apr 2018 14:53:08 +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" Subject: Re: hrtimer (rdmavt RNR timer) was lost In-Reply-To: <3F128C9216C9B84BB6ED23EF16290AFB634C8C87@CRSMSX101.amr.corp.intel.com> Message-ID: References: <3F128C9216C9B84BB6ED23EF16290AFB634C8C87@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 Fri, 20 Apr 2018, Wan, Kaike wrote: Please do not send html mail. It's rejected by the list server. > -0 [001] d.h. 3598473310671: hrtimer_start: hrtimer=00000000708914d7 function=rvt_rc_rnr_retry [rdmavt] expires=712172295802 softexpires=712172295802mode=REL base=0000000066dda1ea next=0000000039cae92b > -0 [001] d.h. 3598473311561: hrtimer_post_add: hrtimer=00000000708914d7 function=rvt_rc_rnr_retry [rdmavt] base=0000000066dda1ea next=0000000039cae92b > > --> The target was first added. The expires was 712172295802. The call > was made from cpu 1 while the timer base was on cpu 3. > -0 [003] dn.. 3598605305357: hrtimer_start: hrtimer=0000000004346740 function=tick_sched_timer expires=716767000000 softexpires=716767000000mode=ABS|PINNED base=0000000066dda1ea next=00000000708914d7 > -0 [003] dn.. 3598605305781: hrtimer_post_add: hrtimer=0000000004346740 function=tick_sched_timer base=0000000066dda1ea next=00000000708914d7 > > --> the target timer was the next one to trigger. The call was from cpu 3. > > -0 [003] dN.. 3598605306604: hrtimer_pre_remove: hrtimer=0000000004346740 function=tick_sched_timer base=0000000066dda1ea next=00000000708914d7 > -0 [003] dN.. 3598605306802: hrtimer_post_remove: hrtimer=0000000004346740 function=tick_sched_timer base=0000000066dda1ea next=00000000708914d7 > > --> The tick_sched_timer was removed > > -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 > > --> The tick_sched_timer was added again with a new expires (712171000000 > < 716767000000), which replaced the target (712172295802) as the > head->next. > > -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 > > > --> A new hrtimer (00000000662d2dd8) was added (from cpu 2). Its expires > (712172915662) was larger than the target's (712172295802). How could > it become the next hrtimer to trigger??? The next pointer was not set > properly here. I have no idea how that can happen assumed that you did not strip anything from the trace. If you stripped stuff, please send me the full trace or upload it somewhere. Can you apply the following debug patch and enable the hrtimer_start trace point and send me the full trace or upload it somewhere? 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/lib/timerqueue.c +++ b/lib/timerqueue.c @@ -57,6 +57,10 @@ bool timerqueue_add(struct timerqueue_he rb_link_node(&node->node, parent, p); rb_insert_color(&node->node, &head->head); + trace_printk("head %p next %p next->exp %llu node %p node->exp %llu\n", + head, head->next, head->next ? head->next->expires : 0ULL, + node, node->expires); + if (!head->next || node->expires < head->next->expires) { head->next = node; return true; @@ -84,6 +88,11 @@ bool timerqueue_del(struct timerqueue_he head->next = rb_entry_safe(rbn, struct timerqueue_node, node); } + + trace_printk("head %p next %p next->exp %llu node %p node->exp %llu\n", + head, head->next, head->next ? head->next->expires : 0ULL, + node, node->expires); + rb_erase(&node->node, &head->head); RB_CLEAR_NODE(&node->node); return head->next != NULL;