[v4,06/21] test-date: add a subcommand to measure times in shell scripts

Commit Message

John Cai via GitGitGadget Jan. 23, 2019, 2:40 p.m. UTC

From: Johannes Schindelin <[e-mail]>

In the next commit, we want to teach Git's test suite to optionally
output test results in JUnit-style .xml files. These files contain
information about the time spent. So we need a way to measure time.

While we could use `date +%s` for that, this will give us only seconds,
i.e. very coarse-grained timings.

GNU `date` supports `date +%s.%N` (i.e. nanosecond-precision output),
but there is no equivalent in BSD `date` (read: on macOS, we would not
be able to obtain precise timings).

So let's introduce `test-tool date getnanos`, with an optional start
time, that outputs preciser values.

Granted, it is a bit pointless to try measuring times accurately in
shell scripts, certainly to nanosecond precision. But it is better than
second-granularity.

Signed-off-by: Johannes Schindelin <[e-mail]>
---
 t/helper/test-date.c | 12 ++++++++++++
 1 file changed, 12 insertions(+)

Comments

Junio C Hamano Jan. 23, 2019, 10:29 p.m. UTC | #1

"Johannes Schindelin via GitGitGadget" <[e-mail]>
writes:

> From: Johannes Schindelin <[e-mail]>
>
> In the next commit, we want to teach Git's test suite to optionally
> output test results in JUnit-style .xml files. These files contain
> information about the time spent. So we need a way to measure time.
>
> While we could use `date +%s` for that, this will give us only seconds,
> i.e. very coarse-grained timings.
>
> GNU `date` supports `date +%s.%N` (i.e. nanosecond-precision output),
> but there is no equivalent in BSD `date` (read: on macOS, we would not
> be able to obtain precise timings).
>
> So let's introduce `test-tool date getnanos`, with an optional start
> time, that outputs preciser values.

I think the goal to have our own stopwatch so that we do not have to
worry about differences among system-provided ones makes sense.

The only thing that may become an issue is how widely available
getnanotime() is.  As "test-date" itself is built on any platform an
end-user/developer runs our tests, which is wider set of platforms
than what we run Travis and other CIs on, unconditionally relying on
its availability might pose an issue.  I dunno.

> diff --git a/t/helper/test-date.c b/t/helper/test-date.c
> index a0837371ab..792a805374 100644
> --- a/t/helper/test-date.c
> +++ b/t/helper/test-date.c
> @@ -7,6 +7,7 @@ static const char *usage_msg = "\n"
>  "  test-tool date parse [date]...\n"
>  "  test-tool date approxidate [date]...\n"
>  "  test-tool date timestamp [date]...\n"
> +"  test-tool date getnanos [start-nanos]\n"
>  "  test-tool date is64bit\n"
>  "  test-tool date time_t-is64bit\n";
>  
> @@ -82,6 +83,15 @@ static void parse_approx_timestamp(const char **argv, struct timeval *now)
>  	}
>  }
>  
> +static void getnanos(const char **argv, struct timeval *now)
> +{
> +	double seconds = getnanotime() / 1.0e9;
> +
> +	if (*argv)
> +		seconds -= strtod(*argv, NULL);
> +	printf("%lf\n", seconds);
> +}
> +
>  int cmd__date(int argc, const char **argv)
>  {
>  	struct timeval now;
> @@ -108,6 +118,8 @@ int cmd__date(int argc, const char **argv)
>  		parse_approxidate(argv+1, &now);
>  	else if (!strcmp(*argv, "timestamp"))
>  		parse_approx_timestamp(argv+1, &now);
> +	else if (!strcmp(*argv, "getnanos"))
> +		getnanos(argv+1, &now);
>  	else if (!strcmp(*argv, "is64bit"))
>  		return sizeof(timestamp_t) == 8 ? 0 : 1;
>  	else if (!strcmp(*argv, "time_t-is64bit"))

Johannes Schindelin Jan. 27, 2019, 2:54 p.m. UTC | #2

Hi Junio,

On Wed, 23 Jan 2019, Junio C Hamano wrote:

> "Johannes Schindelin via GitGitGadget" <[e-mail]>
> writes:
> 
> > From: Johannes Schindelin <[e-mail]>
> >
> > In the next commit, we want to teach Git's test suite to optionally
> > output test results in JUnit-style .xml files. These files contain
> > information about the time spent. So we need a way to measure time.
> >
> > While we could use `date +%s` for that, this will give us only seconds,
> > i.e. very coarse-grained timings.
> >
> > GNU `date` supports `date +%s.%N` (i.e. nanosecond-precision output),
> > but there is no equivalent in BSD `date` (read: on macOS, we would not
> > be able to obtain precise timings).
> >
> > So let's introduce `test-tool date getnanos`, with an optional start
> > time, that outputs preciser values.
> 
> I think the goal to have our own stopwatch so that we do not have to
> worry about differences among system-provided ones makes sense.

And so that we do not have to worry about all kinds of unportable shell
commands. That was my main motivation here, TBH.

> The only thing that may become an issue is how widely available
> getnanotime() is.  As "test-date" itself is built on any platform an
> end-user/developer runs our tests, which is wider set of platforms
> than what we run Travis and other CIs on, unconditionally relying on
> its availability might pose an issue.  I dunno.

Well, getnanotime() itself looks (I checked) at highres_nanos()' output,
which can be 0 on unsuported platforms, and falls back to
gettimeofday_nanos(). The worst that can happen there, as far as I can
tell, is that the platform has a certain granularity (which is true of
highres_nanos(), too), and that granularity can be 1 second. Which is not
very good, but if that's the best the platform can provide, I am prepared
to take it. Which is exactly what this patch does.

Do you have any splendid idea how to improve this approach?

Ciao,
Dscho

Junio C Hamano Jan. 27, 2019, 11:14 p.m. UTC | #3

Junio C Hamano <[e-mail]> writes:

> I think the goal to have our own stopwatch so that we do not have to
> worry about differences among system-provided ones makes sense.
>
> The only thing that may become an issue is how widely available
> getnanotime() is.  As "test-date" itself is built on any platform an
> end-user/developer runs our tests, which is wider set of platforms
> than what we run Travis and other CIs on, unconditionally relying on
> its availability might pose an issue.

Sorry for a false alarm, as the codebase in many places like
fsmonitor, progress, trace and wt-status have been assuming
getnanotime() to be available for quite some time, and this is just
another user of the same function.

Junio C Hamano Jan. 28, 2019, 6:49 p.m. UTC | #4

Junio C Hamano <[e-mail]> writes:

> Junio C Hamano <[e-mail]> writes:
>
>> I think the goal to have our own stopwatch so that we do not have to
>> worry about differences among system-provided ones makes sense.
>>
>> The only thing that may become an issue is how widely available
>> getnanotime() is.  As "test-date" itself is built on any platform an
>> end-user/developer runs our tests, which is wider set of platforms
>> than what we run Travis and other CIs on, unconditionally relying on
>> its availability might pose an issue.
>
> Sorry for a false alarm, as the codebase in many places like
> fsmonitor, progress, trace and wt-status have been assuming
> getnanotime() to be available for quite some time, and this is just
> another user of the same function.

And there was yet another misunderstanding on my part.  I thought
that the mention of getnanotime() was about

https://www.freebsd.org/cgi/man.cgi?query=getnanotime&sektion=9

and I did not realize that the hits I saw in "git grep getnanotime"
were referring to an unrelated function trace.c::getnanotime() of
our own.  Of course, it is safe to use that function in the tests
;-)

Again, sorry for the false alarm.

We _might_ get a complaint from freebsd devs when they want to use
their getnanotime(9) to implement highres_nanos(), and the cleanest
solution to that complaint will be to rename our own getnanotime()
to git_nanotime() or something, but (1) that is totally outside the
scope of this series that adds one more caller to the function and
(2) we can do that when we actually get such a complaint.

Patch

diff --git a/t/helper/test-date.c b/t/helper/test-date.c
index a0837371ab..792a805374 100644
--- a/t/helper/test-date.c
+++ b/t/helper/test-date.c
@@ -7,6 +7,7 @@  static const char *usage_msg = "\n"
 "  test-tool date parse [date]...\n"
 "  test-tool date approxidate [date]...\n"
 "  test-tool date timestamp [date]...\n"
+"  test-tool date getnanos [start-nanos]\n"
 "  test-tool date is64bit\n"
 "  test-tool date time_t-is64bit\n";
 
@@ -82,6 +83,15 @@  static void parse_approx_timestamp(const char **argv, struct timeval *now)
 	}
 }
 
+static void getnanos(const char **argv, struct timeval *now)
+{
+	double seconds = getnanotime() / 1.0e9;
+
+	if (*argv)
+		seconds -= strtod(*argv, NULL);
+	printf("%lf\n", seconds);
+}
+
 int cmd__date(int argc, const char **argv)
 {
 	struct timeval now;
@@ -108,6 +118,8 @@  int cmd__date(int argc, const char **argv)
 		parse_approxidate(argv+1, &now);
 	else if (!strcmp(*argv, "timestamp"))
 		parse_approx_timestamp(argv+1, &now);
+	else if (!strcmp(*argv, "getnanos"))
+		getnanos(argv+1, &now);
 	else if (!strcmp(*argv, "is64bit"))
 		return sizeof(timestamp_t) == 8 ? 0 : 1;
 	else if (!strcmp(*argv, "time_t-is64bit"))