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; }