Patchwork Remove line buffering from log file

login
register
mail settings
Submitter Peter Chubb
Date Sept. 29, 2011, 2:43 a.m.
Message ID <w4wrcsysno.wl%peter@chubb.wattle.id.au>
Download mbox | patch
Permalink /patch/116883/
State New
Headers show

Comments

Peter Chubb - Sept. 29, 2011, 2:43 a.m.
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.

Signed-off-by: Peter Chubb <peter.chubb@nicta.com.au>
Signed-off-by: Hans Jang <hsjang@ok-labs.com>
Signed-off-by: Bernard Blackham <bernard.blackham@nicta.com.au>
---
 exec.c |    6 ++++--
 1 files changed, 4 insertions(+), 2 deletions(-)


--
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
Stefan Weil - Sept. 29, 2011, 4:47 a.m.
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
Peter Chubb - Sept. 29, 2011, 5:03 a.m.
>>>>> "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
Peter Maydell - Sept. 29, 2011, 7:57 a.m.
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
Blue Swirl - Sept. 29, 2011, 8:11 p.m.
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.
Stefan Weil - Sept. 29, 2011, 9:26 p.m.
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.

Patch

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)