From nobody Thu Dec 01 21:08:03 2022 X-Original-To: freebsd-dtrace@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 4NNTF92VMxz4jLMK for ; Thu, 1 Dec 2022 21:08:13 +0000 (UTC) (envelope-from markjdb@gmail.com) Received: from mail-qt1-x829.google.com (mail-qt1-x829.google.com [IPv6:2607:f8b0:4864:20::829]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (2048 bits) client-digest SHA256) (Client CN "smtp.gmail.com", Issuer "GTS CA 1D4" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4NNTF81g8vz3NH6; Thu, 1 Dec 2022 21:08:12 +0000 (UTC) (envelope-from markjdb@gmail.com) Authentication-Results: mx1.freebsd.org; dkim=pass header.d=gmail.com header.s=20210112 header.b=RSH0qbEn; spf=pass (mx1.freebsd.org: domain of markjdb@gmail.com designates 2607:f8b0:4864:20::829 as permitted sender) smtp.mailfrom=markjdb@gmail.com; dmarc=none Received: by mail-qt1-x829.google.com with SMTP id e15so2599913qts.1; Thu, 01 Dec 2022 13:08:12 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=in-reply-to:content-disposition:mime-version:references:message-id :subject:cc:to:from:date:sender:from:to:cc:subject:date:message-id :reply-to; bh=zMErbTGKujtfk3EVQsOGLmpiav6EoVBX14tNTC92IQ8=; b=RSH0qbEnnfr8aTeXppgVDc7I6rjI874wxeunAOEuDCErBpiqcpHCzw7eMCMM1mnRmZ MSZZj4dTPTUGfgoQYCSD8+9eDibcXV9Pg9FFs0Oeailwf1TH69KwmnAyceuIn5o3ptiP 75b8hAGQXfGS+EoDp5tThch4mOJ091mGSGWNiZ4LU/P4sAH6TXI56znsy0atq/ub0SWn k+CTP3/N9YRROPf3Z65V0mOyehbUUvIOlS+h/Ge6J23Mo1+Y7MwF+acfA7ckzkFvVtJk omvpayPFTIdEFBT3TnoOaT4WU1GBhm2IaQPnY3nGmrRQ7U8pjomM32O2uqnkonLLsuDg vHvQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=in-reply-to:content-disposition:mime-version:references:message-id :subject:cc:to:from:date:sender:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=zMErbTGKujtfk3EVQsOGLmpiav6EoVBX14tNTC92IQ8=; b=aTQhFCiUmcUr3daidnoXeQVthHZeSCBEjVTTOKX6vya9Bk8aUcu7ct/GIc0SM+T8h7 9VCq0ruL3mS1p65rG57D+rT1JruFLA6qTkgYgpy9MwqR3OZDzjEyg18ohJzBrTcLwcjT Zq4GUQz7+slVOBMovFKkwxMyTchieuWxm3zwBSO3skTA5lWuLouyxMuPAF2e7xoV1jG8 3ApU7CktOXDBDLDdrgk9iYEzbVY5C272I+43qxMXl7/ede2W9VBozpcJVn4dY8MyOw0R VbIGnGbegTXBCuIQBO1fKsi3IS5GbmCG0zK64oK98oKSBFLZ9zjsScFfQv6w7RrQxWGU +nLw== X-Gm-Message-State: ANoB5plQ0AiSiaGB2VRSQ9U8FpzMraC/Vr4sMXXpvgn4ZMMSP6uHhKWJ hN3Mt+chTMY9hlUp+KLE/eYMEVK3Xp8= X-Google-Smtp-Source: AA0mqf5mZUCqkL6b2+f3b776HIECsedJDqznBzyAcMb+gcJ7Jbq29Hn3mXjtDe7EGsyOGW3qE5se8g== X-Received: by 2002:ac8:5c56:0:b0:3a5:20b1:e390 with SMTP id j22-20020ac85c56000000b003a520b1e390mr64224229qtj.626.1669928890073; Thu, 01 Dec 2022 13:08:10 -0800 (PST) Received: from nuc (192-0-220-237.cpe.teksavvy.com. [192.0.220.237]) by smtp.gmail.com with ESMTPSA id r26-20020ac867da000000b003a5689134afsm3121592qtp.36.2022.12.01.13.08.05 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 01 Dec 2022 13:08:06 -0800 (PST) Date: Thu, 1 Dec 2022 16:08:03 -0500 From: Mark Johnston To: Mateusz Piotrowski <0mp@freebsd.org> Cc: freebsd-dtrace@freebsd.org Subject: Re: In DTrace, why does timestamp increase after a call to chill() but vtimestamp and walltimestamp do not? Message-ID: References: List-Id: A discussion list for developers working on DTrace in FreeBSD List-Archive: https://lists.freebsd.org/archives/freebsd-dtrace List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-dtrace@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: X-Spamd-Result: default: False [-1.67 / 15.00]; NEURAL_HAM_LONG(-1.00)[-1.000]; SUBJECT_ENDS_QUESTION(1.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; NEURAL_HAM_SHORT(-0.97)[-0.968]; MID_RHS_NOT_FQDN(0.50)[]; FORGED_SENDER(0.30)[markj@freebsd.org,markjdb@gmail.com]; R_SPF_ALLOW(-0.20)[+ip6:2607:f8b0:4000::/36]; R_DKIM_ALLOW(-0.20)[gmail.com:s=20210112]; MIME_GOOD(-0.10)[text/plain]; FROM_HAS_DN(0.00)[]; RCVD_TLS_LAST(0.00)[]; TO_MATCH_ENVRCPT_ALL(0.00)[]; DMARC_NA(0.00)[freebsd.org]; RCVD_IN_DNSWL_NONE(0.00)[2607:f8b0:4864:20::829:from]; ARC_NA(0.00)[]; FROM_NEQ_ENVFROM(0.00)[markj@freebsd.org,markjdb@gmail.com]; MLMMJ_DEST(0.00)[freebsd-dtrace@freebsd.org]; DKIM_TRACE(0.00)[gmail.com:+]; RCVD_COUNT_THREE(0.00)[3]; TO_DN_SOME(0.00)[]; DWL_DNSWL_NONE(0.00)[gmail.com:dkim]; RCPT_COUNT_TWO(0.00)[2]; FREEMAIL_ENVFROM(0.00)[gmail.com]; MIME_TRACE(0.00)[0:+]; ASN(0.00)[asn:15169, ipnet:2607:f8b0::/32, country:US]; RCVD_VIA_SMTP_AUTH(0.00)[] X-Rspamd-Queue-Id: 4NNTF81g8vz3NH6 X-Spamd-Bar: - X-ThisMailContainsUnwantedMimeParts: N On Wed, Nov 23, 2022 at 09:07:23AM -0500, Mark Johnston wrote: > On Mon, Nov 21, 2022 at 06:19:16PM +0100, Mateusz Piotrowski wrote: > > Hello all, > > > > I'd like to understand why calling chill() in a DTrace action block increases the timestampvariable, but not vtimestamp and walltimestamp. > > Here's an example showing timestamp increasing after a call to chill(): > > I think you found a bug in dtrace. When a dtrace probe fires and > actions attached to that probe are executed, the value of *timestamp is > cached in a struct dtrace_mstate on the firing CPU's stack. This means > that in D, within a probe body, multiple accesses of *timestamp will > return the same cached value. > > As it turns out, the implementation of chill() will invalidate that > cached value, but only for "timestamp", not for walltimestamp, which > seems incorrect. Below is an untested patch which should fix your > example. I tested this and found that it isn't sufficient. Even if we re-read the walltimestamp value, it is usually the same before and after a chill(). The reason is that walltimestamp returns the last saved timecounter value rather than querying the timecounter directly and so is not very precise. This cannot be changed without violating the invariant that DIF execution cannot invoke code that is not part of dtrace itself. Otherwise, reading walltimestamp could cause a probe to fire. It is possible that a timer interrupt on a different CPU will update the timehands during a chill() and so the probe will see different values before and after, but whether or not this happen is up to chance. So, I think you examples behave as expected, even though the results are a bit unintuitive. > I think the behaviour of vtimestamp that you observe is expected. From > the description, "The counter does not include the time that is spent in > DTrace predicates and actions", so I wouldn't expect it to advance while > dtrace_probe() is running. And indeed, it gets advanced once at the > beginning of dtrace_probe().