* [PATCH 1/2] V3: cyclictest: clean up getopt_long() parameters
@ 2012-05-15 23:36 Frank Rowand
2012-05-15 23:39 ` [PATCH 2/2] V3: cyclictest: report large measured clock latency Frank Rowand
0 siblings, 1 reply; 5+ messages in thread
From: Frank Rowand @ 2012-05-15 23:36 UTC (permalink / raw)
To: linux-rt-users@vger.kernel.org, williams, jkacur; +Cc: dvhart, lclaudio
V3: unchanged from V2
cyclictest getopt_long() parameter clean up.
Clean up before following patch which will add a new option.
Some elements of long_options were not in alphabetical order.
Some elements of optstring were not in alphabetical order.
'-e', '--latency' was missing help text
short form of --duration ('D') was missing from optstring
Change a few instances of leading spaces to tabs.
Add white space to long_options to improve readability.
Some cases of the switch processing the result of
getopt_long() were not in alphabetical order.
Did _not_ clean up option value parsing and processing.
Signed-off-by: Frank Rowand <frank.rowand@am.sony.com>
---
src/cyclictest/cyclictest.c | 143 73 + 70 - 0 !
1 file changed, 73 insertions(+), 70 deletions(-)
Index: b/src/cyclictest/cyclictest.c
===================================================================
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -923,10 +923,11 @@ static void display_help(int error)
"-D --duration=t specify a length for the test run\n"
" default is in seconds, but 'm', 'h', or 'd' maybe added\n"
" to modify value to minutes, hours or days\n"
+ "-e --latency=PM_QOS write PM_QOS to /dev/cpu_dma_latency\n"
"-E --event event tracing (used with -b)\n"
"-f --ftrace function trace (when -b is active)\n"
"-h --histogram=US dump a latency histogram to stdout after the run\n"
- " (with same priority about many threads)\n"
+ " (with same priority about many threads)\n"
" US is the max time to be be tracked in microseconds\n"
"-H --histofall=US same as -h except with an additional summary column\n"
"-i INTV --interval=INTV base interval of thread in us default=1000\n"
@@ -944,6 +945,8 @@ static void display_help(int error)
"-Q --priospread spread priority levels starting at specified value\n"
"-r --relative use relative timer instead of absolute\n"
"-s --system use sys_nanosleep and sys_setitimer\n"
+ "-S --smp Standard SMP testing: options -a -t -n and\n"
+ " same priority of all threads\n"
"-t --threads one thread per available processor\n"
"-t [NUM] --threads=NUM number of threads:\n"
" without NUM, threads = max_cpus\n"
@@ -951,16 +954,14 @@ static void display_help(int error)
"-T TRACE --tracer=TRACER set tracing function\n"
" configured tracers: %s\n"
"-u --unbuffered force unbuffered output for live processing\n"
+ "-U --numa Standard NUMA testing (similar to SMP option)\n"
+ " thread data structures allocated from local node\n"
"-v --verbose output values on stdout for statistics\n"
" format: n:c:v n=tasknum c=count v=value in us\n"
- "-w --wakeup task wakeup tracing (used with -b)\n"
- "-W --wakeuprt rt task wakeup tracing (used with -b)\n"
- "-y POLI --policy=POLI policy of realtime thread, POLI may be fifo(default) or rr\n"
- " format: --policy=fifo(default) or --policy=rr\n"
- "-S --smp Standard SMP testing: options -a -t -n and\n"
- " same priority of all threads\n"
- "-U --numa Standard NUMA testing (similar to SMP option)\n"
- " thread data structures allocated from local node\n",
+ "-w --wakeup task wakeup tracing (used with -b)\n"
+ "-W --wakeuprt rt task wakeup tracing (used with -b)\n"
+ "-y POLI --policy=POLI policy of realtime thread, POLI may be fifo(default) or rr\n"
+ " format: --policy=fifo(default) or --policy=rr\n",
tracers
);
if (error)
@@ -1044,48 +1045,51 @@ static void process_options (int argc, c
for (;;) {
int option_index = 0;
- /** Options for getopt */
+ /*
+ * Options for getopt
+ * Ordered alphabetically by single letter name
+ */
static struct option long_options[] = {
- {"affinity", optional_argument, NULL, 'a'},
- {"breaktrace", required_argument, NULL, 'b'},
- {"preemptirqs", no_argument, NULL, 'B'},
- {"clock", required_argument, NULL, 'c'},
- {"context", no_argument, NULL, 'C'},
- {"distance", required_argument, NULL, 'd'},
- {"event", no_argument, NULL, 'E'},
- {"ftrace", no_argument, NULL, 'f'},
- {"histogram", required_argument, NULL, 'h'},
- {"histofall", required_argument, NULL, 'H'},
- {"interval", required_argument, NULL, 'i'},
- {"irqsoff", no_argument, NULL, 'I'},
- {"loops", required_argument, NULL, 'l'},
- {"mlockall", no_argument, NULL, 'm' },
- {"refresh_on_max", no_argument, NULL, 'M' },
- {"nanosleep", no_argument, NULL, 'n'},
- {"nsecs", no_argument, NULL, 'N'},
- {"oscope", required_argument, NULL, 'o'},
- {"priority", required_argument, NULL, 'p'},
- {"policy", required_argument, NULL, 'y'},
- {"preemptoff", no_argument, NULL, 'P'},
- {"quiet", no_argument, NULL, 'q'},
- {"relative", no_argument, NULL, 'r'},
- {"system", no_argument, NULL, 's'},
- {"threads", optional_argument, NULL, 't'},
- {"unbuffered", no_argument, NULL, 'u'},
- {"verbose", no_argument, NULL, 'v'},
- {"duration",required_argument, NULL, 'D'},
- {"wakeup", no_argument, NULL, 'w'},
- {"wakeuprt", no_argument, NULL, 'W'},
- {"help", no_argument, NULL, '?'},
- {"tracer", required_argument, NULL, 'T'},
- {"traceopt", required_argument, NULL, 'O'},
- {"smp", no_argument, NULL, 'S'},
- {"numa", no_argument, NULL, 'U'},
- {"latency", required_argument, NULL, 'e'},
- {"priospread", no_argument, NULL, 'Q'},
+ {"affinity", optional_argument, NULL, 'a'},
+ {"breaktrace", required_argument, NULL, 'b'},
+ {"preemptirqs", no_argument, NULL, 'B'},
+ {"clock", required_argument, NULL, 'c'},
+ {"context", no_argument, NULL, 'C'},
+ {"distance", required_argument, NULL, 'd'},
+ {"duration", required_argument, NULL, 'D'},
+ {"latency", required_argument, NULL, 'e'},
+ {"event", no_argument, NULL, 'E'},
+ {"ftrace", no_argument, NULL, 'f'},
+ {"histogram", required_argument, NULL, 'h'},
+ {"histofall", required_argument, NULL, 'H'},
+ {"interval", required_argument, NULL, 'i'},
+ {"irqsoff", no_argument, NULL, 'I'},
+ {"loops", required_argument, NULL, 'l'},
+ {"mlockall", no_argument, NULL, 'm'},
+ {"refresh_on_max", no_argument, NULL, 'M'},
+ {"nanosleep", no_argument, NULL, 'n'},
+ {"nsecs", no_argument, NULL, 'N'},
+ {"oscope", required_argument, NULL, 'o'},
+ {"traceopt", required_argument, NULL, 'O'},
+ {"priority", required_argument, NULL, 'p'},
+ {"preemptoff", no_argument, NULL, 'P'},
+ {"quiet", no_argument, NULL, 'q'},
+ {"priospread", no_argument, NULL, 'Q'},
+ {"relative", no_argument, NULL, 'r'},
+ {"system", no_argument, NULL, 's'},
+ {"smp", no_argument, NULL, 'S'},
+ {"threads", optional_argument, NULL, 't'},
+ {"tracer", required_argument, NULL, 'T'},
+ {"unbuffered", no_argument, NULL, 'u'},
+ {"numa", no_argument, NULL, 'U'},
+ {"verbose", no_argument, NULL, 'v'},
+ {"wakeup", no_argument, NULL, 'w'},
+ {"wakeuprt", no_argument, NULL, 'W'},
+ {"policy", required_argument, NULL, 'y'},
+ {"help", no_argument, NULL, '?'},
{NULL, 0, NULL, 0}
};
- int c = getopt_long(argc, argv, "a::b:Bc:Cd:Efh:H:i:Il:MnNo:O:p:PmqQrsSt::uUvD:wWT:y:e:",
+ int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrsSt::uUvD:wWT:y:",
long_options, &option_index);
if (c == -1)
break;
@@ -1109,6 +1113,13 @@ static void process_options (int argc, c
case 'c': clocksel = atoi(optarg); break;
case 'C': tracetype = CTXTSWITCH; break;
case 'd': distance = atoi(optarg); break;
+ case 'D': duration = parse_time_string(optarg); break;
+ case 'e': /* power management latency target value */
+ /* note: default is 0 (zero) */
+ latency_target_value = atoi(optarg);
+ if (latency_target_value < 0)
+ latency_target_value = 0;
+ break;
case 'E': enable_events = 1; break;
case 'f': tracetype = FUNCTION; ftrace = 1; break;
case 'H': histofall = 1; /* fall through */
@@ -1124,6 +1135,8 @@ static void process_options (int argc, c
}
break;
case 'l': max_cycles = atoi(optarg); break;
+ case 'm': lockall = 1; break;
+ case 'M': refresh_on_max = 1; break;
case 'n': use_nanosleep = MODE_CLOCK_NANOSLEEP; break;
case 'N': use_nsecs = 1; break;
case 'o': oscope_reduction = atoi(optarg); break;
@@ -1146,6 +1159,14 @@ static void process_options (int argc, c
case 'Q': priospread = 1; break;
case 'r': timermode = TIMER_RELTIME; break;
case 's': use_system = MODE_SYS_OFFSET; break;
+ case 'S': /* SMP testing */
+ if (numa)
+ fatal("numa and smp options are mutually exclusive\n");
+ smp = 1;
+ num_threads = max_cpus;
+ setaffinity = AFFINITY_USEALL;
+ use_nanosleep = MODE_CLOCK_NANOSLEEP;
+ break;
case 't':
if (smp) {
warn("-t ignored due to --smp\n");
@@ -1163,22 +1184,6 @@ static void process_options (int argc, c
strncpy(tracer, optarg, sizeof(tracer));
break;
case 'u': setvbuf(stdout, NULL, _IONBF, 0); break;
- case 'v': verbose = 1; break;
- case 'm': lockall = 1; break;
- case 'M': refresh_on_max = 1; break;
- case 'D': duration = parse_time_string(optarg);
- break;
- case 'w': tracetype = WAKEUP; break;
- case 'W': tracetype = WAKEUPRT; break;
- case 'y': handlepolicy(optarg); break;
- case 'S': /* SMP testing */
- if (numa)
- fatal("numa and smp options are mutually exclusive\n");
- smp = 1;
- num_threads = max_cpus;
- setaffinity = AFFINITY_USEALL;
- use_nanosleep = MODE_CLOCK_NANOSLEEP;
- break;
case 'U': /* NUMA testing */
if (smp)
fatal("numa and smp options are mutually exclusive\n");
@@ -1194,12 +1199,10 @@ static void process_options (int argc, c
warn("ignoring --numa or -U\n");
#endif
break;
- case 'e': /* power management latency target value */
- /* note: default is 0 (zero) */
- latency_target_value = atoi(optarg);
- if (latency_target_value < 0)
- latency_target_value = 0;
- break;
+ case 'v': verbose = 1; break;
+ case 'w': tracetype = WAKEUP; break;
+ case 'W': tracetype = WAKEUPRT; break;
+ case 'y': handlepolicy(optarg); break;
case '?': display_help(0); break;
}
^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH 2/2] V3: cyclictest: report large measured clock latency
2012-05-15 23:36 [PATCH 1/2] V3: cyclictest: clean up getopt_long() parameters Frank Rowand
@ 2012-05-15 23:39 ` Frank Rowand
2012-05-15 23:44 ` Frank Rowand
0 siblings, 1 reply; 5+ messages in thread
From: Frank Rowand @ 2012-05-15 23:39 UTC (permalink / raw)
To: linux-rt-users@vger.kernel.org, williams@redhat.com,
jkacur@redhat.com
Cc: dvhart@linux.intel.com, lclaudio@uudg.org
V3: Use src/lib/error.c functions instead of fprintf.
Fix printf format warnings for 32 bit vs 64 bit systems with cast.
Fix bad continuation line white space prefix.
Remove unused variable zero_diff.
cyclictest: ARM panda clock resolution will be ~30 usec unless
CONFIG_OMAP_32K_TIMER=n, resulting in a poor latency report.
This patch does _not_ fix the problem, it merely provides the
instrumentation to make it visible. The value of measured
resolution is useful information for any system.
Signed-off-by: Frank Rowand <frank.rowand@am.sony.com>
---
src/cyclictest/cyclictest.c | 109 108 + 1 - 0 !
1 file changed, 108 insertions(+), 1 deletion(-)
Index: b/src/cyclictest/cyclictest.c
===================================================================
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -174,6 +174,8 @@ static int use_nsecs = 0;
static int refresh_on_max;
static int force_sched_other;
static int priospread = 0;
+static int check_clock_resolution;
+static int ct_debug;
static pthread_cond_t refresh_on_max_cond = PTHREAD_COND_INITIALIZER;
static pthread_mutex_t refresh_on_max_lock = PTHREAD_MUTEX_INITIALIZER;
@@ -944,6 +946,9 @@ static void display_help(int error)
"-q --quiet print only a summary on exit\n"
"-Q --priospread spread priority levels starting at specified value\n"
"-r --relative use relative timer instead of absolute\n"
+ "-R --resolution check clock resolution, calling clock_gettime() many\n"
+ " times. list of clock_gettime() values will be\n"
+ " reported with -X\n"
"-s --system use sys_nanosleep and sys_setitimer\n"
"-S --smp Standard SMP testing: options -a -t -n and\n"
" same priority of all threads\n"
@@ -960,6 +965,7 @@ static void display_help(int error)
" format: n:c:v n=tasknum c=count v=value in us\n"
"-w --wakeup task wakeup tracing (used with -b)\n"
"-W --wakeuprt rt task wakeup tracing (used with -b)\n"
+ "-X --dbg_cyclictest print info useful for debugging cyclictest\n"
"-y POLI --policy=POLI policy of realtime thread, POLI may be fifo(default) or rr\n"
" format: --policy=fifo(default) or --policy=rr\n",
tracers
@@ -1076,6 +1082,7 @@ static void process_options (int argc, c
{"quiet", no_argument, NULL, 'q'},
{"priospread", no_argument, NULL, 'Q'},
{"relative", no_argument, NULL, 'r'},
+ {"resolution", no_argument, NULL, 'R'},
{"system", no_argument, NULL, 's'},
{"smp", no_argument, NULL, 'S'},
{"threads", optional_argument, NULL, 't'},
@@ -1085,11 +1092,12 @@ static void process_options (int argc, c
{"verbose", no_argument, NULL, 'v'},
{"wakeup", no_argument, NULL, 'w'},
{"wakeuprt", no_argument, NULL, 'W'},
+ {"dbg_cyclictest", no_argument, NULL, 'X'},
{"policy", required_argument, NULL, 'y'},
{"help", no_argument, NULL, '?'},
{NULL, 0, NULL, 0}
};
- int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrsSt::uUvD:wWT:y:",
+ int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrRsSt::uUvD:wWXT:y:",
long_options, &option_index);
if (c == -1)
break;
@@ -1158,6 +1166,7 @@ static void process_options (int argc, c
case 'q': quiet = 1; break;
case 'Q': priospread = 1; break;
case 'r': timermode = TIMER_RELTIME; break;
+ case 'R': check_clock_resolution = 1; break;
case 's': use_system = MODE_SYS_OFFSET; break;
case 'S': /* SMP testing */
if (numa)
@@ -1202,6 +1211,7 @@ static void process_options (int argc, c
case 'v': verbose = 1; break;
case 'w': tracetype = WAKEUP; break;
case 'W': tracetype = WAKEUPRT; break;
+ case 'X': ct_debug = 1; break;
case 'y': handlepolicy(optarg); break;
case '?': display_help(0); break;
@@ -1483,6 +1493,103 @@ int main(int argc, char **argv)
if (check_timer())
warn("High resolution timers not available\n");
+ if (check_clock_resolution) {
+ int clock;
+ uint64_t diff;
+ int k;
+ uint64_t min_non_zero_diff = UINT64_MAX;
+ struct timespec now;
+ struct timespec prev;
+ uint64_t reported_resolution = UINT64_MAX;
+ struct timespec res;
+ struct timespec *time;
+ int times;
+
+ clock = clocksources[clocksel];
+
+ if (clock_getres(clock, &res)) {
+ warn("clock_getres failed");
+ } else {
+ reported_resolution = (NSEC_PER_SEC * res.tv_sec) + res.tv_nsec;
+ }
+
+
+ /*
+ * Calculate how many calls to clock_gettime are needed.
+ * Then call it that many times.
+ * Goal is to collect timestamps for ~ 0.001 sec.
+ * This will reliably capture resolution <= 500 usec.
+ */
+ times = 1000;
+ clock_gettime(clock, &prev);
+ for (k=0; k < times; k++) {
+ clock_gettime(clock, &now);
+ }
+
+ diff = calcdiff_ns(now, prev);
+ if (diff == 0) {
+ /*
+ * No clock rollover occurred.
+ * Use the default value for times.
+ */
+ times = -1;
+ } else {
+ int call_time;
+ call_time = diff / times; /* duration 1 call */
+ times = NSEC_PER_SEC / call_time; /* calls per second */
+ times /= 1000; /* calls per msec */
+ if (times < 1000)
+ times = 1000;
+ }
+ /* sanity check */
+ if ((times <= 0) || (times > 100000))
+ times = 100000;
+
+ time = calloc(times, sizeof(*time));
+
+ for (k=0; k < times; k++) {
+ clock_gettime(clock, &time[k]);
+ }
+
+ if (ct_debug) {
+ info("For %d consecutive calls to clock_gettime():\n", times);
+ info("time, delta time (nsec)\n");
+ }
+
+ prev = time[0];
+ for (k=1; k < times; k++) {
+
+ diff = calcdiff_ns(time[k], prev);
+ prev = time[k];
+
+ if (diff && (diff < min_non_zero_diff)) {
+ min_non_zero_diff = diff;
+ }
+
+ if (ct_debug)
+ info("%ld.%06ld %5llu\n",
+ time[k].tv_sec, time[k].tv_nsec,
+ (unsigned long long)diff);
+ }
+
+ free(time);
+
+
+ if (verbose ||
+ (min_non_zero_diff && (min_non_zero_diff > reported_resolution))) {
+ /*
+ * Measured clock resolution includes the time to call
+ * clock_gettime(), so it will be slightly larger than
+ * actual resolution.
+ */
+ warn("reported clock resolution: %llu nsec\n",
+ (unsigned long long)reported_resolution);
+ warn("measured clock resolution approximately: %llu nsec\n",
+ (unsigned long long)min_non_zero_diff);
+ }
+
+ }
+
mode = use_nanosleep + use_system;
sigemptyset(&sigset);
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH 2/2] V3: cyclictest: report large measured clock latency
2012-05-15 23:39 ` [PATCH 2/2] V3: cyclictest: report large measured clock latency Frank Rowand
@ 2012-05-15 23:44 ` Frank Rowand
0 siblings, 0 replies; 5+ messages in thread
From: Frank Rowand @ 2012-05-15 23:44 UTC (permalink / raw)
To: linux-rt-users@vger.kernel.org, williams@redhat.com,
jkacur@redhat.com
Cc: dvhart@linux.intel.com, lclaudio@uudg.org
On 05/15/12 16:39, Frank Rowand wrote:
>
> V3: Use src/lib/error.c functions instead of fprintf.
> Fix printf format warnings for 32 bit vs 64 bit systems with cast.
One issue with using warn() and info() instead of fprintf() is that
the compiler no longer warns about format mismatches. Just an FYI...
> Fix bad continuation line white space prefix.
> Remove unused variable zero_diff.
>
< snip >
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH 2/2] V3: cyclictest: report large measured clock latency
[not found] <502965C1.2090409@am.sony.com>
@ 2012-10-15 23:43 ` John Kacur
2012-10-16 0:18 ` Frank Rowand
0 siblings, 1 reply; 5+ messages in thread
From: John Kacur @ 2012-10-15 23:43 UTC (permalink / raw)
To: Frank Rowand; +Cc: jkacur@redhat.com, linux-rt-users
On Mon, 13 Aug 2012, Frank Rowand wrote:
Hi Frank - I added the extra comment to your patch as you requested
"One issue with using warn() and info() instead of fprintf() is that
the compiler no longer warns about format mismatches."
Another thing about using the warn function - I'm not sure I like that
WARN: printed out when you use your -R
./cyclictest -R
WARN: reported clock resolution: 1 nsec
WARN: measured clock resolution approximately: 699 nsec
Nice patch though.
Signed-off-by: John Kacur <jkacur@redhat.com>
>
> V3: Use src/lib/error.c functions instead of fprintf.
> Fix printf format warnings for 32 bit vs 64 bit systems with cast.
> Fix bad continuation line white space prefix.
> Remove unused variable zero_diff.
>
> cyclictest: ARM panda clock resolution will be ~30 usec unless
> CONFIG_OMAP_32K_TIMER=n, resulting in a poor latency report.
>
> This patch does _not_ fix the problem, it merely provides the
> instrumentation to make it visible. The value of measured
> resolution is useful information for any system.
>
> Signed-off-by: Frank Rowand <frank.rowand@am.sony.com>
> ---
> src/cyclictest/cyclictest.c | 109 108 + 1 - 0 !
> 1 file changed, 108 insertions(+), 1 deletion(-)
>
> Index: b/src/cyclictest/cyclictest.c
> ===================================================================
> --- a/src/cyclictest/cyclictest.c
> +++ b/src/cyclictest/cyclictest.c
> @@ -174,6 +174,8 @@ static int use_nsecs = 0;
> static int refresh_on_max;
> static int force_sched_other;
> static int priospread = 0;
> +static int check_clock_resolution;
> +static int ct_debug;
>
> static pthread_cond_t refresh_on_max_cond = PTHREAD_COND_INITIALIZER;
> static pthread_mutex_t refresh_on_max_lock = PTHREAD_MUTEX_INITIALIZER;
> @@ -944,6 +946,9 @@ static void display_help(int error)
> "-q --quiet print only a summary on exit\n"
> "-Q --priospread spread priority levels starting at specified value\n"
> "-r --relative use relative timer instead of absolute\n"
> + "-R --resolution check clock resolution, calling clock_gettime() many\n"
> + " times. list of clock_gettime() values will be\n"
> + " reported with -X\n"
> "-s --system use sys_nanosleep and sys_setitimer\n"
> "-S --smp Standard SMP testing: options -a -t -n and\n"
> " same priority of all threads\n"
> @@ -960,6 +965,7 @@ static void display_help(int error)
> " format: n:c:v n=tasknum c=count v=value in us\n"
> "-w --wakeup task wakeup tracing (used with -b)\n"
> "-W --wakeuprt rt task wakeup tracing (used with -b)\n"
> + "-X --dbg_cyclictest print info useful for debugging cyclictest\n"
> "-y POLI --policy=POLI policy of realtime thread, POLI may be fifo(default) or rr\n"
> " format: --policy=fifo(default) or --policy=rr\n",
> tracers
> @@ -1076,6 +1082,7 @@ static void process_options (int argc, c
> {"quiet", no_argument, NULL, 'q'},
> {"priospread", no_argument, NULL, 'Q'},
> {"relative", no_argument, NULL, 'r'},
> + {"resolution", no_argument, NULL, 'R'},
> {"system", no_argument, NULL, 's'},
> {"smp", no_argument, NULL, 'S'},
> {"threads", optional_argument, NULL, 't'},
> @@ -1085,11 +1092,12 @@ static void process_options (int argc, c
> {"verbose", no_argument, NULL, 'v'},
> {"wakeup", no_argument, NULL, 'w'},
> {"wakeuprt", no_argument, NULL, 'W'},
> + {"dbg_cyclictest", no_argument, NULL, 'X'},
> {"policy", required_argument, NULL, 'y'},
> {"help", no_argument, NULL, '?'},
> {NULL, 0, NULL, 0}
> };
> - int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrsSt::uUvD:wWT:y:",
> + int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrRsSt::uUvD:wWXT:y:",
> long_options, &option_index);
> if (c == -1)
> break;
> @@ -1158,6 +1166,7 @@ static void process_options (int argc, c
> case 'q': quiet = 1; break;
> case 'Q': priospread = 1; break;
> case 'r': timermode = TIMER_RELTIME; break;
> + case 'R': check_clock_resolution = 1; break;
> case 's': use_system = MODE_SYS_OFFSET; break;
> case 'S': /* SMP testing */
> if (numa)
> @@ -1202,6 +1211,7 @@ static void process_options (int argc, c
> case 'v': verbose = 1; break;
> case 'w': tracetype = WAKEUP; break;
> case 'W': tracetype = WAKEUPRT; break;
> + case 'X': ct_debug = 1; break;
> case 'y': handlepolicy(optarg); break;
>
> case '?': display_help(0); break;
> @@ -1483,6 +1493,103 @@ int main(int argc, char **argv)
> if (check_timer())
> warn("High resolution timers not available\n");
>
> + if (check_clock_resolution) {
> + int clock;
> + uint64_t diff;
> + int k;
> + uint64_t min_non_zero_diff = UINT64_MAX;
> + struct timespec now;
> + struct timespec prev;
> + uint64_t reported_resolution = UINT64_MAX;
> + struct timespec res;
> + struct timespec *time;
> + int times;
> +
> + clock = clocksources[clocksel];
> +
> + if (clock_getres(clock, &res)) {
> + warn("clock_getres failed");
> + } else {
> + reported_resolution = (NSEC_PER_SEC * res.tv_sec) + res.tv_nsec;
> + }
> +
> +
> + /*
> + * Calculate how many calls to clock_gettime are needed.
> + * Then call it that many times.
> + * Goal is to collect timestamps for ~ 0.001 sec.
> + * This will reliably capture resolution <= 500 usec.
> + */
> + times = 1000;
> + clock_gettime(clock, &prev);
> + for (k=0; k < times; k++) {
> + clock_gettime(clock, &now);
> + }
> +
> + diff = calcdiff_ns(now, prev);
> + if (diff == 0) {
> + /*
> + * No clock rollover occurred.
> + * Use the default value for times.
> + */
> + times = -1;
> + } else {
> + int call_time;
> + call_time = diff / times; /* duration 1 call */
> + times = NSEC_PER_SEC / call_time; /* calls per second */
> + times /= 1000; /* calls per msec */
> + if (times < 1000)
> + times = 1000;
> + }
> + /* sanity check */
> + if ((times <= 0) || (times > 100000))
> + times = 100000;
> +
> + time = calloc(times, sizeof(*time));
> +
> + for (k=0; k < times; k++) {
> + clock_gettime(clock, &time[k]);
> + }
> +
> + if (ct_debug) {
> + info("For %d consecutive calls to clock_gettime():\n", times);
> + info("time, delta time (nsec)\n");
> + }
> +
> + prev = time[0];
> + for (k=1; k < times; k++) {
> +
> + diff = calcdiff_ns(time[k], prev);
> + prev = time[k];
> +
> + if (diff && (diff < min_non_zero_diff)) {
> + min_non_zero_diff = diff;
> + }
> +
> + if (ct_debug)
> + info("%ld.%06ld %5llu\n",
> + time[k].tv_sec, time[k].tv_nsec,
> + (unsigned long long)diff);
> + }
> +
> + free(time);
> +
> +
> + if (verbose ||
> + (min_non_zero_diff && (min_non_zero_diff > reported_resolution))) {
> + /*
> + * Measured clock resolution includes the time to call
> + * clock_gettime(), so it will be slightly larger than
> + * actual resolution.
> + */
> + warn("reported clock resolution: %llu nsec\n",
> + (unsigned long long)reported_resolution);
> + warn("measured clock resolution approximately: %llu nsec\n",
> + (unsigned long long)min_non_zero_diff);
> + }
> +
> + }
> +
> mode = use_nanosleep + use_system;
>
> sigemptyset(&sigset);
>
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH 2/2] V3: cyclictest: report large measured clock latency
2012-10-15 23:43 ` John Kacur
@ 2012-10-16 0:18 ` Frank Rowand
0 siblings, 0 replies; 5+ messages in thread
From: Frank Rowand @ 2012-10-16 0:18 UTC (permalink / raw)
To: John Kacur; +Cc: Rowand, Frank, linux-rt-users@vger.kernel.org
On 10/15/12 16:43, John Kacur wrote:
>
>
> On Mon, 13 Aug 2012, Frank Rowand wrote:
>
> Hi Frank - I added the extra comment to your patch as you requested
> "One issue with using warn() and info() instead of fprintf() is that
> the compiler no longer warns about format mismatches."
>
> Another thing about using the warn function - I'm not sure I like that
> WARN: printed out when you use your -R
>
> ./cyclictest -R
> WARN: reported clock resolution: 1 nsec
> WARN: measured clock resolution approximately: 699 nsec
The warns could be printed "if (ct_debug && ...)" instead of
"if (verbose || ...)", because -verbose is really about printing data
for each event instead of a more traditional meaning.
>
> Nice patch though.
> Signed-off-by: John Kacur <jkacur@redhat.com>
>>
>> V3: Use src/lib/error.c functions instead of fprintf.
>> Fix printf format warnings for 32 bit vs 64 bit systems with cast.
>> Fix bad continuation line white space prefix.
>> Remove unused variable zero_diff.
>>
>> cyclictest: ARM panda clock resolution will be ~30 usec unless
>> CONFIG_OMAP_32K_TIMER=n, resulting in a poor latency report.
>>
>> This patch does _not_ fix the problem, it merely provides the
>> instrumentation to make it visible. The value of measured
>> resolution is useful information for any system.
>>
>> Signed-off-by: Frank Rowand <frank.rowand@am.sony.com>
>> ---
>> src/cyclictest/cyclictest.c | 109 108 + 1 - 0 !
>> 1 file changed, 108 insertions(+), 1 deletion(-)
>>
>> Index: b/src/cyclictest/cyclictest.c
>> ===================================================================
>> --- a/src/cyclictest/cyclictest.c
>> +++ b/src/cyclictest/cyclictest.c
>> @@ -174,6 +174,8 @@ static int use_nsecs = 0;
>> static int refresh_on_max;
>> static int force_sched_other;
>> static int priospread = 0;
>> +static int check_clock_resolution;
>> +static int ct_debug;
>>
>> static pthread_cond_t refresh_on_max_cond = PTHREAD_COND_INITIALIZER;
>> static pthread_mutex_t refresh_on_max_lock = PTHREAD_MUTEX_INITIALIZER;
>> @@ -944,6 +946,9 @@ static void display_help(int error)
>> "-q --quiet print only a summary on exit\n"
>> "-Q --priospread spread priority levels starting at specified value\n"
>> "-r --relative use relative timer instead of absolute\n"
>> + "-R --resolution check clock resolution, calling clock_gettime() many\n"
>> + " times. list of clock_gettime() values will be\n"
>> + " reported with -X\n"
>> "-s --system use sys_nanosleep and sys_setitimer\n"
>> "-S --smp Standard SMP testing: options -a -t -n and\n"
>> " same priority of all threads\n"
>> @@ -960,6 +965,7 @@ static void display_help(int error)
>> " format: n:c:v n=tasknum c=count v=value in us\n"
>> "-w --wakeup task wakeup tracing (used with -b)\n"
>> "-W --wakeuprt rt task wakeup tracing (used with -b)\n"
>> + "-X --dbg_cyclictest print info useful for debugging cyclictest\n"
>> "-y POLI --policy=POLI policy of realtime thread, POLI may be fifo(default) or rr\n"
>> " format: --policy=fifo(default) or --policy=rr\n",
>> tracers
>> @@ -1076,6 +1082,7 @@ static void process_options (int argc, c
>> {"quiet", no_argument, NULL, 'q'},
>> {"priospread", no_argument, NULL, 'Q'},
>> {"relative", no_argument, NULL, 'r'},
>> + {"resolution", no_argument, NULL, 'R'},
>> {"system", no_argument, NULL, 's'},
>> {"smp", no_argument, NULL, 'S'},
>> {"threads", optional_argument, NULL, 't'},
>> @@ -1085,11 +1092,12 @@ static void process_options (int argc, c
>> {"verbose", no_argument, NULL, 'v'},
>> {"wakeup", no_argument, NULL, 'w'},
>> {"wakeuprt", no_argument, NULL, 'W'},
>> + {"dbg_cyclictest", no_argument, NULL, 'X'},
>> {"policy", required_argument, NULL, 'y'},
>> {"help", no_argument, NULL, '?'},
>> {NULL, 0, NULL, 0}
>> };
>> - int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrsSt::uUvD:wWT:y:",
>> + int c = getopt_long(argc, argv, "a::b:Bc:Cd:D:e:Efh:H:i:Il:MnNo:O:p:PmqQrRsSt::uUvD:wWXT:y:",
>> long_options, &option_index);
>> if (c == -1)
>> break;
>> @@ -1158,6 +1166,7 @@ static void process_options (int argc, c
>> case 'q': quiet = 1; break;
>> case 'Q': priospread = 1; break;
>> case 'r': timermode = TIMER_RELTIME; break;
>> + case 'R': check_clock_resolution = 1; break;
>> case 's': use_system = MODE_SYS_OFFSET; break;
>> case 'S': /* SMP testing */
>> if (numa)
>> @@ -1202,6 +1211,7 @@ static void process_options (int argc, c
>> case 'v': verbose = 1; break;
>> case 'w': tracetype = WAKEUP; break;
>> case 'W': tracetype = WAKEUPRT; break;
>> + case 'X': ct_debug = 1; break;
>> case 'y': handlepolicy(optarg); break;
>>
>> case '?': display_help(0); break;
>> @@ -1483,6 +1493,103 @@ int main(int argc, char **argv)
>> if (check_timer())
>> warn("High resolution timers not available\n");
>>
>> + if (check_clock_resolution) {
>> + int clock;
>> + uint64_t diff;
>> + int k;
>> + uint64_t min_non_zero_diff = UINT64_MAX;
>> + struct timespec now;
>> + struct timespec prev;
>> + uint64_t reported_resolution = UINT64_MAX;
>> + struct timespec res;
>> + struct timespec *time;
>> + int times;
>> +
>> + clock = clocksources[clocksel];
>> +
>> + if (clock_getres(clock, &res)) {
>> + warn("clock_getres failed");
>> + } else {
>> + reported_resolution = (NSEC_PER_SEC * res.tv_sec) + res.tv_nsec;
>> + }
>> +
>> +
>> + /*
>> + * Calculate how many calls to clock_gettime are needed.
>> + * Then call it that many times.
>> + * Goal is to collect timestamps for ~ 0.001 sec.
>> + * This will reliably capture resolution <= 500 usec.
>> + */
>> + times = 1000;
>> + clock_gettime(clock, &prev);
>> + for (k=0; k < times; k++) {
>> + clock_gettime(clock, &now);
>> + }
>> +
>> + diff = calcdiff_ns(now, prev);
>> + if (diff == 0) {
>> + /*
>> + * No clock rollover occurred.
>> + * Use the default value for times.
>> + */
>> + times = -1;
>> + } else {
>> + int call_time;
>> + call_time = diff / times; /* duration 1 call */
>> + times = NSEC_PER_SEC / call_time; /* calls per second */
>> + times /= 1000; /* calls per msec */
>> + if (times < 1000)
>> + times = 1000;
>> + }
>> + /* sanity check */
>> + if ((times <= 0) || (times > 100000))
>> + times = 100000;
>> +
>> + time = calloc(times, sizeof(*time));
>> +
>> + for (k=0; k < times; k++) {
>> + clock_gettime(clock, &time[k]);
>> + }
>> +
>> + if (ct_debug) {
>> + info("For %d consecutive calls to clock_gettime():\n", times);
>> + info("time, delta time (nsec)\n");
>> + }
>> +
>> + prev = time[0];
>> + for (k=1; k < times; k++) {
>> +
>> + diff = calcdiff_ns(time[k], prev);
>> + prev = time[k];
>> +
>> + if (diff && (diff < min_non_zero_diff)) {
>> + min_non_zero_diff = diff;
>> + }
>> +
>> + if (ct_debug)
>> + info("%ld.%06ld %5llu\n",
>> + time[k].tv_sec, time[k].tv_nsec,
>> + (unsigned long long)diff);
>> + }
>> +
>> + free(time);
>> +
>> +
>> + if (verbose ||
>> + (min_non_zero_diff && (min_non_zero_diff > reported_resolution))) {
>> + /*
>> + * Measured clock resolution includes the time to call
>> + * clock_gettime(), so it will be slightly larger than
>> + * actual resolution.
>> + */
>> + warn("reported clock resolution: %llu nsec\n",
>> + (unsigned long long)reported_resolution);
>> + warn("measured clock resolution approximately: %llu nsec\n",
>> + (unsigned long long)min_non_zero_diff);
>> + }
>> +
>> + }
>> +
>> mode = use_nanosleep + use_system;
>>
>> sigemptyset(&sigset);
>>
>>
>
> .
>
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2012-10-16 0:18 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2012-05-15 23:36 [PATCH 1/2] V3: cyclictest: clean up getopt_long() parameters Frank Rowand
2012-05-15 23:39 ` [PATCH 2/2] V3: cyclictest: report large measured clock latency Frank Rowand
2012-05-15 23:44 ` Frank Rowand
[not found] <502965C1.2090409@am.sony.com>
2012-10-15 23:43 ` John Kacur
2012-10-16 0:18 ` Frank Rowand
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.