kscreen daemon race

Tue May 31 12:05:06 UTC 2016

Hey,

I've been looking into the bug 358011, that is:

https://bugs.kde.org/show_bug.cgi?id=358011 dual screen not setup after reboot

This bugreport seems to be a common problem, and it's a good example for 
what's wrong with the screen configuration on startup.

TL;DR: We have a race condition when the kscreen daemon starts. It looks up a 
known config, then applies it and subsequently resaves the config. The same 
happens on config changes, it writes, then re-reads and then re-writes the 
config change.
I've managed to prevent this from happening by adding a timer that avoids 
saving the config as a direct reaction to our own config changes.

So what happens on kded5 startup after loading the kscreen2 module:

- the kscreen config is requested and received
- the kscreen daemon (KD) looks into its config directory for a suitable config 
file
  (a config file is identified by a combined hash of all screen attached, so 
unique per connected set of outputs)
- KD usually finds a config
- KD ignores configChanged events before it starts ...
- a KScreen::SetConfigOperation to apply the "known config"
- SetConfigOperation returns after a while (say 100ms later)
- we re-enable the change monitor
- we receive a configChanged signal
- we save the new config (usually to the existing config file)

I don't think this behavior is desirable. I don't see a reason why the daemon 
should save its config right after applying it. I think this causes more 
problems than we want, since the startup may overwrite the user's config. This 
behavior seems to be desired by the code in KD, it's already blocking 
configChanged signals during the SetOperation (which, to be honest may result 
in nightmarish behavior in any way, so it might be a kludge which aims too 
short).

>From libkscreen perspective, SetConfigOperation::finished cannot guarantee that 
all configChanged signals are already fired and that it's safe to watch for new, 
independent changes now. At least on X11, we simply don't know, and what we 
can do is wait a bit and cross fingers that we're not catching our own noise. 
The changed signal *may* come from a re-request of the edid information, but 
this is a bit hard to track down, and not too useful, anyway, since changed 
Edid may affect a large number of a screen's properties.
In the Wayland backend, that's a different story and we can prevent this 
behavior at an earlier stage, so this timer is "probably not needed" (I 
haven't tested that).

Approaching a fix, I've added a timer that waits a second before it enabled the 
changed signals. (I've also added timestamps to the daemon code to demonstrate 
the timing of events and get a ballpark figure.)

This effectively prevents KD from catching reactions to its own changes and 
does not trigger saving the config file on every login. It still reacts to 
changes from libkscreen, but will avoid re-saving the config a few times. The 
timer may not be the neatest of solutions for this, but it does help narrowing 
down the problem and may be a last resort action. Most importantly, it avoids 
the re-writing of the config on startup and plugging/unplugging a monitor 
effectively.

The 1000ms value is somewhat arbitrary: I can imagine even doing it a lot 
longer, because there's simply no reason to react to changes during the first 
seconds, but that's debatable. 1000ms means that I *hope* things have trickled 
through by then.

Another possible approach would be to delay the SetConfigOperation::finished 
signal only in the xrandr backend. This would be perhaps a bit cleaner, but I 
haven't tried it yet.

Maybe there's yet another solution?

So, gory details and logs I'm basing my theory on...

All this is, at least what I can make up from the following logs of kded5. 
(I've removed the lines irrelevant to my theory.)

This what happens during startup, on the user's machine, and also on my 
laptop.

KScreen::BackendManager::startBackend starting external backend launcher for 
""
KScreenDaemon::configReady "03:06:04.535" Config KScreen::Config(0x1bc2a80) is 
ready
KScreenDaemon::applyConfig Applying config
KScreenDaemon::applyKnownConfig "03:06:04.543" Applying known config 
"3f784869a2c8b2de9beaffcca16265bb"
KScreenDaemon::doApplyConfig "03:06:04.543" doApplyConfig()
KScreen::ConfigMonitor::Private::backendConfigChanged Requesting missing EDID 
for outputs (67)
KScreenDaemon::doApplyConfig(const ConfigPtr&)::<lambda "03:06:04.569" Config 
applied
KScreenDaemon::setMonitorForChanges Monitor for changes:  true
KScreenDaemon::configChanged "03:06:04.572" Change detected
KScreenDaemon::saveCurrentConfig "03:06:04.943" Saving current config to file

This is the startup with a timer:

KScreenDaemon::configReady "03:08:06.194" Config KScreen::Config(0xd9c500) is 
ready
KScreenDaemon::applyConfig Applying config
KScreenDaemon::applyKnownConfig "03:08:06.200" Applying known config 
"3f784869a2c8b2de9beaffcca16265bb"
KScreen::ConfigMonitor::Private::backendConfigChanged Requesting missing EDID 
for outputs (67)
KScreenDaemon::doApplyConfig(const ConfigPtr&)::<lambda "03:08:06.234" Config 
applied, starting timer...
KScreenDaemon::enableChangeMonitor "03:08:07.236" Enabling change monitor
KScreenDaemon::setMonitorForChanges Monitor for changes:  true

KScreen::ConfigMonitor::Private::backendConfigChanged Requesting missing EDID 
for outputs (67, 71)
KScreenDaemon::configChanged "03:06:19.314" Change detected
KScreenDaemon::applyKnownConfig "03:06:19.325" Applying known config 
"f7b6582a1cb38eaf08369c07a3d1f211"
KScreenDaemon::setMonitorForChanges Monitor for changes:  false
KScreenDaemon::doApplyConfig(const ConfigPtr&)::<lambda "03:06:19.504" Config 
applied
KScreenDaemon::setMonitorForChanges Monitor for changes:  true

The problem happens here, we're enabling the change monitor before the config 
change signal makes it through:

KScreen::ConfigMonitor::Private::backendConfigChanged Requesting missing EDID 
for outputs (67, 71)
KScreenDaemon::configChanged "03:06:19.521" Change detected
KScreenDaemon::saveCurrentConfig "03:06:19.837" Saving current config to file

and it even happens again...

KScreenDaemon::configChanged "03:06:20.260" Change detected
KScreenDaemon::saveCurrentConfig "03:06:20.552" Saving current config to file

So we're ending up reacting to our own changes and resaving the config a few 
times over. The problem seems to be that the SetConfigOperation returns finished 
before all configChanged signals have fired. The SetConfigOpertion finishes too 
early, so we're reconnecting the ChangeMonitor too early, and catching our own 
noise -- and reacting to it.

Adding a timer

I've done an experiment adding a timer after the SetConfigOperation::finished 
fires, delaying reconnecting for a second. This is the resulting log:

KScreen::ConfigMonitor::Private::backendConfigChanged Requesting missing EDID 
for outputs (67, 71)
KScreenDaemon::configChanged "03:08:23.579" Change detected
KScreenDaemon::applyKnownConfig "03:08:23.590" Applying known config 
"f7b6582a1cb38eaf08369c07a3d1f211"
KScreenDaemon::setMonitorForChanges Monitor for changes:  false
KScreenDaemon::doApplyConfig(const ConfigPtr&)::<lambda "03:08:23.769" Config 
applied, starting timer...

KScreen::ConfigMonitor::Private::backendConfigChanged Requesting missing EDID 
for outputs (67, 71)
KScreenDaemon::saveCurrentConfig "03:08:23.864" Saving current config to file
KScreen::ConfigMonitor::Private::backendConfigChanged Requesting missing EDID 
for outputs (67, 71)

Again, two changed signals arrive after SetConfigOperation::finished fires, but 
since we're still disconnected delayed by the timer, no subsequent config 
changes arrive.

KScreenDaemon::enableChangeMonitor "03:08:24.770" Enabling change monitor
KScreenDaemon::setMonitorForChanges Monitor for changes:  true

So, that's an improvement, but of course I'm cheating. I've looked into how 
SetConfigOperation works, and I don't think we can sensibly be sure that we're 
not triggering a config changed signal after finishing the operation. X11 is 
just too async, not atomic enough for us to be sure it's really done applying 
the changes.
-- 
sebas

Sebastian Kügler    •    http://vizZzion.org    •    http://www.kde.org