#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)
Change History (21)
comment:1 Changed 14 years ago by sascha_silbe
comment:2 Changed 14 years ago by sascha_silbe
- Cc sascha_silbe added
comment:3 follow-up: ↓ 4 Changed 14 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 14 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.
comment:5 Changed 14 years ago by quozl
- Keywords r? added
comment:6 Changed 14 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 14 years ago by quozl
I'm also concerned about performance regression, so I'll try to quantify it.
comment:8 Changed 14 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).
comment:9 Changed 14 years ago by quozl
- Keywords r? added; r! removed
comment:10 Changed 14 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 14 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 14 years ago by sascha_silbe
Patch looks good to me.
comment:12 Changed 14 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 14 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 14 years ago by erikos
- Keywords r+ added; r! removed
comment:15 Changed 14 years ago by erikos
- Bug Status changed from Unconfirmed to Assigned
- Resolution set to fixed
- Status changed from new to closed
James, thanks for the patch and following up on the ticket that thoroughly.
comment:16 Changed 14 years ago by sayamindu
Cherry-picked for 0.84
comment:17 Changed 10 years ago by dnarvaez
- Component changed from sugar-toolkit to Sugar
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).