Re: Expensive memory.stat + cpu.stat reads
From: Ivan Babrou
Date: Fri Jul 14 2023 - 20:36:52 EST
On Thu, Jul 13, 2023 at 4:25 PM Ivan Babrou <ivan@xxxxxxxxxxxxxx> wrote:
> > 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 reading
> > 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 such
> > 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 = 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 = 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 = 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 = 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 =
per_cpu_ptr(&cgroup_rstat_cpu_lock,
cpu);
10 struct cgroup *pos = NULL;
unsigned long flags;
/*
* The _irqsave() is needed because cgroup_rstat_lock 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 =
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), cpu);
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 loops.
* 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.