On Thu, 27 May 2021 at 09:51, Odin Ugedal <odin@xxxxxxx> wrote: > > Hi, > > Did some quick testing with bpftrace, and it looks like it is > "update_tg_cfs_load" that does this; > > kretfunc:attach_entity_load_avg: cfs_rq: 0xffff8a3e6773e400, > se.load_sum: 0, se.load_avg: 0, se->load.weight: 1048576 diff.sum: 0, > diff.load: 0, new_sum: 0, new_load: 0, period_contrib: 821 > > // quite some time passes > > kretfunc:update_tg_cfs_load: cfs_rq: 0xffff8a3e6773e400, old load_sum > 0, old load_avg: 0, new load_sum: 47876096, new load_avg: 1022 > tg_load_avg_contrib: 0, period_contrib: 82, on_list: 0, throttled: 0/0 > stack: > bpf_prog_a37cf01922e02958_update_tg_cfs_l+504 > bpf_get_stackid_raw_tp+115 > bpf_prog_a37cf01922e02958_update_tg_cfs_l+504 > bpf_trampoline_6442466486_1+144 > update_tg_cfs_load+5 > update_load_avg+450 > enqueue_entity+91 > enqueue_task_fair+134 > move_queued_task+172 > affine_move_task+1282 > __set_cpus_allowed_ptr+317 > update_tasks_cpumask+70 > update_cpumasks_hier+448 > update_cpumask+345 > cpuset_write_resmask+796 > cgroup_file_write+162 > kernfs_fop_write_iter+284 > new_sync_write+345 > vfs_write+511 > ksys_write+103 > do_syscall_64+51 > entry_SYSCALL_64_after_hwframe+68 > > // There might be more stuff happening here > // __update_load_avg_cfs_rq runs way too often to be able to > // trace it without filtering, and didn't look into that. > > kretfunc:update_tg_cfs_load: cfs_rq: 0xffff8a3e6773e400, old load_sum > 48117265, old load_avg: 1025, new load_sum: 0, new load_avg: 2 > tg_load_avg_contrib: 1022, period_contrib: 223, on_list: 1, throttled: > 1/1 stack: > bpf_prog_a37cf01922e02958_update_tg_cfs_l+504 > bpf_get_stackid_raw_tp+115 > bpf_prog_a37cf01922e02958_update_tg_cfs_l+504 > bpf_trampoline_6442466486_1+144 > update_tg_cfs_load+5 > update_load_avg+450 > update_blocked_averages+723 > newidle_balance+533 > pick_next_task_fair+57 > __schedule+376 > schedule+91 > schedule_hrtimeout_range_clock+164 > do_sys_poll+1043 > __x64_sys_poll+179 > do_syscall_64+51 > entry_SYSCALL_64_after_hwframe+68 > > This particular example resulted in a 75/25 share of cpu time for the > two groups. > > From this, it also looks like it doesn't matter if new load_avg is 0 or not > (when new load_sum is 0), since tg_load_avg_contrib will not be properly > removed either way (without this patch). There might be some other precision > > > > I have added a trace in cfs_rq_is_decayed() but I'm not able to > > reproduce a situation where load_sum == 0 but not load_avg even with > > the script in the cover letter > > Hmm, strange. I am able to reproduce on both v5.12 and v5.13. I am running on > a non SMT 4 core CPU (4670k), with CONFIG_HZ=250. Since this is timing > sensitive, > you might need to tweak the timings for either the CFS bw period/quota, or the > time waiting between changing what cpu it runs on. If you have more than 4 cpus, > you can also try to start on CPU 0 and move it through all cores and > then onto CPU n. > Maybe that makes it possible to reproduce. I finally got it this morning with your script and I confirm that the problem of load_sum == 0 but load_avg != 0 comes from update_tg_cfs_load(). Then, it seems that we don't call update_tg_load_avg for this cfs_rq in __update_blocked_fair() because of a recent update while propagating child's load changes. At the end we remove the cfs_rq from the list without updating its contribution. I'm going to prepare a patch to fix this > > Since bpftrace doesn't work properly in v5.13, this particular test was > on v1.12 with cherry-pick of 0258bdfaff5bd13c4d2383150b7097aecd6b6d82 and > the other patch in this patchset. > > testscript.bt: > > kfunc:attach_entity_load_avg {@a_sum[tid] = > args->cfs_rq->avg.load_sum; @a_load[tid] = > args->cfs_rq->avg.load_avg;} > kretfunc:attach_entity_load_avg{printf("%s: cfs_rq: %p, se.load_sum: > %llu, se.load_avg: %llu, se->load.weight: %llu diff.sum: %llu, > diff.load: %llu, new_sum: %llu, new_load: %llu, period_contrib: > %llu\n", probe, args->cfs_rq,args->se->avg.load_sum, > args->se->avg.load_avg, > args->se->load.weight,args->cfs_rq->avg.load_sum - @a_sum[tid], > args->cfs_rq->avg.load_avg - @a_load[tid], args->cfs_rq->avg.load_sum, > args->cfs_rq->avg.load_avg, args->cfs_rq->avg.period_contrib)} > > kfunc:update_tg_cfs_load {@beg_load_avg[tid] = > args->cfs_rq->avg.load_avg; @beg_load_sum[tid] = > args->cfs_rq->avg.load_sum} > kretfunc:update_tg_cfs_load {printf("%s: cfs_rq: %p, old load_sum > %llu, old load_avg: %llu, new load_sum: %llu, new load_avg: %llu > tg_load_avg_contrib: %llu, period_contrib: %llu, on_list: %d, > throttled: %d/%d stack: %s\n",probe, args->cfs_rq, @beg_load_sum[tid], > @beg_load_avg[tid], args->cfs_rq->avg.load_sum, > args->cfs_rq->avg.load_avg, args->cfs_rq->tg_load_avg_contrib, > args->cfs_rq->avg.period_contrib,args->cfs_rq->on_list, > args->cfs_rq->throttled, args->cfs_rq->throttle_count,kstack)} > > Thanks > Odin