From nobody Sat Jul 16 09:50:02 2022 X-Original-To: dev-commits-src-main@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 4LlNkM1ljYz4T3xc; Sat, 16 Jul 2022 09:50:03 +0000 (UTC) (envelope-from git@FreeBSD.org) Received: from mxrelay.nyi.freebsd.org (mxrelay.nyi.freebsd.org [IPv6:2610:1c1:1:606c::19:3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "R3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4LlNkM1Ckjz49py; Sat, 16 Jul 2022 09:50:03 +0000 (UTC) (envelope-from git@FreeBSD.org) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1657965003; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=7vgYOLl1FjG7qv9Q6NmR5+k/309A+sFSD1834SYOook=; b=TZzBZlV0YNU5vx1mZZhWaJ/o326X85s51X/6a7QDXg30yhBr6yio4AdqaLhSqkY2VRDBo1 Z4/yO74ciJrNBn0s5tGVvVQWWpgyhJhuQwTvVSdr9JudBPTwQKz16OIpDhH1BYSTbikJYY cww3bbTQhb3iieMhRTn2M/d/FxARlaMcRwUqEHv1i0BUpszQzrfSIjfB5Eq992D+WCnYKZ s21B8az71wrpl5NvJE4FSK8wWxta3zX9cv0IK1IgBH948VDAdc6NA9hgm+psL4f9QZzbjs 348jrB+1Vy3R8Riseam0SDWunh5ODvtVpD9UdbX4fXmAUygZcttU+YtqJyaJIQ== Received: from gitrepo.freebsd.org (gitrepo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:5]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id 4LlNkM08v3zHJ0; Sat, 16 Jul 2022 09:50:03 +0000 (UTC) (envelope-from git@FreeBSD.org) Received: from gitrepo.freebsd.org ([127.0.1.44]) by gitrepo.freebsd.org (8.16.1/8.16.1) with ESMTP id 26G9o2nu034358; Sat, 16 Jul 2022 09:50:02 GMT (envelope-from git@gitrepo.freebsd.org) Received: (from git@localhost) by gitrepo.freebsd.org (8.16.1/8.16.1/Submit) id 26G9o2AZ034355; Sat, 16 Jul 2022 09:50:02 GMT (envelope-from git) Date: Sat, 16 Jul 2022 09:50:02 GMT Message-Id: <202207160950.26G9o2AZ034355@gitrepo.freebsd.org> To: src-committers@FreeBSD.org, dev-commits-src-all@FreeBSD.org, dev-commits-src-main@FreeBSD.org From: Dmitry Chagin Subject: git: fc90f3a28145 - main - ktrace: Increase precision of timestamps. List-Id: Commit messages for the main branch of the src repository List-Archive: https://lists.freebsd.org/archives/dev-commits-src-main List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-dev-commits-src-main@freebsd.org X-BeenThere: dev-commits-src-main@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit X-Git-Committer: dchagin X-Git-Repository: src X-Git-Refname: refs/heads/main X-Git-Reftype: branch X-Git-Commit: fc90f3a28145872afb7106d391bc922572eb2b71 Auto-Submitted: auto-generated ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1657965003; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=7vgYOLl1FjG7qv9Q6NmR5+k/309A+sFSD1834SYOook=; b=vaYq1p/d9Lpjj/fI3xiO/kBTusHb8+1dasGWIrPyLFFK3NCFVWBe/aHPZxNTCVz55HCHqx Kf002UuWWj2w6vDOmDvxI+vkDglIY0w0rmCjFm/vV9WPZcwlxkUcnWPb1VjJNc0N6DTTm/ 2U1FrFLZsgq7V8cs4EZQr8/LwGr1iQ1JBhMWZH45+TO2sE8FATlgCC7gLIoQV+V7eaSCl7 bmLBGB96cUQ67XPhnGfqfOjD2yrT+gVUueQoY21QxRNEx5HE/h2NgdJ4QbFQ7yJk9cz2yd P4Cq1Nbw1QJ6toBXlGtvF3VmyiBFWIOHS5l46wqdZ+K29WuORituX4jPeGx7kw== ARC-Seal: i=1; s=dkim; d=freebsd.org; t=1657965003; a=rsa-sha256; cv=none; b=V9pDBBbk+fJCPls+enpCbYad12jJpw7SuBOZujmxawjbzURSjT9VuptocBZMbszqcEl6SO /1fNBB2HX28gRypf9KkdgnZ8HAYjcD+rtRTdsZyUFZCgdTQfUZupPbyYS0pLRfURlBbBXw ABAicaHI5JnenGj9GtbYsYc0Ubf7uWaWH5FAXc5EzzGNfSIOnxGtI3WsccM8EPpeUHS3VE 7+cj9JMiLM8Q2NUDWoAuOfmRBUG243GAXDMHBJm6J4X+dVqusw+Qqmd7JtmK/g0aiOFxn1 vX9zLU8gUlNuBeTHBiHAlEXLIapn2KbD+ILR5KflHKocdsc9RwE1FCKWKOs+sw== ARC-Authentication-Results: i=1; mx1.freebsd.org; none X-ThisMailContainsUnwantedMimeParts: N The branch main has been updated by dchagin: URL: https://cgit.FreeBSD.org/src/commit/?id=fc90f3a28145872afb7106d391bc922572eb2b71 commit fc90f3a28145872afb7106d391bc922572eb2b71 Author: Dmitry Chagin AuthorDate: 2022-07-16 09:46:12 +0000 Commit: Dmitry Chagin CommitDate: 2022-07-16 09:46:12 +0000 ktrace: Increase precision of timestamps. Replace struct timeval in header with struct timespec. To differentiate header formats, add a new KTR_VERSIONED flag set in the header type field similar to the existing KTRDROP flag. To make it easier to extend ktrace headers in the future, extend the existing header with a version field (version 0 is reserved for older records without KTR_VERSIONED) as well as new fields holding the thread ID and CPU ID. Reviewed by: jhb, pauamma Differential Revision: https://reviews.freebsd.org/D35774 MFC after: 2 weeks --- sys/kern/kern_ktrace.c | 9 ++-- sys/sys/ktrace.h | 24 +++++++++- usr.bin/kdump/kdump.1 | 4 +- usr.bin/kdump/kdump.c | 120 ++++++++++++++++++++++++++++++++++++------------- 4 files changed, 122 insertions(+), 35 deletions(-) diff --git a/sys/kern/kern_ktrace.c b/sys/kern/kern_ktrace.c index be3081ac9983..1e029bace1ee 100644 --- a/sys/kern/kern_ktrace.c +++ b/sys/kern/kern_ktrace.c @@ -322,9 +322,12 @@ ktr_getrequest_entered(struct thread *td, int type) p->p_traceflag &= ~KTRFAC_DROP; } mtx_unlock(&ktrace_mtx); - microtime(&req->ktr_header.ktr_time); + nanotime(&req->ktr_header.ktr_time); + req->ktr_header.ktr_type |= KTR_VERSIONED; req->ktr_header.ktr_pid = p->p_pid; req->ktr_header.ktr_tid = td->td_tid; + req->ktr_header.ktr_cpu = PCPU_GET(cpuid); + req->ktr_header.ktr_version = KTR_VERSION1; bcopy(td->td_name, req->ktr_header.ktr_comm, sizeof(req->ktr_header.ktr_comm)); req->ktr_buffer = NULL; @@ -1301,9 +1304,9 @@ ktr_writerequest(struct thread *td, struct ktr_request *req) mtx_unlock(&ktrace_mtx); kth = &req->ktr_header; - KASSERT(((u_short)kth->ktr_type & ~KTR_DROP) < nitems(data_lengths), + KASSERT(((u_short)kth->ktr_type & ~KTR_TYPE) < nitems(data_lengths), ("data_lengths array overflow")); - datalen = data_lengths[(u_short)kth->ktr_type & ~KTR_DROP]; + datalen = data_lengths[(u_short)kth->ktr_type & ~KTR_TYPE]; buflen = kth->ktr_len; auio.uio_iov = &aiov[0]; auio.uio_offset = 0; diff --git a/sys/sys/ktrace.h b/sys/sys/ktrace.h index f417fdf8a22a..ed5c6c11eaf2 100644 --- a/sys/sys/ktrace.h +++ b/sys/sys/ktrace.h @@ -52,7 +52,7 @@ /* * ktrace record header */ -struct ktr_header { +struct ktr_header_v0 { int ktr_len; /* length of buf */ short ktr_type; /* trace record type */ pid_t ktr_pid; /* process id */ @@ -61,6 +61,21 @@ struct ktr_header { intptr_t ktr_tid; /* was ktr_buffer */ }; +struct ktr_header { + int ktr_len; /* length of buf */ + short ktr_type; /* trace record type */ + short ktr_version; /* ktr_header version */ + pid_t ktr_pid; /* process id */ + char ktr_comm[MAXCOMLEN + 1];/* command name */ + struct timespec ktr_time; /* timestamp */ + intptr_t ktr_tid; /* thread id */ + int ktr_cpu; /* cpu id */ +}; + +#define KTR_VERSION0 0 +#define KTR_VERSION1 1 +#define KTR_OFFSET_V0 sizeof(struct ktr_header_v0) - \ + sizeof(struct ktr_header) /* * Test for kernel trace point (MP SAFE). * @@ -236,6 +251,13 @@ struct ktr_struct_array { * between the previous record and this record was dropped. */ #define KTR_DROP 0x8000 +/* + * KTR_VERSIONED - If this bit is set in ktr_type, then the kernel + * exposes the new struct ktr_header (versioned), otherwise the old + * struct ktr_header_v0 is exposed. + */ +#define KTR_VERSIONED 0x4000 +#define KTR_TYPE (KTR_DROP | KTR_VERSIONED) /* * kernel trace points (in p_traceflag) diff --git a/usr.bin/kdump/kdump.1 b/usr.bin/kdump/kdump.1 index b0247b5535b9..1c5c0c3edc14 100644 --- a/usr.bin/kdump/kdump.1 +++ b/usr.bin/kdump/kdump.1 @@ -28,7 +28,7 @@ .\" @(#)kdump.1 8.1 (Berkeley) 6/6/93 .\" $FreeBSD$ .\" -.Dd March 28, 2014 +.Dd July 16, 2022 .Dt KDUMP 1 .Os .Sh NAME @@ -53,6 +53,8 @@ in the current directory is displayed. .Pp The options are as follows: .Bl -tag -width Fl +.It Fl c +Display the CPU number with each trace entry. .It Fl d Display all numbers in decimal. .It Fl E diff --git a/usr.bin/kdump/kdump.c b/usr.bin/kdump/kdump.c index 4990dea638cf..75fb5bd8c1d3 100644 --- a/usr.bin/kdump/kdump.c +++ b/usr.bin/kdump/kdump.c @@ -103,6 +103,8 @@ int fetchprocinfo(struct ktr_header *, u_int *); u_int findabi(struct ktr_header *); int fread_tail(void *, int, int); void dumpheader(struct ktr_header *, u_int); +void dumptimeval(struct ktr_header_v0 *kth); +void dumptimespec(struct ktr_header *kth); void ktrsyscall(struct ktr_syscall *, u_int); void ktrsysret(struct ktr_sysret *, u_int); void ktrnamei(char *, int); @@ -134,10 +136,11 @@ void usage(void); #define TIMESTAMP_RELATIVE 0x4 bool decimal, fancy = true, resolv; -static bool abiflag, suppressdata, syscallno, tail, threads; +static bool abiflag, suppressdata, syscallno, tail, threads, cpuflag; static int timestamp, maxdata; static const char *tracefile = DEF_TRACEFILE; static struct ktr_header ktr_header; +static short version; #define TIME_FORMAT "%b %e %T %Y" #define eqs(s1, s2) (strcmp((s1), (s2)) == 0) @@ -345,7 +348,7 @@ main(int argc, char *argv[]) timestamp = TIMESTAMP_NONE; - while ((ch = getopt(argc,argv,"f:dElm:np:AHRrSsTt:")) != -1) + while ((ch = getopt(argc,argv,"f:cdElm:np:AHRrSsTt:")) != -1) switch (ch) { case 'A': abiflag = true; @@ -353,6 +356,9 @@ main(int argc, char *argv[]) case 'f': tracefile = optarg; break; + case 'c': + cpuflag = true; + break; case 'd': decimal = true; break; @@ -434,6 +440,11 @@ main(int argc, char *argv[]) TAILQ_INIT(&trace_procs); drop_logged = 0; while (fread_tail(&ktr_header, sizeof(struct ktr_header), 1)) { + if (ktr_header.ktr_type & KTR_VERSIONED) { + ktr_header.ktr_type &= ~KTR_VERSIONED; + version = ktr_header.ktr_version; + } else + version = KTR_VERSION0; if (ktr_header.ktr_type & KTR_DROP) { ktr_header.ktr_type &= ~KTR_DROP; if (!drop_logged && threads) { @@ -459,6 +470,9 @@ main(int argc, char *argv[]) errx(1, "%s", strerror(ENOMEM)); size = ktrlen; } + if (version == KTR_VERSION0 && + fseek(stdin, KTR_OFFSET_V0, SEEK_CUR) < 0) + errx(1, "%s", strerror(errno)); if (ktrlen && fread_tail(m, ktrlen, 1) == 0) errx(1, "data too short"); if (fetchprocinfo(&ktr_header, (u_int *)m) != 0) @@ -583,15 +597,80 @@ findabi(struct ktr_header *kth) } void -dumpheader(struct ktr_header *kth, u_int sv_flags) +dumptimeval(struct ktr_header_v0 *kth) { - static char unknown[64]; static struct timeval prevtime, prevtime_e; struct timeval temp; + const char *sign; + + if (timestamp & TIMESTAMP_ABSOLUTE) { + printf("%jd.%06ld ", (intmax_t)kth->ktr_time.tv_sec, + kth->ktr_time.tv_usec); + } + if (timestamp & TIMESTAMP_ELAPSED) { + if (prevtime_e.tv_sec == 0) + prevtime_e = kth->ktr_time; + timersub(&kth->ktr_time, &prevtime_e, &temp); + printf("%jd.%06ld ", (intmax_t)temp.tv_sec, + temp.tv_usec); + } + if (timestamp & TIMESTAMP_RELATIVE) { + if (prevtime.tv_sec == 0) + prevtime = kth->ktr_time; + if (timercmp(&kth->ktr_time, &prevtime, <)) { + timersub(&prevtime, &kth->ktr_time, &temp); + sign = "-"; + } else { + timersub(&kth->ktr_time, &prevtime, &temp); + sign = ""; + } + prevtime = kth->ktr_time; + printf("%s%jd.%06ld ", sign, (intmax_t)temp.tv_sec, + temp.tv_usec); + } +} + +void +dumptimespec(struct ktr_header *kth) +{ + static struct timespec prevtime, prevtime_e; + struct timespec temp; + const char *sign; + + if (timestamp & TIMESTAMP_ABSOLUTE) { + printf("%jd.%09ld ", (intmax_t)kth->ktr_time.tv_sec, + kth->ktr_time.tv_nsec); + } + if (timestamp & TIMESTAMP_ELAPSED) { + if (prevtime_e.tv_sec == 0) + prevtime_e = kth->ktr_time; + timespecsub(&kth->ktr_time, &prevtime_e, &temp); + printf("%jd.%09ld ", (intmax_t)temp.tv_sec, + temp.tv_nsec); + } + if (timestamp & TIMESTAMP_RELATIVE) { + if (prevtime.tv_sec == 0) + prevtime = kth->ktr_time; + if (timespeccmp(&kth->ktr_time, &prevtime, <)) { + timespecsub(&prevtime, &kth->ktr_time, &temp); + sign = "-"; + } else { + timespecsub(&kth->ktr_time, &prevtime, &temp); + sign = ""; + } + prevtime = kth->ktr_time; + printf("%s%jd.%09ld ", sign, (intmax_t)temp.tv_sec, + temp.tv_nsec); + } +} + +void +dumpheader(struct ktr_header *kth, u_int sv_flags) +{ + static char unknown[64]; const char *abi; const char *arch; const char *type; - const char *sign; switch (kth->ktr_type) { case KTR_SYSCALL: @@ -652,32 +731,13 @@ dumpheader(struct ktr_header *kth, u_int sv_flags) printf("%6jd %-8.*s ", (intmax_t)kth->ktr_pid, MAXCOMLEN, kth->ktr_comm); if (timestamp) { - if (timestamp & TIMESTAMP_ABSOLUTE) { - printf("%jd.%06ld ", (intmax_t)kth->ktr_time.tv_sec, - kth->ktr_time.tv_usec); - } - if (timestamp & TIMESTAMP_ELAPSED) { - if (prevtime_e.tv_sec == 0) - prevtime_e = kth->ktr_time; - timersub(&kth->ktr_time, &prevtime_e, &temp); - printf("%jd.%06ld ", (intmax_t)temp.tv_sec, - temp.tv_usec); - } - if (timestamp & TIMESTAMP_RELATIVE) { - if (prevtime.tv_sec == 0) - prevtime = kth->ktr_time; - if (timercmp(&kth->ktr_time, &prevtime, <)) { - timersub(&prevtime, &kth->ktr_time, &temp); - sign = "-"; - } else { - timersub(&kth->ktr_time, &prevtime, &temp); - sign = ""; - } - prevtime = kth->ktr_time; - printf("%s%jd.%06ld ", sign, (intmax_t)temp.tv_sec, - temp.tv_usec); - } + if (version == KTR_VERSION0) + dumptimeval((struct ktr_header_v0 *)kth); + else + dumptimespec(kth); } + if (cpuflag && version > KTR_VERSION0) + printf("%3d ", kth->ktr_cpu); printf("%s ", type); if (abiflag != 0) { switch (sv_flags & SV_ABI_MASK) {