Current-Users archive
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]
Re: ATF tests still failing to complete within 2 hours on amd64
On Dec 14, 11:16am, paul%whooppee.com@localhost (Paul Goyette) wrote:
-- Subject: Re: ATF tests still failing to complete within 2 hours on amd64
| On Wed, 14 Dec 2011, Andreas Gustafsson wrote:
|
| > Christos Zoulas wrote:
| >> Is there a way atf can produce a report on how long each test took?
| >
| > Not to my knowledge.
| >
| >> It would be useful to have this information over time.
| >
| > The qemu process that runs the tests is invoked via time(1) and the
| > output is part of the archived logs, so the total run time can be
| > extracted, but not that of the individual tests.
|
| I'm also working on modifying the atf command used by anita in order to
| add a time-stamp.
|
| And I've separately suggested time-stamping as a desirable enhancement
| to jmmv in private email exchange. I think he said that he would look
| at it in the context of kyua...
Here's a simple patch that adds a timestamp in the form:
[[[Xd]Yh]Zm]Ws]Uns
If people think that this is ok, I will add it properly and document it.
Then we can run the tests in an older tree and then compare with the newer.
christos
Index: atf-c/tc.c
===================================================================
RCS file: /cvsroot/src/external/bsd/atf/dist/atf-c/tc.c,v
retrieving revision 1.11
diff -u -p -u -r1.11 tc.c
--- atf-c/tc.c 9 Nov 2011 14:42:42 -0000 1.11
+++ atf-c/tc.c 14 Dec 2011 23:21:00 -0000
@@ -39,6 +39,7 @@
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
+#include <time.h>
#include "atf-c/defs.h"
#include "atf-c/error.h"
@@ -74,6 +75,7 @@ struct context {
size_t expect_fail_count;
int expect_exitcode;
int expect_signo;
+ struct timespec start_time;
};
static void context_init(struct context *, const atf_tc_t *, const char *);
@@ -81,8 +83,8 @@ static void check_fatal_error(atf_error_
static void report_fatal_error(const char *, ...)
ATF_DEFS_ATTRIBUTE_NORETURN;
static atf_error_t write_resfile(const int, const char *, const int,
- const atf_dynstr_t *);
-static void create_resfile(const char *, const char *, const int,
+ const atf_dynstr_t *, const struct timespec
*);
+static void create_resfile(const struct context *, const char *, const int,
atf_dynstr_t *);
static void error_in_expect(struct context *, const char *, ...)
ATF_DEFS_ATTRIBUTE_NORETURN;
@@ -112,6 +114,7 @@ context_init(struct context *ctx, const
ctx->tc = tc;
ctx->resfile = resfile;
ctx->fail_count = 0;
+ clock_gettime(CLOCK_MONOTONIC, &ctx->start_time);
ctx->expect = EXPECT_PASS;
check_fatal_error(atf_dynstr_init(&ctx->expect_reason));
ctx->expect_previous_fail_count = 0;
@@ -146,6 +149,54 @@ report_fatal_error(const char *msg, ...)
abort();
}
+#define DY (24 * HR)
+#define HR (MN * 60)
+#define MN 60
+#define SC 1
+static const struct {
+ int divisor;
+ const char *fmt;
+} timeunit[] = {
+ { DY, "d" },
+ { HR, "h" },
+ { MN, "m" },
+ { SC, "s" },
+};
+
+/*
+ * Needs up to 9 iovecs
+ */
+static size_t
+fmttime(struct iovec iov[], size_t count, const struct timespec *duration,
+ char *buf, size_t buflen)
+{
+ time_t sec = duration->tv_sec;
+ long nsec = duration->tv_nsec;
+ size_t bi;
+ int len;
+
+ bi = 0;
+ for (size_t i = 0; i < __arraycount(timeunit); i++) {
+ if (sec < timeunit[i].divisor && bi == 0)
+ continue;
+ time_t pr = sec / timeunit[i].divisor;
+ sec %= timeunit[i].divisor;
+ INV(buflen > bi);
+ len = snprintf(&buf[bi], buflen - bi, "%lld", (long long)pr);
+ INV(len > 0);
+ iov[count].iov_base = &buf[bi];
+ iov[count++].iov_len = len;
+ iov[count].iov_base = __UNCONST(timeunit[i].fmt);
+ iov[count++].iov_len = strlen(timeunit[i].fmt);
+ bi += len + 1;
+ }
+ len = snprintf(&buf[bi], buflen - bi, "%ldns", nsec);
+ iov[count].iov_base = &buf[bi];
+ iov[count++].iov_len = len;
+ return count;
+}
+
+
/** Writes to a results file.
*
* The results file is supposed to be already open.
@@ -155,14 +206,15 @@ report_fatal_error(const char *msg, ...)
*/
static atf_error_t
write_resfile(const int fd, const char *result, const int arg,
- const atf_dynstr_t *reason)
+ const atf_dynstr_t *reason, const struct timespec *duration)
{
static char NL[] = "\n", CS[] = ": ";
- char buf[64];
+ char buf[64], timebuf[512];
const char *r;
- struct iovec iov[5];
+ struct iovec iov[20];
ssize_t ret;
- int count = 0;
+ size_t count = 0;
+
INV(arg == -1 || reason != NULL);
@@ -183,6 +235,10 @@ write_resfile(const int fd, const char *
iov[count++].iov_len = strlen(r);
}
+ iov[count].iov_base = CS;
+ iov[count++].iov_len = sizeof(CS) - 1;
+ count = fmttime(iov, count, duration, timebuf, sizeof(timebuf));
+
iov[count].iov_base = NL;
iov[count++].iov_len = sizeof(NL) - 1;
@@ -204,15 +260,19 @@ write_resfile(const int fd, const char *
* not return any error code.
*/
static void
-create_resfile(const char *resfile, const char *result, const int arg,
+create_resfile(const struct context *ctx, const char *result, const int arg,
atf_dynstr_t *reason)
{
atf_error_t err;
+ const char *resfile = ctx->resfile;
+ struct timespec end_time, duration;
+ clock_gettime(CLOCK_MONOTONIC, &end_time);
+ timespecsub(&end_time, &ctx->start_time, &duration);
if (strcmp("/dev/stdout", resfile) == 0) {
- err = write_resfile(STDOUT_FILENO, result, arg, reason);
+ err = write_resfile(STDOUT_FILENO, result, arg, reason, &duration);
} else if (strcmp("/dev/stderr", resfile) == 0) {
- err = write_resfile(STDERR_FILENO, result, arg, reason);
+ err = write_resfile(STDERR_FILENO, result, arg, reason, &duration);
} else {
const int fd = open(resfile, O_WRONLY | O_CREAT | O_TRUNC,
S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
@@ -220,7 +280,7 @@ create_resfile(const char *resfile, cons
err = atf_libc_error(errno, "Cannot create results file '%s'",
resfile);
} else {
- err = write_resfile(fd, result, arg, reason);
+ err = write_resfile(fd, result, arg, reason, &duration);
close(fd);
}
}
@@ -282,7 +342,7 @@ expected_failure(struct context *ctx, at
{
check_fatal_error(atf_dynstr_prepend_fmt(reason, "%s: ",
atf_dynstr_cstring(&ctx->expect_reason)));
- create_resfile(ctx->resfile, "expected_failure", -1, reason);
+ create_resfile(ctx, "expected_failure", -1, reason);
exit(EXIT_SUCCESS);
}
@@ -292,7 +352,7 @@ fail_requirement(struct context *ctx, at
if (ctx->expect == EXPECT_FAIL) {
expected_failure(ctx, reason);
} else if (ctx->expect == EXPECT_PASS) {
- create_resfile(ctx->resfile, "failed", -1, reason);
+ create_resfile(ctx, "failed", -1, reason);
exit(EXIT_FAILURE);
} else {
error_in_expect(ctx, "Test case raised a failure but was not "
@@ -327,7 +387,7 @@ pass(struct context *ctx)
error_in_expect(ctx, "Test case was expecting a failure but got "
"a pass instead");
} else if (ctx->expect == EXPECT_PASS) {
- create_resfile(ctx->resfile, "passed", -1, NULL);
+ create_resfile(ctx, "passed", -1, NULL);
exit(EXIT_SUCCESS);
} else {
error_in_expect(ctx, "Test case asked to explicitly pass but was "
@@ -340,7 +400,7 @@ static void
skip(struct context *ctx, atf_dynstr_t *reason)
{
if (ctx->expect == EXPECT_PASS) {
- create_resfile(ctx->resfile, "skipped", -1, reason);
+ create_resfile(ctx, "skipped", -1, reason);
exit(EXIT_SUCCESS);
} else {
error_in_expect(ctx, "Can only skip a test case when running in "
@@ -944,7 +1004,7 @@ _atf_tc_expect_exit(struct context *ctx,
check_fatal_error(atf_dynstr_init_ap(&formatted, reason, ap2));
va_end(ap2);
- create_resfile(ctx->resfile, "expected_exit", exitcode, &formatted);
+ create_resfile(ctx, "expected_exit", exitcode, &formatted);
}
static void
@@ -961,7 +1021,7 @@ _atf_tc_expect_signal(struct context *ct
check_fatal_error(atf_dynstr_init_ap(&formatted, reason, ap2));
va_end(ap2);
- create_resfile(ctx->resfile, "expected_signal", signo, &formatted);
+ create_resfile(ctx, "expected_signal", signo, &formatted);
}
static void
@@ -977,7 +1037,7 @@ _atf_tc_expect_death(struct context *ctx
check_fatal_error(atf_dynstr_init_ap(&formatted, reason, ap2));
va_end(ap2);
- create_resfile(ctx->resfile, "expected_death", -1, &formatted);
+ create_resfile(ctx, "expected_death", -1, &formatted);
}
static void
@@ -993,7 +1053,7 @@ _atf_tc_expect_timeout(struct context *c
check_fatal_error(atf_dynstr_init_ap(&formatted, reason, ap2));
va_end(ap2);
- create_resfile(ctx->resfile, "expected_timeout", -1, &formatted);
+ create_resfile(ctx, "expected_timeout", -1, &formatted);
}
/* ---------------------------------------------------------------------
Home |
Main Index |
Thread Index |
Old Index