Log output far too verbose

[Daniel Silverstone]

Currently the acpid log output is far too verbose.

Ideally it would be small enough that we could log it using syslog to daemon.log but since it currently produces ca. 17 lines of log for each battery event in my laptop, said events occurring semi-regularly and producing around 60 to 90 thousand lines of log per day, it would be too much to syslog right now.

There are various ways to make it simpler (E.g. not sending the handler-output log lines if there's no handler output) and we should look into these

[Mark Thomas (mark-ubuntu-efaref)]

This is causing bug 59695 (the infamous laptop-killing bug), or rather, is the actual cause of the drive problem.

On my laptop, ACPID gets a battery event roughly every 15 seconds, each of these produces a write to the log file.

Laptop hard drives seem to be set up for bursty I/O (a reasonably assumption for general laptop usage), so their worst-case scenario is precisely this, a single write every 15 seconds. The laptop parks after 10 seconds of inactivity, then gets woken up about 5 seconds later, and this repeats continuously whenever the laptop is idle.

The simplest fix is to disable ACPID logging by adding "-l /dev/null" to the command line. Ultimately ACPID should be changed to only log errors and infrequent events.

This needs to be communicated upstream - it will happen on any distro that uses ACPID and lets it log its output. I've seen it on Debian, too.

[Christian Vogler (christian-vogler)]

I cannot confirm this on an Asus G1S-A1 laptop (Gutsy, x86-64). /var/log/acpid accumulates less than 3k per week on this model, despite intensive use.

However, I do see bug 59695 regardless.

I think that we have to be careful with pinpointing a single source for the hard drive problems. If it is indeed caused by filesystem and daemon activity, it is far more likely that there is a confluence of causes.

[Mark Thomas (mark-ubuntu-efaref)]

Are you seeing battery events at all in that log? Seems strange that they wouldn't appear.

You are right that it could be any process that's causing the writes, though specifically it has to be something that writes regularly with intervals greater than the hard disk park time. If several processes are writing to the disk then they are likely to interleave and keep the drive unparked constantly. On my Toshiba Libretto L5 and two ThinkPads I have access to it's been ACPID, and the existence of this bug led me to believe it's ACPID for others too.

[Christian Vogler (christian-vogler)]

Yes, I see these in the log, but only if I plug/unplug the AC adapter. There are no regularly scheduled battery events in the log, no matter whether I run the laptop on mains or battery.

[Felix Hagemann (flixh)]

I can confirm the excessive logging on a Samsung X20 running Feisty.
On battery power a battery event gets logged to /var/log/acpid every 30-40s. Disabling the logging with -l /dev/null in /etc/default/acpid gets rid of that.
Please note that for every battery event also /etc/acpi/power.sh is executed, so this might wake up your drive even if you disabled logging.

[Brian Ealdwine (eode)]

This is not what is causing #59695 (recently duped to #17216) for me. I have no problem with excessive log writes from acpid, although there may be some other log that is causing the problem. I verified this tailing acpid while running lm-profiler.

-b

[Mark Thomas (mark-ubuntu-efaref)]

What did lm-profiler claim was touching the hard disk? That's probably the easiest way to work out what's causing the disk to unpark in each case, as it seems that various programs can cause the effect of bug 59695. There should probably be some kind of review of installed services to see what does this sort of thing. Ideally when my laptop is idle, nothing should touch the disk.

Interestingly it's not just Linux. There is a program on my Windows laptop that does the same thing (logs some security rubbish every 20-30 seconds or so), and according to smartmontools its Load_Unload_Cycle is 683863, so there go the theories about Windows having some kind of workaround built in. My employer requires the app to be installed, but then they will pay for the new HD when it fails.

[Brian Ealdwine (eode)]

Partial correction -- It has started logging more often, after unplugging and plugging in the battery, but seems to log mostly around once every 1-2 minutes. However, that doesn't fully account for the writes I get from reiserfs/0 (or 1) every 30 seconds (I.e., I'm still saying that acpid is not the definitive culprit of the above bugs, although it may be a contributor).

[Brian Ealdwine (eode)]

Further correction -- lm-profiler is not reliable for this, as it causes log writes itself. :-/ It does seem that acpid may be the main culprit.

[ubuntu_demon (ubuntu-demon)]

Maybe btrace will show you whether acpid logging is indeed too verbose.

sudo aptitude install blktrace
sudo btrace /dev/sda

When I ran btrace myself I got this : "/sys/kernel/debug does not appear to be a debug filesystem"
That's probably because I have encrypted my disk during the installation (using the alternate cd)

I got this information here :
https://launchpad.net/ubuntu/+bug/17878/comments/31

[ubuntu_demon (ubuntu-demon)]

regarding my previous post about btrace : https://bugs.launchpad.net/ubuntu/+source/acpid/+bug/31512/comments/10

You need to first do this :
sudo mount -t debugfs none_debug /sys/kernel/debug

[ubuntu_demon (ubuntu-demon)]

btrace howto :
http://ubuntuforums.org/showpost.php?p=3722850&postcount=374

[William Gallafent (william-gallaf-deactivatedaccount)]

Toshiba Satellite Pro 4600 notebook produces the following, when running on AC power (and the battery is 100% charged, and has been full for hours):

.....
[Fri Nov 23 23:54:30 2007] received event "battery BAT1 00000080 00000001"
[Fri Nov 23 23:54:30 2007] notifying client 4319[107:115]
[Fri Nov 23 23:54:30 2007] notifying client 5092[0:0]
[Fri Nov 23 23:54:30 2007] completed event "battery BAT1 00000080 00000001"
[Fri Nov 23 23:54:47 2007] received event "battery BAT1 00000080 00000001"
[Fri Nov 23 23:54:47 2007] notifying client 4319[107:115]
[Fri Nov 23 23:54:47 2007] notifying client 5092[0:0]
[Fri Nov 23 23:54:47 2007] completed event "battery BAT1 00000080 00000001"
[Fri Nov 23 23:55:21 2007] received event "battery BAT1 00000080 00000001"
[Fri Nov 23 23:55:21 2007] notifying client 4319[107:115]
[Fri Nov 23 23:55:21 2007] notifying client 5092[0:0]
[Fri Nov 23 23:55:21 2007] completed event "battery BAT1 00000080 00000001"
[Fri Nov 23 23:55:54 2007] received event "battery BAT1 00000080 00000001"
[Fri Nov 23 23:55:54 2007] notifying client 4319[107:115]
[Fri Nov 23 23:55:54 2007] notifying client 5092[0:0]
[Fri Nov 23 23:55:54 2007] completed event "battery BAT1 00000080 00000001"
.....

In conjunction with possibly sub-optimal defaults in other areas (brand new default ubuntu 7.10 server installation, no laptop-mode or anything else unusual), this was causing rapidly increasing load/unload count on the hard drive. Redirecting logging to /dev/null, suggested above as a workaround, possibly coupled with hdparm -B 254 as suggested elsewhere, has reduced the rate of increase of that figure.

I certainly consider that the "advanced configuration and power interface" daemon, of all things, writing to a log file several times each minute, thus preventing power saving operations from taking place, when nothing of any interest is happening, is a bug!

[Mark Thomas (mark-ubuntu-efaref)]

William,

It should work without the hdparm -B 254 workaround. If it doesn't then you have some other program running that is also accessing the disk (suggestions have been thunderbird amongst other things). This is one of those annoying bugs where you have to squash all of them before the problem is fixed. I have managed to do that on my laptop using the acpid workaround - I left it on, idle, overnight, and the load cycle count increased by 1 when the nightly cronjobs kicked in, and then 1 again when I checked the laptop in the morning.

Disabling power-saving operations on the drive is an unsatisfactory workaround imo, as it will reduce battery life, increase general power consumption, and expose the disk to a greater risk of shock damage as the heads are not parked. Maybe someone should put a bounty up for finding and fixing all the idle-writers in Ubuntu.

You are right about there being a cruel irony that, for me at least, acpid with the primary culprit.

[Daniel Hahler (blueyed)]

This bug is quite old (and the comments shifted to offtopic).
acpid 1.0.6 uses syslog logging now (Hardy has 1.0.4) and there's a similar bug report in Debian, which I'll link.

[Arthur Archnix (arthur-archnix)]

What does that mean, "add -l /dev/null" to the command line"? What is the full command to disable acpid logging? I'm getting an event in the log every second, but I can't figure out how to disable it.

sudo acpid -l /dev/null just returns: acpid: can't open /proc/acpi/event: Device or resource busy

[Mark Warriner (warriner)]

To disable acpid logging, edit /etc/default/acpid and add "-l /dev/null" to the end of the OPTIONS string. On my system, the line looks like this with the change:
OPTIONS="-s /var/run/acpid.socket -l /dev/null"

I am running hardy amd64. Once in a while, /var/log/apcid gets so large that it quickly consumes all available disk space, causing a multitude problems. Disabling acpid logging seems to be an effective workaround for this issue as well.

[Greg A (etulfetulf)]

Please can someone confirm if this has been fixed in Intrepid testing? In theory this patch should have been merged from Debian, however it is not specifically mentioned in the package changelog.

[Timo Jyrinki (timo-jyrinki)]

Looks fixed to me.