Reading accelerometer blocks the whole main event loop

We have some Acer Veriton Z4660G and Z4860G AIO desktops which equip with an accelerometer SMO8840. We have traced the codes and found that g_timeout_add (700, poll_orientation, drv_data) registers the poll_orientation callback function. The function will be called each 700ms. However, the function takes 6~7 seconds for the execution which will block the main event loop. And each calling poll_orientation cannot be finished in each period 700 ms.

I add some debug messages as a patch in the attachment which logs into dmesg and chmod 777 /dev/kmsg is needed. iio-sensor-proxy-to-upstream-diff.txt I emulate as the gsd-power to send the dbus method call "ReleaseLight" to iio-sensor-proxy.

ps ax | grep iio; \
date; \
echo "Method call test start" >> /dev/kmsg; \
gdbus call --system --dest net.hadess.SensorProxy --object-path /net/hadess/SensorProxy --method net.hadess.SensorProxy.ReleaseLight; \
echo "Method call test end" >> /dev/kmsg; \
date; \
ps ax | grep iio
  619 ?        Dsl    0:00 /usr/sbin/iio-sensor-proxy
 2434 pts/0    S+     0:00 grep iio
Wed Nov 14 17:26:54 CST 2018
()
Wed Nov 14 17:27:04 CST 2018
  619 ?        Dsl    0:00 /usr/sbin/iio-sensor-proxy
 2845 pts/0    R+     0:00 grep iio

It takes about 10 seconds. We can get more detail timing in the dmesg:

[   91.541552] Method call test start
[   93.193693] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_y_raw contents
[   93.193699] iio-proxy: sysfs_get_int end
[   93.193703] iio-proxy: sysfs_get_int start
[   93.193712] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_z_raw contents
[   95.339109] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_z_raw contents
[   95.339115] iio-proxy: sysfs_get_int end
[   95.339126] iio-proxy: accel_changed_func start
[   95.339132] iio-proxy: accel_changed_func end
[   95.339135] iio-proxy: poll_orientation end
[   95.339147] iio-proxy: poll_orientation start
[   95.339151] iio-proxy: sysfs_get_int start
[   95.339158] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_x_raw contents
[   97.483265] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_x_raw contents
[   97.483272] iio-proxy: sysfs_get_int end
[   97.483276] iio-proxy: sysfs_get_int start
[   97.483288] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_y_raw contents
[   99.628640] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_y_raw contents
[   99.628648] iio-proxy: sysfs_get_int end
[   99.628652] iio-proxy: sysfs_get_int start
[   99.628662] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_z_raw contents
[  101.777200] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_z_raw contents
[  101.777208] iio-proxy: sysfs_get_int end
[  101.777223] iio-proxy: accel_changed_func start
[  101.777230] iio-proxy: accel_changed_func end
[  101.777234] iio-proxy: poll_orientation end
[  101.777245] iio-proxy: handle_method_call start, method_name: ReleaseLight
[  101.777251] iio-proxy: handle_generic_method_call start, method_name: ReleaseLight
[  101.777255] iio-proxy: client_release start
[  101.777351] iio-proxy: handle_generic_method_call end, method_name: ReleaseLight
[  101.777356] iio-proxy: handle_method_call end, method_name: ReleaseLight
[  101.777373] iio-proxy: poll_orientation start
[  101.777377] iio-proxy: sysfs_get_int start
[  101.777387] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_x_raw contents
[  101.778165] Method call test end

dmesg-to-upstream.txt The dbus method call "ReleaseLight" is pended and waiting for poll_orientation finished in main event loop.
poll_orientation will read the 3 axes of the accelerometer by calling sysfs_get_int 3 times. sysfs_get_int takes more than 2 seconds for reading the file each time. So, poll_orientation takes almost 7 seconds for blocking exection.

The IO blocks the single thread main event loop.

When user want to suspend the system, logind will send a dbus signal 'PrepareForSleep' and gsd-power will catch the signal, then do the following things: It is the calling path in gnome-settings-daemon: handle_suspend_actions -> backlight_disable -> iio_proxy_claim_light sends the dbus method call "ReleaseLight" to iio-sensor-proxy. So, here goes to the previous comment.

However, the maxium delay time before sleep is 5000000us -> 5 seconds.

gdbus introspect --system --dest org.freedesktop.login1 --object-path /org/freedesktop/login1

node /org/freedesktop/login1 {
...
  interface org.freedesktop.login1.Manager {
...
    properties:
      readonly t InhibitDelayMaxUSec = 5000000;
  };
...
};

logind.txt 5s is less than 7s. So, the jobs which should be done before suspend will be pended to after system resume. It makes the display turn on (by CPU up) and turn off (the pended jobs which turn off display) again quickly. More than 15 seconds later, the display will be turned on again by the dbus signal "WakeUpScreen".

I placed a comment to dmesg and suspended the system echo "Going to suspend" > /dev/kmsg; systemctl suspend

[  581.209260] Going to suspend
[  581.230850] gsd-power: handle_suspend_actions start
[  581.230859] gsd-power: backlight_disable start
[  581.230864] gsd-power: iio_proxy_claim_light start
[  581.230868] gsd-power: iio_proxy_claim_light g signal disconnect
[  581.230877] gsd-power: iio_proxy_claim_light g dbus proxy call sync
[  582.045229] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_y_raw contents
[  582.045245] iio-proxy: sysfs_get_int end
[  582.045252] iio-proxy: sysfs_get_int start
[  582.045287] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_z_raw contents
[  584.189849] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_z_raw contents
[  584.189855] iio-proxy: sysfs_get_int end
[  584.189866] iio-proxy: accel_changed_func start
[  584.189872] iio-proxy: accel_changed_func end
[  584.189875] iio-proxy: poll_orientation end
[  584.189886] iio-proxy: poll_orientation start
[  584.189890] iio-proxy: sysfs_get_int start
[  584.189898] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_x_raw contents
[  586.333642] iio-proxy: sysfs_get_int going to free /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_x_raw contents
[  586.333648] iio-proxy: sysfs_get_int end
[  586.333651] iio-proxy: sysfs_get_int start
[  586.333660] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_y_raw contents
[  586.407657] PM: suspend entry (deep)
[  586.407659] PM: Syncing filesystems ... done.
...
[  589.354277] CPU1 is up
...
[  591.776963] gsd-power: iio_proxy_claim_light iio proxy changed
[  591.776969] gsd-power: iio_proxy_claim_light end
[  591.776974] gsd-power: backlight_disable gnome screen set dpms mode
[  591.777032] gsd-power: backlight_disable screen device disable
[  591.777047] gsd-power: backlight_disable g command line sync
[  591.778317] gsd-power: backlight_disable end
[  591.778329] gsd-power: handle_suspend_actions middle
[  591.778333] gsd-power: uninhibit_suspend start
[  591.778353] gsd-power: uninhibit_suspend end and removed suspend delay inhibitor
[  591.778357] gsd-power: handle_suspend_actions end
[  591.778435] gsd-power: screensaver_signal_cb with signal ActiveChanged
[  591.778645] gsd-power: backlight_disable start
[  591.778650] gsd-power: iio_proxy_claim_light start
[  591.778654] gsd-power: iio_proxy_claim_light g signal disconnect
[  591.778659] gsd-power: iio_proxy_claim_light g dbus proxy call sync
[  592.724717] r8169 0000:02:00.0 enp2s0f0: link up
[  592.724725] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0f0: link becomes ready
...
[  604.640595] iio-proxy: handle_method_call start, method_name: ReleaseLight
[  604.640601] iio-proxy: handle_generic_method_call start, method_name: ReleaseLight
[  604.640604] iio-proxy: client_release start
[  604.640649] iio-proxy: handle_generic_method_call end, method_name: ReleaseLight
[  604.640653] iio-proxy: handle_method_call end, method_name: ReleaseLight
[  604.640666] iio-proxy: poll_orientation start
[  604.640669] iio-proxy: sysfs_get_int start
[  604.640677] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_x_raw contents
[  604.640964] gsd-power: iio_proxy_claim_light iio proxy changed
[  604.640971] gsd-power: iio_proxy_claim_light end
[  604.640975] gsd-power: backlight_disable gnome screen set dpms mode
[  604.641035] gsd-power: backlight_disable screen device disable
[  604.641046] gsd-power: backlight_disable g command line sync
[  604.642328] gsd-power: backlight_disable end
[  604.642340] gsd-power: idle_set_mode
[  604.646268] gsd-power: handle_screensaver_active ActiveChanged signal: 1
[  604.646339] gsd-power: handle_resume_actions start
[  604.646345] gsd-power: iio_proxy_claim_light start
[  604.646351] gsd-power: iio_proxy_claim_light g dbus proxy call sync
...
[  617.503892] iio-proxy: handle_method_call start, method_name: ClaimLight
[  617.503989] iio-proxy: handle_method_call end, method_name: ClaimLight
[  617.504003] iio-proxy: poll_orientation start
[  617.504006] iio-proxy: sysfs_get_int start
[  617.504014] iio-proxy: sysfs_get_int going to get /sys/devices/pci0000:00/0000:00:15.0/i2c_designware.0/i2c-7/i2c-SMO8840:00/iio:device0/in_accel_x_raw contents
[  617.504365] gsd-power: iio_proxy_claim_light iio proxy changed
[  617.504381] gsd-power: iio_proxy_claim_light end
[  617.766855] gsd-power: handle_resume_actions end
[  617.766934] gsd-power: screensaver_signal_cb with signal WakeUpScreen

dmesg-to-upstream.txt We can see that the jobs which should be done before suspend are pended to after resume in dmesg.

hadess / iio-sensor-proxy

Reading accelerometer blocks the whole main event loop #245