Created attachment 362506 [details]
Occurrence 1: C stack trace

Created attachment 362507 [details]
Occurence 1: JS stack trace

messageTray.js:225:
    store: function() {
        this._settings.set_string('application-id', this.id + '.desktop');

        let apps = this._masterSettings.get_strv('application-children');
        if (apps.indexOf(this._canonicalId) < 0) {
            apps.push(this._canonicalId);
            this._masterSettings.set_strv('application-children', apps);
        }
    },

Created attachment 362508 [details]
Occurence 3: C stack trace

Created attachment 362509 [details]
Occurence 3: JS stack trace

Occurence 2 was much like this one.

Created attachment 362510 [details] [review]
GJS patch to instrument changed signals and break on spurious ones

Notice the calls to hash() - These guarantee that it happens on every login for me. Without them it happens sometimes but not consistently. Usually also continuing quickly after the breakpoint is reached results in less further spurious events.

Another way to reproduce it is to run gnome-shell under valgrind. So many events are emitted that the shell never loads at all, at least when the taskbar shell extension is enabled (https://bugzilla.gnome.org/show_bug.cgi?id=786186)

Created attachment 362511 [details]
Occurence 3: C stack trace

Created attachment 362512 [details]
Occurence 3: C stack trace

Looks like a bug in the dconf backend, since that’s what’s supposed to handle not emitting ::changed signals if a value hasn’t actually changed.

Created attachment 363469 [details]
C stacktrace with dconf debug symbols

OK, thanks for having a look. Here's another stacktrace which includes dconf debug symbols. The JS stacktrace is the same as in comment 2, i.e. the JS is calling Gio.Settings.set_string().

Based on what you've said about it being the responsibility of the dconf backend to not emit changed signals when a value is set to its current value, I understand that in frame #33 it is correct to call g_settings_backend_write from the dconf backend, but in frame #30 it is incorrect to call g_settings_backend_dispatch_signal from gsettings, since the value of the setting did not change.

I'm a bit confused as to why in frame #30, dconf_engine_change_notify is called in the code, but g_settings_backend_dispatch_signal is directly called instead in the stack trace.

More generally, I don't see any code in this stacktrace in dconf which obviously checks whether the value has changed before dispatching the signal. Where is that meant to happen?

(In reply to Daniel Playfair Cal from comment #9)
> …but in frame #30 it is
> incorrect to call g_settings_backend_dispatch_signal from gsettings, since
> the value of the setting did not change.

I think you mean ‘from dconf’; apart from that you are correct, I think.

> I'm a bit confused as to why in frame #30, dconf_engine_change_notify is
> called in the code, but g_settings_backend_dispatch_signal is directly
> called instead in the stack trace.

Compiler optimisations, perhaps. What optimisation level was this code compiled with?

> More generally, I don't see any code in this stacktrace in dconf which
> obviously checks whether the value has changed before dispatching the
> signal. Where is that meant to happen?

dconf_engine_emit_changes() in dconf-engine.c calls dconf_changeset_describe() which returns the size of the changeset. If that’s > 0, some changes have happened.

It would be useful if you could print out the details of the changeset in dconf_engine_emit_changes() from gdb. Stepping through dconf_engine_change_notify() (in dconfsettingsbackend.c) and printing its locals would also be useful.

OK, I will try printing some values to see whats going on. I didn't change the default optimisation level from the arch PKGBUILD, so I guess I will try adding -Og/-O0 to CFLAGS/CPPFLAGS during ./configure and make and see if that clarifies things.

dconf_changeset_describe() just returns the size of the hashtable changeset->table. If there were "changes" in the table where the value of the key was the same as its current value, it looks like these would also be included. This would mean that there must be code earlier that filters out such "changes"?

In gsettingsbackend.c in glib, the documentation for g_settings_backend_changed() reads:

 * The implementation must call this function during any call to
 * g_settings_backend_write(), before the call returns (except in the
 * case that no keys are actually changed and it cares to detect this
 * fact).
...

 * The implementation may call this function at any other time it likes

This makes me wonder whether dconf "cares to detect" whether the new values are different from the old values, and even if it did, whether it is practical to expect that all backends do this in all circumstances, given that it hasn't been part of the contract. There are other circumstances where I get false changed signals from gsettings (i.e. apparently not in response to g_settings_backend_write() calls, e.g. attachment 362512 [details]).

desrt, what’s the intended behaviour of dconf here?

Created attachment 364044 [details] [review]
Check whether a changeset would have any effect before emitting changed signals

I tried printing changeset->table from dconf_engine_emit_changes, and in each case it was a single key/value pair. The occurrences with stacktraces like Occurrence 1 always happen with the same settings, e.g. "application-id" in from messageTray.js.

This patch works for me and seems to successfully eliminate the problem from Occurrence 1 (which occurs when JS code sets the value of a setting to what it already was). The aim of the patch is to check for each key/value in a changeset whether the value to be set is different from the current value in the backend. If this is not the case for all key/value pairs in a changeset, the changeset is treated as though it was empty.

I assume it is correct to pass in engine->pending as read_through to dconf_engine_read, because a changed value in that queue has already arranged for a signal to be emitted, so that is effectively the "current value" that needs to be checked against.


Occurence 3 and similar still happens, albeit less frequently. When Occurence 3 happens, it looks like all of the settings (or at least a large number of them) change at the same time, and like in attachment 362512 [details], dconf doesn't seem to be in the stacktrace.

Created attachment 364049 [details] [review]
Check whether a changeset would have any effect before emitting changed signals

Corrected type of engine param

Created attachment 364081 [details] [review]
Check whether a changeset would have any effect before emitting changed signals

Aaaaaand also corrected the type signature of the declaration.

(I don’t want to ignore your patches, but I don’t think we can proceed any further with this until desrt pops up and explains what the intention with dconf was here. Thanks for your patience!)

(In reply to Daniel Playfair Cal from comment #11)
> This makes me wonder whether dconf "cares to detect" whether the new values
> are different from the old values, and even if it did, whether it is
> practical to expect that all backends do this in all circumstances, given
> that it hasn't been part of the contract. There are other circumstances
> where I get false changed signals from gsettings (i.e. apparently not in
> response to g_settings_backend_write() calls, e.g. attachment 362512 [details]
> [details]).

(In reply to Philip Withnall from comment #12)
> desrt, what’s the intended behaviour of dconf here?

The current behaviour is the intended behaviour.  The "cares to detect" wording is specifically to give backends the option not to have to filter spurious changes.

In general, the advice here has been to application authors: don't make spurious changes if you don't want spurious change signals.

In terms of ignoring a request to write a value to the database, I have to say that I'm not really comfortable with that: the user asked to do a write, so we must do a write.  Consider the (admittedly somewhat contrived) case where there are two simultaneous writers to GSettings, synchronised by some external mechanism to ensure sequence.

Value /x starts out 'false'.

We do two gsettings (or dconf) writes in two separate processes, synchronised to be in sequence:

process 1: set /x to 'true'
--barrier--
process 2: set /x to 'false'.

Clearly, the final result here should be that the value should be 'false' in the end, but with the patch here, it will end up being 'true' because the changes from process #1 will still be in flight, so process #2 will see the value as 'false' and decide not to write the changeset.

So we can't do that.

But this is about change signals.  We can avoid the change signal, even while submitting the write.  I think that would be reasonable, but we'd have to be careful here: the "tags" mechanism ensures that we don't fire an extra change signal again later (since we already did it), but in the case above, we'd want to ensure that we *did* fire the signal later, since it's possible that the value may have actually been observed as being "true" at some point in the middle before the "false" was committed.  This is somewhat more complicated than your patch here...

Note: I think two processes don't even actually have to be the case here.  It's possible to imagine the scenario I describe above with two separate DConfClient projects in one process...

Thanks so much for reviewing, I really appreciate it!


I think I understand the problem with this change - it assumes that the client has an up to date copy of the current database to check the effect of a changeset when in fact the client's copy may not be up to date and so it cannot reliably check the effect a change will have by the time it is written.

If I understand correctly, your alternative suggestion is to patch the service/writer responsible for writing the database (rather than the client/engine) such that when it receives requests to write keys, it only emits change notifications if the value has changed. This does seem like a much cleaner way of solving this problem. I understand this to mean patching dconf_writer_handle_change() and helpers to not emit spurious changes.

With regards to your test scenario, I think that it would work correctly with such a patch. The only way that process 2 could have observed the value as being true before writing it to false is if the change signal caused by process 1's write had reached process 2 before it started its write. In this case, the value in the database would be true, so process 2's write would still trigger a change event. If there were other writes in between by other processes, then change events would have been emitted when/if the value had changed, which would be eventually received by process 2.


Also, I'm trying to understand the impact of such a change on the tag mechanism, but there is one thing that seems wrong with it currently. last_handled is set to the last tag for which the reply to a write was received, so that when the change notification arrives (immediately after the reply) it is ignored, on the basis that the client already emitted a change notification when the write request was sent.

What if the following sequence of events happens (with the existing code), assuming that the starting value is true:
1. processes 1 and 2 both request to write false and true respectively, and each emit the corresponding optimistic change notification locally
2. process 1's request to write false succeeds, and a reply and change notification is sent over D-Bus with the value false
3. process 2 receives this change notification with the value false, and emits it locally.
4. process 2's request to write true succeeds, and a reply and change notification is sent over D-Bus with the value true
5. process 2 receives a reply to its request and updates its last_handled tag to refer to that request
6. process 2 receives the change notification resulting from its request to write true. It does not emit a change notification locally.

Shouldn't process 2 emit a change notification at step 6? its previous observed value was false, since process 1 caused a change in between the request and the response. Therefore the change notification following the response should emit a change notification to indicate that the value has changed back to true.

I don't think this would be different with a patch to dconf-service to not emit spurious changed signals, since in all cases in this example the change requests did result in a change of the value in the database.

Created attachment 365361 [details] [review]
service: filter changesets when performing writes such that changed events are only emitted when new values differ from existing values

This is my attempt to implement your suggestion.

In dconf_writer_real_change(), the changeset being applied is filtered to include only changes that would change the contents of the database. Only these changes are then emitted in dconf_writer_real_end()

Created attachment 365362 [details] [review]
engine: do not emit a local change notification in dconf_engine_change_fast unless the value is different form the current value

This is similar to my previous patch, except that instead of avoiding sending a write to the service, it only avoids emitting the local optimistic change notification. This is still necessary to break the loop where an application changes a value to what it already holds (according to the view of that process) and a change signal is emitted anyway.

This patch does not prevent the change from being sent to the service and applied normally.

bump

Any chance of another review? I'd love to get this fixed...

My patch here also fixes a related problem with similar symptoms: https://bugzilla.gnome.org/show_bug.cgi?id=790640

Created attachment 366937 [details] [review]
dconf service: filter changesets when performing writes such that changed events are only emitted when new values differ from existing values

Update to add tests and fix up spaces before function call parentheses

Created attachment 366938 [details] [review]
dconf engine: do not emit a local change notification in dconf_engine_change_fast unless the value is different form the current value

Updates:
 - Make the tests pass (account for empty databases in dconf_engine_change_fast, and correct inverted logic relating to has_no_effect)
 - Add test for dconf_engine_changeset_has_no_effect
 - Add spaces before function parentheses

To answer my own question, process 2 in my example would never have observed the value being false (as set by process 1), because all reads read through the pending and in flight queues. Process 2's pending or in flight request to write true to the key would ensure that no other value for that key could be observed locally (unless it requested further writes), so it is correct to ignore the resulting Notify signal, assuming it arrives immediately after the reply.

With the latest two patches I've posted, I think that still makes sense.

On the engine side, the optimistic signal is not sent if it would not result in a different observable value from what is currently observable in that process (via dconf_engine_read). It still gets submitted over DBus, goes into the pending and in flight queues, etc, same as before. It is still not possible for the engine process to observe any value other than the latest value that it requested to write, if there is such a value. So I think the tags mechanism still works.

On the service side, Notify signals are not sent over DBus if they did not result in a change to the canonical database. In this case, they could never have resulted in a change in the observed values in any engine processes. The fact that dconf_engine_read() calls dconf_engine_acquire_sources() before reading ensures that it always reads an up to date value.

Unless I've missed something, that means that:

Before and after these patches:
 * In all cases where an engine process might observe a key changing value, a unique changed signal is sent to the client code (possibly after the new value is observed, but eventually).
 * When a write is sent, at most one changed signal is sent as a result in each process


After these patches:
 * When a write is requested but does not result in a different observable value for the engine process requesting the write, a local changed signal is not sent as a result.
 * When a write request is received by the service process but does not result in a change to the database, a Notify signal is not sent as a result, and engine processes will not emit changed signals as a result.

One potential issue I noticed is that with the engine patch, the queues lock is acquired twice during one call of dconf_engine_change_fast() - once in dconf_engine_changeset_has_no_effect()->dconf_engine_read(), and then again in dconf_engine_change_fast() itself. Perhaps I should change it so that the lock is only acquired once. I can imagine in some very unlikely situation, two calls to dconf_engine_change_fast() from different threads might result in the signal being sent only once when it should be sent twice, because a changeset looked like it would have no effect when dconf_engine_changeset_has_no_effect() was called, but in the time between that and when the change was actually pushed to the queues, an entire second write had occurred and the first write to arrive (which is the second write to complete) now does result in a change in the observed value.

By the way, both of these patches are open as merge requests on gitlab: https://gitlab.gnome.org/GNOME/dconf/merge_requests

-- GitLab Migration Automatic Message --

This bug has been migrated to GNOME's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.gnome.org/GNOME/dconf/issues/40.