[PATCH] cyclictest: stop any tracing after hitting a breaktrace threshold

[PATCH] cyclictest: stop any tracing after hitting a breaktrace threshold

[Clark Williams]

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

John,

This patch is against the devel/v0.98 branch. It turns off tracing in the tracemark() so that we don't lose information about what was going on when we hit the latency:


The current logic of using --tracemark and --notrace works for running
cyclictest with trace-cmd, but even if we are not doing any trace
manipulation in cyclictest, we still need to stop tracing when we hit a
breaktrace threshold (i.e. -b <n>).

Modify startup logic to hold open file descriptors for the tracemark file
*and* the tracing_on file. When we hit a threshold and call the tracemark()
function, write the marker to the trace buffers and then write a "0\n" to
the tracing_on file to turn off tracing, otherwise we lose the information
immediately prior to the point where we hit the latency.

Signed-off-by: Clark Williams <williams@redhat.com>
---
 src/cyclictest/cyclictest.c | 32 ++++++++++++++++++++++++++------
 1 file changed, 26 insertions(+), 6 deletions(-)

diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
index 902167010416..00e5f3d59a5b 100644
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -489,7 +489,12 @@ static void tracemark(char *fmt, ...)
 	va_start(ap, fmt);
 	len = vsnprintf(tracebuf, TRACEBUFSIZ, fmt, ap);
 	va_end(ap);
+
+	/* write the tracemark message */
 	write(tracemark_fd, tracebuf, len);
+
+	/* now stop any trace */
+	write(trace_fd, "0\n", 2);
 }
 
 
@@ -535,13 +540,28 @@ static void open_tracemark_fd(void)
 {
 	char path[MAX_PATH];
 
-	if (tracemark_fd >= 0)
-		return;
+	/*
+	 * open the tracemark file if it's not already open
+	 */
+	if (tracemark_fd < 0) {
+		sprintf(path, "%s/%s", fileprefix, "trace_marker");
+		tracemark_fd = open(path, O_WRONLY);
+		if (tracemark_fd < 0) {
+			warn("unable to open trace_marker file: %s\n", path);
+			return;
+		}
+	}
 
-	sprintf(path, "%s/%s", fileprefix, "trace_marker");
-	tracemark_fd = open(path, O_WRONLY);
-	if (tracemark_fd < 0)
-		warn("unable to open trace_marker file: %s\n", path);
+	/*
+	 * if we're not tracing and the tracing_on fd is not open,
+	 * open the tracing_on file so that we can stop the trace
+	 * if we hit a breaktrace threshold
+	 */
+	if (notrace && trace_fd < 0) {
+		sprintf(path, "%s/%s", fileprefix, "tracing_on");
+		if ((trace_fd = open(path, O_WRONLY)) < 0)
+			warn("unable to open tracing_on file: %s\n", path);
+	}
 }
 
 static void debugfs_prepare(void)
-- 
2.5.5


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 801 bytes --]

Re: [PATCH] cyclictest: stop any tracing after hitting a breaktrace threshold

[Luiz Capitulino]

On Tue, 3 May 2016 12:59:53 -0500
Clark Williams <williams@redhat.com> wrote:

> John,
> 
> This patch is against the devel/v0.98 branch. It turns off tracing in the tracemark() so that we don't lose information about what was going on when we hit the latency:
> 
> 
> The current logic of using --tracemark and --notrace works for running
> cyclictest with trace-cmd, but even if we are not doing any trace
> manipulation in cyclictest, we still need to stop tracing when we hit a
> breaktrace threshold (i.e. -b <n>).

Does it solve the problem for you if you revert ba4dd1bf54 and start
cyclictest with:

# cyclictest [...] -bX

Or with:

# cyclictest [...] -bX --tracemark

Also, how do I reproduce your issue? Are you doing tracing by hand?

More comments below.

> 
> Modify startup logic to hold open file descriptors for the tracemark file
> *and* the tracing_on file. When we hit a threshold and call the tracemark()
> function, write the marker to the trace buffers and then write a "0\n" to
> the tracing_on file to turn off tracing, otherwise we lose the information
> immediately prior to the point where we hit the latency.
> 
> Signed-off-by: Clark Williams <williams@redhat.com>
> ---
>  src/cyclictest/cyclictest.c | 32 ++++++++++++++++++++++++++------
>  1 file changed, 26 insertions(+), 6 deletions(-)
> 
> diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
> index 902167010416..00e5f3d59a5b 100644
> --- a/src/cyclictest/cyclictest.c
> +++ b/src/cyclictest/cyclictest.c
> @@ -489,7 +489,12 @@ static void tracemark(char *fmt, ...)
>  	va_start(ap, fmt);
>  	len = vsnprintf(tracebuf, TRACEBUFSIZ, fmt, ap);
>  	va_end(ap);
> +
> +	/* write the tracemark message */
>  	write(tracemark_fd, tracebuf, len);
> +
> +	/* now stop any trace */
> +	write(trace_fd, "0\n", 2);
>  }

We do tracing(0) when we hit the latency threshold, so I don't
think this is necessary.

However, have you checked that writing to tracing_on won't break
trace-cmd when it exec()ed cyclictest?

>  
>  
> @@ -535,13 +540,28 @@ static void open_tracemark_fd(void)
>  {
>  	char path[MAX_PATH];
>  
> -	if (tracemark_fd >= 0)
> -		return;
> +	/*
> +	 * open the tracemark file if it's not already open
> +	 */
> +	if (tracemark_fd < 0) {
> +		sprintf(path, "%s/%s", fileprefix, "trace_marker");
> +		tracemark_fd = open(path, O_WRONLY);
> +		if (tracemark_fd < 0) {
> +			warn("unable to open trace_marker file: %s\n", path);
> +			return;
> +		}
> +	}
>  
> -	sprintf(path, "%s/%s", fileprefix, "trace_marker");
> -	tracemark_fd = open(path, O_WRONLY);
> -	if (tracemark_fd < 0)
> -		warn("unable to open trace_marker file: %s\n", path);
> +	/*
> +	 * if we're not tracing and the tracing_on fd is not open,
> +	 * open the tracing_on file so that we can stop the trace
> +	 * if we hit a breaktrace threshold
> +	 */
> +	if (notrace && trace_fd < 0) {
> +		sprintf(path, "%s/%s", fileprefix, "tracing_on");
> +		if ((trace_fd = open(path, O_WRONLY)) < 0)
> +			warn("unable to open tracing_on file: %s\n", path);
> +	}
>  }
>  
>  static void debugfs_prepare(void)

Re: [PATCH] cyclictest: stop any tracing after hitting a breaktrace threshold

[Clark Williams]

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

On Tue, 3 May 2016 15:56:44 -0400
Luiz Capitulino <lcapitulino@redhat.com> wrote:

> On Tue, 3 May 2016 12:59:53 -0500
> Clark Williams <williams@redhat.com> wrote:
> 
> > John,
> > 
> > This patch is against the devel/v0.98 branch. It turns off tracing in the tracemark() so that we don't lose information about what was going on when we hit the latency:
> > 
> > 
> > The current logic of using --tracemark and --notrace works for running
> > cyclictest with trace-cmd, but even if we are not doing any trace
> > manipulation in cyclictest, we still need to stop tracing when we hit a
> > breaktrace threshold (i.e. -b <n>).  
> 
> Does it solve the problem for you if you revert ba4dd1bf54 and start
> cyclictest with:
> 
> # cyclictest [...] -bX
> 
> Or with:
> 
> # cyclictest [...] -bX --tracemark
> 
> Also, how do I reproduce your issue? Are you doing tracing by hand?

I'm running: 
	trace-cmd start -e all -p function

Then kicking off loads and finally running:
	cyclictest --numa -p95 -qmu -b 300 --tracemark --notrace

The intent here is that cyclictest do nothing wrt tracing other than stop it when the breaktrace threshold is set. 


> > +
> > +	/* write the tracemark message */
> >  	write(tracemark_fd, tracebuf, len);
> > +
> > +	/* now stop any trace */
> > +	write(trace_fd, "0\n", 2);
> >  }  
> 
> We do tracing(0) when we hit the latency threshold, so I don't
> think this is necessary.

Tracing didn't seem to stop in my scenario above. I suspect it's the --notrace option, which I used to make absolutely certain we didn't touch any tracing bits. 

> 
> However, have you checked that writing to tracing_on won't break
> trace-cmd when it exec()ed cyclictest?
> 

I haven't run cyclictest as a child of trace-cmd. I'll try that, but my use-case is really in running rteval, which runs cyclictest as a measurement tool. So for tracing I need to to 'trace-cmd start' before running rteval. 

The intent is to be able to do something like this:

    trace-cmd start -e all -p function
    rteval --duration=12h --cyclictest-breaktrace=150
    trace-cmd extract

That sets a breaktrace threshold of 150 microseconds so that if we terminate the run early, I'll have an ftrace file I can use narrow down on what's causing latency spikes. 

Clark

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 801 bytes --]

Re: [PATCH] cyclictest: stop any tracing after hitting a breaktrace threshold

[Luiz Capitulino]

On Tue, 3 May 2016 15:28:39 -0500
Clark Williams <williams@redhat.com> wrote:

> The intent is to be able to do something like this:
> 
>     trace-cmd start -e all -p function
>     rteval --duration=12h --cyclictest-breaktrace=150
>     trace-cmd extract

Ah, ok, I get it now. This makes sense.

I think I'd refactor the code opening tracing_on to its own
function so that we avoid the duplicate code in setup_tracer(),
but in any case:

Reviewed-by: Luiz Capitulino <lcapitulino@redhat.com>

Re: [PATCH] cyclictest: stop any tracing after hitting a breaktrace threshold

[John Kacur]

On Wed, 4 May 2016, Luiz Capitulino wrote:

> On Tue, 3 May 2016 15:28:39 -0500
> Clark Williams <williams@redhat.com> wrote:
> 
> > The intent is to be able to do something like this:
> > 
> >     trace-cmd start -e all -p function
> >     rteval --duration=12h --cyclictest-breaktrace=150
> >     trace-cmd extract
> 
> Ah, ok, I get it now. This makes sense.
> 
> I think I'd refactor the code opening tracing_on to its own
> function so that we avoid the duplicate code in setup_tracer(),
> but in any case:
> 
> Reviewed-by: Luiz Capitulino <lcapitulino@redhat.com>
> --

Sorry, resending with a sane mailer

I don't see a better solution for now, so
adding Luiz Reviewed by
Signed-off-by: John Kacur <jkacur@redhat.com>

and pushed to devel