From nobody Mon Nov 21 17:19:16 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 4NGDdl0PcXz4jVxs for ; Mon, 21 Nov 2022 17:19:23 +0000 (UTC) (envelope-from mpp302@gmail.com) Received: from mail-qk1-f180.google.com (mail-qk1-f180.google.com [209.85.222.180]) (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 4NGDdk0YyRz3K94 for ; Mon, 21 Nov 2022 17:19:22 +0000 (UTC) (envelope-from mpp302@gmail.com) Authentication-Results: mx1.freebsd.org; dkim=none; spf=pass (mx1.freebsd.org: domain of mpp302@gmail.com designates 209.85.222.180 as permitted sender) smtp.mailfrom=mpp302@gmail.com; dmarc=none Received: by mail-qk1-f180.google.com with SMTP id x21so8500347qkj.0 for ; Mon, 21 Nov 2022 09:19:22 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=to:date:message-id:subject:mime-version:from:x-gm-message-state :from:to:cc:subject:date:message-id:reply-to; bh=DCsvt5tCRGkyY91QHBxE6IuRRmAGOwg/slKyvcyv03w=; b=JKA54pHVpByRu7h2/rIwG0Qk64bmmZY1wjDqQaI3JwRpvE1J6n90Ucqif6V8wHpxsN giwXHQPzWseWb7EywRO78rhwCXdFHBMtbMnRfocqFyJWq/bGtURU7ODBbYtY7WHy3HFR VtCTr7EM+TXPGFAlSBdNqpMp0WPVm1Rsz1ekXIcaPe0Lm8gH21R3XbF8vk1rAJRv2hA+ ilpxkVftvdzqOclnCU9qHNeCBpoqOBrcIpfXrFPHKFcSJwiOZ6S9a92Z0nzmZR29VKfu TSp5ujdaSy7pAJJh07/QlrIkG4I0mFpz9smi1UqnLu8pu3HIGZiZ1MKNZYVwSdx6AmjK +9hg== X-Gm-Message-State: ANoB5pn7o5/LTB5DRZfR0FhD6a9H8f1keO08Fhmy/Pebcte6czcPcbuG RJQe+FogMNS7kmiz+GZqi5KK+p+GqX0= X-Google-Smtp-Source: AA0mqf6R1hr9vculBaJ6XePW0JE8aXEeeRp2VtMOnhjheJRz8yCF42vARp0h9kEd/2DpHR1HhNbPrA== X-Received: by 2002:a05:620a:108c:b0:6cd:fd44:d83e with SMTP id g12-20020a05620a108c00b006cdfd44d83emr3558433qkk.594.1669051160853; Mon, 21 Nov 2022 09:19:20 -0800 (PST) Received: from smtpclient.apple (ip5f5af5a7.dynamic.kabel-deutschland.de. [95.90.245.167]) by smtp.gmail.com with ESMTPSA id z11-20020ac8100b000000b003a50ef44a77sm6832490qti.28.2022.11.21.09.19.20 for (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Mon, 21 Nov 2022 09:19:20 -0800 (PST) From: Mateusz Piotrowski <0mp@FreeBSD.org> Content-Type: multipart/alternative; boundary="Apple-Mail=_9AFBAE28-2D18-4A94-8979-B2FE01D2F5D1" 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 (Mac OS X Mail 16.0 \(3696.120.41.1.1\)) Subject: In DTrace, why does timestamp increase after a call to chill() but vtimestamp and walltimestamp do not? Message-Id: Date: Mon, 21 Nov 2022 18:19:16 +0100 To: freebsd-dtrace@freebsd.org X-Mailer: Apple Mail (2.3696.120.41.1.1) X-Spamd-Result: default: False [-1.47 / 15.00]; SUBJECT_ENDS_QUESTION(1.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; NEURAL_HAM_LONG(-1.00)[-0.999]; NEURAL_HAM_SHORT(-0.97)[-0.970]; MV_CASE(0.50)[]; FORGED_SENDER(0.30)[0mp@FreeBSD.org,mpp302@gmail.com]; R_SPF_ALLOW(-0.20)[+ip4:209.85.128.0/17:c]; MIME_GOOD(-0.10)[multipart/alternative,text/plain]; RCVD_VIA_SMTP_AUTH(0.00)[]; TO_MATCH_ENVRCPT_ALL(0.00)[]; PREVIOUSLY_DELIVERED(0.00)[freebsd-dtrace@freebsd.org]; RCPT_COUNT_ONE(0.00)[1]; MIME_TRACE(0.00)[0:+,1:+,2:~]; DMARC_NA(0.00)[freebsd.org]; RCVD_TLS_LAST(0.00)[]; RCVD_IN_DNSWL_NONE(0.00)[209.85.222.180:from]; FROM_HAS_DN(0.00)[]; ARC_NA(0.00)[]; TO_DOM_EQ_FROM_DOM(0.00)[]; R_DKIM_NA(0.00)[]; RCVD_COUNT_THREE(0.00)[3]; TO_DN_NONE(0.00)[]; MLMMJ_DEST(0.00)[freebsd-dtrace@freebsd.org]; FREEMAIL_ENVFROM(0.00)[gmail.com]; MID_RHS_MATCH_FROM(0.00)[]; ASN(0.00)[asn:15169, ipnet:209.85.128.0/17, country:US]; FROM_NEQ_ENVFROM(0.00)[0mp@FreeBSD.org,mpp302@gmail.com]; RWL_MAILSPIKE_POSSIBLE(0.00)[209.85.222.180:from] X-Rspamd-Queue-Id: 4NGDdk0YyRz3K94 X-Spamd-Bar: - X-ThisMailContainsUnwantedMimeParts: N --Apple-Mail=_9AFBAE28-2D18-4A94-8979-B2FE01D2F5D1 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=us-ascii 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(): # dtrace -w -c true -n 'pid$target:::entry {self->t =3D $1; = chill(1); printf("%d\n", $1 - self->t);}' timestamp dtrace: description 'pid$target:::entry ' matched 3082 probes dtrace: allowing destructive actions dtrace: pid 6734 has exited CPU ID FUNCTION:NAME 5 83475 _r_debug_postinit:entry 11258 =20 5 85771 atexit:entry 2218 =20 5 86468 __libc_atexit:entry 491 =20 5 86428 exit:entry 441 =20 5 85397 __cxa_thread_call_dtors:entry 441 =20 5 86213 __cxa_finalize:entry 447 =20 5 86213 __cxa_finalize:entry 565 =20 5 83470 _rtld_addr_phdr:entry 454 =20 5 86213 __cxa_finalize:entry 431 =20 5 83470 _rtld_addr_phdr:entry 1645 =20 5 84405 _exit:entry 432 If we run the same script but use walltimestamp (or vtimestamp), we'll = see the counter did not increase: # dtrace -w -c true -n 'pid$target:::entry {self->t =3D $1; = chill(1); printf("%d\n", $1 - self->t);}' walltimestamp dtrace: description 'pid$target:::entry ' matched 3082 probes dtrace: allowing destructive actions dtrace: pid 6707 has exited CPU ID FUNCTION:NAME 4 83475 _r_debug_postinit:entry 0 =20 4 85771 atexit:entry 0 =20 4 86468 __libc_atexit:entry 0 =20 4 86428 exit:entry 0 =20 4 85397 __cxa_thread_call_dtors:entry 0 =20 4 86213 __cxa_finalize:entry 0 =20 4 86213 __cxa_finalize:entry 0 =20 4 83470 _rtld_addr_phdr:entry 0 =20 4 86213 __cxa_finalize:entry 0 =20 4 83470 _rtld_addr_phdr:entry 0 =20 4 84405 _exit:entry 0 This is understandable for vtimestamp, as it does not increase when = executing DTrace code, but I don't understand walltimestamp's behavior = here. I'm running FreeBSD 13.1-RELEASE-p1 here on amd64. Best, Mateusz= --Apple-Mail=_9AFBAE28-2D18-4A94-8979-B2FE01D2F5D1 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=us-ascii
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():

        # dtrace -w -c = true -n 'pid$target:::entry {self->t =3D $1; chill(1); printf("%d\n", = $1 - self->t);}' timestamp
        dtrace: = description 'pid$target:::entry ' matched 3082 = probes
        dtrace: = allowing destructive actions
        dtrace: pid = 6734 has exited
        CPU   =   ID                   =  FUNCTION:NAME
          5 =  83475          _r_debug_postinit:entry = 11258
      =   
          5 =  85771                 =     atexit:entry 2218
      =   
          5 =  86468             =  __libc_atexit:entry 491
      =   
          5 =  86428                 =       exit:entry 441
      =   
          5 =  85397    __cxa_thread_call_dtors:entry = 441
      =   
          5 =  86213             = __cxa_finalize:entry 447
      =   
          5 =  86213             = __cxa_finalize:entry 565
      =   
          5 =  83470           =  _rtld_addr_phdr:entry 454
      =   
          5 =  86213             = __cxa_finalize:entry 431
      =   
          5 =  83470           =  _rtld_addr_phdr:entry 1645
      =   
          5 =  84405                 =      _exit:entry 432

If we run the same script but use = walltimestamp (or vtimestamp), we'll see the counter did not = increase:

      =   # dtrace -w -c true -n 'pid$target:::entry {self->t =3D $1; = chill(1); printf("%d\n", $1 - self->t);}' = walltimestamp
        dtrace: = description 'pid$target:::entry ' matched 3082 = probes
        dtrace: = allowing destructive actions
        dtrace: pid = 6707 has exited
        CPU   =   ID                   =  FUNCTION:NAME
          4 =  83475          _r_debug_postinit:entry = 0
      =   
          4 =  85771                 =     atexit:entry 0
      =   
          4 =  86468             =  __libc_atexit:entry 0
      =   
          4 =  86428                 =       exit:entry 0
      =   
          4 =  85397    __cxa_thread_call_dtors:entry = 0
      =   
          4 =  86213             = __cxa_finalize:entry 0
      =   
          4 =  86213             = __cxa_finalize:entry 0
      =   
          4 =  83470           =  _rtld_addr_phdr:entry 0
      =   
          4 =  86213             = __cxa_finalize:entry 0
      =   
          4 =  83470           =  _rtld_addr_phdr:entry 0
      =   
          4 =  84405                 =      _exit:entry 0

This is understandable for vtimestamp, as = it does not increase when executing DTrace code, but I don't understand = walltimestamp's behavior here.

I'm running FreeBSD 13.1-RELEASE-p1 here on = amd64.

Best,
Mateusz
= --Apple-Mail=_9AFBAE28-2D18-4A94-8979-B2FE01D2F5D1--