From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755722AbcBWXR5 (ORCPT ); Tue, 23 Feb 2016 18:17:57 -0500 Received: from smtprelay0005.hostedemail.com ([216.40.44.5]:56000 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1752384AbcBWXR4 (ORCPT ); Tue, 23 Feb 2016 18:17:56 -0500 X-Session-Marker: 726F737465647440676F6F646D69732E6F7267 X-Spam-Summary: 2,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::,RULES_HIT:41:355:379:541:599:800:960:966:973:988:989:1260:1277:1311:1313:1314:1345:1359:1437:1515:1516:1518:1534:1544:1593:1594:1605:1711:1730:1747:1777:1792:2196:2198:2199:2200:2393:2553:2559:2562:2692:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3872:3873:3874:4250:4321:4362:4385:4605:5007:6119:6238:6261:7774:7875:7903:8526:9040:10004:10848:10967:11026:11232:11473:11658:11914:12043:12291:12294:12296:12438:12517:12519:12555:12663:12683:12740:14096:14097:14659:21067:21080:30012:30054:30064:30090:30091,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:fn,MSBL:0,DNSBL:none,Custom_rules:0:0:0,LFtime:1,LUA_SUMMARY:none X-HE-Tag: meat51_44d349c9a0c21 X-Filterd-Recvd-Size: 4934 Date: Tue, 23 Feb 2016 18:17:51 -0500 From: Steven Rostedt To: Josef Bacik Cc: , Subject: Re: [PATCH] trace-cmd: use nonblocking reads for streaming Message-ID: <20160223181751.31dafea1@gandalf.local.home> In-Reply-To: <1450371712-12218-1-git-send-email-jbacik@fb.com> References: <1450371712-12218-1-git-send-email-jbacik@fb.com> X-Mailer: Claws Mail 3.13.1 (GTK+ 2.24.29; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thu, 17 Dec 2015 12:01:52 -0500 Josef Bacik wrote: > I noticed while using the streaming infrastructure in trace-cmd that I was > seemingly missing events. Using other tracing methods I got these events and > record->missed_events was never being set. This is because the streaming > infrastructure uses blocking reads on the per cpu trace pipe's, which means > we'll wait for an entire pages worth of data to be ready before passing it along > to the recorder. This makes it impossible to do long term tracing that requires > coupling two different events that could occur on different CPU's, and I imagine > it has been what is screwing up my trace-cmd profile runs on our giant 40 cpu > boxes. Fix trace-cmd instead to use a nonblocking read with select to wait for > data on the pipe so we don't burn CPU unnecessarily. With this patch I'm no > longer seeing missed events in my app. Thanks, I just want to make sure I understand what is happening here. This wasn't trace-cmd's default code right? This was your own app. And I'm guessing you were matching events perhaps. That is, after seeing some event, you looked for the other event. But if that event happened on a CPU that isn't very active, it would wait forever, as the read was waiting for a full page? Or is there something else. I don't have a problem with the patch. I just want to understand the issue. Thanks! -- Steve > > Signed-off-by: Josef Bacik > --- > trace-cmd.h | 1 + > trace-record.c | 9 +++++++-- > trace-recorder.c | 30 ++++++++++++++++++++++++++++++ > 3 files changed, 38 insertions(+), 2 deletions(-) > > diff --git a/trace-cmd.h b/trace-cmd.h > index 3a230b4..c94f784 100644 > --- a/trace-cmd.h > +++ b/trace-cmd.h > @@ -282,6 +282,7 @@ struct tracecmd_recorder *tracecmd_create_buffer_recorder(const char *file, int > struct tracecmd_recorder *tracecmd_create_buffer_recorder_maxkb(const char *file, int cpu, unsigned flags, const char *buffer, int maxkb); > > int tracecmd_start_recording(struct tracecmd_recorder *recorder, unsigned long sleep); > +long tracecmd_stream_recording(struct tracecmd_recorder *recorder, unsigned long sleep); > void tracecmd_stop_recording(struct tracecmd_recorder *recorder); > void tracecmd_stat_cpu(struct trace_seq *s, int cpu); > long tracecmd_flush_recording(struct tracecmd_recorder *recorder); > diff --git a/trace-record.c b/trace-record.c > index 49a8280..7981932 100644 > --- a/trace-record.c > +++ b/trace-record.c > @@ -2450,8 +2450,13 @@ static int create_recorder(struct buffer_instance *instance, int cpu, > } > > while (!finished) { > - if (tracecmd_start_recording(recorder, sleep_time) < 0) > - break; > + if (type == TRACE_TYPE_STREAM) { > + if (tracecmd_stream_recording(recorder, sleep_time) < 0) > + break; > + } else { > + if (tracecmd_start_recording(recorder, sleep_time) < 0) > + break; > + } > } > tracecmd_free_recorder(recorder); > > diff --git a/trace-recorder.c b/trace-recorder.c > index 16d1be0..13e2e9f 100644 > --- a/trace-recorder.c > +++ b/trace-recorder.c > @@ -440,6 +440,36 @@ long tracecmd_flush_recording(struct tracecmd_recorder *recorder) > return total; > } > > +#define USECS_IN_SEC 1000000UL > +long tracecmd_stream_recording(struct tracecmd_recorder *recorder, unsigned long sleep) > +{ > + static int nonblock = 0; > + fd_set rfds; > + struct timeval tv; > + long total = 0; > + long ret; > + > + if (!nonblock) > + set_nonblock(recorder); > + > + FD_ZERO(&rfds); > + FD_SET(recorder->trace_fd, &rfds); > + tv.tv_sec = sleep / USECS_IN_SEC; > + tv.tv_usec = sleep % USECS_IN_SEC; > + ret = select(FD_SETSIZE, &rfds, NULL, NULL, &tv); > + if (ret <= 0) > + return 0; > + > + do { > + ret = read_data(recorder); > + if (ret < 0) > + return ret; > + total += ret; > + } while (ret); > + > + return total; > +} > + > int tracecmd_start_recording(struct tracecmd_recorder *recorder, unsigned long sleep) > { > struct timespec req;