Skip to contentSkip to conversation

perf,stat: reduce interval-print to 10ms

PATCH In review [email protected] 4 participants 7 messages Oct 2, 2015 – Oct 3, 2015 perf events

lore
Share & tools
lore

[email protected]

author
#0 lore raw

PATCH 1/1 perf,stat: reduce interval-print to 10ms

From: Kan Liang <[email protected]>

The interval-print used to be limited to 100ms. However, for example, 10ms is required to do sophisticated bandwidth analysis using uncore event.
The test shows that the overhead of the system-wide uncore monitoring with 10ms interval is only ~2%. So this patch reduces interval-print to 10ms.
But 10ms may not work well for all cases. For example, when the cpus/threads number is very large, for system-wide core event monitoring the overhead could be high. To handle this issue, a warning will be displayed when the interval-print is set between 10ms to 100ms. So the users can make a decision according to their specific cases.

#perf stat -e uncore_imc_1/cas_count_read/ -a --interval-print 10 -- sleep 1

print interval < 100ms. The overhead percentage could be high in some cases. Please proceed with caution.
# time counts unit events

      0.010200451               0.10 MiB  uncore_imc_1/cas_count_read/
      0.020475117               0.02 MiB  uncore_imc_1/cas_count_read/
      0.030692800               0.01 MiB  uncore_imc_1/cas_count_read/
      0.040948161               0.02 MiB  uncore_imc_1/cas_count_read/
      0.051159564               0.00 MiB  uncore_imc_1/cas_count_read/
Signed-off-by Kan Liang <[email protected]>
---
 tools/perf/Documentation/perf-stat.txt |  2 +-
 tools/perf/builtin-stat.c              | 13 +++++++++----
 2 files changed, 10 insertions(+), 5 deletions(-)
tools/perf/Documentation/perf-stat.txt +1 -1
index 47469ab..7586fe0 100644
@@ -128,7 +128,7 @@ perf stat --repeat 10 --null --sync --pre 'make -s O=defconfig-build/clean' -- m
 
 -I msecs::
 --interval-print msecs::
-	Print count deltas every N milliseconds (minimum: 100ms)
+	Print count deltas every N milliseconds (minimum: 10ms)
 	example: perf stat -I 1000 -e cycles -a sleep 5
 
 --per-socket::
tools/perf/builtin-stat.c +9 -4
index a96fb5c..5ef88f7 100644
@@ -1179,7 +1179,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_STRING(0, "post", &post_cmd, "command",
 			"command to run after to the measured command"),
 	OPT_UINTEGER('I', "interval-print", &stat_config.interval,
-		    "print counts at regular interval in ms (>= 100)"),
+		    "print counts at regular interval in ms (>= 10)"),
 	OPT_SET_UINT(0, "per-socket", &stat_config.aggr_mode,
 		     "aggregate counts per processor socket", AGGR_SOCKET),
 	OPT_SET_UINT(0, "per-core", &stat_config.aggr_mode,

@@ -1332,9 +1332,14 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 		thread_map__read_comms(evsel_list->threads);
 
 	if (interval && interval < 100) {
-		pr_err("print interval must be >= 100ms\n");
-		parse_options_usage(stat_usage, options, "I", 1);
-		goto out;
+		if (interval < 10) {
+			pr_err("print interval must be >= 10ms\n");
+			parse_options_usage(stat_usage, options, "I", 1);
+			goto out;
+		} else
+			pr_warning("print interval < 100ms. "
+				   "The overhead percentage could be high in some cases. "
+				   "Please proceed with caution.\n");
 	}
 
 	if (perf_evlist__alloc_stats(evsel_list, interval))
Signature · 1 line
1.8.3.1
Acked-by on v1 1/1
#1 lore raw
Quoted 2 lines · On Fri, Oct 02, 2015 at 05:04:34AM -0400, [email protected] wrote:

From: Kan Liang <[email protected]>

SNIP

Quoted 18 lines
tools/perf/builtin-stat.c +1 -2
index a96fb5c..5ef88f7 100644
@@ -1179,7 +1179,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_STRING(0, "post", &post_cmd, "command",
 			"command to run after to the measured command"),
 	OPT_UINTEGER('I', "interval-print", &stat_config.interval,
-		    "print counts at regular interval in ms (>= 100)"),
+		    "print counts at regular interval in ms (>= 10)"),
 	OPT_SET_UINT(0, "per-socket", &stat_config.aggr_mode,
 		     "aggregate counts per processor socket", AGGR_SOCKET),
 	OPT_SET_UINT(0, "per-core", &stat_config.aggr_mode,

@@ -1332,9 +1332,14 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 		thread_map__read_comms(evsel_list->threads);
 
 	if (interval && interval < 100) {
-		pr_err("print interval must be >= 100ms\n");

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused) · line 1342

Quoted 10 lines
tools/perf/builtin-stat.c +8 -2
-		parse_options_usage(stat_usage, options, "I", 1);
-		goto out;
+		if (interval < 10) {
+			pr_err("print interval must be >= 10ms\n");
+			parse_options_usage(stat_usage, options, "I", 1);
+			goto out;
+		} else
+			pr_warning("print interval < 100ms. "
+				   "The overhead percentage could be high in some cases. "
+				   "Please proceed with caution.\n");

with '-I' 10 this warning flies away quite fast ;-)

I guess it's better than nothing, and I'm not sure about putting some sleep after that warning..

Acked-by Jiri Olsa <[email protected]>

thanks,
jirka

maintainer
#2 lore raw

Em Fri, Oct 02, 2015 at 06:56:24PM +0200, Jiri Olsa escreveu:

Quoted 37 lines · On Fri, Oct 02, 2015 at 05:04:34AM -0400, [email protected] wrote:
Quoted 2 lines

From: Kan Liang <[email protected]>

SNIP

Quoted 18 lines
tools/perf/builtin-stat.c +1 -2
index a96fb5c..5ef88f7 100644
@@ -1179,7 +1179,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_STRING(0, "post", &post_cmd, "command",
 			"command to run after to the measured command"),
 	OPT_UINTEGER('I', "interval-print", &stat_config.interval,
-		    "print counts at regular interval in ms (>= 100)"),
+		    "print counts at regular interval in ms (>= 10)"),
 	OPT_SET_UINT(0, "per-socket", &stat_config.aggr_mode,
 		     "aggregate counts per processor socket", AGGR_SOCKET),
 	OPT_SET_UINT(0, "per-core", &stat_config.aggr_mode,

@@ -1332,9 +1332,14 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 		thread_map__read_comms(evsel_list->threads);
 
 	if (interval && interval < 100) {
-		pr_err("print interval must be >= 100ms\n");

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused) · line 1342

Quoted 10 lines
tools/perf/builtin-stat.c +8 -2
-		parse_options_usage(stat_usage, options, "I", 1);
-		goto out;
+		if (interval < 10) {
+			pr_err("print interval must be >= 10ms\n");
+			parse_options_usage(stat_usage, options, "I", 1);
+			goto out;
+		} else
+			pr_warning("print interval < 100ms. "
+				   "The overhead percentage could be high in some cases. "
+				   "Please proceed with caution.\n");

with '-I' 10 this warning flies away quite fast ;-)

Quoted 4 lines

I guess it's better than nothing, and I'm not sure about putting some sleep after that warning..

Acked-by Jiri Olsa <[email protected]>

Right, this should appear in the man page as well, I added the patch below, we could also print that warning when the workload ends.

- Arnaldo

tools/perf/Documentation/perf-stat.txt +2 -0
index 7586fe08ac9a..641caf66ff26 100644
@@ -130,6 +130,8 @@ perf stat --repeat 10 --null --sync --pre 'make -s O=defconfig-build/clean' -- m
 --interval-print msecs::
 	Print count deltas every N milliseconds (minimum: 10ms)
 	example: perf stat -I 1000 -e cycles -a sleep 5
+	The overhead percentage could be high in some cases, for instance
+	with small, sub 100ms intervals.  Use with caution.
 
 --per-socket::
 Aggregate counts per processor socket for system-wide mode measurements.  This
author
#3 lore raw
Quoted 41 lines
Quoted 9 lines

SNIP

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const

Quoted 5 lines
tools/perf/builtin-stat.c +0 -0
index a96fb5c..5ef88f7 100644
@@ -1179,7 +1179,7 @@ int cmd_stat(int argc, const char **argv, const

char *prefix __maybe_unused)

Quoted 2 lines

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const · line 1180

Quoted 2 lines
tools/perf/builtin-stat.c +0 -0
 	OPT_STRING(0, "post", &post_cmd, "command",
 			"command to run after to the measured

command"),

Quoted 5 lines

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const · line 1184

Quoted 5 lines
tools/perf/builtin-stat.c +1 -1
 	OPT_UINTEGER('I', "interval-print", &stat_config.interval,
-		    "print counts at regular interval in ms (>= 100)"),
+		    "print counts at regular interval in ms (>= 10)"),
 	OPT_SET_UINT(0, "per-socket", &stat_config.aggr_mode,
 		     "aggregate counts per processor socket",

AGGR_SOCKET),

Quoted 1 line

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const · line 1185

Quoted 1 line
tools/perf/builtin-stat.c +0 -0
 	OPT_SET_UINT(0, "per-core", &stat_config.aggr_mode, @@ -

1332,9

Quoted 1 line
Quoted 1 line

+1332,14 @@ int cmd_stat(int argc, const char **argv, const char

*prefix __maybe_unused)

Quoted 13 lines

tools/perf/builtin-stat.c

Quoted 13 lines
tools/perf/builtin-stat.c +7 -3
 		thread_map__read_comms(evsel_list->threads);
 
 	if (interval && interval < 100) {
-		pr_err("print interval must be >= 100ms\n");
-		parse_options_usage(stat_usage, options, "I", 1);
-		goto out;
+		if (interval < 10) {
+			pr_err("print interval must be >= 10ms\n");
+			parse_options_usage(stat_usage, options, "I", 1);
+			goto out;
+		} else
+			pr_warning("print interval < 100ms. "
+				   "The overhead percentage could be high

in some cases. "

Quoted 4 lines

tools/perf/builtin-stat.c

Quoted 1 line
tools/perf/builtin-stat.c +1 -0
+				   "Please proceed with caution.\n");

with '-I' 10 this warning flies away quite fast ;-)

Quoted 8 lines
Quoted 4 lines

I guess it's better than nothing, and I'm not sure about putting some sleep after that warning..

Acked-by Jiri Olsa <[email protected]>

Right, this should appear in the man page as well, I added the patch below, we could also print that warning when the workload ends.

OK. We can print the warning message again at the end as the patch below.

tools/perf/builtin-stat.c +5 -0
index 5ef88f7..01209c7 100644
@@ -1377,6 +1377,11 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 	if (!forever && status != -1 && !interval)
 		print_counters(NULL, argc, argv);
 
+	if (interval && interval < 100)
+		pr_warning("print interval < 100ms. "
+			   "The overhead percentage could be high in some cases. "
+			   "Please proceed with caution.\n");
+
 	perf_evlist__free_stats(evsel_list);
 out:
 	perf_evlist__delete(evsel_list);

Thanks,
Kan

Quoted 17 lines

- Arnaldo

tools/perf/Documentation/perf-stat.txt +0 -0
index 7586fe08ac9a..641caf66ff26 100644
@@ -130,6 +130,8 @@ perf stat --repeat 10 --null --sync --pre 'make -s

O=defconfig-build/clean' -- m --interval-print msecs::

tools/perf/Documentation/perf-stat.txt +2 -0
 	Print count deltas every N milliseconds (minimum: 10ms)
 	example: perf stat -I 1000 -e cycles -a sleep 5
+	The overhead percentage could be high in some cases, for instance
+	with small, sub 100ms intervals.  Use with caution.
 
 --per-socket::
 Aggregate counts per processor socket for system-wide mode

measurements. This

maintainer
#4 lore raw

Em Fri, Oct 02, 2015 at 08:22:06PM +0000, Liang, Kan escreveu:

Quoted 24 lines
Quoted 12 lines
Quoted 7 lines

Review

Quoted 7 lines
(quoted diff) +7 -0
+		if (interval < 10) {
+			pr_err("print interval must be >= 10ms\n");
+			parse_options_usage(stat_usage, options, "I", 1);
+			goto out;
+		} else
+			pr_warning("print interval < 100ms. "
+				   "The overhead percentage could be high

in some cases. "

Quoted 4 lines

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused) · line 1383

Quoted 1 line
tools/perf/builtin-stat.c +1 -0
+				   "Please proceed with caution.\n");

with '-I' 10 this warning flies away quite fast ;-)

Quoted 7 lines
Quoted 4 lines

I guess it's better than nothing, and I'm not sure about putting some sleep after that warning..

Acked-by Jiri Olsa <[email protected]>

Right, this should appear in the man page as well, I added the patch below, we could also print that warning when the workload ends.

OK. We can print the warning message again at the end as the patch below.

+++ b/tools/perf/builtin-stat.c

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused) · line 1383

Quoted 7 lines
tools/perf/builtin-stat.c +4 -0
@@ -1377,6 +1377,11 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 	if (!forever && status != -1 && !interval)
 		print_counters(NULL, argc, argv);
 
+	if (interval && interval < 100)
+		pr_warning("print interval < 100ms. "
+			   "The overhead percentage could be high in some cases. "
+			   "Please proceed with caution.\n");

Yeah, something like that, but the warning then becomes strange, "proceed"? I guess that something like:

pr_warning("print interval < 100ms. "
"The overhead percentage could have been high. " "Take that into account when interpreting the these numbers.\n");

Right?

- Arnaldo

Quoted 4 lines
tools/perf/builtin-stat.c +1 -0
+
 	perf_evlist__free_stats(evsel_list);
 out:
 	perf_evlist__delete(evsel_list);
author
#5 lore raw
Quoted 51 lines

-----Original Message-----
From: Arnaldo Carvalho de Melo [mailto:[email protected]]
Sent: Friday, October 02, 2015 4:40 PM
To: Liang, Kan
Cc: Jiri Olsa; [email protected]; [email protected]; [email protected]; [email protected]; Stephane Eranian
Subject: Re: [PATCH 1/1] perf,stat: reduce interval-print to 10ms

Em Fri, Oct 02, 2015 at 08:22:06PM +0000, Liang, Kan escreveu:

Quoted 3 lines
Quoted 3 lines
Quoted 3 lines

Review

Quoted 3 lines
(quoted diff) +3 -0
+		if (interval < 10) {
+			pr_err("print interval must be >= 10ms\n");
+			parse_options_usage(stat_usage, options,

"I", 1);

Quoted 4 lines
Quoted 4 lines
Quoted 4 lines

Review

Quoted 4 lines
(quoted diff) +4 -0
+			goto out;
+		} else
+			pr_warning("print interval < 100ms. "
+				   "The overhead percentage could

be high

Quoted 8 lines
Quoted 8 lines

in some cases. "

Quoted 7 lines

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused) · line 1383

Quoted 1 line
tools/perf/builtin-stat.c +1 -0
+				   "Please proceed with caution.\n");

with '-I' 10 this warning flies away quite fast ;-)

I guess it's better than nothing, and I'm not sure about putting some sleep after that warning..

Quoted 6 lines
Quoted 4 lines
Quoted 1 line
Acked-by Jiri Olsa <[email protected]>

Right, this should appear in the man page as well, I added the patch below, we could also print that warning when the workload ends.

OK. We can print the warning message again at the end as the patch

below.

Review int cmd_stat(int argc, const char **argv, const

Quoted 3 lines

+++ b/tools/perf/builtin-stat.c

(quoted diff) +0 -0
@@ -1377,6 +1377,11 @@ int cmd_stat(int argc, const char **argv, const

char *prefix __maybe_unused)

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)

Quoted 6 lines
tools/perf/builtin-stat.c +3 -0
 	if (!forever && status != -1 && !interval)
 		print_counters(NULL, argc, argv);
 
+	if (interval && interval < 100)
+		pr_warning("print interval < 100ms. "
+			   "The overhead percentage could be high in some

cases. "

tools/perf/builtin-stat.c int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused) · line 1383

Quoted 1 line
tools/perf/builtin-stat.c +1 -0
+			   "Please proceed with caution.\n");

Yeah, something like that, but the warning then becomes strange, "proceed"? I guess that something like:

Quoted 7 lines

pr_warning("print interval < 100ms. "
"The overhead percentage could have been high.
"
"Take that into account when interpreting the
these numbers.\n");

Right?

Yes.

Thanks,
Kan

Quoted 7 lines

- Arnaldo

Quoted 4 lines
tools/perf/builtin-stat.c +1 -0
+
 	perf_evlist__free_stats(evsel_list);
 out:
 	perf_evlist__delete(evsel_list);
merge bot
#6 lore raw

[tip:perf/core] perf stat: Reduce min --interval-print to 10ms

In reply to [email protected]
perf stat: Reduce min --interval-print to 10ms
Commit-ID:  19afd10410957b1c808c2c49a88e6dd8b23aa894
Gitweb:     http://git.kernel.org/tip/19afd10410957b1c808c2c49a88e6dd8b23aa894
Author:     Kan Liang <[email protected]>
AuthorDate: Fri, 2 Oct 2015 05:04:34 -0400
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Fri, 2 Oct 2015 17:07:55 -0300

perf stat: Reduce min --interval-print to 10ms

The --interval-print parameter was limited to 100ms. However, for example, 10ms is required to do sophisticated bandwidth analysis using uncore events.

The test shows that the overhead of the system-wide uncore monitoring with 10ms interval is only ~2%. So this patch reduces the minimal interval-print allowd to 10ms.

But 10ms may not work well for all cases. For example, when the cpus/threads number is very large, for system-wide core event monitoring the overhead could be high.

To handle this issue, a warning will be displayed when the interval-print is set between 10ms to 100ms. So users can make a decision according to their specific cases.

 # perf stat -e uncore_imc_1/cas_count_read/ -a --interval-print 10 -- sleep 1

print interval < 100ms. The overhead percentage could be high in some cases. Please proceed with caution.
# time counts unit events

      0.010200451               0.10 MiB  uncore_imc_1/cas_count_read/
      0.020475117               0.02 MiB  uncore_imc_1/cas_count_read/
      0.030692800               0.01 MiB  uncore_imc_1/cas_count_read/
      0.040948161               0.02 MiB  uncore_imc_1/cas_count_read/
      0.051159564               0.00 MiB  uncore_imc_1/cas_count_read/
Signed-off-by Kan Liang <[email protected]>
Acked-by Jiri Olsa <[email protected]>
Cc Andi Kleen <[email protected]>
Cc Namhyung Kim <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
[ Added warning about overhead when using sub 100ms intervals to the man page ]
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>
---
 tools/perf/Documentation/perf-stat.txt |  5 +++--
 tools/perf/builtin-stat.c              | 13 +++++++++----
 2 files changed, 12 insertions(+), 6 deletions(-)
tools/perf/Documentation/perf-stat.txt +3 -2
index 47469ab..4e074a6 100644
@@ -128,8 +128,9 @@ perf stat --repeat 10 --null --sync --pre 'make -s O=defconfig-build/clean' -- m
 
 -I msecs::
 --interval-print msecs::
-	Print count deltas every N milliseconds (minimum: 100ms)
-	example: perf stat -I 1000 -e cycles -a sleep 5
+Print count deltas every N milliseconds (minimum: 10ms)
+The overhead percentage could be high in some cases, for instance with small, sub 100ms intervals.  Use with caution.
+	example: 'perf stat -I 1000 -e cycles -a sleep 5'
 
 --per-socket::
 Aggregate counts per processor socket for system-wide mode measurements.  This
tools/perf/builtin-stat.c +9 -4
index a96fb5c..5ef88f7 100644
@@ -1179,7 +1179,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_STRING(0, "post", &post_cmd, "command",
 			"command to run after to the measured command"),
 	OPT_UINTEGER('I', "interval-print", &stat_config.interval,
-		    "print counts at regular interval in ms (>= 100)"),
+		    "print counts at regular interval in ms (>= 10)"),
 	OPT_SET_UINT(0, "per-socket", &stat_config.aggr_mode,
 		     "aggregate counts per processor socket", AGGR_SOCKET),
 	OPT_SET_UINT(0, "per-core", &stat_config.aggr_mode,

@@ -1332,9 +1332,14 @@ int cmd_stat(int argc, const char **argv, const char *prefix __maybe_unused)
 		thread_map__read_comms(evsel_list->threads);
 
 	if (interval && interval < 100) {
-		pr_err("print interval must be >= 100ms\n");
-		parse_options_usage(stat_usage, options, "I", 1);
-		goto out;
+		if (interval < 10) {
+			pr_err("print interval must be >= 10ms\n");
+			parse_options_usage(stat_usage, options, "I", 1);
+			goto out;
+		} else
+			pr_warning("print interval < 100ms. "
+				   "The overhead percentage could be high in some cases. "
+				   "Please proceed with caution.\n");
 	}
 
 	if (perf_evlist__alloc_stats(evsel_list, interval))