From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from out-182.mta0.migadu.com (out-182.mta0.migadu.com [91.218.175.182]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 52B7933D5 for ; Fri, 12 Apr 2024 01:14:44 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=91.218.175.182 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1712884486; cv=none; b=VLJDbgN09lrTFSA30Mlag9FBQo7OFIyebRxXOdr8kuNvG/r+VJB5Ib/BxsMQL7/2EqUNsqBgzW9DfeGp5TZgFveTVTrRCLplN2NBBS0IsvL2HHh24LKJFRrsql3DaqXvxuFbuVhHQwFglab5acIEibQzuc0jBPmqKKOAkqSHL1o= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1712884486; c=relaxed/simple; bh=e6+AYuksM/OkdD9KeQZdNWHeNxAHypqErI5Qn8MY/Wc=; h=Message-ID:Date:MIME-Version:Subject:To:Cc:References:From: In-Reply-To:Content-Type; b=b2Xd5x4frkVh+r4q/XL5Il4R2Z7xzcFgT05zwGQ/RCgyq0/9XPyqit2uX/rImkAS6/Qs2RcGhqHjzIeXJzLpQFEYVLHlFvhzxXm6bhjwYNsx9PcaBfQBKf1v7B+wWeZaeGBf8omIoN4QsSyrTTRVuZ2RHjSUGrgxErqIs7qleFQ= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=linux.dev; spf=pass smtp.mailfrom=linux.dev; dkim=pass (1024-bit key) header.d=linux.dev header.i=@linux.dev header.b=sBSbOsbh; arc=none smtp.client-ip=91.218.175.182 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=linux.dev Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=linux.dev Authentication-Results: smtp.subspace.kernel.org; dkim=pass (1024-bit key) header.d=linux.dev header.i=@linux.dev header.b="sBSbOsbh" Message-ID: DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linux.dev; s=key1; t=1712884482; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=X33cbovPiEfTGdBBISnr1h/yfgzXYiMloxhJKyuAgEA=; b=sBSbOsbh6k4hKzZ2xR90un+SIdTm4jYFsZv4PE+/Pzkh3SBcCsyJRL+49sY9o+3kYpkQOY rl9eYQisrhV+7huBD/oHaWThlgOAozgySpOYtdZsb1cTr6Uvsovl4VUwlDcaXGc7laDNjQ h8TFOMGFvcwn68Omajr3lJx3B7qR8go= Date: Thu, 11 Apr 2024 18:14:35 -0700 Precedence: bulk X-Mailing-List: bpf@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 Subject: Re: Incorrect BPF stats accounting for fentry on arm64 Content-Language: en-GB To: Ivan Babrou , bpf Cc: kernel-team , Xu Kuohai , linux-kernel , linux-arm-kernel@lists.infradead.org References: X-Report-Abuse: Please report any abuse attempt to abuse@migadu.com and include these headers. From: Yonghong Song In-Reply-To: Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit X-Migadu-Flow: FLOW_OUT On 4/11/24 11:09 AM, Ivan Babrou wrote: > Hello, > > We're seeing incorrect data for bpf runtime stats on arm64. Here's an example: > > $ sudo bpftool prog show id 693110 > 693110: tracing name __tcp_retransmit_skb tag e37be2fbe8be4726 gpl > run_time_ns 2493581964213176 run_cnt 1133532 recursion_misses 1 > loaded_at 2024-04-10T22:33:09+0000 uid 62727 > xlated 312B jited 344B memlock 4096B map_ids 8550445,8550441 > btf_id 8726522 > pids prometheus-ebpf(2224907) > > According to bpftool, this program reported 66555800ns of runtime at > one point and then it jumped to 2493581675247416ns just 53s later when > we looked at it again. This is happening only on arm64 nodes in our > fleet on both v6.1.82 and v6.6.25. > > We have two services that are involved: > > * ebpf_exporter attaches bpf programs to the kernel and exports > prometheus metrics and opentelementry traces driven by its probes > * bpf_stats_exporter runs bpftool every 53s to capture bpf runtime metrics > > The problematic fentry is attached to __tcp_retransmit_skb, but an > identical one is also attached to tcp_send_loss_probe, which does not > exhibit the same issue: > > SEC("fentry/__tcp_retransmit_skb") > int BPF_PROG(__tcp_retransmit_skb, struct sock *sk) > { > return handle_sk((struct pt_regs *) ctx, sk, sk_kind_tcp_retransmit_skb); > } > > SEC("fentry/tcp_send_loss_probe") > int BPF_PROG(tcp_send_loss_probe, struct sock *sk) > { > return handle_sk((struct pt_regs *) ctx, sk, sk_kind_tcp_send_loss_probe); > } > > In handle_sk we do a map lookup and an optional ringbuf push. There is > no sleeping (I don't think it's even allowed on v6.1). It's > interesting that it only happens for the retransmit, but not for the > loss probe. > > The issue manifests some time after we restart ebpf_exporter and > reattach the probes. It doesn't happen immediately, as we need to > capture metrics 53s apart to produce a visible spike in metrics. > > There is no corresponding spike in execution count, only in execution time. > > It doesn't happen deterministically. Some ebpf_exporter restarts show > it, some don't. > > It doesn't keep happening after ebpf_exporter restart. It happens once > and that's it. > > Maybe recursion_misses plays a role here? We see none for > tcp_send_loss_probe. We do see some for inet_sk_error_report > tracepoint, but it doesn't spike like __tcp_retransmit_skb does. > > The biggest smoking gun is that it only happens on arm64. I am not an expert for arm64. But you or somebody could check and compare arm64 and x86 jit trampoline codes to see whether anything is suspicious. > > I'm happy to try out patches to figure this one out. > From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from bombadil.infradead.org (bombadil.infradead.org [198.137.202.133]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.lore.kernel.org (Postfix) with ESMTPS id 879C0C4345F for ; Fri, 12 Apr 2024 01:15:03 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=lists.infradead.org; s=bombadil.20210309; h=Sender:Content-Type: Content-Transfer-Encoding:List-Subscribe:List-Help:List-Post:List-Archive: List-Unsubscribe:List-Id:In-Reply-To:From:References:Cc:To:Subject: MIME-Version:Date:Message-ID:Reply-To:Content-ID:Content-Description: Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID: List-Owner; bh=HnRynmMM1abB3pOXmeLFCrHQnFXxTPdpgVUnW33FNQo=; b=hoEAmltpEc2smP 6Fn29B+KfYlHaQHYsee51eqmV02d+fXsfabzVrR8NFfp4Pf30KMeiH3vTFe8iPXCzkHv1BuO1Q1dc pn9uNtCdxR1lbseDxNb7ymYueVzOxyPR/nS3Be/J8ii7qZXGGXrLyUJ600ArMY7yNQ7DGZMQ9papW BJ+zcrkGR45PWUcDYvtzZFg+c4JTF8DEQhUaB5+OdMng4fwI12NVTTWlZiUpntk1y57pVuypfpVwd uuMAe3SkswPB4dMzVhlWzbE2obMG1N+S/eXsYuh8ye0qWXrTAdJBCerv4DLwxlEkdT+fIPI7X0Wrb 7r4Gt3jxMYf7xCiAfzVw==; Received: from localhost ([::1] helo=bombadil.infradead.org) by bombadil.infradead.org with esmtp (Exim 4.97.1 #2 (Red Hat Linux)) id 1rv5VE-0000000Eizq-30Ja; Fri, 12 Apr 2024 01:14:52 +0000 Received: from out-189.mta0.migadu.com ([2001:41d0:1004:224b::bd]) by bombadil.infradead.org with esmtps (Exim 4.97.1 #2 (Red Hat Linux)) id 1rv5VB-0000000Eiyj-0ybO for linux-arm-kernel@lists.infradead.org; Fri, 12 Apr 2024 01:14:51 +0000 Message-ID: DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linux.dev; s=key1; t=1712884482; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=X33cbovPiEfTGdBBISnr1h/yfgzXYiMloxhJKyuAgEA=; b=sBSbOsbh6k4hKzZ2xR90un+SIdTm4jYFsZv4PE+/Pzkh3SBcCsyJRL+49sY9o+3kYpkQOY rl9eYQisrhV+7huBD/oHaWThlgOAozgySpOYtdZsb1cTr6Uvsovl4VUwlDcaXGc7laDNjQ h8TFOMGFvcwn68Omajr3lJx3B7qR8go= Date: Thu, 11 Apr 2024 18:14:35 -0700 MIME-Version: 1.0 Subject: Re: Incorrect BPF stats accounting for fentry on arm64 Content-Language: en-GB To: Ivan Babrou , bpf Cc: kernel-team , Xu Kuohai , linux-kernel , linux-arm-kernel@lists.infradead.org References: X-Report-Abuse: Please report any abuse attempt to abuse@migadu.com and include these headers. From: Yonghong Song In-Reply-To: X-Migadu-Flow: FLOW_OUT X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20240411_181449_580309_78D1195A X-CRM114-Status: GOOD ( 21.27 ) X-BeenThere: linux-arm-kernel@lists.infradead.org X-Mailman-Version: 2.1.34 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset="us-ascii"; Format="flowed" Sender: "linux-arm-kernel" Errors-To: linux-arm-kernel-bounces+linux-arm-kernel=archiver.kernel.org@lists.infradead.org On 4/11/24 11:09 AM, Ivan Babrou wrote: > Hello, > > We're seeing incorrect data for bpf runtime stats on arm64. Here's an example: > > $ sudo bpftool prog show id 693110 > 693110: tracing name __tcp_retransmit_skb tag e37be2fbe8be4726 gpl > run_time_ns 2493581964213176 run_cnt 1133532 recursion_misses 1 > loaded_at 2024-04-10T22:33:09+0000 uid 62727 > xlated 312B jited 344B memlock 4096B map_ids 8550445,8550441 > btf_id 8726522 > pids prometheus-ebpf(2224907) > > According to bpftool, this program reported 66555800ns of runtime at > one point and then it jumped to 2493581675247416ns just 53s later when > we looked at it again. This is happening only on arm64 nodes in our > fleet on both v6.1.82 and v6.6.25. > > We have two services that are involved: > > * ebpf_exporter attaches bpf programs to the kernel and exports > prometheus metrics and opentelementry traces driven by its probes > * bpf_stats_exporter runs bpftool every 53s to capture bpf runtime metrics > > The problematic fentry is attached to __tcp_retransmit_skb, but an > identical one is also attached to tcp_send_loss_probe, which does not > exhibit the same issue: > > SEC("fentry/__tcp_retransmit_skb") > int BPF_PROG(__tcp_retransmit_skb, struct sock *sk) > { > return handle_sk((struct pt_regs *) ctx, sk, sk_kind_tcp_retransmit_skb); > } > > SEC("fentry/tcp_send_loss_probe") > int BPF_PROG(tcp_send_loss_probe, struct sock *sk) > { > return handle_sk((struct pt_regs *) ctx, sk, sk_kind_tcp_send_loss_probe); > } > > In handle_sk we do a map lookup and an optional ringbuf push. There is > no sleeping (I don't think it's even allowed on v6.1). It's > interesting that it only happens for the retransmit, but not for the > loss probe. > > The issue manifests some time after we restart ebpf_exporter and > reattach the probes. It doesn't happen immediately, as we need to > capture metrics 53s apart to produce a visible spike in metrics. > > There is no corresponding spike in execution count, only in execution time. > > It doesn't happen deterministically. Some ebpf_exporter restarts show > it, some don't. > > It doesn't keep happening after ebpf_exporter restart. It happens once > and that's it. > > Maybe recursion_misses plays a role here? We see none for > tcp_send_loss_probe. We do see some for inet_sk_error_report > tracepoint, but it doesn't spike like __tcp_retransmit_skb does. > > The biggest smoking gun is that it only happens on arm64. I am not an expert for arm64. But you or somebody could check and compare arm64 and x86 jit trampoline codes to see whether anything is suspicious. > > I'm happy to try out patches to figure this one out. > _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel