trace-cmd: introduce --initital-delay for record command

PATCH In review David Hildenbrand 2 participants 7 messages Dec 18, 2017 Documentation

Share & tools

David Hildenbrand

author

2017-12-18 11:24 UTC #0 lore raw

PATCH 1/1 trace-cmd: introduce --initital-delay for record command

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 <[email protected]>

---
 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(-)

Documentation/trace-cmd-record.1.txt +10 -0

index 68afa16..d429caf 100644
@@ -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
 --------

trace-cmd.h +2 -1

index 6fd34d7..bae7153 100644
@@ -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);

trace-record.c +10 -1

index f128257..cd6e158 100644
@@ -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;

trace-recorder.c +8 -1

index 85150fd..a48c9e8 100644
@@ -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) {

Signature · 1 line

2.14.3

Steven Rostedt

2017-12-18 15:42 UTC #1 lore raw

Quoted 10 lines · On Mon, 18 Dec 2017 12:24:12 +0100 David Hildenbrand <[email protected]> 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

David Hildenbrand

author

2017-12-18 16:23 UTC #2 lore raw

Quoted 9 lines · Steven Rostedt

Quoted 6 lines · On Mon, 18 Dec 2017 12:24:12 +0100 David Hildenbrand <[email protected]> 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.

Quoted 9 lines

Quoted 4 lines
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!

Quoted 2 lines

-- Steve

Signature · 3 lines

Thanks,

David / dhildenb

Steven Rostedt

2017-12-18 17:52 UTC #3 lore raw

Quoted 1 line · On Mon, 18 Dec 2017 17:23:24 +0100 David Hildenbrand <[email protected]> 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

Quoted 5 lines

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.

David Hildenbrand

author

2017-12-18 20:56 UTC #4 lore raw

Quoted 10 lines · Steven Rostedt

Quoted 1 line · On Mon, 18 Dec 2017 17:23:24 +0100 David Hildenbrand <[email protected]> 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.

Quoted 6 lines

# 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!

Quoted 8 lines

-- Steve
Quoted 5 lines
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.

Signature · 3 lines

Thanks,

David / dhildenb

Steven Rostedt

2017-12-18 21:43 UTC #5 lore raw

Quoted 4 lines · On Mon, 18 Dec 2017 21:56:33 +0100 David Hildenbrand <[email protected]> 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

David Hildenbrand

author

2017-12-18 22:45 UTC #6 lore raw

Quoted 11 lines · Steven Rostedt

Quoted 4 lines · On Mon, 18 Dec 2017 21:56:33 +0100 David Hildenbrand <[email protected]> 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

Quoted 3 lines

-- Steve

Signature · 3 lines

Thanks,

David / dhildenb