logging is slow

[quozl]

Logging to .sugar/default/logs is quite slow; activities that emit more log lines are slower.

The effect is more easily observed on hardware that has a slow path to log storage, such as the XO-1 and XO-1.5. The effect is absent when logs are written to a temporary filesystem.

The effect is most apparent as a variability in the starting time of an activity, such as Terminal or Write. Terminal takes between 2 and 3 seconds to start on XO-1.5 hardware, but roughly one out of four starts takes up to 8 seconds.

The cause of the slowness is the blocking writes to the log, and these are caused by the explicit use of O_SYNC when the log file is opened.

 dev.laptop.org ticket 9924 is where the problem was first reported. A patch that removes O_SYNC is attached to that ticket. Only that patch is proposed.

Reasons to continue using O_SYNC are:

• increase the chances of useful logs being available for post-event diagnosis, especially when a child may force a power fail or reset.

Reasons to avoid using O_SYNC are:

• activity startup time and responsiveness.

Monitoring logs with tail(1) or cat(1) while developing or testing is unaffected.

Reducing log output during normal operation of an activity would also reduce the effect of this symptom.

[sascha_silbe]

As there are good reasons to use O_SYNC in some special cases it would be great to have a way to enable that (another environment variable, flag file, gconf setting, whatever - DON'T tie it to the log level, though).

[quozl]

Do you really thing another environment variable will help? The same can be said for enabling X synchronous though ... there are some classes of debugging where it is important to have it available, and it isn't.

Do you wish to optimise for execution or debugging?

For debugging a reproducible system hang or crash problem in the presence of a technical expert, no such environment variable is required, since the expert would either mount the filesystem -o sync, tail the log through a serial port, or edit the source to add O_SYNC to whatever is needed.

Again, what we lose by taking this patch is the probability of good logs after a once-off event that led up to a system hang or crash, or immediately prior to a forced power down or reboot. The frequency of such problem reports is much lower, in my experience, than reproducible problems.

I can't advise you on how often those logs are needed. You'd be better able to judge that, since you guys watch your bug stream. Looking at the OLPC bug stream, we don't get these sort of problems much at all.

[tomeu]

Replying to quozl:

Do you wish to optimise for execution or debugging?

Cannot SLs leave this decision to downstreams? A gconf property would make that trivial and consistent with other similar customizations.

[quozl]

alternate proposed implementation using gconf

[tomeu]

Patch looks good to me. I'm a bit concerned at gconf making activity startup slower, but as OLPC is the downstream that is most concerned about performance, I would leave it at OLPC's discretion.

We need to add this new key to the defaults file:

 http://git.sugarlabs.org/projects/sugar/repos/mainline/blobs/master/data/sugar.schemas.in

[quozl]

I'm also concerned about performance regression, so I'll try to quantify it.

[quozl]

Adding an import gconf to a program that does not already do this costs an extra 165ms on XO-1.5 hardware.

Adding a gconf key lookup costs 25ms (plus or minus 2ms) extra startup time on XO-1.5 hardware.

These are an unacceptable burden on every activity startup, multiplied by 3 million children.

An alternate implementation uses environment variables. This implementation costs under 2ms on XO-1.5 hardware.

The variable name SUGAR_LOGS_SYNC was chosen to fit the other environment variables already associated with logging. (SUGAR_LOGGER_LEVEL and SUGAR_LOGS_DIR).

[quozl]

alternate proposed implementation using environment variables

[alsroot]

it is pretty annoying to have synced logs, especially in case of performing testing, in fact I have O_SYNC removed in my local sugar

[quozl]

Short patch that removes O_SYNC with no option to enable it for debugging without editing source. Following a discussion between silbe and others on #sugar on 2010-03-08/09

[sascha_silbe]

Patch looks good to me.

[tomeu]

Looks good to me if deployers like it.

[erikos]

r+ for the last patch: 0001-Removes-the-use-of-O_SYNC-on-logs.patch

[erikos]

 http://git.sugarlabs.org/projects/sugar-toolkit/repos/mainline/commits/f8ef93bd2106d24dfb9d20934abc4d0c1e7ce741

James, thanks for the patch and following up on the ticket that thoroughly.

[sayamindu]

Cherry-picked for 0.84