util: make time formatting a bit smarter

Instead of outputting "5h 55s 50ms 3us" we'll now output "5h
55.050003s". Also, while outputting the accuracy is configurable.

Basically we now try use "dot notation" for all time values > 1min. For
>= 1s we use 's' as unit, otherwise for >= 1ms we use 'ms' as unit, and
finally 'us'.

This should give reasonably values in most cases.

18 files changed, 146 insertions, 47 deletions

diff --git a/src/analyze/systemd-analyze.c b/src/analyze/systemd-analyze.c
index 01bf55eda5..029ce9c9eb 100644
--- a/src/analyze/systemd-analyze.c
+++ b/src/analyze/systemd-analyze.c
@@ -331,19 +331,19 @@ static int pretty_boot_time(DBusConnection *bus, char **_buf) {
 
         size = strpcpyf(&ptr, size, "Startup finished in ");
         if (t->firmware_time)
-                size = strpcpyf(&ptr, size, "%s (firmware) + ", format_timespan(ts, sizeof(ts), t->firmware_time - t->loader_time));
+                size = strpcpyf(&ptr, size, "%s (firmware) + ", format_timespan(ts, sizeof(ts), t->firmware_time - t->loader_time, USEC_PER_MSEC));
         if (t->loader_time)
-                size = strpcpyf(&ptr, size, "%s (loader) + ", format_timespan(ts, sizeof(ts), t->loader_time));
+                size = strpcpyf(&ptr, size, "%s (loader) + ", format_timespan(ts, sizeof(ts), t->loader_time, USEC_PER_MSEC));
         if (t->kernel_time)
-                size = strpcpyf(&ptr, size, "%s (kernel) + ", format_timespan(ts, sizeof(ts), t->kernel_done_time));
+                size = strpcpyf(&ptr, size, "%s (kernel) + ", format_timespan(ts, sizeof(ts), t->kernel_done_time, USEC_PER_MSEC));
         if (t->initrd_time > 0)
-                size = strpcpyf(&ptr, size, "%s (initrd) + ", format_timespan(ts, sizeof(ts), t->userspace_time - t->initrd_time));
+                size = strpcpyf(&ptr, size, "%s (initrd) + ", format_timespan(ts, sizeof(ts), t->userspace_time - t->initrd_time, USEC_PER_MSEC));
 
-        size = strpcpyf(&ptr, size, "%s (userspace) ", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time));
+        size = strpcpyf(&ptr, size, "%s (userspace) ", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time, USEC_PER_MSEC));
         if (t->kernel_time > 0)
-                size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->firmware_time + t->finish_time));
+                size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->firmware_time + t->finish_time, USEC_PER_MSEC));
         else
-                size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time));
+                size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time, USEC_PER_MSEC));
 
         ptr = strdup(buf);
         if (!ptr)
@@ -530,7 +530,7 @@ static int analyze_plot(DBusConnection *bus) {
                 b = u->ixt * SCALE_X > width * 2 / 3;
                 if (u->time)
                         svg_text(b, u->ixt, y, "%s (%s)",
-                                 u->name, format_timespan(ts, sizeof(ts), u->time));
+                                 u->name, format_timespan(ts, sizeof(ts), u->time, USEC_PER_MSEC));
                 else
                         svg_text(b, u->ixt, y, "%s", u->name);
                 y++;
@@ -559,7 +559,7 @@ static int analyze_blame(DBusConnection *bus) {
                 char ts[FORMAT_TIMESPAN_MAX];
 
                 if (times[i].time > 0)
-                        printf("%16s %s\n", format_timespan(ts, sizeof(ts), times[i].time), times[i].name);
+                        printf("%16s %s\n", format_timespan(ts, sizeof(ts), times[i].time, USEC_PER_MSEC), times[i].name);
         }
 
         free_unit_times(times, (unsigned) n);
diff --git a/src/cgtop/cgtop.c b/src/cgtop/cgtop.c
index 280470dbd0..1c05e6049c 100644
--- a/src/cgtop/cgtop.c
+++ b/src/cgtop/cgtop.c
@@ -803,7 +803,7 @@ int main(int argc, char *argv[]) {
                         else
                                 arg_delay += USEC_PER_SEC;
 
-                        fprintf(stdout, "\nIncreased delay to %s.", format_timespan(h, sizeof(h), arg_delay));
+                        fprintf(stdout, "\nIncreased delay to %s.", format_timespan(h, sizeof(h), arg_delay, 0));
                         fflush(stdout);
                         sleep(1);
                         break;
@@ -816,7 +816,7 @@ int main(int argc, char *argv[]) {
                         else
                                 arg_delay -= USEC_PER_SEC;
 
-                        fprintf(stdout, "\nDecreased delay to %s.", format_timespan(h, sizeof(h), arg_delay));
+                        fprintf(stdout, "\nDecreased delay to %s.", format_timespan(h, sizeof(h), arg_delay, 0));
                         fflush(stdout);
                         sleep(1);
                         break;
diff --git a/src/core/main.c b/src/core/main.c
index aa28cc6651..92f066c707 100644
--- a/src/core/main.c
+++ b/src/core/main.c
@@ -1752,7 +1752,7 @@ int main(int argc, char *argv[]) {
                 after_startup = now(CLOCK_MONOTONIC);
                 log_full(arg_action == ACTION_TEST ? LOG_INFO : LOG_DEBUG,
                          "Loaded units and determined initial transaction in %s.",
-                          format_timespan(timespan, sizeof(timespan), after_startup - before_startup));
+                         format_timespan(timespan, sizeof(timespan), after_startup - before_startup, 0));
 
                 if (arg_action == ACTION_TEST) {
                         printf("-> By jobs:\n");
diff --git a/src/core/manager.c b/src/core/manager.c
index 2e89f19839..f90ccd5b5f 100644
--- a/src/core/manager.c
+++ b/src/core/manager.c
@@ -2415,10 +2415,10 @@ void manager_check_finished(Manager *m) {
                                            "INITRD_USEC=%llu", (unsigned long long) initrd_usec,
                                            "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
                                            "MESSAGE=Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.",
-                                           format_timespan(kernel, sizeof(kernel), kernel_usec),
-                                           format_timespan(initrd, sizeof(initrd), initrd_usec),
-                                           format_timespan(userspace, sizeof(userspace), userspace_usec),
-                                           format_timespan(sum, sizeof(sum), total_usec),
+                                           format_timespan(kernel, sizeof(kernel), kernel_usec, USEC_PER_MSEC),
+                                           format_timespan(initrd, sizeof(initrd), initrd_usec, USEC_PER_MSEC),
+                                           format_timespan(userspace, sizeof(userspace), userspace_usec, USEC_PER_MSEC),
+                                           format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC),
                                            NULL);
                 } else {
                         kernel_usec = m->userspace_timestamp.monotonic - m->kernel_timestamp.monotonic;
@@ -2430,9 +2430,9 @@ void manager_check_finished(Manager *m) {
                                            "KERNEL_USEC=%llu", (unsigned long long) kernel_usec,
                                            "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
                                            "MESSAGE=Startup finished in %s (kernel) + %s (userspace) = %s.",
-                                           format_timespan(kernel, sizeof(kernel), kernel_usec),
-                                           format_timespan(userspace, sizeof(userspace), userspace_usec),
-                                           format_timespan(sum, sizeof(sum), total_usec),
+                                           format_timespan(kernel, sizeof(kernel), kernel_usec, USEC_PER_MSEC),
+                                           format_timespan(userspace, sizeof(userspace), userspace_usec, USEC_PER_MSEC),
+                                           format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC),
                                            NULL);
                 }
         } else {
@@ -2444,7 +2444,7 @@ void manager_check_finished(Manager *m) {
                                    MESSAGE_ID(SD_MESSAGE_STARTUP_FINISHED),
                                    "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
                                    "MESSAGE=Startup finished in %s.",
-                                   format_timespan(sum, sizeof(sum), total_usec),
+                                   format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC),
                                    NULL);
         }
 
@@ -2452,7 +2452,7 @@ void manager_check_finished(Manager *m) {
 
         sd_notifyf(false,
                    "READY=1\nSTATUS=Startup finished in %s.",
-                   format_timespan(sum, sizeof(sum), total_usec));
+                   format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC));
 }
 
 static int create_generator_dir(Manager *m, char **generator, const char *name) {
diff --git a/src/core/mount-setup.c b/src/core/mount-setup.c
index fe50fb19da..e45a6bc1c8 100644
--- a/src/core/mount-setup.c
+++ b/src/core/mount-setup.c
@@ -423,7 +423,7 @@ int mount_setup(bool loaded_policy) {
                 after_relabel = now(CLOCK_MONOTONIC);
 
                 log_info("Relabelled /dev and /run in %s.",
-                         format_timespan(timespan, sizeof(timespan), after_relabel - before_relabel));
+                         format_timespan(timespan, sizeof(timespan), after_relabel - before_relabel, 0));
         }
 
         /* Create a few default symlinks, which are normally created
diff --git a/src/core/selinux-setup.c b/src/core/selinux-setup.c
index 0723d7c8ba..7a32ed59a0 100644
--- a/src/core/selinux-setup.c
+++ b/src/core/selinux-setup.c
@@ -101,7 +101,7 @@ int selinux_setup(bool *loaded_policy) {
                after_load = now(CLOCK_MONOTONIC);
 
                log_info("Successfully loaded SELinux policy in %s.",
-                         format_timespan(timespan, sizeof(timespan), after_load - before_load));
+                        format_timespan(timespan, sizeof(timespan), after_load - before_load, 0));
 
                *loaded_policy = true;
 
diff --git a/src/core/timer.c b/src/core/timer.c
index 16b49174d3..16ca573177 100644
--- a/src/core/timer.c
+++ b/src/core/timer.c
@@ -177,7 +177,7 @@ static void timer_dump(Unit *u, FILE *f, const char *prefix) {
                                 "%s%s: %s\n",
                                 prefix,
                                 timer_base_to_string(v->base),
-                                strna(format_timespan(timespan1, sizeof(timespan1), v->value)));
+                                strna(format_timespan(timespan1, sizeof(timespan1), v->value, 0)));
                 }
         }
 }
@@ -330,7 +330,7 @@ static void timer_enter_waiting(Timer *t, bool initial) {
                 log_debug_unit(UNIT(t)->id,
                                "%s: Monotonic timer elapses in %s.",
                                UNIT(t)->id,
-                               format_timespan(buf, sizeof(buf), t->next_elapse_monotonic > ts.monotonic ? t->next_elapse_monotonic - ts.monotonic : 0));
+                               format_timespan(buf, sizeof(buf), t->next_elapse_monotonic > ts.monotonic ? t->next_elapse_monotonic - ts.monotonic : 0, 0));
 
                 r = unit_watch_timer(UNIT(t), CLOCK_MONOTONIC, false, t->next_elapse_monotonic, &t->monotonic_watch);
                 if (r < 0)
diff --git a/src/core/unit.c b/src/core/unit.c
index a0d36569a8..dbb1882965 100644
--- a/src/core/unit.c
+++ b/src/core/unit.c
@@ -701,7 +701,7 @@ void unit_dump(Unit *u, FILE *f, const char *prefix) {
                 fprintf(f, "%s\tDropIn Path: %s\n", prefix, *j);
 
         if (u->job_timeout > 0)
-                fprintf(f, "%s\tJob Timeout: %s\n", prefix, format_timespan(timespan, sizeof(timespan), u->job_timeout));
+                fprintf(f, "%s\tJob Timeout: %s\n", prefix, format_timespan(timespan, sizeof(timespan), u->job_timeout, 0));
 
         condition_dump_list(u->conditions, f, prefix);
 
diff --git a/src/journal/journalctl.c b/src/journal/journalctl.c
index 642e20d43f..1f26787cf7 100644
--- a/src/journal/journalctl.c
+++ b/src/journal/journalctl.c
@@ -804,7 +804,7 @@ static int setup_keys(void) {
                 fprintf(stderr,
                         ANSI_HIGHLIGHT_OFF "\n"
                         "The sealing key is automatically changed every %s.\n",
-                        format_timespan(tsb, sizeof(tsb), arg_interval));
+                        format_timespan(tsb, sizeof(tsb), arg_interval, 0));
 
                 hn = gethostname_malloc();
 
@@ -878,10 +878,10 @@ static int verify(sd_journal *j) {
                                         log_info("=> Validated from %s to %s, final %s entries not sealed.",
                                                  format_timestamp(a, sizeof(a), first),
                                                  format_timestamp(b, sizeof(b), validated),
-                                                 format_timespan(c, sizeof(c), last > validated ? last - validated : 0));
+                                                 format_timespan(c, sizeof(c), last > validated ? last - validated : 0, 0));
                                 } else if (last > 0)
                                         log_info("=> No sealing yet, %s of entries not sealed.",
-                                                 format_timespan(c, sizeof(c), last - first));
+                                                 format_timespan(c, sizeof(c), last - first, 0));
                                 else
                                         log_info("=> No sealing yet, no entries in file.");
                         }
diff --git a/src/journal/test-journal-verify.c b/src/journal/test-journal-verify.c
index b6677215c0..ad2e2d4c3b 100644
--- a/src/journal/test-journal-verify.c
+++ b/src/journal/test-journal-verify.c
@@ -117,7 +117,7 @@ int main(int argc, char *argv[]) {
                 log_info("=> Validated from %s to %s, %s missing",
                          format_timestamp(a, sizeof(a), from),
                          format_timestamp(b, sizeof(b), to),
-                         format_timespan(c, sizeof(c), total > to ? total - to : 0));
+                         format_timespan(c, sizeof(c), total > to ? total - to : 0, 0));
         }
 
         journal_file_close(f);
diff --git a/src/shared/dbus-common.c b/src/shared/dbus-common.c
index 0e38933d8a..5afce7627a 100644
--- a/src/shared/dbus-common.c
+++ b/src/shared/dbus-common.c
@@ -1097,7 +1097,7 @@ int generic_print_property(const char *name, DBusMessageIter *iter, bool all) {
                 } else if (strstr(name, "USec")) {
                         char timespan[FORMAT_TIMESPAN_MAX];
 
-                        printf("%s=%s\n", name, format_timespan(timespan, sizeof(timespan), u));
+                        printf("%s=%s\n", name, format_timespan(timespan, sizeof(timespan), u, 0));
                 } else
                         printf("%s=%llu\n", name, (unsigned long long) u);
 
diff --git a/src/shared/label.c b/src/shared/label.c
index a8bf6bd4f9..1fe4574633 100644
--- a/src/shared/label.c
+++ b/src/shared/label.c
@@ -82,7 +82,7 @@ int label_init(const char *prefix) {
                 l = after_mallinfo.uordblks > before_mallinfo.uordblks ? after_mallinfo.uordblks - before_mallinfo.uordblks : 0;
 
                 log_debug("Successfully loaded SELinux database in %s, size on heap is %iK.",
-                          format_timespan(timespan, sizeof(timespan), after_timestamp - before_timestamp),
+                          format_timespan(timespan, sizeof(timespan), after_timestamp - before_timestamp, 0),
                           (l+1023)/1024);
         }
 #endif
diff --git a/src/shared/time-util.c b/src/shared/time-util.c
index 476b847ead..b6a2bec156 100644
--- a/src/shared/time-util.c
+++ b/src/shared/time-util.c
@@ -225,7 +225,7 @@ char *format_timestamp_relative(char *buf, size_t l, usec_t t) {
         return buf;
 }
 
-char *format_timespan(char *buf, size_t l, usec_t t) {
+char *format_timespan(char *buf, size_t l, usec_t t, usec_t accuracy) {
         static const struct {
                 const char *suffix;
                 usec_t usec;
@@ -243,6 +243,7 @@ char *format_timespan(char *buf, size_t l, usec_t t) {
 
         unsigned i;
         char *p = buf;
+        bool something = false;
 
         assert(buf);
         assert(l > 0);
@@ -250,17 +251,23 @@ char *format_timespan(char *buf, size_t l, usec_t t) {
         if (t == (usec_t) -1)
                 return NULL;
 
-        if (t == 0) {
-                snprintf(p, l, "0");
-                p[l-1] = 0;
-                return p;
-        }
-
         /* The result of this function can be parsed with parse_sec */
 
         for (i = 0; i < ELEMENTSOF(table); i++) {
                 int k;
                 size_t n;
+                bool done = false;
+                usec_t a, b;
+
+                if (t == 0 || t < accuracy) {
+                        if (!something) {
+                                snprintf(p, l, "0");
+                                p[l-1] = 0;
+                                return p;
+                        }
+
+                        break;
+                }
 
                 if (t < table[i].usec)
                         continue;
@@ -268,13 +275,55 @@ char *format_timespan(char *buf, size_t l, usec_t t) {
                 if (l <= 1)
                         break;
 
-                k = snprintf(p, l, "%s%llu%s", p > buf ? " " : "", (unsigned long long) (t / table[i].usec), table[i].suffix);
+                a = t / table[i].usec;
+                b = t % table[i].usec;
+
+                /* Let's see if we should shows this in dot notation */
+                if (t < USEC_PER_MINUTE && b > 0) {
+                        usec_t cc;
+                        int j;
+
+                        j = 0;
+                        for (cc = table[i].usec; cc > 1; cc /= 10)
+                                j++;
+
+                        for (cc = accuracy; cc > 1; cc /= 10) {
+                                b /= 10;
+                                j--;
+                        }
+
+                        if (j > 0) {
+                                k = snprintf(p, l,
+                                             "%s%llu.%0*llu%s",
+                                             p > buf ? " " : "",
+                                             (unsigned long long) a,
+                                             j,
+                                             (unsigned long long) b,
+                                             table[i].suffix);
+
+                                t = 0;
+                                done = true;
+                        }
+                }
+
+                /* No? Then let's show it normally */
+                if (!done) {
+                        k = snprintf(p, l,
+                                     "%s%llu%s",
+                                     p > buf ? " " : "",
+                                     (unsigned long long) a,
+                                     table[i].suffix);
+
+                        t = b;
+                }
+
                 n = MIN((size_t) k, l);
 
                 l -= n;
                 p += n;
 
-                t %= table[i].usec;
+
+                something = true;
         }
 
         *p = 0;
diff --git a/src/shared/time-util.h b/src/shared/time-util.h
index a02cdfc79f..3fc339507c 100644
--- a/src/shared/time-util.h
+++ b/src/shared/time-util.h
@@ -74,7 +74,7 @@ struct timeval *timeval_store(struct timeval *tv, usec_t u);
 
 char *format_timestamp(char *buf, size_t l, usec_t t);
 char *format_timestamp_relative(char *buf, size_t l, usec_t t);
-char *format_timespan(char *buf, size_t l, usec_t t);
+char *format_timespan(char *buf, size_t l, usec_t t, usec_t accuracy);
 
 void dual_timestamp_serialize(FILE *f, const char *name, dual_timestamp *t);
 void dual_timestamp_deserialize(const char *value, dual_timestamp *t);
diff --git a/src/shared/watchdog.c b/src/shared/watchdog.c
index 13265e7692..ddbe7afd3c 100644
--- a/src/shared/watchdog.c
+++ b/src/shared/watchdog.c
@@ -60,7 +60,7 @@ static int update_timeout(void) {
                 }
 
                 watchdog_timeout = (usec_t) sec * USEC_PER_SEC;
-                log_info("Set hardware watchdog to %s.", format_timespan(buf, sizeof(buf), watchdog_timeout));
+                log_info("Set hardware watchdog to %s.", format_timespan(buf, sizeof(buf), watchdog_timeout, 0));
 
                 flags = WDIOS_ENABLECARD;
                 r = ioctl(watchdog_fd, WDIOC_SETOPTIONS, &flags);
diff --git a/src/systemctl/systemctl.c b/src/systemctl/systemctl.c
index 323521a81a..fe71085d42 100644
--- a/src/systemctl/systemctl.c
+++ b/src/systemctl/systemctl.c
@@ -2944,8 +2944,8 @@ static int print_property(const char *name, DBusMessageIter *iter) {
 
                                         printf("%s={ value=%s ; next_elapse=%s }\n",
                                                base,
-                                               format_timespan(timespan1, sizeof(timespan1), value),
-                                               format_timespan(timespan2, sizeof(timespan2), next_elapse));
+                                               format_timespan(timespan1, sizeof(timespan1), value, 0),
+                                               format_timespan(timespan2, sizeof(timespan2), next_elapse, 0));
                                 }
 
                                 dbus_message_iter_next(&sub);
diff --git a/src/test/test-efivars.c b/src/test/test-efivars.c
index e54a83665a..43ea5917b6 100644
--- a/src/test/test-efivars.c
+++ b/src/test/test-efivars.c
@@ -36,8 +36,8 @@ int main(int argc, char* argv[]) {
                 return 1;
         }
 
-        log_info("Firmware began %s before kernel.", format_timespan(s, sizeof(s), fw.monotonic));
-        log_info("Loader began %s before kernel.", format_timespan(s, sizeof(s), l.monotonic));
+        log_info("Firmware began %s before kernel.", format_timespan(s, sizeof(s), fw.monotonic, 0));
+        log_info("Loader began %s before kernel.", format_timespan(s, sizeof(s), l.monotonic, 0));
 
         log_info("Firmware began %s.", format_timestamp(s, sizeof(s), fw.realtime));
         log_info("Loader began %s.", format_timestamp(s, sizeof(s), l.realtime));
diff --git a/src/test/test-time.c b/src/test/test-time.c
index e9d188fced..36a33046a2 100644
--- a/src/test/test-time.c
+++ b/src/test/test-time.c
@@ -79,8 +79,58 @@ static void test_parse_nsec(void) {
         assert_se(parse_nsec(".s ", &u) < 0);
 }
 
+static void test_format_timespan_one(usec_t x, usec_t accuracy) {
+        char *r;
+        char l[FORMAT_TIMESPAN_MAX];
+        usec_t y;
+
+        log_info("%llu     (at accuracy %llu)", (unsigned long long) x, (unsigned long long) accuracy);
+
+        r = format_timespan(l, sizeof(l), x, accuracy);
+        assert_se(r);
+
+        log_info(" = <%s>", l);
+
+        assert_se(parse_sec(l, &y) >= 0);
+
+        log_info(" = %llu", (unsigned long long) y);
+
+        if (accuracy <= 0)
+                accuracy = 1;
+
+        assert_se(x / accuracy == y / accuracy);
+}
+
+static void test_format_timespan(usec_t accuracy) {
+        test_format_timespan_one(0, accuracy);
+        test_format_timespan_one(1, accuracy);
+        test_format_timespan_one(1*USEC_PER_SEC, accuracy);
+        test_format_timespan_one(999*USEC_PER_MSEC, accuracy);
+        test_format_timespan_one(1234567, accuracy);
+        test_format_timespan_one(12, accuracy);
+        test_format_timespan_one(123, accuracy);
+        test_format_timespan_one(1234, accuracy);
+        test_format_timespan_one(12345, accuracy);
+        test_format_timespan_one(123456, accuracy);
+        test_format_timespan_one(1234567, accuracy);
+        test_format_timespan_one(12345678, accuracy);
+        test_format_timespan_one(1200000, accuracy);
+        test_format_timespan_one(1230000, accuracy);
+        test_format_timespan_one(1230000, accuracy);
+        test_format_timespan_one(1234000, accuracy);
+        test_format_timespan_one(1234500, accuracy);
+        test_format_timespan_one(1234560, accuracy);
+        test_format_timespan_one(1234567, accuracy);
+        test_format_timespan_one(986087, accuracy);
+        test_format_timespan_one(500 * USEC_PER_MSEC, accuracy);
+        test_format_timespan_one(9*USEC_PER_YEAR/5 - 23, accuracy);
+}
+
 int main(int argc, char *argv[]) {
         test_parse_sec();
         test_parse_nsec();
+        test_format_timespan(1);
+        test_format_timespan(USEC_PER_MSEC);
+        test_format_timespan(USEC_PER_SEC);
         return 0;
 }