src/analyze/systemd-analyze

   1 #!/usr/bin/python
   2
   3 import sys, os
   4 import argparse
   5 from gi.repository import Gio
   6 try:
   7         import cairo
   8 except ImportError:
   9         cairo = None
  10
  11 def acquire_time_data():
  12         manager = Gio.DBusProxy.new_for_bus_sync(bus, Gio.DBusProxyFlags.NONE,
  13                 None, 'org.freedesktop.systemd1', '/org/freedesktop/systemd1', 'org.freedesktop.systemd1.Manager', None)
  14         units = manager.ListUnits()
  15
  16         l = []
  17
  18         for i in units:
  19                 if i[5] != "":
  20                         continue
  21
  22                 properties = Gio.DBusProxy.new_for_bus_sync(bus, Gio.DBusProxyFlags.NONE,
  23                         None, 'org.freedesktop.systemd1', i[6], 'org.freedesktop.DBus.Properties', None)
  24
  25                 ixt = properties.Get('(ss)', 'org.freedesktop.systemd1.Unit', 'InactiveExitTimestampMonotonic')
  26                 aet = properties.Get('(ss)', 'org.freedesktop.systemd1.Unit', 'ActiveEnterTimestampMonotonic')
  27                 axt = properties.Get('(ss)', 'org.freedesktop.systemd1.Unit', 'ActiveExitTimestampMonotonic')
  28                 iet = properties.Get('(ss)', 'org.freedesktop.systemd1.Unit', 'InactiveEnterTimestampMonotonic')
  29
  30                 l.append((str(i[0]), ixt, aet, axt, iet))
  31
  32         return l
  33
  34 def acquire_start_time():
  35         properties = Gio.DBusProxy.new_for_bus_sync(bus, Gio.DBusProxyFlags.NONE,
  36                 None, 'org.freedesktop.systemd1', '/org/freedesktop/systemd1', 'org.freedesktop.DBus.Properties', None)
  37
  38         # Note that the firmware/loader times are returned as positive
  39         # values but are atcually considered negative from the point
  40         # in time of kernel initialization. Also, the monotonic kernel
  41         # time will always be 0 since that's where the epoch of the
  42         # monotonic clock ist. Since we want to know whether the
  43         # kernel time stamp is set at all, we will thus ask for the
  44         # realtime clock for this timestamp, instead.
  45
  46         firmware_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'FirmwareTimestampMonotonic')
  47         loader_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'LoaderTimestampMonotonic')
  48         kernel_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'KernelTimestamp')
  49         initrd_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'InitRDTimestampMonotonic')
  50         userspace_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'UserspaceTimestampMonotonic')
  51         finish_time = properties.Get('(ss)', 'org.freedesktop.systemd1.Manager', 'FinishTimestampMonotonic')
  52
  53         if finish_time == 0:
  54                 sys.stderr.write("Bootup is not yet finished. Please try again later.\n")
  55                 sys.exit(1)
  56
  57         assert firmware_time >= loader_time
  58         assert initrd_time <= userspace_time
  59         assert userspace_time <= finish_time
  60
  61         return firmware_time, loader_time, kernel_time, initrd_time, userspace_time, finish_time
  62
  63 def draw_box(context, j, k, l, m, r = 0, g = 0, b = 0):
  64         context.save()
  65         context.set_source_rgb(r, g, b)
  66         context.rectangle(j, k, l, m)
  67         context.fill()
  68         context.restore()
  69
  70 def draw_text(context, x, y, text, size = 12, r = 0, g = 0, b = 0, vcenter = 0.5, hcenter = 0.5):
  71         context.save()
  72
  73         context.set_source_rgb(r, g, b)
  74         context.select_font_face("Sans", cairo.FONT_SLANT_NORMAL, cairo.FONT_WEIGHT_NORMAL)
  75         context.set_font_size(size)
  76
  77         if vcenter or hcenter:
  78                 x_bearing, y_bearing, width, height = context.text_extents(text)[:4]
  79
  80                 if hcenter:
  81                         x = x - width*hcenter - x_bearing
  82
  83                 if vcenter:
  84                         y = y - height*vcenter - y_bearing
  85
  86         context.move_to(x, y)
  87         context.show_text(text)
  88
  89         context.restore()
  90
  91 def time():
  92
  93         firmware_time, loader_time, kernel_time, initrd_time, userspace_time, finish_time = acquire_start_time()
  94
  95         sys.stdout.write("Startup finished in ")
  96
  97         if firmware_time > 0:
  98                 sys.stdout.write("%lums (firmware) + " % ((firmware_time - loader_time) / 1000))
  99         if loader_time > 0:
 100                 sys.stdout.write("%lums (loader) + " % (loader_time / 1000))
 101         if initrd_time > 0:
 102                 sys.stdout.write("%lums (kernel) + %lums (initrd) + " % (initrd_time / 1000, (userspace_time - initrd_time) / 1000))
 103         elif kernel_time > 0:
 104                 sys.stdout.write("%lums (kernel) + " % (userspace_time  / 1000))
 105
 106         sys.stdout.write("%lums (userspace) " % ((finish_time - userspace_time) / 1000))
 107
 108         if kernel_time > 0:
 109                 sys.stdout.write("= %lums\n" % ((firmware_time + finish_time) / 1000))
 110         else:
 111                 sys.stdout.write("= %lums\n" % ((finish_time - userspace_time) / 1000))
 112
 113 def blame():
 114
 115         data = acquire_time_data()
 116         s = sorted(data, key = lambda i: i[2] - i[1], reverse = True)
 117
 118         for name, ixt, aet, axt, iet in s:
 119
 120                 if ixt <= 0 or aet <= 0:
 121                         continue
 122
 123                 if aet <= ixt:
 124                         continue
 125
 126                 sys.stdout.write("%6lums %s\n" % ((aet - ixt) / 1000, name))
 127
 128 def plot():
 129         if cairo is None:
 130                 sys.stderr.write("Failed to initilize python-cairo required for 'plot' verb.\n")
 131                 sys.exit(1)
 132         firmware_time, loader_time, kernel_time, initrd_time, userspace_time, finish_time = acquire_start_time()
 133         data = acquire_time_data()
 134         s = sorted(data, key = lambda i: i[1])
 135
 136         # Account for kernel and initramfs bars if they exist
 137         if initrd_time > 0:
 138                 count = 3
 139         else:
 140                 count = 2
 141
 142         for name, ixt, aet, axt, iet in s:
 143
 144                 if (ixt >= userspace_time and ixt <= finish_time) or \
 145                                 (aet >= userspace_time and aet <= finish_time) or \
 146                                 (axt >= userspace_time and axt <= finish_time):
 147                         count += 1
 148
 149         border = 100
 150         bar_height = 20
 151         bar_space = bar_height * 0.1
 152
 153         # 1000px = 10s, 1px = 10ms
 154         width = finish_time/10000 + border*2
 155         height = count * (bar_height + bar_space) + border * 2
 156
 157         if width < 1000:
 158                 width = 1000
 159
 160         surface = cairo.SVGSurface(sys.stdout, width, height)
 161         context = cairo.Context(surface)
 162
 163         draw_box(context, 0, 0, width, height, 1, 1, 1)
 164
 165         context.translate(border + 0.5, border + 0.5)
 166
 167         context.save()
 168         context.set_line_width(1)
 169         context.set_source_rgb(0.7, 0.7, 0.7)
 170
 171         for x in range(0, int(finish_time/10000) + 100, 100):
 172                 context.move_to(x, 0)
 173                 context.line_to(x, height-border*2)
 174
 175         context.move_to(0, 0)
 176         context.line_to(width-border*2, 0)
 177
 178         context.move_to(0, height-border*2)
 179         context.line_to(width-border*2, height-border*2)
 180
 181         context.stroke()
 182         context.restore()
 183
 184         osrel = "Linux"
 185         if os.path.exists("/etc/os-release"):
 186                 for line in open("/etc/os-release"):
 187                         if line.startswith('PRETTY_NAME='):
 188                                 osrel = line[12:]
 189                                 osrel = osrel.strip('\"\n')
 190                                 break
 191
 192         banner = "{} {} ({} {}) {}".format(osrel, *(os.uname()[1:5]))
 193         draw_text(context, 0, -15, banner, hcenter = 0, vcenter = 1)
 194
 195         for x in range(0, int(finish_time/10000) + 100, 100):
 196                 draw_text(context, x, -5, "%lus" % (x/100), vcenter = 0, hcenter = 0)
 197
 198         y = 0
 199
 200         # draw boxes for kernel and initramfs boot time
 201         if initrd_time > 0:
 202                 draw_box(context, 0, y, initrd_time/10000, bar_height, 0.7, 0.7, 0.7)
 203                 draw_text(context, 10, y + bar_height/2, "kernel", hcenter = 0)
 204                 y += bar_height + bar_space
 205
 206                 draw_box(context, initrd_time/10000, y, userspace_time/10000-initrd_time/10000, bar_height, 0.7, 0.7, 0.7)
 207                 draw_text(context, initrd_time/10000 + 10, y + bar_height/2, "initramfs", hcenter = 0)
 208                 y += bar_height + bar_space
 209
 210         else:
 211                 draw_box(context, 0, y, userspace_time/10000, bar_height, 0.6, 0.6, 0.6)
 212                 draw_text(context, 10, y + bar_height/2, "kernel", hcenter = 0)
 213                 y += bar_height + bar_space
 214
 215         draw_box(context, userspace_time/10000, y, finish_time/10000-userspace_time/10000, bar_height, 0.7, 0.7, 0.7)
 216         draw_text(context, userspace_time/10000 + 10, y + bar_height/2, "userspace", hcenter = 0)
 217         y += bar_height + bar_space
 218
 219         for name, ixt, aet, axt, iet in s:
 220
 221                 drawn = False
 222                 left = -1
 223
 224                 if ixt >= userspace_time and ixt <= finish_time:
 225
 226                         # Activating
 227                         a = ixt
 228                         b = min(filter(lambda x: x >= ixt, (aet, axt, iet, finish_time))) - ixt
 229
 230                         draw_box(context, a/10000, y, b/10000, bar_height, 1, 0, 0)
 231                         drawn = True
 232
 233                         if left < 0:
 234                                 left = a
 235
 236                 if aet >= userspace_time and aet <= finish_time:
 237
 238                         # Active
 239                         a = aet
 240                         b = min(filter(lambda x: x >= aet, (axt, iet, finish_time))) - aet
 241
 242                         draw_box(context, a/10000, y, b/10000, bar_height, .8, .6, .6)
 243                         drawn = True
 244
 245                         if left < 0:
 246                                 left = a
 247
 248                 if axt >= userspace_time and axt <= finish_time:
 249
 250                         # Deactivating
 251                         a = axt
 252                         b = min(filter(lambda x: x >= axt, (iet, finish_time))) - axt
 253
 254                         draw_box(context, a/10000, y, b/10000, bar_height, .6, .4, .4)
 255                         drawn = True
 256
 257                         if left < 0:
 258                                 left = a
 259
 260                 if drawn:
 261                         x = left/10000
 262
 263                         if x < width/2-border:
 264                                 draw_text(context, x + 10, y + bar_height/2, name, hcenter = 0)
 265                         else:
 266                                 draw_text(context, x - 10, y + bar_height/2, name, hcenter = 1)
 267
 268                         y += bar_height + bar_space
 269
 270         draw_text(context, 0, height-border*2, "Legend: Red = Activating; Pink = Active; Dark Pink = Deactivating", hcenter = 0, vcenter = -1)
 271
 272         if initrd_time > 0:
 273                 draw_text(context, 0, height-border*2 + bar_height, "Startup finished in %lums (kernel) + %lums (initramfs) + %lums (userspace) = %lums" % ( \
 274                         initrd_time/1000, \
 275                         (userspace_time - initrd_time)/1000, \
 276                         (finish_time - userspace_time)/1000, \
 277                         finish_time/1000), hcenter = 0, vcenter = -1)
 278         else:
 279                 draw_text(context, 0, height-border*2 + bar_height, "Startup finished in %lums (kernel) + %lums (userspace) = %lums" % ( \
 280                         userspace_time/1000, \
 281                         (finish_time - userspace_time)/1000, \
 282                         finish_time/1000), hcenter = 0, vcenter = -1)
 283
 284         surface.finish()
 285
 286 parser = argparse.ArgumentParser(formatter_class=argparse.RawDescriptionHelpFormatter,
 287                                  description='Process systemd profiling information',
 288                                  epilog='''\
 289 time - print time spent in the kernel before reaching userspace
 290 blame - print list of running units ordered by time to init
 291 plot - output SVG graphic showing service initialization
 292 ''')
 293
 294 parser.add_argument('action', choices=('time', 'blame', 'plot'),
 295                     default='time', nargs='?',
 296                     help='action to perform (default: time)')
 297 parser.add_argument('--user', action='store_true',
 298                     help='use the session bus')
 299
 300 args = parser.parse_args()
 301
 302 if args.user:
 303         bus = Gio.BusType.SESSION
 304 else:
 305         bus = Gio.BusType.SYSTEM
 306
 307 verb = {'time' : time,
 308         'blame': blame,
 309         'plot' : plot,
 310         }
 311 verb.get(args.action)()