chiark / gitweb /
util: make time formatting a bit smarter
authorLennart Poettering <lennart@poettering.net>
Thu, 4 Apr 2013 00:56:56 +0000 (02:56 +0200)
committerLennart Poettering <lennart@poettering.net>
Thu, 4 Apr 2013 00:56:56 +0000 (02:56 +0200)
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:
src/analyze/systemd-analyze.c
src/cgtop/cgtop.c
src/core/main.c
src/core/manager.c
src/core/mount-setup.c
src/core/selinux-setup.c
src/core/timer.c
src/core/unit.c
src/journal/journalctl.c
src/journal/test-journal-verify.c
src/shared/dbus-common.c
src/shared/label.c
src/shared/time-util.c
src/shared/time-util.h
src/shared/watchdog.c
src/systemctl/systemctl.c
src/test/test-efivars.c
src/test/test-time.c

index 01bf55e..029ce9c 100644 (file)
@@ -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);
index 280470d..1c05e60 100644 (file)
@@ -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;
index aa28cc6..92f066c 100644 (file)
@@ -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");
index 2e89f19..f90ccd5 100644 (file)
@@ -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) {
index fe50fb1..e45a6bc 100644 (file)
@@ -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
index 0723d7c..7a32ed5 100644 (file)
@@ -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;
 
index 16b4917..16ca573 100644 (file)
@@ -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)
index a0d3656..dbb1882 100644 (file)
@@ -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);
 
index 642e20d..1f26787 100644 (file)
@@ -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.");
                         }
index b667721..ad2e2d4 100644 (file)
@@ -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);
index 0e38933..5afce76 100644 (file)
@@ -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);
 
index a8bf6bd..1fe4574 100644 (file)
@@ -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
index 476b847..b6a2bec 100644 (file)
@@ -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;
index a02cdfc..3fc3395 100644 (file)
@@ -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);
index 13265e7..ddbe7af 100644 (file)
@@ -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);
index 323521a..fe71085 100644 (file)
@@ -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);
index e54a836..43ea591 100644 (file)
@@ -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));
index e9d188f..36a3304 100644 (file)
@@ -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;
 }