Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Message-ID: <0b9023b6-9742-b317-7596-98026a0c5d03@meta.com>
Date:   Thu, 8 Dec 2022 10:01:08 -0800
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:102.0)
 Gecko/20100101 Thunderbird/102.5.1
Subject: Re: [PATCH bpf-next] bpf: btf: don't log ignored BTF mismatches
Content-Language: en-US
To:     Connor O'Brien <connoro@google.com>
Cc:     bpf@vger.kernel.org, Martin KaFai Lau <martin.lau@linux.dev>,
        Alexei Starovoitov <ast@kernel.org>,
        Daniel Borkmann <daniel@iogearbox.net>,
        Andrii Nakryiko <andrii@kernel.org>,
        Song Liu <song@kernel.org>, Yonghong Song <yhs@fb.com>,
        John Fastabend <john.fastabend@gmail.com>,
        KP Singh <kpsingh@kernel.org>,
        Stanislav Fomichev <sdf@google.com>,
        Hao Luo <haoluo@google.com>, Jiri Olsa <jolsa@kernel.org>,
        linux-kernel@vger.kernel.org
References: <20221109024155.2810410-1-connoro@google.com>
 <5708a47d-5400-e75e-ccf6-96177366ea38@meta.com>
 <CALE1s+NfHYpE_=fNr47U2groVDwhdHJJDSo6-2gdN8mR5G700g@mail.gmail.com>
From:   Yonghong Song <yhs@meta.com>
In-Reply-To: <CALE1s+NfHYpE_=fNr47U2groVDwhdHJJDSo6-2gdN8mR5G700g@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?utf-8?B?UnRWWEN5eTl6OHkwTDA1d21yUzJWMkgvcEhkRGZCYWlVM0p5OVF1SlVzTUdz?=
 =?utf-8?B?MjNiVlZNbCthOG5PZnpmS0VhWi9wSWY3VExwT1NIWGhDakgyam5CMFVlanhS?=
 =?utf-8?B?eDJmV2dNRW5kUWplbG1kRmJmOHM1Z2xkTWo4c09PM1ZGa0U0bjRrWis3bnlO?=
 =?utf-8?B?ZytnWWZNV2I1NTVla2w1VjFtbU1wM3NSaU12T20zdkIraEdBRExNMlZkNW1v?=
 =?utf-8?B?aEZaVXZkSkhWcFluRC9ZNkpOcWY5QTJGalZ3WE5PWkMzSHlnODloS3BxT091?=
 =?utf-8?B?MDhYQSttTjBEVmxLOGEyMkJyRzJtemd2M25YeGVXTnk2emxUVlRtbGp3djNC?=
 =?utf-8?B?dkdXb2t4aVgwZ2t1WU1hV0ROQTAxNEdYUHdMRTlLbUFlWGJNV2FLZ0NDSUZi?=
 =?utf-8?B?RzlxaUlZeUVkaDV6Sk53ajdCUWlKa3RZTnZiVUxMRnFZTjhETGJ1elVTcldX?=
 =?utf-8?B?YlhnMVhIbXdWa3V5QllQL21OeHVGa2pBelJ6cnZ0bllJUWZ2dE5iVnprUFkr?=
 =?utf-8?B?OWlwOXhqUGRXUkNGcmpzb1NscjlNL0ZCT1VWRG9WM3RjWHlKY3JQdWVnZDdE?=
 =?utf-8?B?UkNDRUN6UG5HMFNwK2Fid0Y2VjFyVldZSWhVRWJZS1puNGU1QmxaU0w1Wkli?=
 =?utf-8?B?clNzUUJSME50OWJkKzFKSEFOZDBDRzNiYWNuaHpJTFdzMXFLaFhKayt4amp6?=
 =?utf-8?B?V20rRGxxZFExaGxmNWVkd25WbW5saUdsTTBMaEE1Zmk4S094d3h3WTY1aTRX?=
 =?utf-8?B?cXNROGd5cnNKZitxbk5Fa1p2REJVQURXVkJjQjhiYjNpc1A2eWV4amNnMXdq?=
 =?utf-8?B?eWxRWG8wWTdRKy8xNXRhRVJNM2J3Q2J4MU9xanNlcFp2YWZoUmIzNit1dk5n?=
 =?utf-8?B?Y1BiMDZnMVgxcnAvYStKeTNnN3hyWFZhOTNTY0MzYVZ0VkRpbkZ5ckZSSjNV?=
 =?utf-8?B?aEtuUTNLUERtM2x6bWRCR1kxM1Y3RDFVWUZ3WG5OZ25ySjZEcndGMEZrWnpZ?=
 =?utf-8?B?c3ExZTZobmdScE5UNmlqN2ZOYXB3QlFpcnZUdGw2aTZyMzJIZlNzbFIyMTg4?=
 =?utf-8?B?UTdCUUE3a1ZZaXEwQzZjRkFPVnVuVEVzS1Y3Ym1iUlEwZk44YTlGTFcrdWlp?=
 =?utf-8?B?bUlQcndGaEViaGdFQi9yak81NnFwL05oT0ltUGVkbEVGcjMxQkdtUE82WFMz?=
 =?utf-8?B?WUlOY0RrZUFHTnJheUdUVHZ0SFF3bEhXQmd2L3YvWERpb1hhUUdaWWtpOXNS?=
 =?utf-8?B?TXF4NWRsNDVENW9lY0o3UlplT2NmNUJGa3ZScDRxZTk5cWJ5S0ZiQkprSjRS?=
 =?utf-8?B?UmtUL0lXOUpHNHNOaDR4MmxlNjRFay9rclRaUGpldHJKUWFxdWlPcUI0aEw1?=
 =?utf-8?B?RHV3QWcrR1NweXpDMStNTGdaT0JnNm9QQk9WUzdzSmVka3pRK1RmZjZRUFVE?=
 =?utf-8?B?alpGMjM0MFdPTzZXNGt6Yi96WGtyUHBuWXBWdmRkZFZjbVFYNTdyNlJpL1Ni?=
 =?utf-8?B?ZUNhM0tMejc2RTRraEdRb0FtMEVnMWZjNkJKUXA2VlJMeWJJVGpQbEhXc0lm?=
 =?utf-8?B?YVB3VmdKR24yV0Q5TytDb0JtK2NLNUo3ek9VV1Exc3lmSWoySjNzRjNzbEps?=
 =?utf-8?B?RjBLcGs5RTJtbzRoY1J4QzJPUDFXdVgybGtwVW84bzhzL3hBc0ozUERQanJs?=
 =?utf-8?B?a25tOVJFWVBTZTZWTkRYRW4yZFVpTFQvV3cxU0pTNXNNTUVxV2ZBSlNvNEVL?=
 =?utf-8?B?QnAyZENiTVlEbDRHMm9LdkxremRTN1Y3RVpkVndsK1JTeTRjN0NjVm5GaEtk?=
 =?utf-8?B?RkVGMFVsYXg4TFhWbCtrTkJFVG1FdGRkSGd2bFRHempPOHFrTTV2bWlFUUNu?=
 =?utf-8?B?aEJGd09OdllUb29ONExiOVBhTmd0cjlUT3BOV29MVE9hbVJpVXh0NEVzdVBP?=
 =?utf-8?B?TDd4R3pRM0czQVNSZ0MxZk91UWlrcmk4WVE1M3FXd2ZsTEh0NkpWTFk1OXF2?=
 =?utf-8?B?WUppTTBOSHY1bTZpcEhjc3ZVMHQvTE0zNUpvZ3M5aXgxS2RVQ0lCYU04RTQz?=
 =?utf-8?B?cnRuUHBOeFFvTGU0MC9ydEorZXhvUWxHdGJOS1NYZXB3WjhWYzVpYmlYWkdp?=
 =?utf-8?B?amZPWnV1R2hYc2Fsdnd4bXVvN3FpZlYvcUd1ak1MUy9LTVpVME5LMERrejk3?=
 =?utf-8?B?RWc9PQ==?=
X-OriginatorOrg: meta.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 23bcd4b8-507d-495f-a95d-08dad9463090
X-MS-Exchange-CrossTenant-AuthSource: SN6PR1501MB2064.namprd15.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 08 Dec 2022 18:01:11.3633
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 8ae927fe-1255-47a7-a2af-5f3a069daaa2
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: kb7Q91dBsCyJhisAix0ec0CeNCidEFS6IXyvzwO63Mjyty8JGfNC3a2C4FviZQud
X-MS-Exchange-Transport-CrossTenantHeadersStamped: CH3PR15MB5563
X-Proofpoint-GUID: 6yK3DitxOpjlaHUbkjymcyWZRppE7dpm
X-Proofpoint-ORIG-GUID: 6yK3DitxOpjlaHUbkjymcyWZRppE7dpm
Content-Transfer-Encoding: 7bit
X-Proofpoint-UnRewURL: 0 URL was un-rewritten
MIME-Version: 1.0
X-Proofpoint-Virus-Version: vendor=baseguard
 engine=ICAP:2.0.205,Aquarius:18.0.923,Hydra:6.0.545,FMLib:17.11.122.1
 definitions=2022-12-08_11,2022-12-08_01,2022-06-22_01
X-Spam-Status: No, score=-3.1 required=5.0 tests=BAYES_00,DKIM_SIGNED,
        DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,NICE_REPLY_A,RCVD_IN_DNSWL_LOW,
        RCVD_IN_MSPIKE_H3,RCVD_IN_MSPIKE_WL,SPF_HELO_NONE,SPF_NONE
        autolearn=ham autolearn_force=no version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
        lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org


On 12/7/22 6:19 PM, Connor O'Brien wrote:
> On Wed, Nov 9, 2022 at 8:45 AM Yonghong Song <yhs@meta.com> wrote:
>>
>>
>>
>> On 11/8/22 6:41 PM, Connor O'Brien wrote:
>>> Enabling CONFIG_MODULE_ALLOW_BTF_MISMATCH is an indication that BTF
>>> mismatches are expected and module loading should proceed
>>> anyway. Logging with pr_warn() on every one of these "benign"
>>> mismatches creates unnecessary noise when many such modules are
>>> loaded. Instead, limit logging to the case where a BTF mismatch
>>> actually prevents a module form loading.
>>>
>>> Signed-off-by: Connor O'Brien <connoro@google.com>
>>> ---
>>>    kernel/bpf/btf.c | 7 ++++---
>>>    1 file changed, 4 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/kernel/bpf/btf.c b/kernel/bpf/btf.c
>>> index 5579ff3a5b54..406370487413 100644
>>> --- a/kernel/bpf/btf.c
>>> +++ b/kernel/bpf/btf.c
>>> @@ -7190,11 +7190,12 @@ static int btf_module_notify(struct notifier_block *nb, unsigned long op,
>>>                }
>>>                btf = btf_parse_module(mod->name, mod->btf_data, mod->btf_data_size);
>>>                if (IS_ERR(btf)) {
>>> -                     pr_warn("failed to validate module [%s] BTF: %ld\n",
>>> -                             mod->name, PTR_ERR(btf));
>>
>> I think such warning still useful even with
>> CONFIG_MODULE_ALLOW_BTF_MISMATCH.
>> Can we use pr_warn_ratelimited instead of pr_warn in the above to
>> avoid excessive warnings?
> 
> I gave this a try on a Pixel 6 but I'm not sure it quite addresses the
> issue. The amount of logging doesn't seem to decrease much, I think
> because the interval between loading one mismatched module and the
> next can be greater than the default rate limit. To my mind, the issue
> is the total volume of these messages more so than their rate.
> 
> For context, Android devices using the GKI may load hundreds of
> separately-built modules, and BTF mismatches are possible for any/all
> of these. It was pointed out to me that btf_verifier_log_type can also
> print several more lines per mismatched module. ~5 lines of logging
> for each mismatched module can start to add up, in terms of both
> overhead and the noise added to the kernel logs.
> 
> This is more subjective but I think the warnings also read as though
> this is a more serious failure that might prevent affected modules
> from working correctly; anecdotally, I've gotten multiple questions
> about them asking if something is broken. This can be a red herring
> for anyone unfamiliar with BTF who is reading the logs to debug
> unrelated issues. In the CONFIG_MODULE_ALLOW_BTF_MISMATCH=y case the
> flood of warnings seems out of proportion to the actual result
> (modules still load successfully, just without debug info) especially
> since the user has explicitly enabled a config saying they expect
> mismatches.
> 
> If there needs to be some logging in the "mismatch allowed" case,
> could an acceptable middle ground be to use pr_warn_once to send a

So it looks like pr_warn_ratelimited still produces a lot of warning.
In this case, I guess pr_warn_once should be okay.

> single message reporting that mismatches were detected & module BTF
> debug info might be unavailable? Alternatively, if we could opt out of
> module BTF loading then that would also avoid this issue, but that's
> already been proposed before ([1], [2]) so I thought working with the
> existing config option might be preferred.
> 
> [1] https://lore.kernel.org/bpf/20220209052141.140063-1-connoro@google.com/
> [2] https://lore.kernel.org/bpf/20221004222725.2813510-1-sdf@google.com/