[PATCH 1/2] trace-cmd: Fix crash when trace-cmd is executed with args "profile -F sleep 1"

[PATCH 1/2] trace-cmd: Fix crash when trace-cmd is executed with args "profile -F sleep 1"

[Tzvetomir Stoyanov]

A fix for https://bugzilla.kernel.org/show_bug.cgi?id=203411
When trace-cmd is running in "profile" mode, trace files are not generated.
Instead, pipes are used to collect trace data from recorder threads. Some
internal functions, originally designed for working with files, are reused
in pipes use case:
 init_cpu()
 allocate_page()
 get_next_page()
There was an undesired behaviour in those functions, when working with pipes,
which causes the segmentation fault, described in the bug report.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 lib/trace-cmd/trace-input.c | 69 ++++++++++++++++++++++++-------------
 1 file changed, 45 insertions(+), 24 deletions(-)

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index ba20ef1..8d1001a 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -62,6 +62,7 @@ struct cpu_data {
 	struct list_head	page_maps;
 	struct page_map		*page_map;
 	struct page		**pages;
+	int			num_pages;
 	struct tep_record	*next;
 	struct page		*page;
 	struct kbuffer		*kbuf;
@@ -921,34 +922,50 @@ static struct page *allocate_page(struct tracecmd_input *handle,
 	struct cpu_data *cpu_data = &handle->cpu_data[cpu];
 	struct page *page;
 	int index;
+	int ret;
 
 	index = (offset - cpu_data->file_offset) / handle->page_size;
-	if (cpu_data->pages[index]) {
-		cpu_data->pages[index]->ref_count++;
-		return cpu_data->pages[index];
-	}
-
-	page = malloc(sizeof(*page));
-	if (!page)
+	if (index >= cpu_data->num_pages)
 		return NULL;
+	page = cpu_data->pages[index];
+	if (page && !handle->read_page) {
+		page->ref_count++;
+		return page;
+	}
 
-	memset(page, 0, sizeof(*page));
-	page->offset = offset;
-	page->handle = handle;
-	page->cpu = cpu;
+	if (!page) {
+		page = malloc(sizeof(*page));
+		if (!page)
+			return NULL;
 
-	page->map = allocate_page_map(handle, page, cpu, offset);
+		memset(page, 0, sizeof(*page));
+		page->offset = offset;
+		page->handle = handle;
+		page->cpu = cpu;
+	}
 
 	if (!page->map) {
-		free(page);
-		return NULL;
+		page->map = allocate_page_map(handle, page, cpu, offset);
+		if (!page->map) {
+			free(page);
+			return NULL;
+		}
+
+		cpu_data->pages[index] = page;
+		cpu_data->page_cnt++;
+		page->ref_count = 1;
+
+		return page;
 	}
 
-	cpu_data->pages[index] = page;
-	cpu_data->page_cnt++;
-	page->ref_count = 1;
+	if (handle->read_page) {
+		ret = read_page(handle, offset, cpu, page->map);
+		if (ret < 0)
+			return NULL;
+		return page;
+	}
 
-	return page;
+	return NULL;
 }
 
 static void __free_page(struct tracecmd_input *handle, struct page *page)
@@ -960,6 +977,8 @@ static void __free_page(struct tracecmd_input *handle, struct page *page)
 		die("Page ref count is zero!\n");
 
 	page->ref_count--;
+	if (cpu_data->page == page)
+		cpu_data->page = NULL;
 	if (page->ref_count)
 		return;
 
@@ -1125,7 +1144,7 @@ static int get_page(struct tracecmd_input *handle, int cpu,
 
 static int get_next_page(struct tracecmd_input *handle, int cpu)
 {
-	off64_t offset;
+	off64_t offset = 0;
 
 	if (!handle->cpu_data[cpu].page && !handle->use_pipe)
 		return 0;
@@ -1137,7 +1156,8 @@ static int get_next_page(struct tracecmd_input *handle, int cpu)
 		return 0;
 	}
 
-	offset = handle->cpu_data[cpu].offset + handle->page_size;
+	if (!handle->use_pipe)
+		offset = handle->cpu_data[cpu].offset + handle->page_size;
 
 	return get_page(handle, cpu, offset);
 }
@@ -2026,7 +2046,6 @@ tracecmd_read_prev(struct tracecmd_input *handle, struct tep_record *record)
 static int init_cpu(struct tracecmd_input *handle, int cpu)
 {
 	struct cpu_data *cpu_data = &handle->cpu_data[cpu];
-	int num_pages;
 	int i;
 
 	cpu_data->offset = cpu_data->file_offset;
@@ -2040,13 +2059,13 @@ static int init_cpu(struct tracecmd_input *handle, int cpu)
 		return 0;
 	}
 
-	num_pages = (cpu_data->size + handle->page_size - 1) / handle->page_size;
-	cpu_data->pages = calloc(num_pages + 1, sizeof(*cpu_data->pages));
+	cpu_data->num_pages = (cpu_data->size + handle->page_size - 1) / handle->page_size;
+	cpu_data->pages = calloc(cpu_data->num_pages + 1, sizeof(*cpu_data->pages));
 	if (!cpu_data->pages)
 		return -1;
 
 	/* Add stopper */
-	cpu_data->pages[num_pages] = PAGE_STOPPER;
+	cpu_data->pages[cpu_data->num_pages] = PAGE_STOPPER;
 
 	if (handle->use_pipe) {
 		/* Just make a page, it will be nuked later */
@@ -2056,8 +2075,10 @@ static int init_cpu(struct tracecmd_input *handle, int cpu)
 
 		memset(cpu_data->page, 0, sizeof(*cpu_data->page));
 		cpu_data->pages[0] = cpu_data->page;
+		cpu_data->num_pages = 1;
 		cpu_data->page_cnt = 1;
 		cpu_data->page->ref_count = 1;
+		cpu_data->page->cpu = cpu;
 		return 0;
 	}
 
-- 
2.20.1

[PATCH 2/2] trace-cmd: Fix a possible race condition and deadlock in trace-cmd

[Tzvetomir Stoyanov]

When pipes are used for communication between trace-cmd main
thread and per-cpu recorder threads, there is a possible race
condition in stop_threads(), which can cause a deadlock between
the main thread and cpu recorder thread:
   In trace_stream_read(), the select() call can return 0 if threads
   have no data to send. This will force stop_threads() to stop reading
   the thread's pipes and enter a waitpid() loop, to wait for all threads
   to be terminated. However, there is a case when some threads are still
   flushing its data - tracecmd_flush_recording() tries a blocking write()
   to the pipe. A dead lock appears - the cpu thread is blocked in write(),
   as its buffer is full and no one is reading it. The main thread is blocked
   in waitpid(), to wait the same thread to exit.
The deadlock can be (randomly) observed with the command
"trace-cmd profile -p function -F sleep 10"

The proposed fix increases select timeout from 0 to 1 second, to ensure
the threads are flushed its data before going in waitpid() loop.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 tracecmd/trace-record.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 4523128..9aef5c3 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -626,7 +626,7 @@ static void delete_thread_data(void)
 
 static void stop_threads(enum trace_type type)
 {
-	struct timeval tv = { 0, 0 };
+	struct timeval tv = { 1, 0 };
 	int ret;
 	int i;
 
-- 
2.20.1

Re: [PATCH 1/2] trace-cmd: Fix crash when trace-cmd is executed with args "profile -F sleep 1"

[Steven Rostedt]

On Thu,  2 May 2019 15:09:51 +0300
Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:

> A fix for https://bugzilla.kernel.org/show_bug.cgi?id=203411

This should be a tag below.

> When trace-cmd is running in "profile" mode, trace files are not generated.
> Instead, pipes are used to collect trace data from recorder threads. Some
> internal functions, originally designed for working with files, are reused
> in pipes use case:
>  init_cpu()
>  allocate_page()
>  get_next_page()
> There was an undesired behaviour in those functions, when working with pipes,
> which causes the segmentation fault, described in the bug report.

Also, the full description should always be used in the commit log. If
the bugzilla server were to one day disappear, we would lose that
information.

> 

Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=203411

Also, I bisected this down to:

Fixes: 62e82cc6cdc9 ("trace-cmd: Use lookup table instead of link list for pages")

Please add that tag too.

> Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> ---
>  lib/trace-cmd/trace-input.c | 69 ++++++++++++++++++++++++-------------
>  1 file changed, 45 insertions(+), 24 deletions(-)
> 
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index ba20ef1..8d1001a 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -62,6 +62,7 @@ struct cpu_data {
>  	struct list_head	page_maps;
>  	struct page_map		*page_map;
>  	struct page		**pages;
> +	int			num_pages;

This should be placed next to the other "int"s in the structure.
Placing it here will cause a "hole" in the data. As on 64 bit, most
compilers will try to keep the 8 byte words aligned by 8 bytes (not
always, but mostly). An int is 4 bytes, so the compiler will likely pad
the structure with 4 bytes of zeros, creating that "hole".

Also, let's call this: nr_pages

as that is more in sync with what we use for counting objects in
structures (and is a common notation in the Linux kernel).

>  	struct tep_record	*next;
>  	struct page		*page;
>  	struct kbuffer		*kbuf;
> @@ -921,34 +922,50 @@ static struct page *allocate_page(struct tracecmd_input *handle,
>  	struct cpu_data *cpu_data = &handle->cpu_data[cpu];
>  	struct page *page;
>  	int index;
> +	int ret;
>  
>  	index = (offset - cpu_data->file_offset) / handle->page_size;
> -	if (cpu_data->pages[index]) {
> -		cpu_data->pages[index]->ref_count++;
> -		return cpu_data->pages[index];
> -	}
> -
> -	page = malloc(sizeof(*page));
> -	if (!page)
> +	if (index >= cpu_data->num_pages)
>  		return NULL;

I'm not sure if this is correct. Looking at the patch that broke this
we have:

@@ -907,12 +913,12 @@ static struct page *allocate_page(struct tracecmd_input *handle,
 {
        struct cpu_data *cpu_data = &handle->cpu_data[cpu];
        struct page *page;
+       int index;
 
-       list_for_each_entry(page, &cpu_data->pages, list) {
-               if (page->offset == offset) {
-                       page->ref_count++;
-                       return page;
-               }
+       index = (offset - cpu_data->file_offset) / handle->page_size;
+       if (cpu_data->pages[index]) {
+               cpu_data->pages[index]->ref_count++;
+               return cpu_data->pages[index];
        }
 

Which shows to me that we would continue if index didn't match.

So I would like to go back to that broken commit, and see exactly how
the profile code worked before, and make make it work the same way again.

Just making it not crash, doesn't mean that it works.

Thanks!

-- Steve


> +	page = cpu_data->pages[index];
> +	if (page && !handle->read_page) {
> +		page->ref_count++;
> +		return page;
> +	}
>  
> -	memset(page, 0, sizeof(*page));
> -	page->offset = offset;
> -	page->handle = handle;
> -	page->cpu = cpu;
> +	if (!page) {
> +		page = malloc(sizeof(*page));
> +		if (!page)
> +			return NULL;
>  
> -	page->map = allocate_page_map(handle, page, cpu, offset);
> +		memset(page, 0, sizeof(*page));
> +		page->offset = offset;
> +		page->handle = handle;
> +		page->cpu = cpu;
> +	}
>  
>  	if (!page->map) {
> -		free(page);
> -		return NULL;
> +		page->map = allocate_page_map(handle, page, cpu, offset);
> +		if (!page->map) {
> +			free(page);
> +			return NULL;
> +		}
> +
> +		cpu_data->pages[index] = page;
> +		cpu_data->page_cnt++;
> +		page->ref_count = 1;
> +
> +		return page;
>  	}
>  
> -	cpu_data->pages[index] = page;
> -	cpu_data->page_cnt++;
> -	page->ref_count = 1;
> +	if (handle->read_page) {
> +		ret = read_page(handle, offset, cpu, page->map);
> +		if (ret < 0)
> +			return NULL;
> +		return page;
> +	}
>  
> -	return page;
> +	return NULL;
>  }
>  
>  static void __free_page(struct tracecmd_input *handle, struct page *page)
> @@ -960,6 +977,8 @@ static void __free_page(struct tracecmd_input *handle, struct page *page)
>  		die("Page ref count is zero!\n");
>  
>  	page->ref_count--;
> +	if (cpu_data->page == page)
> +		cpu_data->page = NULL;
>  	if (page->ref_count)
>  		return;
>  
> @@ -1125,7 +1144,7 @@ static int get_page(struct tracecmd_input *handle, int cpu,
>  
>  static int get_next_page(struct tracecmd_input *handle, int cpu)
>  {
> -	off64_t offset;
> +	off64_t offset = 0;
>  
>  	if (!handle->cpu_data[cpu].page && !handle->use_pipe)
>  		return 0;
> @@ -1137,7 +1156,8 @@ static int get_next_page(struct tracecmd_input *handle, int cpu)
>  		return 0;
>  	}
>  
> -	offset = handle->cpu_data[cpu].offset + handle->page_size;
> +	if (!handle->use_pipe)
> +		offset = handle->cpu_data[cpu].offset + handle->page_size;
>  
>  	return get_page(handle, cpu, offset);
>  }
> @@ -2026,7 +2046,6 @@ tracecmd_read_prev(struct tracecmd_input *handle, struct tep_record *record)
>  static int init_cpu(struct tracecmd_input *handle, int cpu)
>  {
>  	struct cpu_data *cpu_data = &handle->cpu_data[cpu];
> -	int num_pages;
>  	int i;
>  
>  	cpu_data->offset = cpu_data->file_offset;
> @@ -2040,13 +2059,13 @@ static int init_cpu(struct tracecmd_input *handle, int cpu)
>  		return 0;
>  	}
>  
> -	num_pages = (cpu_data->size + handle->page_size - 1) / handle->page_size;
> -	cpu_data->pages = calloc(num_pages + 1, sizeof(*cpu_data->pages));
> +	cpu_data->num_pages = (cpu_data->size + handle->page_size - 1) / handle->page_size;
> +	cpu_data->pages = calloc(cpu_data->num_pages + 1, sizeof(*cpu_data->pages));
>  	if (!cpu_data->pages)
>  		return -1;
>  
>  	/* Add stopper */
> -	cpu_data->pages[num_pages] = PAGE_STOPPER;
> +	cpu_data->pages[cpu_data->num_pages] = PAGE_STOPPER;
>  
>  	if (handle->use_pipe) {
>  		/* Just make a page, it will be nuked later */
> @@ -2056,8 +2075,10 @@ static int init_cpu(struct tracecmd_input *handle, int cpu)
>  
>  		memset(cpu_data->page, 0, sizeof(*cpu_data->page));
>  		cpu_data->pages[0] = cpu_data->page;
> +		cpu_data->num_pages = 1;
>  		cpu_data->page_cnt = 1;
>  		cpu_data->page->ref_count = 1;
> +		cpu_data->page->cpu = cpu;
>  		return 0;
>  	}
>