Opened 11 years ago

Closed 11 years ago

Last modified 7 years ago

#1656 closed defect (fixed)

logging is slow

Reported by: quozl Owned by: erikos
Priority: High Milestone:
Component: Sugar Version: 0.84.x
Severity: Unspecified Keywords: r+
Cc: sascha_silbe Distribution/OS: Unspecified
Bug Status: Assigned

Description

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.

Attachments (3)

0001-dev.laptop.org-9924-remove-O_SYNC-on-log-file-open.patch (1.6 KB) - added by quozl 11 years ago.
alternate proposed implementation using gconf
0001-Removes-the-use-of-O_SYNC-unless-an-environment-vari.patch (1.4 KB) - added by quozl 11 years ago.
alternate proposed implementation using environment variables
0001-Removes-the-use-of-O_SYNC-on-logs.patch (1.1 KB) - added by quozl 11 years ago.
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

Download all attachments as: .zip

Change History (21)

comment:1 Changed 11 years ago by 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).

comment:2 Changed 11 years ago by sascha_silbe

  • Cc sascha_silbe added

comment:3 follow-up: Changed 11 years ago by 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.

comment:4 in reply to: ↑ 3 Changed 11 years ago by 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.

Changed 11 years ago by quozl

alternate proposed implementation using gconf

comment:5 Changed 11 years ago by quozl

  • Keywords r? added

comment:6 Changed 11 years ago by tomeu

  • Keywords r! added; r? removed

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

comment:7 Changed 11 years ago by quozl

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

comment:8 Changed 11 years ago by 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).

Changed 11 years ago by quozl

alternate proposed implementation using environment variables

comment:9 Changed 11 years ago by quozl

  • Keywords r? added; r! removed

comment:10 Changed 11 years ago by alsroot

  • Milestone changed from Unspecified by Release Team to 0.88
  • Priority changed from Unspecified by Maintainer to High

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

Changed 11 years ago by 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

comment:11 Changed 11 years ago by sascha_silbe

Patch looks good to me.

comment:12 Changed 11 years ago by tomeu

  • Component changed from sugar to sugar-toolkit
  • Owner changed from tomeu to erikos

Looks good to me if deployers like it.

comment:13 Changed 11 years ago by erikos

  • Keywords r! added; r? removed

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

comment:14 Changed 11 years ago by erikos

  • Keywords r+ added; r! removed

comment:15 Changed 11 years ago by erikos

  • Bug Status changed from Unconfirmed to Assigned
  • Resolution set to fixed
  • Status changed from new to closed

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

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

comment:16 Changed 11 years ago by sayamindu

Cherry-picked for 0.84

comment:17 Changed 7 years ago by dnarvaez

  • Component changed from sugar-toolkit to Sugar

comment:18 Changed 7 years ago by dnarvaez

  • Milestone 0.88 deleted

Milestone 0.88 deleted

Note: See TracTickets for help on using tickets.