git: fc90f3a28145 - main - ktrace: Increase precision of timestamps.
Date: Sat, 16 Jul 2022 09:50:02 UTC
The branch main has been updated by dchagin:
URL: https://cgit.FreeBSD.org/src/commit/?id=fc90f3a28145872afb7106d391bc922572eb2b71
commit fc90f3a28145872afb7106d391bc922572eb2b71
Author: Dmitry Chagin <dchagin@FreeBSD.org>
AuthorDate: 2022-07-16 09:46:12 +0000
Commit: Dmitry Chagin <dchagin@FreeBSD.org>
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) {