From owner-freebsd-current@freebsd.org Fri Dec 22 17:08:25 2017 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id AB6FAEA4DE1 for ; Fri, 22 Dec 2017 17:08:25 +0000 (UTC) (envelope-from markjdb@gmail.com) Received: from mail-qk0-x244.google.com (mail-qk0-x244.google.com [IPv6:2607:f8b0:400d:c09::244]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 5B7207E965 for ; Fri, 22 Dec 2017 17:08:25 +0000 (UTC) (envelope-from markjdb@gmail.com) Received: by mail-qk0-x244.google.com with SMTP id j137so17727263qke.10 for ; Fri, 22 Dec 2017 09:08:25 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=sender:date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to:user-agent; bh=giTyGGV8vN3jjozYNix7MLe5+mrr2XfOMzt5j0OW6Hk=; b=ZNLjqMsCQ5DagVY+phjuhOHu0Yd91brdQd9OGeyE4YtJXhJHvCIZ/7Ug/MpKAcg3nK 1fNKF0T+hwbHsj//tv0DqTKNBEk13DisZahg7uGAtXiaZ4nvEKK7vhlaD2O+eW4brjJx waJA4tHijvrwfFCIeQkVEtDJipUOUnHYpySZtA955TKRiQQ17vFuRv+4HTUz+TU4ci1D /fRVJnIXaeO6IDkfMOh/4y6B1BJdnGBHhqZz5BJWVVtpbWnSIYFv71gRRVCjFskj58cv zp7RBlcp+9Q++ng2Lon0nYjARTmPZuaFdlDr6kxHSaGMlUjUq5PChry7zs9wIFINKy0T VmlQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:sender:date:from:to:cc:subject:message-id :references:mime-version:content-disposition:in-reply-to:user-agent; bh=giTyGGV8vN3jjozYNix7MLe5+mrr2XfOMzt5j0OW6Hk=; b=D3TDFTBGWxEZC4LTTCUtGda5G6vOOfCKoDTXu4itcjXhgFan9vdwMYiCX0jL5lubn6 0ICExvj+tM5L8r1LQdJ5gFu7qC15BYVcilJPU0IW2504ZplnJzK8dwFBJRpAKg+u7hc9 6nhHQ/bOWnVCwX8nr8W+wTovkgio+ORayKzOBLONqQn30QVGgUjZH0qYly1oEBIM7esg dT4WlakbHVKAb+O+FbqtzS+tZ0quSDR6112Vp94h68frR7XasF6GYBU/vtnLaN/iV21B bluV7RBxk/Ag5fGTc+8gHU3YuYQ1KqaCDu4fPW3k1NHVFZYB6iBsVnHpKIZIl0NHyEFd +ahw== X-Gm-Message-State: AKGB3mJp9VnYPM7zc4IHr/sHZN9tn9cNhX2t/EOlq/ADGbJDfFy4Ewsc xyobZRzgbu4KIktKs8omrr8w0g== X-Google-Smtp-Source: ACJfBosBYNa2/gYnZNPI8Qq5aHea1wF77+bleAqxG+6Vmgwkk/YNAAC5ooOBK9NjNzTrRfk2K5cqww== X-Received: by 10.55.20.215 with SMTP id 84mr20544126qku.191.1513962504351; Fri, 22 Dec 2017 09:08:24 -0800 (PST) Received: from raichu (toroon0560w-lp140-01-69-159-38-22.dsl.bell.ca. [69.159.38.22]) by smtp.gmail.com with ESMTPSA id 46sm14772983qtx.65.2017.12.22.09.08.23 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Fri, 22 Dec 2017 09:08:23 -0800 (PST) Sender: Mark Johnston Date: Fri, 22 Dec 2017 12:08:18 -0500 From: Mark Johnston To: Colin Percival Cc: "freebsd-current@freebsd.org" Subject: Re: [Request for review] Profiling the FreeBSD kernel boot Message-ID: <20171222170818.GA39071@raichu> References: <010001607d9c59d5-15b6b788-a7ea-4edf-96e4-1235dd1a5c26-000000@email.amazonses.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <010001607d9c59d5-15b6b788-a7ea-4edf-96e4-1235dd1a5c26-000000@email.amazonses.com> User-Agent: Mutt/1.9.1 (2017-09-22) X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.25 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 22 Dec 2017 17:08:25 -0000 On Fri, Dec 22, 2017 at 09:44:46AM +0000, Colin Percival wrote: > Hi everyone, > > For the past few months I've been working on code for profiling the FreeBSD > "kernel boot", i.e., everything between when kernel code starts running and > when we first enter userland as init(8). This is not trivial since it's > impossible to use tools like dtrace to monitor things prior to when said > tools are running. In the case of DTrace, this isn't quite true. We support so-called boot-time DTrace on x86. The caveat is that we can only start tracing after the SI_SUB_DTRACE_ANON sysinit has been executed. That sysinit can't come earlier than SI_SUB_SMP, since it needs to be able to measure TSC skew between CPUs in order to initialize DTrace's high-resolution timer. I don't think boot-time DTrace is quite what you want for this exercise, but it does come in handy sometimes. In case it's of interest: to use boot-time DTrace, invoke dtrace(1) as you normally would and add -A. Rather than starting to trace, dtrace(1) will save a representation of the D script to a file which gets read by the loader during the next boot. The results of the trace can be fetched with "dtrace -a". For instance, to print the amount of time elapsed in microseconds during each vprintf() call, along with a stack: # dtrace -A -n 'fbt::vprintf:entry {self->ts = timestamp;} fbt::vprintf:return /self->ts/ { printf("%d", (timestamp - self->ts) / 1000); self->ts = 0; stack(); }' ... # dtrace -a -e CPU ID FUNCTION:NAME 0 17161 vprintf:return 419 kernel`printf+0x43 kernel`randomdev_modevent+0x26 kernel`module_register_init+0xc0 kernel`mi_startup+0x9c kernel`0xffffffff8028656c ...