[PATCH] perf record: Delete file if a failure occurs writing the perf data file

[PATCH] perf record: Delete file if a failure occurs writing the perf data file

[David Ahern]

If perf fails to write data to the data file (e.g., ENOSPC error) it fails
with the message:
  failed to write perf data, error: No space left on device

and stops — killing the workload too. The file is an unknown state. Trying
to read it (e.g., perf report) fails with a SIGBUS error.

Fix by deleting the file on a failure.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Stephane Eranian <eranian@google.com>
---
 tools/perf/builtin-record.c | 1 +
 tools/perf/util/data.c      | 5 +++++
 tools/perf/util/data.h      | 1 +
 3 files changed, 7 insertions(+)

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 15280b5e5574..8b8944d8ffea 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -562,6 +562,7 @@ static int __cmd_record(struct perf_record *rec, int argc, const char **argv)
 
 out_delete_session:
 	perf_session__delete(session);
+	perf_data_file__unlink(session->file);
 	return err;
 }
 
diff --git a/tools/perf/util/data.c b/tools/perf/util/data.c
index 7d09faf85cf1..a0315a694fa2 100644
--- a/tools/perf/util/data.c
+++ b/tools/perf/util/data.c
@@ -118,3 +118,8 @@ void perf_data_file__close(struct perf_data_file *file)
 {
 	close(file->fd);
 }
+
+void perf_data_file__unlink(struct perf_data_file *file)
+{
+	unlink(file->path);
+}
diff --git a/tools/perf/util/data.h b/tools/perf/util/data.h
index 8c2df80152a5..f55a04295ab6 100644
--- a/tools/perf/util/data.h
+++ b/tools/perf/util/data.h
@@ -44,5 +44,6 @@ static inline unsigned long perf_data_file__size(struct perf_data_file *file)
 
 int perf_data_file__open(struct perf_data_file *file);
 void perf_data_file__close(struct perf_data_file *file);
+void perf_data_file__unlink(struct perf_data_file *file);
 
 #endif /* __PERF_DATA_H */
-- 
1.8.3.4 (Apple Git-47)

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[Jiri Olsa]

On Fri, Nov 08, 2013 at 09:41:46AM -0700, David Ahern wrote:
> If perf fails to write data to the data file (e.g., ENOSPC error) it fails
> with the message:
>   failed to write perf data, error: No space left on device
> 
> and stops — killing the workload too. The file is an unknown state. Trying
> to read it (e.g., perf report) fails with a SIGBUS error.
> 
> Fix by deleting the file on a failure.

I think that's right thing to do

Acked-by: Jiri Olsa <jolsa@redhat.com>

jirka

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[Ingo Molnar]

* David Ahern <dsahern@gmail.com> wrote:

> If perf fails to write data to the data file (e.g., ENOSPC error) it fails
> with the message:
>   failed to write perf data, error: No space left on device
> 
> and stops — killing the workload too. The file is an unknown state. 
> Trying to read it (e.g., perf report) fails with a SIGBUS error.

Ouch - guys please first investiage that SIGBUS, we should not behave 
unexpectedly on _any_ (read: random) perf.data file contents. The SIGBUS 
likely suggests that the parsing isn't robust enough.

> Fix by deleting the file on a failure.

That only works around the issue - if the same data file is produced by 
some other method (or maliciously) then perf report will still SIGBUS ...

Thanks,

	Ingo

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[David Ahern]

On 11/11/13, 2:37 AM, Ingo Molnar wrote:
>
> * David Ahern <dsahern@gmail.com> wrote:
>
>> If perf fails to write data to the data file (e.g., ENOSPC error) it fails
>> with the message:
>>    failed to write perf data, error: No space left on device
>>
>> and stops — killing the workload too. The file is an unknown state.
>> Trying to read it (e.g., perf report) fails with a SIGBUS error.
>
> Ouch - guys please first investiage that SIGBUS, we should not behave
> unexpectedly on _any_ (read: random) perf.data file contents. The SIGBUS
> likely suggests that the parsing isn't robust enough.

I think we know why the SIGBUS is happening. From 'man mmap':


 From man mmap:
        SIGBUS Attempted access to a portion of the buffer that
        does not correspond  to  the  file (for  example, beyond
        the end of the file, ...


With regards to perf-record, on a write() failure the header is not 
updated. From a recent change we try to proceed even though the data 
size is 0 - parsing the events we can. We finally hit upon an event that 
is only partially in the file (eg., header, but no data for event). 
Trying to read the event data leads to the SIGBUS:

Running perf-report in gdb:

WARNING: The /tmp/mnt/perf.data file's data size field is 0 which is 
unexpected.
Was the 'perf record' command properly terminated?


Program received signal SIGBUS, Bus error.
perf_evsel__parse_sample (evsel=0x94eec0, event=0x7ffff7ed9d80, 
data=0x7fffffffd260)
     at util/evsel.c:1242
1242		u16 max_size = event->header.size;
(gdb) bt
#0  perf_evsel__parse_sample (evsel=0x94eec0, event=0x7ffff7ed9d80, 
data=0x7fffffffd260)
     at util/evsel.c:1242
#1  0x000000000047c9ce in flush_sample_queue (s=0x94e2b0, 
tool=0x7fffffffde80)
     at util/session.c:542
#2  0x000000000047e2d4 in __perf_session__process_events (session=0x94e2b0,
     data_offset=<optimized out>, data_size=<optimized out>, 
file_size=1048576, tool=0x7fffffffde80)
     at util/session.c:1388
#3  0x000000000042993c in __cmd_report (rep=0x7fffffffde80) at 
builtin-report.c:509
#4  cmd_report (argc=0, argv=0x7fffffffe370, prefix=<optimized out>) at 
builtin-report.c:967
#5  0x000000000041b063 in run_builtin (p=0x7cdf28, argc=4, 
argv=0x7fffffffe370) at perf.c:319
#6  0x000000000041a8e3 in handle_internal_command (argv=0x7fffffffe370, 
argc=4) at perf.c:376
#7  run_argv (argv=0x7fffffffe180, argcp=0x7fffffffe18c) at perf.c:420
#8  main (argc=4, argv=0x7fffffffe370) at perf.c:521

>
>> Fix by deleting the file on a failure.
>
> That only works around the issue - if the same data file is produced by
> some other method (or maliciously) then perf report will still SIGBUS ...

We could handle SIGBUS in the analysis commands too. See the suggestion 
I had for handling the output failure using the mmap output option which 
uses lngjmp.

David

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[David Ahern]

Ingo:

On 11/11/13, 7:43 AM, David Ahern wrote:
> On 11/11/13, 2:37 AM, Ingo Molnar wrote:
>>
>> * David Ahern <dsahern@gmail.com> wrote:
>>
>>> If perf fails to write data to the data file (e.g., ENOSPC error) it
>>> fails
>>> with the message:
>>>    failed to write perf data, error: No space left on device
>>>
>>> and stops — killing the workload too. The file is an unknown state.
>>> Trying to read it (e.g., perf report) fails with a SIGBUS error.
>>
>> Ouch - guys please first investiage that SIGBUS, we should not behave
>> unexpectedly on _any_ (read: random) perf.data file contents. The SIGBUS
>> likely suggests that the parsing isn't robust enough.

If you agree with the below summary then any further objections to 
deleting the file on write failure?

David

>
> I think we know why the SIGBUS is happening. From 'man mmap':
>
>
>  From man mmap:
>         SIGBUS Attempted access to a portion of the buffer that
>         does not correspond  to  the  file (for  example, beyond
>         the end of the file, ...
>
>
> With regards to perf-record, on a write() failure the header is not
> updated. From a recent change we try to proceed even though the data
> size is 0 - parsing the events we can. We finally hit upon an event that
> is only partially in the file (eg., header, but no data for event).
> Trying to read the event data leads to the SIGBUS:
>
> Running perf-report in gdb:
>
> WARNING: The /tmp/mnt/perf.data file's data size field is 0 which is
> unexpected.
> Was the 'perf record' command properly terminated?
>
>
> Program received signal SIGBUS, Bus error.
> perf_evsel__parse_sample (evsel=0x94eec0, event=0x7ffff7ed9d80,
> data=0x7fffffffd260)
>      at util/evsel.c:1242
> 1242        u16 max_size = event->header.size;
> (gdb) bt
> #0  perf_evsel__parse_sample (evsel=0x94eec0, event=0x7ffff7ed9d80,
> data=0x7fffffffd260)
>      at util/evsel.c:1242
> #1  0x000000000047c9ce in flush_sample_queue (s=0x94e2b0,
> tool=0x7fffffffde80)
>      at util/session.c:542
> #2  0x000000000047e2d4 in __perf_session__process_events (session=0x94e2b0,
>      data_offset=<optimized out>, data_size=<optimized out>,
> file_size=1048576, tool=0x7fffffffde80)
>      at util/session.c:1388
> #3  0x000000000042993c in __cmd_report (rep=0x7fffffffde80) at
> builtin-report.c:509
> #4  cmd_report (argc=0, argv=0x7fffffffe370, prefix=<optimized out>) at
> builtin-report.c:967
> #5  0x000000000041b063 in run_builtin (p=0x7cdf28, argc=4,
> argv=0x7fffffffe370) at perf.c:319
> #6  0x000000000041a8e3 in handle_internal_command (argv=0x7fffffffe370,
> argc=4) at perf.c:376
> #7  run_argv (argv=0x7fffffffe180, argcp=0x7fffffffe18c) at perf.c:420
> #8  main (argc=4, argv=0x7fffffffe370) at perf.c:521
>
>>
>>> Fix by deleting the file on a failure.
>>
>> That only works around the issue - if the same data file is produced by
>> some other method (or maliciously) then perf report will still SIGBUS ...
>
> We could handle SIGBUS in the analysis commands too. See the suggestion
> I had for handling the output failure using the mmap output option which
> uses lngjmp.
>
> David

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[Peter Zijlstra]

On Tue, Nov 12, 2013 at 07:51:16AM -0700, David Ahern wrote:
> > From man mmap:
> >        SIGBUS Attempted access to a portion of the buffer that
> >        does not correspond  to  the  file (for  example, beyond
> >        the end of the file, ...

SIGBUS is basically the std fail for any fault; there's a ton more
reasons than listed in that manpage.

Failing to dirty a page due to -ENOSPACE is one reason we'll
trigger SIGBUS -- as you already found in that memcpy to mmap() instead
of write() patch.

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[David Ahern]

On 11/12/13, 8:04 AM, Peter Zijlstra wrote:
> On Tue, Nov 12, 2013 at 07:51:16AM -0700, David Ahern wrote:
>>>  From man mmap:
>>>         SIGBUS Attempted access to a portion of the buffer that
>>>         does not correspond  to  the  file (for  example, beyond
>>>         the end of the file, ...
>
> SIGBUS is basically the std fail for any fault; there's a ton more
> reasons than listed in that manpage.
>
> Failing to dirty a page due to -ENOSPACE is one reason we'll
> trigger SIGBUS -- as you already found in that memcpy to mmap() instead
> of write() patch.

Sure. Lots of mmaps flying around, so to make sure we are on the same 
page in this case we are talking about perf-report reading a file via mmap.

If the file creation (be it memcpy to mmap() or write()) has a failure 
due to lack of space, then only a partial event is in the file -- e.g., 
perf-header only. Trying to read the rest of the event leads to 
perf-report terminating due to SIGBUS. How should that condition be handled?

The patch in this thread deletes the file. Another option is to rewind 
the file to the last known good write (ie., length after last successful 
call to write_output).

David

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[Peter Zijlstra]

On Tue, Nov 12, 2013 at 08:25:02AM -0700, David Ahern wrote:
> On 11/12/13, 8:04 AM, Peter Zijlstra wrote:
> >On Tue, Nov 12, 2013 at 07:51:16AM -0700, David Ahern wrote:
> >>> From man mmap:
> >>>        SIGBUS Attempted access to a portion of the buffer that
> >>>        does not correspond  to  the  file (for  example, beyond
> >>>        the end of the file, ...
> >
> >SIGBUS is basically the std fail for any fault; there's a ton more
> >reasons than listed in that manpage.
> >
> >Failing to dirty a page due to -ENOSPACE is one reason we'll
> >trigger SIGBUS -- as you already found in that memcpy to mmap() instead
> >of write() patch.
> 
> Sure. Lots of mmaps flying around, so to make sure we are on the same page
> in this case we are talking about perf-report reading a file via mmap.
> 
> If the file creation (be it memcpy to mmap() or write()) has a failure due
> to lack of space, then only a partial event is in the file -- e.g.,
> perf-header only. Trying to read the rest of the event leads to perf-report
> terminating due to SIGBUS. How should that condition be handled?
> 
> The patch in this thread deletes the file. Another option is to rewind the
> file to the last known good write (ie., length after last successful call to
> write_output).

I'd report a warning and continue with all events that you could read
upto that point.

Re: [PATCH] perf record: Delete file if a failure occurs writing the perf data file

[David Ahern]

[-- Attachment #1: Type: text/plain, Size: 880 bytes --]

On 11/12/13, 8:34 AM, Peter Zijlstra wrote:
> On Tue, Nov 12, 2013 at 08:25:02AM -0700, David Ahern wrote:
>> The patch in this thread deletes the file. Another option is to rewind the
>> file to the last known good write (ie., length after last successful call to
>> write_output).
>
> I'd report a warning and continue with all events that you could read
> upto that point.
>

Coming back to this: the answer to that statement is known. The attached 
patch attempt to rewind to the last good write. Subsequent reads to the 
file fail with:

WARNING: The /tmp/mnt/perf.data file's data size field is 0 which is 
unexpected.
Was the 'perf record' command properly terminated?
reading input file (size expected=3 received=-1)broken or missing trace data
incompatible file format (rerun with -v to learn more)


Given that it would seem deleting the file is the best option.

David

[-- Attachment #2: record-reset-on-fail.patch --]
[-- Type: text/plain, Size: 898 bytes --]

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 65615a8bc25e..309f590cf267 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -99,7 +99,22 @@ static int do_write_output(struct perf_record *rec, void *buf, size_t size)
 
 static int write_output(struct perf_record *rec, void *buf, size_t size)
 {
-	return do_write_output(rec, buf, size);
+	off_t len;
+	int rc;
+
+	/* save current length */
+	len = rec->session->header.data_offset + rec->bytes_written;
+
+	rc = do_write_output(rec, buf, size);
+
+	/* on failure reset file to last known good length */
+	if (rc < 0) {
+		pr_debug("truncating file to last known good write: len %ld\n", len);
+	   	if (ftruncate(rec->file.fd, len) != 0)
+			pr_err("Double failure -- write failed and then ftruncate\n");
+	}
+
+	return rc;
 }
 
 static int process_synthesized_event(struct perf_tool *tool,