messages are logged on every input event

[Pat McGowan]

Every key press or mouse movement causes logging like
repowerd[938]: DefaultStateMachine[c2]: handle_user_activity_changing_power_state

On Zesty laptop

This makes debugging cumbersome and is probably not great for battery life

[Alexandros Frantzis (afrantzis)]

Some clarifications: these log messages correspond to activity events as they arrive from USC. They are not sent for every input event, but instead at most once every 0.5s seconds and only if USC gets an input event in that interval.

Now to the concerns:

> This makes debugging cumbersome and

It's true that the log seems somewhat spammed with these messages. However, activity events affect repowerd's state machine fundamentally and we would not be able to debug effectively if we didn't log them.

> is probably not great for battery life

From past measurements, the CPU time used by logging, and thus the effect on power, is negligible. The measurements also make sense from coarse-grained analysis of the processing involved: every time we have an input event the system needs to react to it possibly by compositing and doing other app specific processing. A couple of times per second, if we have input events, we also send an activity event to repowerd, which needs to update its state (inactivity timeouts etc). Logging the activity event is a negligible portion of the overall processing involved.

If we still consider this is an issue we could reduce the maximum rate at which USC sends activity events. For example, we could change from the current 2Hz to 1Hz. The downside is that the accuracy of inactivity timeouts depends on the rate of activity events. With 2Hz we have a maximum error of 0.5s, with 1Hz the maximum error goes up to 1s.

Another related topic is that we currently log to both /var/log/repowerd.log /var/log/syslog. /v/l/syslog logging was added so that we could correlate easily between repowerd events and other system events (e.g. suspending). If we think that the benefit of easy correlation is not worth repowerd "spamming" /v/l/syslog, we could consider logging only to /v/l/repowerd.log.

[Pat McGowan (pat-mcgowan)]

Thanks for the explanation. I think its bad practice to log this way on a production system, maybe just my opinion. Can this be restricted to when a debug option is enabled? Otherwise I am in favor of not spamming syslog.

[Alexandros Frantzis (afrantzis)]

> I think its bad practice to log this way on a production system, maybe just my opinion.
> Can this be restricted to when a debug option is enabled?

We decided to make logging always-on in repowerd based on bad debugging experiences with the old USC/powerd combination. This decision has paid off since it has made it much easier to debug problems in the wild, especially ones that are hard to reproduce. No need to tell the user to enable debugging and then try to reproduce it again... when something goes wrong they can just send us the log file and we will have the full picture of what was going on in repowerd.

As discussed above, the cost of logging is negligible, so, in my opinion, we have much to lose and little to gain by disabling full logging by default. Of course, we can revisit this decision if we find that the cost-benefit scale is starting to tip the other way.

Also note that repowerd logs are log-rotated, so there is no risk of taking up too much disk space.

> Otherwise I am in favor of not spamming syslog.

Sure, I will remove /v/l/syslog output.

[Launchpad Janitor (janitor)]

This bug was fixed in the package repowerd - 2017.03+17.04.20170403-0ubuntu1

---------------
repowerd (2017.03+17.04.20170403-0ubuntu1) zesty; urgency=medium

  * 2017.03 release
    - Fix "Closing the lid does not suspend the device" (LP: #1668596)
    - Fix "messages are logged on every input event" (LP: #1674736)
    - Fix brightness issues when turning on the screen on Fairphone 2
    - Add apport hook

 -- Alexandros Frantzis <email address hidden> Mon, 03 Apr 2017 14:19:32 +0000