The branch main has been updated by dchagin: URL: https://cgit.FreeBSD.org/src/commit/?id=fc90f3a28145872afb7106d391bc922572eb2b71
commit fc90f3a28145872afb7106d391bc922572eb2b71 Author: Dmitry Chagin <[email protected]> AuthorDate: 2022-07-16 09:46:12 +0000 Commit: Dmitry Chagin <[email protected]> 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) {
