From 3ec90c030081111900597ec5475d880893f10a76 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 25 Dec 2012 12:58:54 +0100 Subject: [PATCH] analyze: properly parse firmware/loader time and handle times for container boots correctly --- src/analyze/systemd-analyze | 71 +++++++++++++++++++++++-------------- 1 file changed, 44 insertions(+), 27 deletions(-) diff --git a/src/analyze/systemd-analyze b/src/analyze/systemd-analyze index 88699d672..1512b1653 100755 --- a/src/analyze/systemd-analyze +++ b/src/analyze/systemd-analyze @@ -35,6 +35,17 @@ def acquire_start_time(): properties = Gio.DBusProxy.new_for_bus_sync(bus, Gio.DBusProxyFlags.NONE, None, 'org.freedesktop.systemd1', '/org/freedesktop/systemd1', 'org.freedesktop.DBus.Properties', None) + # Note that the firmware/loader times are returned as positive + # values but are atcually considered negative from the point + # in time of kernel initialization. Also, the monotonic kernel + # time will always be 0 since that's where the epoch of the + # monotonic clock ist. Since we want to know whether the + # kernel time stamp is set at all, we will thus ask for the + # realtime clock for this timestamp, instead. + + firmware_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'FirmwareTimestampMonotonic') + loader_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'LoaderTimestampMonotonic') + kernel_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'KernelTimestamp') initrd_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'InitRDTimestampMonotonic') userspace_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'UserspaceTimestampMonotonic') finish_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'FinishTimestampMonotonic') @@ -43,10 +54,11 @@ def acquire_start_time(): sys.stderr.write("Bootup is not yet finished. Please try again later.\n") sys.exit(1) + assert firmware_time >= loader_time assert initrd_time <= userspace_time assert userspace_time <= finish_time - return initrd_time, userspace_time, finish_time + return firmware_time, loader_time, kernel_time, initrd_time, userspace_time, finish_time def draw_box(context, j, k, l, m, r = 0, g = 0, b = 0): context.save() @@ -78,20 +90,25 @@ def draw_text(context, x, y, text, size = 12, r = 0, g = 0, b = 0, vcenter = 0.5 def time(): - initrd_time, start_time, finish_time = acquire_start_time() + firmware_time, loader_time, kernel_time, initrd_time, userspace_time, finish_time = acquire_start_time() + sys.stdout.write("Startup finished in ") + + if firmware_time > 0: + sys.stdout.write("%lums (firmware) + " % ((firmware_time - loader_time) / 1000)) + if loader_time > 0: + sys.stdout.write("%lums (loader) + " % (loader_time / 1000)) if initrd_time > 0: - sys.stdout.write("Startup finished in %lums (kernel) + %lums (initramfs) + %lums (userspace) = %lums\n" % ( \ - initrd_time/1000, \ - (start_time - initrd_time)/1000, \ - (finish_time - start_time)/1000, \ - finish_time/1000)) - else: - sys.stdout.write("Startup finished in %lums (kernel) + %lums (userspace) = %lums\n" % ( \ - start_time/1000, \ - (finish_time - start_time)/1000, \ - finish_time/1000)) + sys.stdout.write("%lums (kernel) + %lums (initrd) + " % (initrd_time / 1000, (userspace_time - initrd_time) / 1000)) + elif kernel_time > 0: + sys.stdout.write("%lums (kernel) + " % (userspace_time / 1000)) + sys.stdout.write("%lums (userspace) " % ((finish_time - userspace_time) / 1000)) + + if kernel_time > 0: + sys.stdout.write("= %lums\n" % ((firmware_time + finish_time) / 1000)) + else: + sys.stdout.write("= %lums\n" % ((finish_time - userspace_time) / 1000)) def blame(): @@ -112,7 +129,7 @@ def plot(): if cairo is None: sys.stderr.write("Failed to initilize python-cairo required for 'plot' verb.\n") sys.exit(1) - initrd_time, start_time, finish_time = acquire_start_time() + firmware_time, loader_time, kernel_time, initrd_time, userspace_time, finish_time = acquire_start_time() data = acquire_time_data() s = sorted(data, key = lambda i: i[1]) @@ -124,9 +141,9 @@ def plot(): for name, ixt, aet, axt, iet in s: - if (ixt >= start_time and ixt <= finish_time) or \ - (aet >= start_time and aet <= finish_time) or \ - (axt >= start_time and axt <= finish_time): + if (ixt >= userspace_time and ixt <= finish_time) or \ + (aet >= userspace_time and aet <= finish_time) or \ + (axt >= userspace_time and axt <= finish_time): count += 1 border = 100 @@ -186,17 +203,17 @@ def plot(): draw_text(context, 10, y + bar_height/2, "kernel", hcenter = 0) y += bar_height + bar_space - draw_box(context, initrd_time/10000, y, start_time/10000-initrd_time/10000, bar_height, 0.7, 0.7, 0.7) + draw_box(context, initrd_time/10000, y, userspace_time/10000-initrd_time/10000, bar_height, 0.7, 0.7, 0.7) draw_text(context, initrd_time/10000 + 10, y + bar_height/2, "initramfs", hcenter = 0) y += bar_height + bar_space else: - draw_box(context, 0, y, start_time/10000, bar_height, 0.6, 0.6, 0.6) + draw_box(context, 0, y, userspace_time/10000, bar_height, 0.6, 0.6, 0.6) draw_text(context, 10, y + bar_height/2, "kernel", hcenter = 0) y += bar_height + bar_space - draw_box(context, start_time/10000, y, finish_time/10000-start_time/10000, bar_height, 0.7, 0.7, 0.7) - draw_text(context, start_time/10000 + 10, y + bar_height/2, "userspace", hcenter = 0) + draw_box(context, userspace_time/10000, y, finish_time/10000-userspace_time/10000, bar_height, 0.7, 0.7, 0.7) + draw_text(context, userspace_time/10000 + 10, y + bar_height/2, "userspace", hcenter = 0) y += bar_height + bar_space for name, ixt, aet, axt, iet in s: @@ -204,7 +221,7 @@ def plot(): drawn = False left = -1 - if ixt >= start_time and ixt <= finish_time: + if ixt >= userspace_time and ixt <= finish_time: # Activating a = ixt @@ -216,7 +233,7 @@ def plot(): if left < 0: left = a - if aet >= start_time and aet <= finish_time: + if aet >= userspace_time and aet <= finish_time: # Active a = aet @@ -228,7 +245,7 @@ def plot(): if left < 0: left = a - if axt >= start_time and axt <= finish_time: + if axt >= userspace_time and axt <= finish_time: # Deactivating a = axt @@ -255,13 +272,13 @@ def plot(): if initrd_time > 0: draw_text(context, 0, height-border*2 + bar_height, "Startup finished in %lums (kernel) + %lums (initramfs) + %lums (userspace) = %lums" % ( \ initrd_time/1000, \ - (start_time - initrd_time)/1000, \ - (finish_time - start_time)/1000, \ + (userspace_time - initrd_time)/1000, \ + (finish_time - userspace_time)/1000, \ finish_time/1000), hcenter = 0, vcenter = -1) else: draw_text(context, 0, height-border*2 + bar_height, "Startup finished in %lums (kernel) + %lums (userspace) = %lums" % ( \ - start_time/1000, \ - (finish_time - start_time)/1000, \ + userspace_time/1000, \ + (finish_time - userspace_time)/1000, \ finish_time/1000), hcenter = 0, vcenter = -1) surface.finish() -- 2.30.2