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 kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by smtp.lore.kernel.org (Postfix) with ESMTP id EE32AC0015E for ; Sat, 15 Jul 2023 00:30:32 +0000 (UTC) Received: by kanga.kvack.org (Postfix) id 6CFF76B0071; Fri, 14 Jul 2023 20:30:32 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 67EE56B0072; Fri, 14 Jul 2023 20:30:32 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id 51F4E6B0074; Fri, 14 Jul 2023 20:30:32 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from relay.hostedemail.com (smtprelay0014.hostedemail.com [216.40.44.14]) by kanga.kvack.org (Postfix) with ESMTP id 3F7446B0071 for ; Fri, 14 Jul 2023 20:30:32 -0400 (EDT) Received: from smtpin19.hostedemail.com (a10.router.float.18 [10.200.18.1]) by unirelay06.hostedemail.com (Postfix) with ESMTP id 4CEAEB0847 for ; Sat, 15 Jul 2023 00:30:31 +0000 (UTC) X-FDA: 81011965062.19.6E36A76 Received: from mail-wr1-f45.google.com (mail-wr1-f45.google.com [209.85.221.45]) by imf17.hostedemail.com (Postfix) with ESMTP id 4829440002 for ; Sat, 15 Jul 2023 00:30:29 +0000 (UTC) Authentication-Results: imf17.hostedemail.com; dkim=pass header.d=cloudflare.com header.s=google header.b=OKBWZD7h; dmarc=pass (policy=reject) header.from=cloudflare.com; spf=pass (imf17.hostedemail.com: domain of ivan@cloudflare.com designates 209.85.221.45 as permitted sender) smtp.mailfrom=ivan@cloudflare.com ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=hostedemail.com; s=arc-20220608; t=1689381029; h=from:from:sender: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:dkim-signature; bh=9ptAxBcW7aHFl51V3a6EjybWpG1k8jXl2fJumuPzCWI=; b=sJOSvZYvo9EnBs2QlDsTvW25pYS4xYXs/5F8WU/7ISVs3opNXcKGanZEUtPAtZMYiNHRx9 jzBWksXquYzUhdpw6ztm1pJDNoEc49b0+5WeHw6BUFGwtmwDiJ585hhL3GINQn7YcsAeY6 7h2Vb69bDuOfEe4yeFZHEy5c0flz7p4= ARC-Authentication-Results: i=1; imf17.hostedemail.com; dkim=pass header.d=cloudflare.com header.s=google header.b=OKBWZD7h; dmarc=pass (policy=reject) header.from=cloudflare.com; spf=pass (imf17.hostedemail.com: domain of ivan@cloudflare.com designates 209.85.221.45 as permitted sender) smtp.mailfrom=ivan@cloudflare.com ARC-Seal: i=1; s=arc-20220608; d=hostedemail.com; t=1689381029; a=rsa-sha256; cv=none; b=kczfXx7E4JmppKuWG0nLD7kv0eFksmsnteEc1rtXwjro0eBzrdR1SnVd7Tt/vfCYOndg3n /jXILE9stg7l+V61zwIIdd2IBE81lgBIVw8/bJVRp6QVd2Kr2LGdXzR9REJlvm8spCTTTS iIjnjJ1rmJWWclTNHGPSOskxnLFnTj8= Received: by mail-wr1-f45.google.com with SMTP id ffacd0b85a97d-3159d75606dso2517136f8f.1 for ; Fri, 14 Jul 2023 17:30:28 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=cloudflare.com; s=google; t=1689381028; x=1691973028; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:from:to:cc:subject:date :message-id:reply-to; bh=9ptAxBcW7aHFl51V3a6EjybWpG1k8jXl2fJumuPzCWI=; b=OKBWZD7hUGWSmN+3mpSUHI7/TIUCwtTCSVhJFhqPPb2/YEUL9MtgCkWbZCQbhlPV26 ZU9n46fYO9n14gKdH9pdnznVF3xxgsNFqBTEzlvYTseWX2rakSjIVOCOVJv8Woyh/P6/ wutIaHQINaqQLf1SxDMmwhv/hdu/yneXvriNw= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20221208; t=1689381028; x=1691973028; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=9ptAxBcW7aHFl51V3a6EjybWpG1k8jXl2fJumuPzCWI=; b=JfJXdlhiWMnDtX877zD6qPv5nZ5g72p4K7AmhOi/z1in24bzHwRLAeCxdWZUZqy6B+ 5n2QTM1G+O8SmhZtFboCF5SuxWP8H3ZMzcj4EnQ9N+XIXdHDg5sa+rouyMoVANb/Lcrd UoESqDYglkkc3212n7BmZ05JkAfrSA19qQjU7A3Md0pRzHcJOcvGOB6dTeaiSVSWdWPI NZBcLEotDK3SI22VzOemdJ1ZpOOvjmAtHBYLRggKr5E+z8GQkOmu+y1ZYY+JTv7b/6Ui aYYY1Zxd1pVHefvxU9h3KU57N5kYMHaZP0NxXHY3UBGw6TDSWL2eC+8ohI6bzt6FTMqn mb1A== X-Gm-Message-State: ABy/qLalN6fnBstR3qHUBRfpVzUEQulHI8mJcCV0plElQcq81+YjettS XZ2UUf+6Z9BHuVmx/IRA97uelzCRTnthZERwwuJ5Zg== X-Google-Smtp-Source: APBJJlHfci5eY4p/RZE6lnI2l2YdLECrCtLHmAVkgLDkkj7nPdNt5HWBvk0PfmPVd1Sc0Jzre1QRlRPaQxHbfFnP7I0= X-Received: by 2002:a5d:514b:0:b0:313:e9d7:108f with SMTP id u11-20020a5d514b000000b00313e9d7108fmr4937042wrt.33.1689381027716; Fri, 14 Jul 2023 17:30:27 -0700 (PDT) MIME-Version: 1.0 References: <20230706062045.xwmwns7cm4fxd7iu@google.com> In-Reply-To: From: Ivan Babrou Date: Fri, 14 Jul 2023 17:30:16 -0700 Message-ID: Subject: Re: Expensive memory.stat + cpu.stat reads To: Waiman Long Cc: Shakeel Butt , cgroups@vger.kernel.org, Linux MM , kernel-team , Johannes Weiner , Michal Hocko , Roman Gushchin , Muchun Song , Andrew Morton , linux-kernel Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Rspam-User: X-Stat-Signature: hifky8ph65sjfx8pdep3q9ikmm3o797a X-Rspamd-Server: rspam07 X-Rspamd-Queue-Id: 4829440002 X-HE-Tag: 1689381029-479062 X-HE-Meta: U2FsdGVkX1+nS+k3zbA5Ep16wiZNDVbg4OjmgaHRhhVWVMMkR7EQCHvFjP/LkiqdQU2bhplBYvNaKGTMcGoy4OiLxoq0oWinlC/S6svR1YMOgKZU7eFzrRkeHzessCZmDOBGa2LqttWDqmX8umAqf0HuEMJbVPa33Af2rUHMxATxuC5+niW7Rj6qtQIzo95opp3hAwQaKMQoLNQYH99ijjGXRC2/mTc719QCCCj+LsHIG1Q3J13eV5ywxV3IbyiiFMK0PmPITZN/QKHSJVgX2GgGinpDdjap8rbnsI1j27Uxj9lIY4zvQKrWHXKM5Is5mK91jdGYPlFkyBmcgphSyF6uyI4WoP3P1rG3XhQpECbx7Qi4Ghjs85shEbr52df04YKKlwGwMpeotJy8SsJ7RddezBbaAsF7TzS7YJvErcC9ZXA+Xnah8xIlBEM2NdNCQG4PAckOtGt9jJjSJWT1tYCx+Ztjuxz6pC2AwNsqlW0QrflQBPn4cPf/3D63DsFAMD4GWCGf1+YQi/1stGSKJe2Q1l0Mfv1oSVMoHrrwJ4nOKHJ94tSua8cK7yWoEztAv5ztxTYHgDA4eqvwKa7jM2V3uZHCCM0nkKzbjwB4Rsh6JiY/fGimJS9Iq/qVkeiHvoq4u8iYa0DsQbyFI1FPRP2dPO4AGZND/vKgbJlPiT7woeUjXyYh+EM+hHvLdH+b0pLbvhz20gU8o/3wEqZ/36nVKyqlEbxzxVIp2SwXj+0ef02CO5RytgeKlDMBJTvl4f7F7YzTCUqMF8RXK9QiGnx0DeLdlZD2e3QcwleJ8p17GNOUG0YpC7Wa293isJlrAngzqwTuihZ0L9OSGkaX4rTKoJDcrcb/4j59/HnnE2Q7BqG45CraLPCPcGTMmjfnb6laeLNtjTrkic8PsfFMWPdtFEXf9DG8bbV7Dg7FIquBdPn6PV4jXdXO3DLRC6UaVNGwnbtLf5GlaDt5V7P OhHVASet yk9P7WNDK7LIKiCDV7Q0RCJzQCgq+jfznWrCq4mCwLqmsDb6hM80T7V6MkGqmepD6rLwf1cKQXeFLoXUI63Rn2xQE+Ge+8HT1yiCcMmsNQ6GSn66//PXr1dXZ9q1ALf7neBea/FyO7eccWYAKWOYIlxvscUUGMhcpOZa1BhsAUF/zwl20Nzq3LWINyxanIOm0VpsGSg1UqBCTHU/A1QFbNP353C59V2+9qiO306CWTGrA6nW9DBp+b1SnWoAgylTpSP65bBAmRRxVRQ35M1vVgemdmFLtNUc48a4Lv4JgD5XKYU6SzRGdP4nwBbcrX0h/FzupxNT8pi9DqQ4SttPlB1ZwFrAiWTiVC1pMCm4UCtUD/nkRd2IfNPqPwQ== X-Bogosity: Ham, tests=bogofilter, spamicity=0.000000, version=1.2.4 Sender: owner-linux-mm@kvack.org Precedence: bulk X-Loop: owner-majordomo@kvack.org List-ID: On Thu, Jul 13, 2023 at 4:25=E2=80=AFPM Ivan Babrou w= rote: > > My understanding of mem-stat and cpu-stat is that they are independent > > of each other. In theory, reading one shouldn't affect the performance > > of reading the others. Since you are doing mem-stat and cpu-stat readin= g > > repetitively in a loop, it is likely that all the data are in the cache > > most of the time resulting in very fast processing time. If it happens > > that the specific memory location of mem-stat and cpu-stat data are suc= h > > that reading one will cause the other data to be flushed out of the > > cache and have to be re-read from memory again, you could see > > significant performance regression. > > > > It is one of the possible causes, but I may be wrong. > > Do you think it's somewhat similar to how iterating a matrix in rows > is faster than in columns due to sequential vs random memory reads? > > * https://stackoverflow.com/q/9936132 > * https://en.wikipedia.org/wiki/Row-_and_column-major_order > * https://en.wikipedia.org/wiki/Loop_interchange > > I've had a similar suspicion and it would be good to confirm whether > it's that or something else. I can probably collect perf counters for > different runs, but I'm not sure which ones I'll need. > > In a similar vein, if we could come up with a tracepoint that would > tell us the amount of work done (or any other relevant metric that > would help) during rstat flushing, I can certainly collect that > information as well for every reading combination. Since cgroup_rstat_flush_locked appears in flamegraphs for both fast (discrete) and slow (combined) cases, I grabbed some stats for it: * Slow: completed: 19.43s [manual / mem-stat + cpu-stat] $ sudo /usr/share/bcc/tools/funclatency -uT cgroup_rstat_flush_locked Tracing 1 functions for "cgroup_rstat_flush_locked"... Hit Ctrl-C to end. ^C 00:12:55 usecs : count distribution 0 -> 1 : 0 | = | 2 -> 3 : 0 | = | 4 -> 7 : 0 | = | 8 -> 15 : 0 | = | 16 -> 31 : 0 | = | 32 -> 63 : 0 | = | 64 -> 127 : 1 | = | 128 -> 255 : 191 |************ = | 256 -> 511 : 590 |**************************************= **| 512 -> 1023 : 186 |************ = | 1024 -> 2047 : 2 | = | 2048 -> 4095 : 0 | = | 4096 -> 8191 : 0 | = | 8192 -> 16383 : 504 |********************************** = | 16384 -> 32767 : 514 |********************************** = | 32768 -> 65535 : 3 | = | 65536 -> 131071 : 1 | = | avg =3D 8852 usecs, total: 17633268 usecs, count: 1992 * Fast: completed: 0.95s [manual / mem-stat] completed: 0.05s [manual / cpu-stat] $ sudo /usr/share/bcc/tools/funclatency -uT cgroup_rstat_flush_locked Tracing 1 functions for "cgroup_rstat_flush_locked"... Hit Ctrl-C to end. ^C 00:13:27 usecs : count distribution 0 -> 1 : 0 | = | 2 -> 3 : 0 | = | 4 -> 7 : 499 |**************************************= **| 8 -> 15 : 253 |******************** = | 16 -> 31 : 191 |*************** = | 32 -> 63 : 41 |*** = | 64 -> 127 : 12 | = | 128 -> 255 : 2 | = | 256 -> 511 : 2 | = | 512 -> 1023 : 0 | = | 1024 -> 2047 : 0 | = | 2048 -> 4095 : 0 | = | 4096 -> 8191 : 0 | = | 8192 -> 16383 : 34 |** = | 16384 -> 32767 : 21 |* = | avg =3D 857 usecs, total: 904762 usecs, count: 1055 There's a different number of calls into cgroup_rstat_flush_locked and they are much slower in the slow case. There are also two bands in the slow case, with 8ms..32ms having the half of the calls. For mem_cgroup_css_rstat_flush: * Slow: completed: 32.77s [manual / mem-stat + cpu-stat] $ sudo /usr/share/bcc/tools/funclatency -uT mem_cgroup_css_rstat_flush Tracing 1 functions for "mem_cgroup_css_rstat_flush"... Hit Ctrl-C to end. ^C 00:21:25 usecs : count distribution 0 -> 1 : 93078 |* = | 2 -> 3 : 3397714 |**************************************= **| 4 -> 7 : 1009440 |*********** = | 8 -> 15 : 168013 |* = | 16 -> 31 : 93 | = | avg =3D 3 usecs, total: 17189289 usecs, count: 4668338 * Fast: completed: 0.16s [manual / mem-stat] completed: 0.04s [manual / cpu-stat] $ sudo /usr/share/bcc/tools/funclatency -uT mem_cgroup_css_rstat_flush Tracing 1 functions for "mem_cgroup_css_rstat_flush"... Hit Ctrl-C to end. ^C 00:21:57 usecs : count distribution 0 -> 1 : 1441 |*** = | 2 -> 3 : 18780 |**************************************= **| 4 -> 7 : 4826 |********** = | 8 -> 15 : 732 |* = | 16 -> 31 : 1 | = | avg =3D 3 usecs, total: 89174 usecs, count: 25780 There's an 181x difference in the number of calls into mem_cgroup_css_rstat_flush. Does this provide a clue? Perhaps cgroup_rstat_cpu_pop_updated is yielding a ton more iterations for some reason here? * https://elixir.bootlin.com/linux/v6.1/source/kernel/cgroup/rstat.c#L196 It's inlined, but I can place a probe into the loop: 7 for_each_possible_cpu(cpu) { 8 raw_spinlock_t *cpu_lock =3D per_cpu_ptr(&cgroup_rstat_cpu_lock, cpu); 10 struct cgroup *pos =3D NULL; unsigned long flags; /* * The _irqsave() is needed because cgroup_rstat_lo= ck is * spinlock_t which is a sleeping lock on PREEMPT_RT. Acquiring * this lock with the _irq() suffix only disables interrupts on * a non-PREEMPT_RT kernel. The raw_spinlock_t below disables * interrupts on both configurations. The _irqsave() ensures * that interrupts are always disabled and later restored. */ raw_spin_lock_irqsave(cpu_lock, flags); while ((pos =3D cgroup_rstat_cpu_pop_updated(pos, cgrp, cpu))) { struct cgroup_subsys_state *css; cgroup_base_stat_flush(pos, cpu); 26 bpf_rstat_flush(pos, cgroup_parent(pos), cp= u); 28 rcu_read_lock(); 29 list_for_each_entry_rcu(css, &pos->rstat_css_list, rstat_css_node) 31 css->ss->css_rstat_flush(css, cpu); 32 rcu_read_unlock(); } 34 raw_spin_unlock_irqrestore(cpu_lock, flags); I added probes on both line 26 and line 31 to catch the middle and inner lo= ops. * Slow: completed: 32.97s [manual / mem-stat + cpu-stat] Performance counter stats for '/tmp/derp': 4,702,570 probe:cgroup_rstat_flush_locked_L26 9,301,436 probe:cgroup_rstat_flush_locked_L31 * Fast: completed: 0.17s [manual / mem-stat] completed: 0.34s [manual / cpu-stat] Performance counter stats for '/tmp/derp': 31,769 probe:cgroup_rstat_flush_locked_L26 62,849 probe:cgroup_rstat_flush_locked_L31 It definitely looks like cgroup_rstat_cpu_pop_updated is yielding a lot more positions. I'm going to sign off for the week, but let me know if I should place any more probes to nail this down.