tobi-wan-kenobi / bumblebee-status

bumblebee-status is a modular, theme-able status line generator for the i3 window manager.
https://bumblebee-status.readthedocs.io/en/main/
MIT License
1.2k stars 229 forks source link

excessive CPU usage compared to alternative #891

Closed anarcat closed 1 year ago

anarcat commented 2 years ago

Bug Report

Description

Affected module: unknown, possibly all Version used: 2.1.5+dfsg2-1 (as packaged in Debian)

Bumblebee-status steadily uses between 5 and 10% of available CPU time on my workstation.

How to reproduce

It's hard to describe exactly what leads to that problem. I have a handful of modules here, which are best described by just attaching this config file here.

config.txt

here's what it looks like in btop:

╭─┐¹cpu┌──┐menu┌┐preset *┌─────────────────────────────────────────────────────────────────┐17:55:08┌──────────────────────────────────────────────────────┐BAT▲ 83% ■■■■■■■■■■ ┌┐- 1000ms +┌─╮
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                            ⢠                                               ╭─┐i7-7500U┌───────────┐700 MHz┌╮│
│                                                                                                            ⢸           ⣦⣤⣠⣤⣤     ⡀⡀⡀   ⡄     ⡆⢠            │CPU ■■■■■■■■■■   5% ⣀⣀⣀⣀⣀  43°C││
│                                                                                                            ⢸           ⣿⣿⣿⣿⣿⡆⣼⡄ ⣴⣷⣿⡇⢰⢸⣶⣧⣦⡀  ⢀⣧⢸  ⡀         │C0  ⣀⣀⣀⢀⣀⣀⣀⣀⣀⡀   3% ⣀⣀⣀⣀⣀  42°C││
│                                                                                                            ⢸⣰⣦⣠⣤⣤⣄⣀⣤⣤⣄⣸⣿⣿⣿⣿⣿⣷⣿⣧⣶⣿⣿⣿⣷⣿⣿⣿⣿⣿⣇⣤⣤⣼⣿⣿⣧⣴⣧⣄⣠⣦⣄⣤⣤⣤⣤⣤│C1  ⡀⡀⢀⢀⣀⣀⡀⣀⣀⡀   4% ⣀⣀⣀⣀⣀  42°C││
│                                                                                                            ⢸⠹⠟⠙⠛⠛⠋⠉⠛⠛⠋⢹⣿⣿⣿⣿⣿⡿⣿⡟⠿⣿⣿⣿⡿⣿⣿⣿⣿⣿⡏⠛⠛⢻⣿⣿⡟⠛⡟⠋⠙⠛⠋⠛⠛⠛⠛⠛│C2  ⣀⡀⢀⣀⣀⢀⣀⣀⢀⢀   5% ⣀⣀⣀⣀⣀  42°C││
│                                                                                                            ⢸           ⣿⣿⣿⣿⣿⠃⠹⠁ ⠙⡟⡿⡇⠘⠸⠛⡏⠟   ⠈⡟⢸  ⠁         │C3  ⣀⡀⢀⣀⡀⣀⣀⡀⣀⣀   4% ⣀⣀⣀⣀⣀  42°C││
│                                                                                                            ⢸           ⠃⠁⠈⠈⠁           ⠁     ⠃             │Load AVG:   0.43   1.80   1.10 ││
│                                                                                                            ⠈                                               ╰───────────────────────────────╯│
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│ up 00:06:49                                                                                                                                                                                 │
╰─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╯
╭─┐5243┌┐bumblebee-statu┌─────────────────────────────────────────────┬─┐terminate┌┐kill┌┐signals┌───────────────────────────────────────────────────────────────────────────────────┐hide ↵┌─╮
│6.5%                                                                 │     Status:      Elapsed:        IO/R:         IO/W:        Parent:        User:       Threads:        Nice:          │
│                                                                     │    Sleeping      00:05:52      7.99 MiB      16.0 KiB         sh          anarcat          4             0            │
│C                                                                    │                                                                                                                       │
│P                                                                    │                          Memory: 0.1% ⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤⣤ 22.5 MiB                               │
│U                                                                    │ C                                                                                                                     │
│                                                                     │ M                          /usr/bin/python3 /usr/bin/bumblebee-status --iconset awesome-fonts                         │
│                       ⢀⣠⣤⣤⣤⣠⣧⣤⣤⣠⣤⣤⣠⣤⣠⣤⣤⣤⣀⣤⣦⣧⣠⣦⣤⣠⣦⣤⣤⣠⣤⣤⣦⣤⣤⣤⣤⣤⣠⣠⣆⣤⣄⣤⣤⣤│ D                                                                                                                     │
├─┐⁴proc┌┐f bumble del┌───────────────────────────────────────────────┴───────────────────────────────────────────────────────────────────────────────┐per-core┌┐reverse┌┐tree┌┐< cpu lazy >┌─┤
│    Pid: Program:         Command:                                                                                                                     Threads: User:       MemB       Cpu%  │
│    5243 bumblebee-statu  /usr/bin/python3 /usr/bin/bumblebee-status --iconset awesome-fonts                                                                  4 anarcat      23M ⣀⣀⣀⣀⣀  6.5  │
│    5233 sh               /bin/sh -c bumblebee-status --iconset awesome-fonts                                                                                 1 anarcat     524K ⣀⣀⣀⣀⣀  0.0  │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
│                                                                                                                                                                                             │
╰┘↑ select ↓└┘info ↵└┘terminate└┘kill└┘signals└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘0/2└╯

... well that doesn't look quite alright, so here's a screenshot.

snap-20220621T175547

anyways. point is it's taking up a lot of CPU. right now it has been running about 7 minutes and it used a solid 27 seconds of CPU time which is overall ~6% of the CPU.

an equivalent py3status configuration uses about 1% of the CPU. i just restarted with it, let it ran for 90 seconds, and it used about one second of CPU, which is actually less than a percent of CPU.

update: after over an hour (62m07s), 11 seconds of CPU times were used, that's 0.2% usage. here's a screenshot of that:

snap-20220621T190112

here's the py3status configuration file: config.txt

i haven't made a wattage analysis, but i suspect this would have an equally negative impact on the battery life of my laptop. i certainly felt something was tugging at my battery when i spent a whole afternoon working without AC on sunday... but that's of course more subjective, since the workload there varies quite a bit. i can provide powertop comparisons if that's useful.

tobi-wan-kenobi commented 2 years ago

wow, thanks for the detailed analysis!

I suspect this is to a large part due to the fact that the updates happen once a second. Does the picture change if you set a longer update interval?

I have considered switching to something completely event-based, but that would be a pretty big change for all the modules.

I will try to do some profiling as well (no clue yet how to do that in python)

Thanks!

anarcat commented 2 years ago

On 2022-06-21 23:18:18, tobi-wan-kenobi wrote:

wow, thanks for the detailed analysis!

you're welcome! i figured you desserved it :)

I suspect this is to a large part due to the fact that the updates happen once a second. Does the picture change if you set a longer update interval?

i have not tried tweaking the update intervals other than what you see in the config files. in py3status, in have a global, default 1 second interval. in bumblebee, i tried to tweak a bunch of intervals (battery 1m, CPU 5s, load 1m, time 30s, traffic 5s) to try to resolve the problem, but it mostly didn't have any effect.

I have considered switching to something completely event-based, but that would be a pretty big change for all the modules.

yeah, i'm not sure it's worth it. FWIW, py3status looked at switching to asyncio as well in an eventual v4, but that never really materialized (there's a v4 somewhere, but it's been idle for two years).

I will try to do some profiling as well (no clue yet how to do that in python)

there's a bunch of tools, actually.

this is the builtin one:

https://docs.python.org/3/library/profile.html#module-cProfile

it's generally where I start, and never really looked any further. but if you do, you might want to skip the "i'm going to search on the web" queue and look at those...

this one is a sampling profiler that's pretty popular:

https://github.com/P403n1x87/austin

another similar one:

https://github.com/benfred/py-spy

this one does GPU profiling as well which might be relevant here:

https://github.com/emeryberger/scalene

this one is designed for scientific applications, not sure it's a good match:

https://github.com/pythonspeed/filprofiler

i also stumbled upon this which is a visual profiler:

https://github.com/nvdv/vprof

this is all i got, good luck!

-- Si les triangles avaient un Dieu, ils lui donneraient trois côtés.

tobi-wan-kenobi commented 2 years ago

Thanks a lot for the comprehensive pointers! Fair warning: It might be a while until I am able to produce results, it is quite a busy time...

I promise to do my best, though.

anarcat commented 2 years ago

On 2022-06-22 11:49:08, tobi-wan-kenobi wrote:

Thanks a lot for the comprehensive pointers! Fair warning: It might be a while until I am able to produce results, it is quite a busy time...

I promise to do my best, though.

No rush on my part at all, of course. To be honest, I reverted back to py3status at this point and did this report mostly to keep you informed of why. I'm sorry I won't have much more time to contribute to your otherwise awesome project, and know that I've taken a few of your good ideas back on the other side. ;)

tobi-wan-kenobi commented 2 years ago

Glad to hear I was able to spark some ideas :)

Thanks a lot for the help you provided to this project!

tobi-wan-kenobi commented 2 years ago
    13372    0.118    0.000    0.145    0.000 uuid.py:138(__init__)
    75060    0.118    0.000    0.325    0.000 theme.py:36(merge_replace)
53297/53283    0.133    0.000    0.180    0.000 algorithm.py:4(merge)
       35    0.353    0.010    0.354    0.010 {method 'read' of '_io.TextIOWrapper' objects}
20040/4200    0.364    0.000    1.720    0.000 theme.py:125(get)
      360    0.454    0.001    0.454    0.001 {method 'poll' of 'select.poll' objects}
{"version": 1, "click_events": true}
       30   30.036    1.001   30.036    1.001 {built-in method time.sleep}

Seems that - possibly - polling and themes are culprits. Will investigate that further.

tobi-wan-kenobi commented 2 years ago

No idea where the polling is from, but I can see that the theme is a complex function that is iterated quite frequently.

Unfortunately, that is pretty hard to fix as color info can come from a lot of sources and can change frequently....

I will think about ways to reduce the computational complexity, just to see if it improves the situation.

tobi-wan-kenobi commented 1 year ago

closing this, as CPU utilization is much lower now on my system (1-2%)

the complex theme system is part of thr issue, but hard to rework, the rest, I suspect, came from the pulseaudio module with lots of system calls. Those have a better successor with pulsectl now.