| Message ID | w4wrcsysno.wl%peter@chubb.wattle.id.au |
|---|---|
| State | New |
| Headers | show |
Am 29.09.2011 04:43, schrieb Peter Chubb: > > This patch was originally written by Bernard Blackham, and modified by > Peter Chubb. > > From 0d755af2f5bef22432da71f2fe0a9dce7d2882cd Mon Sep 17 00:00:00 2001 > From: Bernard Blackham <bernard.blackham@nicta.com.au> > Date: Fri, 24 Jul 2009 13:38:03 +1000 > Subject: Disable line-based log buffering. > > There's no real reason for line-based buffering in log file output. > If block buffering with a decent sized buffer is used, it can speed > qemu up for -d all or -d exec significantly. > > The only thing you lose is that the last up to 4k of log output may be > lost if > qemu crashes. That's the reason why line buffering is needed today. I enable log file output to see what happened last before the crash. It might be possible to use buffered output with a new function qemu_abort() which replaces the existing calls of abort(). This function could call flush() for the log output before aborting. In addition, SIGSEGV needs to be catched, and the signal handler would have to call flush(), too (is that possible in signal handlers?). Speed is not the primary target when somebody runs qemu -d ... Kind regards, Stefan Weil
>>>>> "Stefan" == Stefan Weil <weil@mail.berlios.de> writes: Stefan> Am 29.09.2011 04:43, schrieb Peter Chubb: >> >> This patch was originally written by Bernard Blackham, and modified >> by Peter Chubb. >> >> From 0d755af2f5bef22432da71f2fe0a9dce7d2882cd Mon Sep 17 00:00:00 >> 2001 From: Bernard Blackham <bernard.blackham@nicta.com.au> Date: >> Fri, 24 Jul 2009 13:38:03 +1000 Subject: Disable line-based log >> buffering. >> >> There's no real reason for line-based buffering in log file output. >> If block buffering with a decent sized buffer is used, it can speed >> qemu up for -d all or -d exec significantly. >> >> The only thing you lose is that the last up to 4k of log output may >> be lost if qemu crashes. Stefan> That's the reason why line buffering is needed today. I Stefan> enable log file output to see what happened last before the Stefan> crash. Thanks for this, I didn't think of this use-case. I don't think I've ever seen a qemu crash that wasn't caused by something really obvious. Stefan> It might be possible to use buffered output with a new Stefan> function qemu_abort() which replaces the existing calls of Stefan> abort(). This function could call flush() for the log output Stefan> before aborting. In addition, SIGSEGV needs to be catched, Stefan> and the signal handler would have to call flush(), too (is Stefan> that possible in signal handlers?). abort() already flushes all open streams. So only signals that cause immediate death are a problem: SIGSEGV is the obvious one. If its handler called abort() then that would flush too. abort() is guaranteed by the POSIX spec to be callable from a signal handler. I'll experiment by adding such a handler and see what happens. Do you have a test case that causes a SEGV? Stefan> Speed is not the primary target when somebody runs qemu -d ... It is if it takes hours to reach the problem that causes the abort(). Speeding up by an order of magnitude is worth it. -- Dr Peter Chubb http://www.gelato.unsw.edu.au peterc AT gelato.unsw.edu.au http://www.ertos.nicta.com.au ERTOS within National ICT Australia
On 29 September 2011 06:03, Peter Chubb <peter.chubb@nicta.com.au> wrote: > Stefan> That's the reason why line buffering is needed today. I > Stefan> enable log file output to see what happened last before the > Stefan> crash. > > Thanks for this, I didn't think of this use-case. I don't think I've > ever seen a qemu crash that wasn't caused by something really obvious. You don't need the logging for the obvious ones :-) > abort() already flushes all open streams. So only signals that cause > immediate death are a problem: SIGSEGV is the obvious one. If its > handler called abort() then that would flush too. abort() is > guaranteed by the POSIX spec to be callable from a signal handler. Catching SIGSEGV is likely to interact badly with the signal handling in linux-user mode, I expect. > Stefan> Speed is not the primary target when somebody runs qemu -d ... > > It is if it takes hours to reach the problem that causes > the abort(). Speeding up by an order of magnitude is worth it. One tactic I've found useful in these cases is to run without logging up to nearly the point where things fail, and then do a savevm. Then you can loadvm on a qemu with logging enabled and only look at the section of execution that causes the problem. -- PMM
On Thu, Sep 29, 2011 at 7:57 AM, Peter Maydell <peter.maydell@linaro.org> wrote: > On 29 September 2011 06:03, Peter Chubb <peter.chubb@nicta.com.au> wrote: >> Stefan> That's the reason why line buffering is needed today. I >> Stefan> enable log file output to see what happened last before the >> Stefan> crash. >> >> Thanks for this, I didn't think of this use-case. I don't think I've >> ever seen a qemu crash that wasn't caused by something really obvious. > > You don't need the logging for the obvious ones :-) > >> abort() already flushes all open streams. So only signals that cause >> immediate death are a problem: SIGSEGV is the obvious one. If its >> handler called abort() then that would flush too. abort() is >> guaranteed by the POSIX spec to be callable from a signal handler. > > Catching SIGSEGV is likely to interact badly with the signal > handling in linux-user mode, I expect. > >> Stefan> Speed is not the primary target when somebody runs qemu -d ... >> >> It is if it takes hours to reach the problem that causes >> the abort(). Speeding up by an order of magnitude is worth it. > > One tactic I've found useful in these cases is to run without > logging up to nearly the point where things fail, and then > do a savevm. Then you can loadvm on a qemu with logging enabled > and only look at the section of execution that causes the problem. This sounds like it should be possible to enable and disable logging during run time. The performance could be improved by taking a trace point like approach, where all possible processing is postponed to outside process. Guest and host code disassembly and op printout could be left to postprocessing, the logs should contain only binary data.
Am 29.09.2011 22:11, schrieb Blue Swirl: > On Thu, Sep 29, 2011 at 7:57 AM, Peter Maydell > <peter.maydell@linaro.org> wrote: >> On 29 September 2011 06:03, Peter Chubb <peter.chubb@nicta.com.au> wrote: >>> Stefan> That's the reason why line buffering is needed today. I >>> Stefan> enable log file output to see what happened last before the >>> Stefan> crash. >>> >>> Thanks for this, I didn't think of this use-case. I don't think I've >>> ever seen a qemu crash that wasn't caused by something really obvious. >> >> You don't need the logging for the obvious ones :-) >> >>> abort() already flushes all open streams. So only signals that cause >>> immediate death are a problem: SIGSEGV is the obvious one. If its >>> handler called abort() then that would flush too. abort() is >>> guaranteed by the POSIX spec to be callable from a signal handler. >> >> Catching SIGSEGV is likely to interact badly with the signal >> handling in linux-user mode, I expect. >> >>> Stefan> Speed is not the primary target when somebody runs qemu -d ... >>> >>> It is if it takes hours to reach the problem that causes >>> the abort(). Speeding up by an order of magnitude is worth it. >> >> One tactic I've found useful in these cases is to run without >> logging up to nearly the point where things fail, and then >> do a savevm. Then you can loadvm on a qemu with logging enabled >> and only look at the section of execution that causes the problem. > > This sounds like it should be possible to enable and disable logging > during run time. The QEMU monitor already supports setting the log level via command 'log'. I used this command to examine problems with some user commands running in an emulated Linux. > The performance could be improved by taking a trace point like > approach, where all possible processing is postponed to outside > process. Guest and host code disassembly and op printout could be left > to postprocessing, the logs should contain only binary data.
Index: qemu-working/exec.c =================================================================== --- qemu-working.orig/exec.c 2011-09-29 09:03:35.866233828 +1000 +++ qemu-working/exec.c 2011-09-29 12:40:56.668973550 +1000 @@ -1594,29 +1594,28 @@ void cpu_single_step(CPUState *env, int /* enable or disable low levels log */ void cpu_set_log(int log_flags) { loglevel = log_flags; if (loglevel && !logfile) { logfile = fopen(logfilename, log_append ? "a" : "w"); if (!logfile) { perror(logfilename); _exit(1); } + +/* Don't use line-based buffering: it hurts -d exec */ #if !defined(CONFIG_SOFTMMU) /* must avoid mmap() usage of glibc by setting a buffer "by hand" */ { static char logfile_buf[4096]; - setvbuf(logfile, logfile_buf, _IOLBF, sizeof(logfile_buf)); + setvbuf(logfile, logfile_buf, _IOFBF, sizeof(logfile_buf)); } -#elif !defined(_WIN32) - /* Win32 doesn't support line-buffering and requires size >= 2 */ - setvbuf(logfile, NULL, _IOLBF, 0); #endif log_append = 1; } if (!loglevel && logfile) { fclose(logfile); logfile = NULL; } } void cpu_set_log_filename(const char *filename)