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
This commit is contained in:
parent
db0110a536
commit
fc90f3a281
@ -322,9 +322,12 @@ ktr_getrequest_entered(struct thread *td, int type)
|
|||||||
p->p_traceflag &= ~KTRFAC_DROP;
|
p->p_traceflag &= ~KTRFAC_DROP;
|
||||||
}
|
}
|
||||||
mtx_unlock(&ktrace_mtx);
|
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_pid = p->p_pid;
|
||||||
req->ktr_header.ktr_tid = td->td_tid;
|
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,
|
bcopy(td->td_name, req->ktr_header.ktr_comm,
|
||||||
sizeof(req->ktr_header.ktr_comm));
|
sizeof(req->ktr_header.ktr_comm));
|
||||||
req->ktr_buffer = NULL;
|
req->ktr_buffer = NULL;
|
||||||
@ -1301,9 +1304,9 @@ ktr_writerequest(struct thread *td, struct ktr_request *req)
|
|||||||
mtx_unlock(&ktrace_mtx);
|
mtx_unlock(&ktrace_mtx);
|
||||||
|
|
||||||
kth = &req->ktr_header;
|
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"));
|
("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;
|
buflen = kth->ktr_len;
|
||||||
auio.uio_iov = &aiov[0];
|
auio.uio_iov = &aiov[0];
|
||||||
auio.uio_offset = 0;
|
auio.uio_offset = 0;
|
||||||
|
@ -52,7 +52,7 @@
|
|||||||
/*
|
/*
|
||||||
* ktrace record header
|
* ktrace record header
|
||||||
*/
|
*/
|
||||||
struct ktr_header {
|
struct ktr_header_v0 {
|
||||||
int ktr_len; /* length of buf */
|
int ktr_len; /* length of buf */
|
||||||
short ktr_type; /* trace record type */
|
short ktr_type; /* trace record type */
|
||||||
pid_t ktr_pid; /* process id */
|
pid_t ktr_pid; /* process id */
|
||||||
@ -61,6 +61,21 @@ struct ktr_header {
|
|||||||
intptr_t ktr_tid; /* was ktr_buffer */
|
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).
|
* Test for kernel trace point (MP SAFE).
|
||||||
*
|
*
|
||||||
@ -236,6 +251,13 @@ struct ktr_struct_array {
|
|||||||
* between the previous record and this record was dropped.
|
* between the previous record and this record was dropped.
|
||||||
*/
|
*/
|
||||||
#define KTR_DROP 0x8000
|
#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)
|
* kernel trace points (in p_traceflag)
|
||||||
|
@ -28,7 +28,7 @@
|
|||||||
.\" @(#)kdump.1 8.1 (Berkeley) 6/6/93
|
.\" @(#)kdump.1 8.1 (Berkeley) 6/6/93
|
||||||
.\" $FreeBSD$
|
.\" $FreeBSD$
|
||||||
.\"
|
.\"
|
||||||
.Dd March 28, 2014
|
.Dd July 16, 2022
|
||||||
.Dt KDUMP 1
|
.Dt KDUMP 1
|
||||||
.Os
|
.Os
|
||||||
.Sh NAME
|
.Sh NAME
|
||||||
@ -53,6 +53,8 @@ in the current directory is displayed.
|
|||||||
.Pp
|
.Pp
|
||||||
The options are as follows:
|
The options are as follows:
|
||||||
.Bl -tag -width Fl
|
.Bl -tag -width Fl
|
||||||
|
.It Fl c
|
||||||
|
Display the CPU number with each trace entry.
|
||||||
.It Fl d
|
.It Fl d
|
||||||
Display all numbers in decimal.
|
Display all numbers in decimal.
|
||||||
.It Fl E
|
.It Fl E
|
||||||
|
@ -103,6 +103,8 @@ int fetchprocinfo(struct ktr_header *, u_int *);
|
|||||||
u_int findabi(struct ktr_header *);
|
u_int findabi(struct ktr_header *);
|
||||||
int fread_tail(void *, int, int);
|
int fread_tail(void *, int, int);
|
||||||
void dumpheader(struct ktr_header *, u_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 ktrsyscall(struct ktr_syscall *, u_int);
|
||||||
void ktrsysret(struct ktr_sysret *, u_int);
|
void ktrsysret(struct ktr_sysret *, u_int);
|
||||||
void ktrnamei(char *, int);
|
void ktrnamei(char *, int);
|
||||||
@ -134,10 +136,11 @@ void usage(void);
|
|||||||
#define TIMESTAMP_RELATIVE 0x4
|
#define TIMESTAMP_RELATIVE 0x4
|
||||||
|
|
||||||
bool decimal, fancy = true, resolv;
|
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 int timestamp, maxdata;
|
||||||
static const char *tracefile = DEF_TRACEFILE;
|
static const char *tracefile = DEF_TRACEFILE;
|
||||||
static struct ktr_header ktr_header;
|
static struct ktr_header ktr_header;
|
||||||
|
static short version;
|
||||||
|
|
||||||
#define TIME_FORMAT "%b %e %T %Y"
|
#define TIME_FORMAT "%b %e %T %Y"
|
||||||
#define eqs(s1, s2) (strcmp((s1), (s2)) == 0)
|
#define eqs(s1, s2) (strcmp((s1), (s2)) == 0)
|
||||||
@ -345,7 +348,7 @@ main(int argc, char *argv[])
|
|||||||
|
|
||||||
timestamp = TIMESTAMP_NONE;
|
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) {
|
switch (ch) {
|
||||||
case 'A':
|
case 'A':
|
||||||
abiflag = true;
|
abiflag = true;
|
||||||
@ -353,6 +356,9 @@ main(int argc, char *argv[])
|
|||||||
case 'f':
|
case 'f':
|
||||||
tracefile = optarg;
|
tracefile = optarg;
|
||||||
break;
|
break;
|
||||||
|
case 'c':
|
||||||
|
cpuflag = true;
|
||||||
|
break;
|
||||||
case 'd':
|
case 'd':
|
||||||
decimal = true;
|
decimal = true;
|
||||||
break;
|
break;
|
||||||
@ -434,6 +440,11 @@ main(int argc, char *argv[])
|
|||||||
TAILQ_INIT(&trace_procs);
|
TAILQ_INIT(&trace_procs);
|
||||||
drop_logged = 0;
|
drop_logged = 0;
|
||||||
while (fread_tail(&ktr_header, sizeof(struct ktr_header), 1)) {
|
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) {
|
if (ktr_header.ktr_type & KTR_DROP) {
|
||||||
ktr_header.ktr_type &= ~KTR_DROP;
|
ktr_header.ktr_type &= ~KTR_DROP;
|
||||||
if (!drop_logged && threads) {
|
if (!drop_logged && threads) {
|
||||||
@ -459,6 +470,9 @@ main(int argc, char *argv[])
|
|||||||
errx(1, "%s", strerror(ENOMEM));
|
errx(1, "%s", strerror(ENOMEM));
|
||||||
size = ktrlen;
|
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)
|
if (ktrlen && fread_tail(m, ktrlen, 1) == 0)
|
||||||
errx(1, "data too short");
|
errx(1, "data too short");
|
||||||
if (fetchprocinfo(&ktr_header, (u_int *)m) != 0)
|
if (fetchprocinfo(&ktr_header, (u_int *)m) != 0)
|
||||||
@ -582,16 +596,81 @@ findabi(struct ktr_header *kth)
|
|||||||
return (0);
|
return (0);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
void
|
||||||
|
dumptimeval(struct ktr_header_v0 *kth)
|
||||||
|
{
|
||||||
|
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
|
void
|
||||||
dumpheader(struct ktr_header *kth, u_int sv_flags)
|
dumpheader(struct ktr_header *kth, u_int sv_flags)
|
||||||
{
|
{
|
||||||
static char unknown[64];
|
static char unknown[64];
|
||||||
static struct timeval prevtime, prevtime_e;
|
|
||||||
struct timeval temp;
|
|
||||||
const char *abi;
|
const char *abi;
|
||||||
const char *arch;
|
const char *arch;
|
||||||
const char *type;
|
const char *type;
|
||||||
const char *sign;
|
|
||||||
|
|
||||||
switch (kth->ktr_type) {
|
switch (kth->ktr_type) {
|
||||||
case KTR_SYSCALL:
|
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,
|
printf("%6jd %-8.*s ", (intmax_t)kth->ktr_pid, MAXCOMLEN,
|
||||||
kth->ktr_comm);
|
kth->ktr_comm);
|
||||||
if (timestamp) {
|
if (timestamp) {
|
||||||
if (timestamp & TIMESTAMP_ABSOLUTE) {
|
if (version == KTR_VERSION0)
|
||||||
printf("%jd.%06ld ", (intmax_t)kth->ktr_time.tv_sec,
|
dumptimeval((struct ktr_header_v0 *)kth);
|
||||||
kth->ktr_time.tv_usec);
|
else
|
||||||
}
|
dumptimespec(kth);
|
||||||
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 (cpuflag && version > KTR_VERSION0)
|
||||||
|
printf("%3d ", kth->ktr_cpu);
|
||||||
printf("%s ", type);
|
printf("%s ", type);
|
||||||
if (abiflag != 0) {
|
if (abiflag != 0) {
|
||||||
switch (sv_flags & SV_ABI_MASK) {
|
switch (sv_flags & SV_ABI_MASK) {
|
||||||
|
Loading…
Reference in New Issue
Block a user