[PATCH v1] trace-cmd: introduce --initital-delay for record command

[PATCH v1] trace-cmd: introduce --initital-delay for record command

[David Hildenbrand]

If recording a big number of events to a big buffer, one might want to
minimize the trace-cmd activity for a certain period in time.
Especially, don't see any trace-cmd activity for some time. If there are
a lot of events, the loop might actually never sleep, resulting in the
"-s" option never becomming active.

E.g. I am using scheduler events to trace thread activity per CPU. Esp.
sched:sched_wakeup and sched:sched_stat_runtime. Even when setting the
sleep time to something huge like 30 seconds, I can see constant activity
from the trace-cmd tasks.

Signed-off-by: David Hildenbrand <david@redhat.com>
---
 Documentation/trace-cmd-record.1.txt | 10 ++++++++++
 trace-cmd.h                          |  3 ++-
 trace-record.c                       | 11 ++++++++++-
 trace-recorder.c                     |  9 ++++++++-
 4 files changed, 30 insertions(+), 3 deletions(-)

diff --git a/Documentation/trace-cmd-record.1.txt b/Documentation/trace-cmd-record.1.txt
index 68afa16..d429caf 100644
--- a/Documentation/trace-cmd-record.1.txt
+++ b/Documentation/trace-cmd-record.1.txt
@@ -326,6 +326,16 @@ OPTIONS
     executed will not be changed. This is useful if you want to monitor the
     output of the command being executed, but not see the output from trace-cmd.
 
+*--initital-delay* 'delay'::
+    The processes that trace-cmd creates to record from the ring buffer need
+    to start copying the data from the ring buffer at some point in time.
+    Setting the 'delay' to zero will cause the processes to start copying
+    from the ring buffer immediately. This is helpful when wanting to
+    minimize trace-cmd activity during some period of time (where -s
+    will not help due to the amount of events being recorded).
+
+    The 'delay' metric is microseconds. The default is set to 0.
+
 EXAMPLES
 --------
 
diff --git a/trace-cmd.h b/trace-cmd.h
index 6fd34d7..bae7153 100644
--- a/trace-cmd.h
+++ b/trace-cmd.h
@@ -285,7 +285,8 @@ struct tracecmd_recorder *tracecmd_create_buffer_recorder_fd(int fd, int cpu, un
 struct tracecmd_recorder *tracecmd_create_buffer_recorder(const char *file, int cpu, unsigned flags, const char *buffer);
 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);
+int tracecmd_start_recording(struct tracecmd_recorder *recorder,
+			     unsigned long sleep, unsigned long initital_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 f128257..cd6e158 100644
--- a/trace-record.c
+++ b/trace-record.c
@@ -79,6 +79,7 @@ static const char *output_file = "trace.dat";
 
 static int latency;
 static int sleep_time = 1000;
+static int initial_sleep_time = 0;
 static int recorder_threads;
 static struct pid_record_data *pids;
 static int buffers;
@@ -2668,7 +2669,8 @@ static int create_recorder(struct buffer_instance *instance, int cpu,
 	}
 
 	while (!finished) {
-		if (tracecmd_start_recording(recorder, sleep_time) < 0)
+		if (tracecmd_start_recording(recorder, sleep_time,
+					     initial_sleep_time) < 0)
 			break;
 	}
 	tracecmd_free_recorder(recorder);
@@ -4211,6 +4213,7 @@ enum {
 	OPT_funcstack		= 254,
 	OPT_date		= 255,
 	OPT_module		= 256,
+	OPT_initital_delay	= 257,
 };
 
 void trace_stop(int argc, char **argv)
@@ -4452,6 +4455,7 @@ static void parse_record_options(int argc,
 			{"quiet", no_argument, NULL, OPT_quiet},
 			{"help", no_argument, NULL, '?'},
 			{"module", required_argument, NULL, OPT_module},
+			{"initital-delay", required_argument, NULL, OPT_initital_delay},
 			{NULL, 0, NULL, 0}
 		};
 
@@ -4732,6 +4736,11 @@ static void parse_record_options(int argc,
 			ctx->instance->filter_mod = optarg;
 			ctx->filtered = 0;
 			break;
+		case OPT_initital_delay:
+			if (!optarg)
+				usage(argv);
+			initial_sleep_time = atoi(optarg);
+			break;
 		case OPT_quiet:
 		case 'q':
 			quiet = 1;
diff --git a/trace-recorder.c b/trace-recorder.c
index 85150fd..a48c9e8 100644
--- a/trace-recorder.c
+++ b/trace-recorder.c
@@ -439,7 +439,8 @@ long tracecmd_flush_recording(struct tracecmd_recorder *recorder)
 	return total;
 }
 
-int tracecmd_start_recording(struct tracecmd_recorder *recorder, unsigned long sleep)
+int tracecmd_start_recording(struct tracecmd_recorder *recorder,
+			     unsigned long sleep, unsigned long initital_sleep)
 {
 	struct timespec req;
 	long read = 1;
@@ -447,6 +448,12 @@ int tracecmd_start_recording(struct tracecmd_recorder *recorder, unsigned long s
 
 	recorder->stop = 0;
 
+	if (initital_sleep) {
+		req.tv_sec = initital_sleep / 1000000;
+		req.tv_nsec = (initital_sleep % 1000000) * 1000;
+		nanosleep(&req, NULL);
+	}
+
 	do {
 		/* Only sleep if we did not read anything last time */
 		if (!read && sleep) {
-- 
2.14.3

Re: [PATCH v1] trace-cmd: introduce --initital-delay for record command

[Steven Rostedt]

On Mon, 18 Dec 2017 12:24:12 +0100
David Hildenbrand <david@redhat.com> wrote:

> If recording a big number of events to a big buffer, one might want to
> minimize the trace-cmd activity for a certain period in time.
> Especially, don't see any trace-cmd activity for some time. If there are
> a lot of events, the loop might actually never sleep, resulting in the
> "-s" option never becomming active.
> 
> E.g. I am using scheduler events to trace thread activity per CPU. Esp.
> sched:sched_wakeup and sched:sched_stat_runtime. Even when setting the
> sleep time to something huge like 30 seconds, I can see constant activity
> from the trace-cmd tasks.

Thanks for reporting this. Honestly, I believe this is fixing a symptom
of a real problem. I'd like to investigate why trace-cmd is running
with a sleep time of 30 seconds. I think that should be fixed.

-- Steve

Re: [PATCH v1] trace-cmd: introduce --initital-delay for record command

[David Hildenbrand]

On 18.12.2017 16:41, Steven Rostedt wrote:
> On Mon, 18 Dec 2017 12:24:12 +0100
> David Hildenbrand <david@redhat.com> wrote:
> 
>> If recording a big number of events to a big buffer, one might want to
>> minimize the trace-cmd activity for a certain period in time.
>> Especially, don't see any trace-cmd activity for some time. If there are
>> a lot of events, the loop might actually never sleep, resulting in the
>> "-s" option never becomming active.
>>
>> E.g. I am using scheduler events to trace thread activity per CPU. Esp.
>> sched:sched_wakeup and sched:sched_stat_runtime. Even when setting the
>> sleep time to something huge like 30 seconds, I can see constant activity
>> from the trace-cmd tasks.
> 
> Thanks for reporting this. Honestly, I believe this is fixing a symptom
> of a real problem. I'd like to investigate why trace-cmd is running
> with a sleep time of 30 seconds. I think that should be fixed.
> 

The problem seems to be that we only sleep if we haven't read something
in the last iteration (!read), hindering us to sleep if there are many
events. Especially on the first run.

If tracing e.g. the scheduler, after each iteration there will already
be new data to pick up in the buffer, resulting in the thread never
going to sleep.

What I need: Start tracing and flush all buffers when exiting. (e.g.
after 30 seconds). Never wakeup in between, so the real trace overhead
in that period of time is purely storing the tracepoints to the buffer
in the kernel. Of course we could implement something like that ("copy
from the buffer only when exiting") or try to see if we can fix the
existing "-s" flag in a way that allows it.

Thanks!

> -- Steve
> 


-- 

Thanks,

David / dhildenb

Re: [PATCH v1] trace-cmd: introduce --initital-delay for record command

[Steven Rostedt]

On Mon, 18 Dec 2017 17:23:24 +0100
David Hildenbrand <david@redhat.com> wrote:

> What I need: Start tracing and flush all buffers when exiting. (e.g.

Why don't you use "trace-cmd start" and "trace-cmd extract"?

"trace-cmd record" is all about not losing events. If you are creating
a big buffer, then I think you want to use this.

# trace-cmd start -p <tracer> -e <events> -b <big-buffer-size>
# run test
# trace-cmd stop
# trace-cmd extract

Wouldn't that work for you?

-- Steve

> after 30 seconds). Never wakeup in between, so the real trace overhead
> in that period of time is purely storing the tracepoints to the buffer
> in the kernel. Of course we could implement something like that ("copy
> from the buffer only when exiting") or try to see if we can fix the
> existing "-s" flag in a way that allows it.

Re: [PATCH v1] trace-cmd: introduce --initital-delay for record command

[David Hildenbrand]

On 18.12.2017 18:52, Steven Rostedt wrote:
> On Mon, 18 Dec 2017 17:23:24 +0100
> David Hildenbrand <david@redhat.com> wrote:
> 
>> What I need: Start tracing and flush all buffers when exiting. (e.g.
> 
> Why don't you use "trace-cmd start" and "trace-cmd extract"?
> 
> "trace-cmd record" is all about not losing events. If you are creating
> a big buffer, then I think you want to use this.
> 
> # trace-cmd start -p <tracer> -e <events> -b <big-buffer-size>
> # run test
> # trace-cmd stop
> # trace-cmd extract
> 
> Wouldn't that work for you?

It works for some scenarios I have in mind. Especially when recording
long runs, it might be beneficial to e.g. wakeup every 30 seconds to
just write out a couple of MB of traces (compared to right now -s
30000000 waking up every couple of milliseconds).

With start/stop/extract the downside is, that buffers have to be huge
for longer runs.

I'll have a try tomorrow if I I''lose events with 20MB buffers per CPU
when recording more than 60 seconds (on a very active system with
mentioned scheduler rtaces being turned on).

Thanks!

> 
> -- Steve
> 
>> after 30 seconds). Never wakeup in between, so the real trace overhead
>> in that period of time is purely storing the tracepoints to the buffer
>> in the kernel. Of course we could implement something like that ("copy
>> from the buffer only when exiting") or try to see if we can fix the
>> existing "-s" flag in a way that allows it.


-- 

Thanks,

David / dhildenb

Re: [PATCH v1] trace-cmd: introduce --initital-delay for record command

[Steven Rostedt]

On Mon, 18 Dec 2017 21:56:33 +0100
David Hildenbrand <david@redhat.com> wrote:
 
> I'll have a try tomorrow if I I''lose events with 20MB buffers per CPU
> when recording more than 60 seconds (on a very active system with
> mentioned scheduler rtaces being turned on).
>

Another option is to add a '-w' option to record that causes the
recorders (what reads the data) to "wait" or force it to sleep even if
it did read something. I'm fine with that.

-- Steve

Re: [PATCH v1] trace-cmd: introduce --initital-delay for record command

[David Hildenbrand]

On 18.12.2017 22:43, Steven Rostedt wrote:
> On Mon, 18 Dec 2017 21:56:33 +0100
> David Hildenbrand <david@redhat.com> wrote:
>  
>> I'll have a try tomorrow if I I''lose events with 20MB buffers per CPU
>> when recording more than 60 seconds (on a very active system with
>> mentioned scheduler rtaces being turned on).
>>
> 
> Another option is to add a '-w' option to record that causes the
> recorders (what reads the data) to "wait" or force it to sleep even if
> it did read something. I'm fine with that.

Also thought about that. Might make sense (and makes -s actually do what
it advertises even when there are a lot of events coming in).

Thanks Steve

> 
> -- Steve
> 


-- 

Thanks,

David / dhildenb