From owner-freebsd-current@freebsd.org Sat Dec 23 03:39:05 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 42735E9575C for ; Sat, 23 Dec 2017 03:39:05 +0000 (UTC) (envelope-from 010001608173caa8-254b1eec-369a-4f21-af28-f0f68adc8506-000000@amazonses.com) Received: from a8-56.smtp-out.amazonses.com (a8-56.smtp-out.amazonses.com [54.240.8.56]) (using TLSv1 with cipher ECDHE-RSA-AES128-SHA (128/128 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 06F6272680 for ; Sat, 23 Dec 2017 03:39:04 +0000 (UTC) (envelope-from 010001608173caa8-254b1eec-369a-4f21-af28-f0f68adc8506-000000@amazonses.com) DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/simple; s=ae7m2yrxjw65l2cqdpjxuucyrvy564tn; d=tarsnap.com; t=1514000337; h=Subject:To:References:Cc:From:Message-ID:Date:MIME-Version:In-Reply-To:Content-Type:Content-Transfer-Encoding; bh=G5N3aJ0Y5DMSExK0/znZ1j02w/VI/FzFGm322kHuWWs=; b=Q2r1uMWnXukPeYFZfL4uwu4sC9hsRZ2kg/1v/44KGASvqcQEz/9VDL7H2gO3itUp euxlynY6xyGjfVwpf/ixKKMhdUAglwXe/T8ITFEXFuFy0re2voCoOCyggzc4s8GIHbR fcbrirOyO54MKtSi1s87LKPvOgJxgaBp9PixFzmA= DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/simple; s=224i4yxa5dv7c2xz3womw6peuasteono; d=amazonses.com; t=1514000337; h=Subject:To:References:Cc:From:Message-ID:Date:MIME-Version:In-Reply-To:Content-Type:Content-Transfer-Encoding:Feedback-ID; bh=G5N3aJ0Y5DMSExK0/znZ1j02w/VI/FzFGm322kHuWWs=; b=d0IrryTfmu2tTSfl9hvawjCSvKq/Rzt4CRpMGM4ugrEazebv+v8YV0DROh3/OSZx 3gpV8tupCFx3dl2NhbeSaG3feZDWL5V0cTPMWeeZ7RKTBU3hq8XIzjIBl/0Ve/Ky96L hGvarDkRrb3WIXvfKkL8Ro02CIEXtetFmYh9BWF8= Subject: Re: [Request for review] Profiling the FreeBSD kernel boot To: Mark Johnston References: <010001607d9c59d5-15b6b788-a7ea-4edf-96e4-1235dd1a5c26-000000@email.amazonses.com> <20171222170818.GA39071@raichu> Cc: "freebsd-current@freebsd.org" From: Colin Percival Message-ID: <010001608173caa8-254b1eec-369a-4f21-af28-f0f68adc8506-000000@email.amazonses.com> Date: Sat, 23 Dec 2017 03:38:57 +0000 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:45.0) Gecko/20100101 Thunderbird/45.5.1 MIME-Version: 1.0 In-Reply-To: <20171222170818.GA39071@raichu> Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: 7bit X-SES-Outgoing: 2017.12.23-54.240.8.56 Feedback-ID: 1.us-east-1.Lv9FVjaNvvR5llaqfLoOVbo2VxOELl7cjN0AOyXnPlk=:AmazonSES X-Mailman-Approved-At: Sat, 23 Dec 2017 03:48:20 +0000 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: Sat, 23 Dec 2017 03:39:05 -0000 On 12/22/17 09:08, Mark Johnston wrote: > On Fri, Dec 22, 2017 at 09:44:46AM +0000, Colin Percival wrote: >> 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. Right. Also, even aside from details like measuring the TSC skew between CPUs, DTrace needs things like traps, memory allocation, and mutexes, none of which exist when we enter hammer_time (or any of the other MD startup code). What I meant is that it's impossible to use DTrace to monitor things which happened prior to when the DTrace *kernel bits* are initialized. > I don't think boot-time DTrace is quite what you want for this exercise, > but it does come in handy sometimes. Absolutely. And for a long time I considered trying to splice together a basic profiling mechanism for pre-DTrace-initialization with using DTrace from when it's ready onwards... but I decided that it would be easier at least to start with to simply use a single mechanism throughout. > 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: [...] Thanks for the example! I think it's very likely that I'll make use of boot-time DTrace for tracking down some of the performance warts I've found -- the ones which happen after DTrace is initialized, that is. -- Colin Percival Security Officer Emeritus, FreeBSD | The power to serve Founder, Tarsnap | www.tarsnap.com | Online backups for the truly paranoid