Awesome: High CPU usage

[gunar]

Output of awesome --version:

awesome v4.3 (Too long)
 • Compiled against Lua 5.3.5 (running with Lua 5.3)
 • D-Bus support: ✔
 • execinfo support: ✔
 • xcb-randr version: 1.6
 • LGI version: 0.9.2

How to reproduce the issue:

I am not sure.

Actual result:

Consistent high CPU usage.

Expected result:

I believe CPU usage used to be around 1%, and now it's averaging 8-10%.

[Elv13]

You need to provide your config if you want us to help you. But don't set your hopes too high. If it isn't your config, then it's just that suddenly Awesome has to handle more events (for whatever reason). There was no recent big changes merged that use more CPU (continuously) by default. The last release that took significantly more CPU was v3.5.0 (2012)[1]

[1] and it went back to mostly v3.4 level over the many point releases that followed. Then with v4.0, there was partial redraw and out-of-order optimizations that reduced it further.

[sim590]

I do have had this to. You can take a look at my config.

$ awesome --version
awesome v4.3 (Too long)
 • Compiled against Lua 5.3.3 (running with Lua 5.3)
 • D-Bus support: ✔
 • execinfo support: ✔
 • xcb-randr version: 1.6
 • LGI version: 0.9.2

I highly doubt that my config is responsible though. Also, this is another matter, but I see a high memory usage. Actually, I see the awesome process gaining huge memory amount over and over. Even if I restart it, it doesn't lose its behaviour. I have to kill -9 awesome and the bad behaviour doesn't come back for a while. I have not found a way to reproduce it. Again, I highly doubt that my config could do that... But, we never know...

High Memory usage. This could go up to 2-3GiB.

I see that there are other issues more appropriate for talking about memory so I don't expect to continue talking about it here.

[psychon]

@sim590 Could you try removing all your widgets and see if that makes the high cpu usage go away? From a quick look: The volume widget updates twice per second (timeout = 0.5). Just that should already be noticable in CPU usage. Your MPD widget updates every two seconds (default timeout of 2 in lain).

The memory usage is likely related. There is an issue "out there" where LGI does some complex stuff which leads to Lua's garbage collector running too slowly. Changing the GC settings to be more aggressive should help with that (random, untested example I just came up with: collectgarbage("setstepmul", 2*collectgarbage("setstepmul", 42))).

[psychon]

Another random idea for debugging timers: Add the following to the very beginning of your rc.lua, before anything else. It should print an overview of active timers and from where they were started.

do
    local timer = require("gears.timer")
    local start, stop = timer.start, timer.stop
    local timers = {}
    function timer:start()
        timers[self] = debug.traceback()
        return start(self)
    end
    function timer:stop()
        timers[self] = nil
        return stop(self)
    end
    timer.start_new(1, function()
        print("Active timers:")
        for timer, traceback in pairs(timers) do
            print(timer, timer.timeout, traceback)
        end
        print("End of timers")
    end)
end

Edit: And really adventurous people could try running strace -p $(pidof awesome) -tt -o /tmp/trace.txt for like two seconds, ctrl-c to quit this and then get me /tmp/trace.txt. That could provide some hints to what AwesomeWM is going (but only if this is really due to updating some widgets that read e.g. CPU stats; this is not useful in figuring out which actual Lua code is using CPU cycles).

[sim590]

@sim590 Could you try removing all your widgets and see if that makes the high cpu usage go away? From a quick look: The volume widget updates twice per second (timeout = 0.5). Just that should already be noticable in CPU usage. Your MPD widget updates every two seconds (default timeout of 2 in lain).

I don't feel like these parameters are really out of proportion. Two updates every 1 or 4 seconds doesn't seem insane. I have had these parameters for a while and I wasn't having CPU issues if I recall correctly.

However, I seem to recognize a change in memory usage. When disabling widgets, memory is stable at 1.5% memory usage. Otherwise, when I reactivate MPD or Alsa widget, memory goes up to >3% over time and never goes down (leak). I'm still investigating.

The memory usage is likely related. There is an issue "out there" where LGI does some complex stuff which leads to Lua's garbage collector running too slowly. Changing the GC settings to be more aggressive should help with that (random, untested example I just came up with: collectgarbage("setstepmul", 2*collectgarbage("setstepmul", 42))).

Default value according to documentation is 200 and therefore «means that the collector runs at "twice" the speed of memory allocation.» Shouldn't that be sufficient behaviour?

collectgarbage("setstepmul", 2*collectgarbage("setstepmul", 42))

If I understand this code correctly, this will recover 200 from the first call, then supply value 2*200=400 to the second call. Thefeore, value 42 is kind of random, yeah? I guess that could attenuate the problem without solving it for sure. But wouldn't that make CPU issues worst since more GC cycles per seconds will be done?

EDIT: I have tried it and CPU memory usage goes up to >3% over time and doesn't go back to 1.5% (leak). It may go even higher. I'm continuing to monitor the behaviour.

There is an issue "out there"

Can this issue be followed somewhere for news?

[sim590]

@psychon Should I open another issue? I had another computer with roughly the same config running during a week and I just found out that my 12GiB memory was full of awesome allocated blocks.

[psychon]

I don't feel like these parameters are really out of proportion. Two updates every 1 or 4 seconds doesn't seem insane.

Well, the idea is to figure out what your WM is doing that causes this CPU usage. Whether the CPU usage is sensible can be figured out afterwards. ;-)

But 3% CPU usage with two updates per second just requires the update to take 15 milliseconds (if my math isn't off). That's not that much time either.
According to tests/test-benchmark.lua, a tag switch takes 5 milliseconds here. Creating and drawing a new wibox takes 14 milliseconds. Updating the textclock takes 0.0025 milliseconds.

So... I don't really know where your CPU usage comes from.

I have had these parameters for a while and I wasn't having CPU issues if I recall correctly.

Uhm, okay. What changed that caused this higher CPU usage then? Do you have any ideas?

Default value according to documentation is 200 and therefore «means that the collector runs at "twice" the speed of memory allocation.» Shouldn't that be sufficient behaviour?

Well, https://github.com/awesomeWM/awesome/issues/1490 and https://github.com/pavouk/lgi/issues/157.
LGI has some objects that reference other objects in a way that is invisible to the GC. Thus, some object is garbage collected and then some other objected becomes garbage, but Lua's GC only notices in the next collection cycle. Thanks to the GC pause ("only start next collection cycle after memory usage doubled"), this leads to ever-increasing memory usage.

Thefeore, value 42 is kind of random, yeah?

Yup, the call is just meant to get the current value. That's not possible without setting the value, so it uses 42 here.

There is an issue "out there"

Can this issue be followed somewhere for news?

https://github.com/awesomeWM/awesome/issues/1490 and https://github.com/pavouk/lgi/issues/157

Should I open another issue?

Feel free.

[gunar]

I believe I've found the culprit. It's this widget.

Can you please help me find where the CPU leak is happening?

The timer runs every 0.2s, is that too often? I sure hope not because the only thing it does it (1) call ping then (2) update a textbox widget. I'd expect these things to take less than 10% of CPU :)

It seems the CPU usage of awesome increases over time (hitting a 10% cap?), so it seems there's a CPU leak but I can't find it.

Thoughts?

[psychon]

Thoughts?

Okay, so... I changed the timeout from 0.2 seconds to 0.1 seconds and CPU usage doubled. Running awesomeWM under callgrind for 60 seconds results in "all the time is spent in Lua code". So, time to ask a Lua profiler.

| FILE                                              : FUNCTION                                : LINE                : TIME        : RELATIVE    : CALLED      |
| [C]                                               : __index                                 :   -1                : 22.908      : 87.63%      :    7218     |
| /usr/share/lua/5.3/lgi/component.lua              : __index                                 :  258                : 18.555      : 70.98%      :   76399     |
| /usr/share/lua/5.3/lgi/class.lua                  : inherited_class_element                 :  132                : 18.437      : 70.53%      :   67413     |
| lib/awful/spawn.lua                               : anonymous                               :  584                : 14.508      : 55.50%      :     882     |
| /usr/share/lua/5.3/lgi/override/Gio.lua           : _element                                :  178                : 14.349      : 54.89%      :   67413     |
| /usr/share/lua/5.3/lgi/component.lua              : anonymous                               :  156                : 12.128      : 46.39%      :    5364     |
| [C]                                               : xpcall                                  :   -1                : 11.236      : 42.98%      :    1588     |
| /usr/share/lua/5.3/lgi/component.lua              : anonymous                               :  258                : 10.870      : 41.58%      :    6017     |
| /usr/share/lua/5.3/lgi/override/GObject-Object.lua: inherited_gobject_element               :  232                : 10.705      : 40.95%      :  129002     |
| /usr/share/lua/5.3/lgi/component.lua              : _element                                :  189                : 10.592      : 40.52%      :  222128     |
| lib/gears/timer.lua                               : anonymous                               :   92                : 10.282      : 39.33%      :     297     |
| lib/gears/object.lua                              : anonymous                               :  145                : 10.248      : 39.20%      :     297     |
| lib/network.lua                                   : pingUpdate                              :   28                : 10.159      : 38.87%      :     295     |
| lib/network.lua                                   : func                                    :   58                : 10.152      : 38.84%      :     294     |
| lib/awful/spawn.lua                               : start_read                              :  581                : 9.897       : 37.86%      :     884     |
| lib/awful/spawn.lua                               : read_lines                              :  569                : 9.535       : 36.48%      :     590     |
| /usr/share/lua/5.3/lgi/class.lua                  : inherited_element                       :  132                : 9.402       : 35.97%      :  129002     |
| lib/awful/spawn.lua                               : done                                    :  571                : 8.554       : 32.72%      :     588     |
| /usr/share/lua/5.3/lgi/override/Gio.lua           : _element                                :  189                : 7.001       : 26.78%      :  129002     |
| [C]                                               : rawget                                  :   -1                : 3.605       : 13.79%      :  745492     |
[snip; more stuff follows, but the inclusive relative CPU time decreases more]

I'd say this is a duplicate of https://github.com/pavouk/lgi/issues/128.

[psychon]

Here is a little something that does basically the same thing as the network widget: Spawning some process a lot and reading its output. It gives me between 4% and 5% CPU usage here and doesn't use anything from AwesomeWM.

local lgi = require("lgi")
local GLib = lgi.GLib
local Gio = lgi.Gio

local function do_read(fd)
    local stream
    stream = Gio.UnixInputStream.new(fd, true)
    stream = Gio.DataInputStream.new(stream)
    local start_read, finish_read
    start_read = function()
        stream:read_line_async(GLib.PRIORITY_DEFAULT, nil, finish_read)
    end
    finish_read = function(obj, res)
        local line, length = obj:read_line_finish(res)
        if not line then
            -- End of file; only works with recent-ish LGI (AwesomeWM contains workarounds for older versions)
            obj:close()
            obj:set_buffer_size(0)
            return
        end
        line = tostring(line)
        assert(line == "25")
        start_read()
    end
    start_read()
end

GLib.timeout_add(GLib.PRIORITY_DEFAULT, 100, function()
    local pid, stdin, stdout, stderr = GLib.spawn_async_with_pipes(nil, { "/bin/echo", "25" }, nil, 0, nil)
    do_read(stdin)
    do_read(stdout)
    do_read(stderr)
    return true
end)

GLib.MainLoop.new():run()

The profiler's result looks similar to what profiling AwesomeWM produces.

| TOTAL TIME = 5.783119
| FILE                                              : FUNCTION                                : LINE                : TIME        : RELATIVE    : CALLED      |
| [C]                                               : __index                                 :   -1                : 5.590       : 96.65%      :    1521     |
| /usr/share/lua/5.2/lgi/component.lua              : __index                                 :  258                : 4.542       : 78.54%      :   24288     |
| /usr/share/lua/5.2/lgi/class.lua                  : inherited_class_element                 :  132                : 4.323       : 74.75%      :   65089     |
| timer.lua                                         : anonymous                               :   17                : 4.090       : 70.73%      :     294     |
| /usr/share/lua/5.2/lgi/override/Gio.lua           : _element                                :  178                : 3.589       : 62.05%      :   22292     |
| /usr/share/lua/5.2/lgi/component.lua              : anonymous                               :  156                : 3.328       : 57.54%      :     984     |
| /usr/share/lua/5.2/lgi/override/GObject-Object.lua: inherited_gobject_element               :  232                : 3.114       : 53.84%      :   42797     |
| /usr/share/lua/5.2/lgi/component.lua              : _element                                :  189                : 2.442       : 42.23%      :   71163     |
| /usr/share/lua/5.2/lgi/component.lua              : anonymous                               :  258                : 2.284       : 39.50%      :    1083     |
| /usr/share/lua/5.2/lgi/override/Gio.lua           : _element                                :  189                : 1.952       : 33.76%      :   42797     |
| timer.lua                                         : anonymous                               :   31                : 1.680       : 29.05%      :      99     |
| timer.lua                                         : do_read                                 :    9                : 1.646       : 28.47%      :     297     |
| timer.lua                                         : start_read                              :   14                : 1.562       : 27.01%      :     297     |
| /usr/share/lua/5.2/lgi/override/Gio.lua           : inherited_element                       :  178                : 1.431       : 24.75%      :   42797     |
| [C]                                               : rawget                                  :   -1                : 0.818       : 14.14%      :  234157     |
| [C]                                               : type                                    :   -1                : 0.302       : 5.22%       :   86043     |
| [C]                                               : match                                   :   -1                : 0.240       : 4.15%       :   64740     |
| [C]                                               : sub                                     :   -1                : 0.182       : 3.15%       :   49677     |
| [C]                                               : getmetatable                            :   -1                : 0.092       : 1.59%       :   25376     |
| /usr/share/lua/5.2/lgi/component.lua              : __index                                 :   76                : 0.041       : 0.70%       :    2563     |

[gunar]

That's a solid analysis @psychon, thank you very much.

Unfortunately, as you know, the issue you referenced is 3 years old and there's been no progress since. I guess my only option right now is to increase the update interval and :crossed_fingers: hope CPU stays within a bearable limit.

Thanks again.

[psychon]

@gunar Two things:

1. Does this mean this issue can be closed?
2. I guess that the following version would be more efficient than your code, but I haven't actually checked. Instead of starting a new ping ten times per second, it starts a single ping and keeps it running, parsing only its output. I guess you also want -i 0.2 in the arguments to ping to make it ping more often, but perhaps this idea is helpful?

awful.spawn.with_line_callback({"ping", "1.1.1.1"}, { stdout = function(line)
    local _, offset = line:find("time=")
    if not offset then return end
    time = line:sub(offset + 1):gsub("ms", "")
    print(tonumber(time))
end })

(also, why are you pinging 1.1.1.1? That address is not routed IIRC)

Your speed.sh could also be done in Lua completely without any external processes by just reading /proc/net/dev and parsing it, but I'm too lazy to convert that shell script to Lua right now.

[Elv13]

(also, why are you pinging 1.1.1.1? That address is not routed IIRC)

It's CloudFlare DNS and VPN address. A faster alternative to 8.8.8.8 in many regions.

[McSinyx]

A bit late to the party, but for media player widget, one could write an completely async one thanks to playerctl:

local myplayer = wibox.widget.textbox()
awful.spawn.with_line_callback(
  "playerctl --follow metadata --format ' {{artist}} <{{status}}> {{title}}'",
  {stdout = function (line)
     myplayer:set_text(line:gsub('<Playing>', '>'):gsub('<.+>', '|'))
   end})

For the volume one, if one's widget library support forced update (e.g. Vicious), then the call to change volume by command could be implemented as

local function update_widget(command, widget)
  awful.spawn.easy_async(command, function () vicious.force{widget} end)
end

I hope this helps.

[gunar]

tl;dr check out the final code.

Thank you very much @psychon, your answer pointed me in the right direction.

I needed to make two changes:

1. The {} syntax for the first argument of with_line_callback wasn't working for me—I changed it to a string.
2. The command ping -A sends way more pings than I'm comfortable with, so I've decided to fixate the interval at 0.5s.

- awful.spawn.with_line_callback({"ping", "1.1.1.1"},  { stdout = function(line)
+ awful.spawn.with_line_callback("ping -i .5 8.8.8.8", { stdout = function(line)

1. Also, one important part of tracking latency is being able to quickly inform when the network went down, so I added a watchdog to check just for that—it takes several seconds for a ping to fail.

I'm so happy! Closing this issue now. Thanks all!

PS: 1.1.1.1 sucks over here, I'm back to 8.8.8.8.