Awesome: W: awesome: a_glib_poll:389: Last main loop iteration took 41.883190 seconds! Increasing limit for this warning to that value

Created on 20 Jan 2017 · 8Comments · Source: awesomeWM/awesome

Output of awesome --version:

awesome v4.0 (Harder, Better, Faster, Stronger)
 • Compiled against Lua 5.1.5 (running with Lua 5.1)
 • D-Bus support: ✔
 • execinfo support: ✔
 • RandR 1.5 support: ✔
 • LGI version: 0.9.1

How to reproduce the issue:

Restart awesome using Ctrl + Mod4 + R.

Actual result:

The wm freezes except mouse interaction.

Expected result:

Reload the configuration and not to freeze.

I do not know exactly what is causing this problem. To have an idea of my configuration files you can see them in these links:

https://github.com/muammar/awesome/blob/master/rc.lua
https://github.com/muammar/awesome/blob/master/widgets.lua
https://github.com/muammar/awesome/blob/master/spotify.lua
https://github.com/muammar/awesome/blob/master/autostart.lua

Some lines of my ~/.xsession-errors file:

2017-01-20 17:31:31 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:32 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:33 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:34 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 1
2017-01-20 17:31:35 W: awesome: event_handle_mappingnotify:930: Unexpected MappingNotify of type 2
2017-01-20 17:31:35 E: Failed to load 'printer-symbolic': Failed to open file 'printer-symbolic': No such file or directory
stack traceback:
    /usr/share/awesome/lib/gears/surface.lua:94: in function </usr/share/awesome/lib/gears/surface.lua:86>
    (tail call): ?
    /usr/share/awesome/lib/naughty/core.lua:579: in function 'notify'
    /usr/share/awesome/lib/naughty/dbus.lua:183: in function </usr/share/awesome/lib/naughty/dbus.lua:108>
2017-01-20 17:31:35 E: Failed to load 'printer-symbolic': Failed to open file 'printer-symbolic': No such file or directory
stack traceback:
    /usr/share/awesome/lib/gears/surface.lua:94: in function </usr/share/awesome/lib/gears/surface.lua:86>
    (tail call): ?
    /usr/share/awesome/lib/naughty/core.lua:579: in function 'notify'
    /usr/share/awesome/lib/naughty/dbus.lua:183: in function </usr/share/awesome/lib/naughty/dbus.lua:108>
2017-01-20 17:31:35 W: awesome: a_glib_poll:389: Last main loop iteration took 41.883190 seconds! Increasing limit for this warning to that value.
2017-01-20 17:31:35 E: Failed to load 'printer-symbolic': Failed to open file 'printer-symbolic': No such file or directory
stack traceback:
    /usr/share/awesome/lib/gears/surface.lua:94: in function </usr/share/awesome/lib/gears/surface.lua:86>
    (tail call): ?
    /usr/share/awesome/lib/naughty/core.lua:579: in function 'notify'
    /usr/share/awesome/lib/naughty/dbus.lua:183: in function </usr/share/awesome/lib/naughty/dbus.lua:108>
2017-01-20 17:31:58 E: Failed to load 'printer-symbolic': Failed to open file 'printer-symbolic': No such file or directory
stack traceback:
    /usr/share/awesome/lib/gears/surface.lua:94: in function </usr/share/awesome/lib/gears/surface.lua:86>
    (tail call): ?
    /usr/share/awesome/lib/naughty/core.lua:579: in function 'notify'
    /usr/share/awesome/lib/naughty/dbus.lua:183: in function </usr/share/awesome/lib/naughty/dbus.lua:108>
2017-01-20 17:31:58 E: Failed to load 'printer-symbolic': Failed to open file 'printer-symbolic': No such file or directory
stack traceback:
    /usr/share/awesome/lib/gears/surface.lua:94: in function </usr/share/awesome/lib/gears/surface.lua:86>
    (tail call): ?
    /usr/share/awesome/lib/naughty/core.lua:579: in function 'notify'
    /usr/share/awesome/lib/naughty/dbus.lua:183: in function </usr/share/awesome/lib/naughty/dbus.lua:108>

I would be more than happy to provide more information.

Source

muammar

Most helpful comment

Most likely culpit is the spotify module. You could use something like the following to check if it really is your spotify code that causes this:

Replace

local file = assert(io.popen('bash $HOME/.config/awesome/scripts/sp current-oneline', 'r'))

with

local start = os.time()
local file = assert(io.popen('bash $HOME/.config/awesome/scripts/sp current-oneline', 'r'))
local delay = os.time() - start
if delay > 2 then print("Due to this spotify shell script, awesome froze for about",delay,"seconds")

You could replace your use of io.popen with something like the following:

https://awesomewm.org/doc/api/libraries/awful.spawn.html#easy_async

Even better would be to use the following which does most of what you are trying to do for you: https://awesomewm.org/doc/api/classes/awful.widget.watch.html

psychon on 21 Jan 2017

👍3

All 8 comments

Hello,

You might want to read this https://awesomewm.org/apidoc/libraries/awful.spawn.html .

Tl;dr; Don't use execute, sleep and popen, they are evil and do just that. Those are blocking functions, so they block your WM. If an application (spotify or else) then want to ask question to the WM and the WM is blocked waiting for an answer from spotify, the you create a "deadlock" until one of them timeout.

This is not a bug in Awesome, so I will close this for now. Eventually, we may print a warning when you attempt to use those 3 functions because your issue will happen. An even longer term solution would be to monkeypatch them to sit on top of coroutines and let the mainloop yeild iterations. But this is complicated to implement and confusing for users.

Elv13 on 21 Jan 2017

Most likely culpit is the spotify module. You could use something like the following to check if it really is your spotify code that causes this:

Replace

local file = assert(io.popen('bash $HOME/.config/awesome/scripts/sp current-oneline', 'r'))

with

local start = os.time()
local file = assert(io.popen('bash $HOME/.config/awesome/scripts/sp current-oneline', 'r'))
local delay = os.time() - start
if delay > 2 then print("Due to this spotify shell script, awesome froze for about",delay,"seconds")

You could replace your use of io.popen with something like the following:

https://awesomewm.org/doc/api/libraries/awful.spawn.html#easy_async

Even better would be to use the following which does most of what you are trying to do for you: https://awesomewm.org/doc/api/classes/awful.widget.watch.html

psychon on 21 Jan 2017

👍3

Thank you very much for your replies. I will give it a try.

muammar on 21 Jan 2017

Actually, sorry! My code is wrong. The current time should be checked after file:close() and not right after the popen. The popen should not really be slow, but instead the reading would cause a freeze.

psychon on 21 Jan 2017

@psychon it's fine :). I understood the issue you were trying to demonstrate with your code. Thanks for the widget.watch function. I think it may suit perfectly for what I am doing here.

muammar on 21 Jan 2017

By the way, this kind of issue is exactly why we added that "slow main loop iteration" warning. This might be the first time I see it actually working for what it is intended to do. Nice :-)

psychon on 21 Jan 2017

Cool. By the way, when the problem triggering is persistent, the time is accumulative in the same session, isn't it?.

muammar on 24 Jan 2017

No, it gets updated and reported only if the current iteration took longer than the last one.