ddcutil 2 slow on Acer XB271HU

[reticulatedpines]

Hi, first, thanks for ddcutil, it's a real time saver for me!

A recent system update, probably ddcutil going to v 2, has made an existing scripted command very slow. Previously, this was < 1s, now > 3s. Following some debugging advice in https://github.com/rockowitz/ddcutil/issues/110, I suspect related to dynamic sleep.

Abbreviated output showing some timing info:

$ /usr/bin/ddcutil --stats --bus 3 --sleep-multiplier=0.2 setvcp 10 + 10
Total non sleep system call time:        273 milliseconds
Total sleep call time:                  4398 milliseconds
Elapsed time:                           4722 milliseconds

$ /usr/bin/ddcutil --stats --bus 3 --disable-dynamic-sleep --sleep-multiplier=0.2 setvcp 10 + 10
Total non sleep system call time:        266 milliseconds
Total sleep call time:                   953 milliseconds
Elapsed time:                           1270 milliseconds

$ /usr/bin/ddcutil --stats --bus 3 --disable-dynamic-sleep --noverify --sleep-multiplier=0.2 setvcp 10 + 10
Total non sleep system call time:        267 milliseconds
Total sleep call time:                   953 milliseconds
Elapsed time:                           1271 milliseconds

$ /usr/bin/ddcutil --stats --bus 3 --skip-ddc-checks --sleep-multiplier=0.2 setvcp 10 + 10
Total non sleep system call time:         32 milliseconds
Total sleep call time:                   111 milliseconds
Elapsed time:                            186 milliseconds

$ /usr/bin/ddcutil --stats --bus 3 --skip-ddc-checks setvcp 10 + 10
Total non sleep system call time:         33 milliseconds
Total sleep call time:                   100 milliseconds
Elapsed time:                            176 milliseconds

Changing brightness seems very reliable with any of the above calls, I've not noticed it ever failing. This monitor has dubious DDC support, you must first put it in factory mode with the physical controls. So, don't feel you have to support it! If you'd like to try, please let me know if you want any additional info. If you just want to close this, that's fine by me.

I am an experienced C dev and should be able to do local builds of branches etc, if that's helpful.

[reticulatedpines]

ddcutil --version shows 2.1.4. Distro is Debian Testing.

[rockowitz]

I'm not sure what to make of your data. It certainly suggests there's a problem with dynamic sleep. The sleep time on the first example is approximately 5 times that on the next 2, implying that the first example executed with a sleep-multiplier of 1.0 .

Examples 2 vs 3 shows essentially identical stacks with or without --noverify, which suggests that --noverify has been set implicltly. Is there a ddcutilrc configuration file? what ae its contents?

The full --stats output should show whether I2C retries are affecting performance. Using option --vstats adds stats on dynamic sleep.

If the cause of the excessing elapsed time does not become apparent, please run your examples with --vstats and submit the output.

[reticulatedpines]

There's no ~/ddc, ~/.ddc or ~/.config/ddc* - anywhere else I should check?

Without --skip-ddc-checks there are lots of reported failures and retries, but, it always seems to adjust brightness successfully. With --skip-ddc-checks there are no reported retries, I would guess this might be expected, since it's doing less checking. Again, brightness changes as expected. This feels possibly like the checks themselves are unreliable with my monitor, but the command works first time?

/usr/bin/ddcutil --stats --vstats --bus 3 --skip-ddc-checks --sleep-multiplier=0.2 setvcp 10 + 10 > ddc_log_01.txt
/usr/bin/ddcutil --stats --vstats --bus 3 --sleep-multiplier=0.2 setvcp 10 + 10 > ddc_log_02.txt
/usr/bin/ddcutil --stats --vstats --bus 3 --skip-ddc-checks setvcp 10 + 10 > ddc_log_03.txt
/usr/bin/ddcutil --stats --vstats --bus 3 setvcp 10 + 10 > ddc_log_04.txt

ddc_log_01.txt ddc_log_02.txt ddc_log_03.txt ddc_log_04.txt

[rockowitz]

The normal location for ddcutil config file is $HOME/.config/ddcutil/ddcutilrc.

It's not so much that the checks themselves are seem unreliable with your monitor, its that they entail several DDC/CI operations, and you're using an aggressive sleep-multiplier and your elapsed time is bloated because of all the retries.

Ideally, you want a sleep-multiplier value large enough that there are few retries. Otherwise, the time saved with shortened sleep times is exceeded by that lost to retries.

I suggest that you use options --disable-dynamic sleep --skip-ddc-checks and use the stats output to pick an optimal sleep-multiplier, which I expect will be much closer to 1.0 than .2.

[reticulatedpines]

Thanks - in that case I don't have a ddcutilrc file.

I don't know how to use --stats to determine the optimal multiplier. It's definitely a lot lower than 1 though:

$ /usr/bin/ddcutil --stats --sleep-multiplier=2.0 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           9085 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=1.0 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           6638 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.9 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           6394 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.8 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           6238 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.7 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           5833 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.6 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           5672 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.5 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           5403 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.4 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           5200 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.3 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           4941 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.2 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           4720 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.1 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           4413 milliseconds
$ /usr/bin/ddcutil --stats --sleep-multiplier=0.05 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           4128 milliseconds

$ /usr/bin/ddcutil --stats --disable-dynamic-sleep --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           4898 milliseconds
$ /usr/bin/ddcutil --stats --disable-dynamic-sleep --sleep-multiplier=0.5 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                           2649 milliseconds
$ /usr/bin/ddcutil --stats --disable-dynamic-sleep --sleep-multiplier=0.1 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                            828 milliseconds
$ /usr/bin/ddcutil --stats --disable-dynamic-sleep --sleep-multiplier=0.05 --bus 3 setvcp 10 - 10|grep Elapsed
Elapsed time:                            552 milliseconds

Dynamic sleep makes things much slower. And I consistently see speedup going as low as 0.05, with or without it.