From patchwork Wed Jun 5 11:19:36 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Tzvetomir Stoyanov X-Patchwork-Id: 10976667 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 2DE192D47 for ; Wed, 5 Jun 2019 11:19:44 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 1F7B527FA5 for ; Wed, 5 Jun 2019 11:19:44 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 13D5228827; Wed, 5 Jun 2019 11:19:44 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-7.9 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 6433628680 for ; Wed, 5 Jun 2019 11:19:43 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1727070AbfFELTm (ORCPT ); Wed, 5 Jun 2019 07:19:42 -0400 Received: from mail-wr1-f65.google.com ([209.85.221.65]:32993 "EHLO mail-wr1-f65.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727411AbfFELTl (ORCPT ); Wed, 5 Jun 2019 07:19:41 -0400 Received: by mail-wr1-f65.google.com with SMTP id n9so6617046wru.0 for ; Wed, 05 Jun 2019 04:19:39 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:mime-version :content-transfer-encoding; bh=eNQkO71pqQ6id/igKjJctLEZz9nALUDYz5rDmSsDQoI=; b=BIs8fEmqeDetdWSlyv/mQ0r/gi41Jln1pT94lAzdUOrRyfS9iDjt4O2C187uvL4Mx/ 9GIhzirRO68qmXNvuIas+dMgdWoQkNrTxYAFgj5WkIxHfLMSKH2LuGBFsChQcViTQMyT mOUePRLjOurqkGfDL4Nj0D5GfO5GBoFPvj3K80uNZ+vdJRjEvihv+72DeLycHSEPQhM1 KD/8IFd/dzIxRbgzhks03k6FPaIk//KlE259Qh3kBYtXgrEbxurhNUUf3YazYXyiRVhG ybQTmkhfAMmWaJwLf22438ifPS81rmZczpR+GLkLvg412luLcfIHbOtqk8FlBpa+pkV1 n5SQ== X-Gm-Message-State: APjAAAUCUElQZpbKCcSDf1EI+X0aYJns19w7yI3dCeRDyOK3YfoVB5A+ CeNl6Z4/dKlfWRsyZ47OrQOvBVWK X-Google-Smtp-Source: APXvYqwiY/LrKRgltSG2SnPCBSRVghscvTvY1NNn8GxYc/gjEJOAJEAs1cVzR6lLORI/EAqac6gxSQ== X-Received: by 2002:adf:dcd1:: with SMTP id x17mr25210138wrm.98.1559733579046; Wed, 05 Jun 2019 04:19:39 -0700 (PDT) Received: from oberon.eng.vmware.com ([146.247.46.5]) by smtp.gmail.com with ESMTPSA id 16sm15583084wmx.45.2019.06.05.04.19.38 (version=TLS1_3 cipher=AEAD-AES256-GCM-SHA384 bits=256/256); Wed, 05 Jun 2019 04:19:38 -0700 (PDT) From: Tzvetomir Stoyanov To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v2 1/2] trace-cmd: Fix crash when trace-cmd is executed with args "profile -F sleep 1" Date: Wed, 5 Jun 2019 14:19:36 +0300 Message-Id: <20190605111937.17894-1-tstoyanov@vmware.com> X-Mailer: git-send-email 2.21.0 MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP 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 --- lib/trace-cmd/trace-input.c | 45 +++++++++++++++++++++++++++---------- 1 file changed, 33 insertions(+), 12 deletions(-) diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c index ba20ef1..264e3c3 100644 --- a/lib/trace-cmd/trace-input.c +++ b/lib/trace-cmd/trace-input.c @@ -28,8 +28,6 @@ /* for debugging read instead of mmap */ static int force_read = 0; -#define PAGE_STOPPER ((struct page *)-1L) - struct page_map { struct list_head list; off64_t offset; @@ -65,6 +63,7 @@ struct cpu_data { struct tep_record *next; struct page *page; struct kbuffer *kbuf; + int nr_pages; int page_cnt; int cpu; int pipe_fd; @@ -146,16 +145,17 @@ static void add_record(struct page *page, struct tep_record *record) record->prev = NULL; page->records = record; } -static const char *show_records(struct page **pages) +static const char *show_records(struct page **pages, int nr_pages) { static char buf[BUFSIZ + 1]; struct tep_record *record; struct page *page; int len; + int i; memset(buf, 0, sizeof(buf)); len = 0; - for (i = 0; pages[i] != PAGE_STOPPER; i--) { + for (i = 0; i < nr_pages; i++) { page = pages[i]; if (!page) continue; @@ -172,7 +172,7 @@ static const char *show_records(struct page **pages) #else static inline void remove_record(struct page *page, struct tep_record *record) {} static inline void add_record(struct page *page, struct tep_record *record) {} -static const char *show_records(struct page **pages) +static const char *show_records(struct page **pages, int nr_pages) { return ""; } @@ -919,10 +919,20 @@ static struct page *allocate_page(struct tracecmd_input *handle, int cpu, off64_t offset) { struct cpu_data *cpu_data = &handle->cpu_data[cpu]; + struct page **pages; struct page *page; int index; index = (offset - cpu_data->file_offset) / handle->page_size; + if (index >= cpu_data->nr_pages) { + pages = realloc(cpu_data->pages, (index + 1) * sizeof(*cpu_data->pages)); + if (!pages) + return NULL; + memset(pages + cpu_data->nr_pages, 0, + (index + 1 - cpu_data->nr_pages) * sizeof(*cpu_data->pages)); + cpu_data->pages = pages; + cpu_data->nr_pages = index + 1; + } if (cpu_data->pages[index]) { cpu_data->pages[index]->ref_count++; return cpu_data->pages[index]; @@ -954,6 +964,7 @@ static struct page *allocate_page(struct tracecmd_input *handle, static void __free_page(struct tracecmd_input *handle, struct page *page) { struct cpu_data *cpu_data = &handle->cpu_data[page->cpu]; + struct page **pages; int index; if (!page->ref_count) @@ -973,6 +984,17 @@ static void __free_page(struct tracecmd_input *handle, struct page *page) cpu_data->page_cnt--; free(page); + + for (index = cpu_data->nr_pages - 1; index > 0; index--) + if (cpu_data->pages[index]) + break; + if (index < (cpu_data->nr_pages - 1)) { + pages = realloc(cpu_data->pages, (index + 1) * sizeof(*cpu_data->pages)); + if (!pages) + return; + cpu_data->pages = pages; + cpu_data->nr_pages = index + 1; + } } static void free_page(struct tracecmd_input *handle, int cpu) @@ -2026,7 +2048,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,14 +2061,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->nr_pages = (cpu_data->size + handle->page_size - 1) / handle->page_size; + if (!cpu_data->nr_pages) + cpu_data->nr_pages = 1; + cpu_data->pages = calloc(cpu_data->nr_pages, sizeof(*cpu_data->pages)); if (!cpu_data->pages) return -1; - /* Add stopper */ - cpu_data->pages[num_pages] = PAGE_STOPPER; - if (handle->use_pipe) { /* Just make a page, it will be nuked later */ cpu_data->page = malloc(sizeof(*cpu_data->page)); @@ -2793,7 +2813,8 @@ void tracecmd_close(struct tracecmd_input *handle) if (handle->cpu_data[cpu].page_cnt) warning("%d pages still allocated on cpu %d%s", handle->cpu_data[cpu].page_cnt, - cpu, show_records(handle->cpu_data[cpu].pages)); + cpu, show_records(handle->cpu_data[cpu].pages, + handle->cpu_data[cpu].nr_pages)); free(handle->cpu_data[cpu].pages); } } From patchwork Wed Jun 5 11:19:37 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Tzvetomir Stoyanov X-Patchwork-Id: 10976665 X-Patchwork-Delegate: rostedt@goodmis.org Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id BD34876 for ; Wed, 5 Jun 2019 11:19:43 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id AFAFF28827 for ; Wed, 5 Jun 2019 11:19:43 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id A40F227FA5; Wed, 5 Jun 2019 11:19:43 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-7.9 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 42E372867C for ; Wed, 5 Jun 2019 11:19:43 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1727370AbfFELTm (ORCPT ); Wed, 5 Jun 2019 07:19:42 -0400 Received: from mail-wm1-f66.google.com ([209.85.128.66]:54443 "EHLO mail-wm1-f66.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727070AbfFELTl (ORCPT ); Wed, 5 Jun 2019 07:19:41 -0400 Received: by mail-wm1-f66.google.com with SMTP id g135so1854825wme.4 for ; Wed, 05 Jun 2019 04:19:40 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=uLvuMS4zyXcsMGYHz/eG5dczspTna0pC14rzNTn4878=; b=HYk9MU7FxE1dOnTLcn5iJECQrU3HlylFJ8O9CXP6rC8VD5W2WkS3Lcb6A7ZtiFVBcz jrjCA4XCsIWH9RF6CLtU3BMgiFaeRjOPKyeiSr4oW9MJu0k2E8RjTb5XneNUJlcivdB2 Nr3jSbE1JMZlEu/kXNArOIVOsZ5cvD6U3ZSq3hZjNbO2Gir5OhyLr5w4kOAw3tjDGIaW +DTVlNfZXmU6858OvmBDDPHwzcLStbkQQE1y6TEkIQ/GQrNI9Av45X8GCZNmp1QSuX7l 6zb1tM0B8ConNknUasI0JwK7v7tfXsO+GCFkJL5qDzzT+XR/PT5UqoJfezEZq9hasNGI SWPg== X-Gm-Message-State: APjAAAVWk/GNXHzh+IW9y6D3GfKbNJK2vl1D6B2wa/Uhc6JGwASgtkXX qxfV9nFwxgAjBq14uVD5uFSnw6wl X-Google-Smtp-Source: APXvYqzUQx6BrmmlyJLZgJEbFf2SPfLrS39+01+Ze9MW6KX7U4hXVgWzdcwUb8NmPJBoOdu99ICP0w== X-Received: by 2002:a7b:cc97:: with SMTP id p23mr5150715wma.120.1559733579755; Wed, 05 Jun 2019 04:19:39 -0700 (PDT) Received: from oberon.eng.vmware.com ([146.247.46.5]) by smtp.gmail.com with ESMTPSA id 16sm15583084wmx.45.2019.06.05.04.19.39 (version=TLS1_3 cipher=AEAD-AES256-GCM-SHA384 bits=256/256); Wed, 05 Jun 2019 04:19:39 -0700 (PDT) From: Tzvetomir Stoyanov To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v2 2/2] trace-cmd: Fix a possible race condition and deadlock in trace-cmd Date: Wed, 5 Jun 2019 14:19:37 +0300 Message-Id: <20190605111937.17894-2-tstoyanov@vmware.com> X-Mailer: git-send-email 2.21.0 In-Reply-To: <20190605111937.17894-1-tstoyanov@vmware.com> References: <20190605111937.17894-1-tstoyanov@vmware.com> MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP 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 removes the select timeout, makes the call blocking, to ensure the threads are flushed its data before going in waitpid() loop. Signed-off-by: Tzvetomir Stoyanov Reviewed-by: Slavomir Kaslev --- tracecmd/trace-record.c | 3 +-- tracecmd/trace-stream.c | 6 ++++++ 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index 4523128..2f5fbd9 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -626,7 +626,6 @@ static void delete_thread_data(void) static void stop_threads(enum trace_type type) { - struct timeval tv = { 0, 0 }; int ret; int i; @@ -643,7 +642,7 @@ static void stop_threads(enum trace_type type) /* Flush out the pipes */ if (type & TRACE_TYPE_STREAM) { do { - ret = trace_stream_read(pids, recorder_threads, &tv); + ret = trace_stream_read(pids, recorder_threads, NULL); } while (ret > 0); } diff --git a/tracecmd/trace-stream.c b/tracecmd/trace-stream.c index dad3466..3814a35 100644 --- a/tracecmd/trace-stream.c +++ b/tracecmd/trace-stream.c @@ -92,6 +92,7 @@ int trace_stream_read(struct pid_record_data *pids, int nr_pids, struct timeval struct pid_record_data *last_pid; fd_set rfds; int top_rfd = 0; + int nr_fd; int ret; int i; @@ -119,18 +120,23 @@ int trace_stream_read(struct pid_record_data *pids, int nr_pids, struct timeval return 1; } + nr_fd = 0; FD_ZERO(&rfds); for (i = 0; i < nr_pids; i++) { /* Do not process closed pipes */ if (pids[i].closed) continue; + nr_fd++; if (pids[i].brass[0] > top_rfd) top_rfd = pids[i].brass[0]; FD_SET(pids[i].brass[0], &rfds); } + if (!nr_fd) + return 0; + ret = select(top_rfd + 1, &rfds, NULL, NULL, tv); if (ret > 0)