pmc: convert native to jsonl and track TSC value of samples

- add '-j' options to filter to enable converting native pmc
  log format to json lines format to enable the use of scripts
  and external tooling

% pmc filter -j pmc.log pmc.jsonl

- Record the tsc value in sampling interrupts as opposed to
  recording nanotime when the sample is copied to a global log
  in hardclock - potentially many milliseconds later.

- At initialize record the tsc_freq and the time of day to give
  us an offset for translating the tsc values in callchain records

2 files changed, 79 insertions, 47 deletions

diff --git a/sys/dev/hwpmc/hwpmc_logging.c b/sys/dev/hwpmc/hwpmc_logging.c
index 1f314518549a..2cc42e5096a7 100644
--- a/sys/dev/hwpmc/hwpmc_logging.c
+++ b/sys/dev/hwpmc/hwpmc_logging.c
@@ -61,6 +61,10 @@ __FBSDID("$FreeBSD$");
 #include <sys/unistd.h>
 #include <sys/vnode.h>
 
+#if defined(__i386__) || defined(__amd64__)
+#include <machine/clock.h>
+#endif
+
 #ifdef NUMA
 #define NDOMAINS vm_ndomains
 #define curdomain PCPU_GET(domain)
@@ -124,29 +128,38 @@ static struct mtx pmc_kthread_mtx;	/* sleep lock */
 	 ((L) & 0xFFFF))
 
 /* reserve LEN bytes of space and initialize the entry header */
-#define	_PMCLOG_RESERVE_SAFE(PO,TYPE,LEN,ACTION) do {			\
+#define	_PMCLOG_RESERVE_SAFE(PO,TYPE,LEN,ACTION, TSC) do {	\
 		uint32_t *_le;						\
 		int _len = roundup((LEN), sizeof(uint32_t));	\
+		struct pmclog_header *ph;							\
 		if ((_le = pmclog_reserve((PO), _len)) == NULL) {	\
-			ACTION;						\
-		}							\
-		*_le = _PMCLOG_TO_HEADER(TYPE,_len);			\
-		_le += 3	/* skip over timestamp */
+			ACTION;											\
+		}													\
+		ph = (struct pmclog_header *)_le;					\
+		ph->pl_header =_PMCLOG_TO_HEADER(TYPE,_len);	\
+		ph->pl_tsc = (TSC);									\
+		_le += sizeof(*ph)/4	/* skip over timestamp */
 
 /* reserve LEN bytes of space and initialize the entry header */
 #define	_PMCLOG_RESERVE(PO,TYPE,LEN,ACTION) do {			\
 		uint32_t *_le;						\
-		int _len = roundup((LEN), sizeof(uint32_t));		\
+		int _len = roundup((LEN), sizeof(uint32_t));	\
+		uint64_t tsc;										\
+		struct pmclog_header *ph;							\
+		tsc = pmc_rdtsc();									\
 		spinlock_enter();									\
 		if ((_le = pmclog_reserve((PO), _len)) == NULL) {	\
 			spinlock_exit();								\
 			ACTION;											\
 		}												\
-		*_le = _PMCLOG_TO_HEADER(TYPE,_len);			\
-		_le += 3	/* skip over timestamp */
+		ph = (struct pmclog_header *)_le;					\
+		ph->pl_header =_PMCLOG_TO_HEADER(TYPE,_len);	\
+		ph->pl_tsc = tsc;									\
+		_le += sizeof(*ph)/4	/* skip over timestamp */
 
 
-#define	PMCLOG_RESERVE_SAFE(P,T,L)		_PMCLOG_RESERVE_SAFE(P,T,L,return)
+
+#define	PMCLOG_RESERVE_SAFE(P,T,L,TSC)		_PMCLOG_RESERVE_SAFE(P,T,L,return,TSC)
 #define	PMCLOG_RESERVE(P,T,L)		_PMCLOG_RESERVE(P,T,L,return)
 #define	PMCLOG_RESERVE_WITH_ERROR(P,T,L) _PMCLOG_RESERVE(P,T,L,		\
 	error=ENOMEM;goto error)
@@ -181,32 +194,32 @@ static struct mtx pmc_kthread_mtx;	/* sleep lock */
 		} while (0)
 
 
+#define TSDELTA 4
 /*
  * Assertions about the log file format.
  */
-
-CTASSERT(sizeof(struct pmclog_callchain) == 8*4 +
+CTASSERT(sizeof(struct pmclog_callchain) == 7*4 + TSDELTA +
     PMC_CALLCHAIN_DEPTH_MAX*sizeof(uintfptr_t));
-CTASSERT(sizeof(struct pmclog_closelog) == 4*4);
-CTASSERT(sizeof(struct pmclog_dropnotify) == 4*4);
-CTASSERT(sizeof(struct pmclog_map_in) == PATH_MAX +
-    4*4 + sizeof(uintfptr_t));
+CTASSERT(sizeof(struct pmclog_closelog) == 3*4 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_dropnotify) == 3*4 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_map_in) == PATH_MAX + TSDELTA +
+    5*4 + sizeof(uintfptr_t));
 CTASSERT(offsetof(struct pmclog_map_in,pl_pathname) ==
-    4*4 + sizeof(uintfptr_t));
-CTASSERT(sizeof(struct pmclog_map_out) == 4*4 + 2*sizeof(uintfptr_t));
-CTASSERT(sizeof(struct pmclog_pmcallocate) == 8*4);
-CTASSERT(sizeof(struct pmclog_pmcattach) == 6*4 + PATH_MAX);
-CTASSERT(offsetof(struct pmclog_pmcattach,pl_pathname) == 6*4);
-CTASSERT(sizeof(struct pmclog_pmcdetach) == 6*4);
-CTASSERT(sizeof(struct pmclog_proccsw) == 6*4 + 8);
-CTASSERT(sizeof(struct pmclog_procexec) == 6*4 + PATH_MAX +
-    sizeof(uintfptr_t));
-CTASSERT(offsetof(struct pmclog_procexec,pl_pathname) == 6*4 +
+    5*4 + TSDELTA + sizeof(uintfptr_t));
+CTASSERT(sizeof(struct pmclog_map_out) == 5*4 + 2*sizeof(uintfptr_t) + TSDELTA);
+CTASSERT(sizeof(struct pmclog_pmcallocate) == 9*4 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_pmcattach) == 5*4 + PATH_MAX + TSDELTA);
+CTASSERT(offsetof(struct pmclog_pmcattach,pl_pathname) == 5*4 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_pmcdetach) == 5*4 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_proccsw) == 7*4 + 8 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_procexec) == 5*4 + PATH_MAX +
+    sizeof(uintfptr_t) + TSDELTA);
+CTASSERT(offsetof(struct pmclog_procexec,pl_pathname) == 5*4 + TSDELTA +
     sizeof(uintfptr_t));
-CTASSERT(sizeof(struct pmclog_procexit) == 6*4 + 8);
-CTASSERT(sizeof(struct pmclog_procfork) == 6*4);
-CTASSERT(sizeof(struct pmclog_sysexit) == 4*4);
-CTASSERT(sizeof(struct pmclog_userdata) == 4*4);
+CTASSERT(sizeof(struct pmclog_procexit) == 5*4 + 8 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_procfork) == 5*4 + TSDELTA);
+CTASSERT(sizeof(struct pmclog_sysexit) == 6*4);
+CTASSERT(sizeof(struct pmclog_userdata) == 6*4);
 
 /*
  * Log buffer structure
@@ -545,8 +558,6 @@ static uint32_t *
 pmclog_reserve(struct pmc_owner *po, int length)
 {
 	uintptr_t newptr, oldptr;
-	uint32_t *lh;
-	struct timespec ts;
 	struct pmclog_buffer *plb, **pplb;
 
 	PMCDBG2(LOG,ALL,1, "po=%p len=%d", po, length);
@@ -612,11 +623,6 @@ pmclog_reserve(struct pmc_owner *po, int length)
 	oldptr = (uintptr_t) plb->plb_ptr;
 
  done:
-	lh = (uint32_t *) oldptr;
-	lh++;				/* skip header */
-	getnanotime(&ts);		/* fill in the timestamp */
-	*lh++ = ts.tv_sec & 0xFFFFFFFF;
-	*lh++ = ts.tv_nsec & 0xFFFFFFF;
 	return ((uint32_t *) oldptr);
  fail:
 	return (NULL);
@@ -693,6 +699,8 @@ int
 pmclog_configure_log(struct pmc_mdep *md, struct pmc_owner *po, int logfd)
 {
 	struct proc *p;
+	struct timespec ts;
+	uint64_t tsc;
 	int error;
 
 	sx_assert(&pmc_sx, SA_XLOCKED);
@@ -720,12 +728,21 @@ pmclog_configure_log(struct pmc_mdep *md, struct pmc_owner *po, int logfd)
 	PROC_LOCK(p);
 	p->p_flag |= P_HWPMC;
 	PROC_UNLOCK(p);
-
+	nanotime(&ts);
+	tsc = pmc_rdtsc();
 	/* create a log initialization entry */
 	PMCLOG_RESERVE_WITH_ERROR(po, INITIALIZE,
 	    sizeof(struct pmclog_initialize));
 	PMCLOG_EMIT32(PMC_VERSION);
 	PMCLOG_EMIT32(md->pmd_cputype);
+#if defined(__i386__) || defined(__amd64__)
+	PMCLOG_EMIT64(tsc_freq);
+#else
+	/* other architectures will need to fill this in */
+	PMCLOG_EMIT64(0);
+#endif
+	memcpy(_le, &ts, sizeof(ts));
+	_le += sizeof(ts)/4;
 	PMCLOG_EMITSTRING(pmc_cpuid, PMC_CPUID_LEN);
 	PMCLOG_DESPATCH_SYNC(po);
 
@@ -917,13 +934,11 @@ pmclog_process_callchain(struct pmc *pm, struct pmc_sample *ps)
 	    ps->ps_nsamples * sizeof(uintfptr_t);
 	po = pm->pm_owner;
 	flags = PMC_CALLCHAIN_TO_CPUFLAGS(ps->ps_cpu,ps->ps_flags);
-	PMCLOG_RESERVE_SAFE(po, CALLCHAIN, recordlen);
+	PMCLOG_RESERVE_SAFE(po, CALLCHAIN, recordlen, ps->ps_tsc);
 	PMCLOG_EMIT32(ps->ps_pid);
 	PMCLOG_EMIT32(ps->ps_tid);
 	PMCLOG_EMIT32(pm->pm_id);
 	PMCLOG_EMIT32(flags);
-	/* unused for now */
-	PMCLOG_EMIT32(0);
 	for (n = 0; n < ps->ps_nsamples; n++)
 		PMCLOG_EMITADDR(ps->ps_pc[n]);
 	PMCLOG_DESPATCH_SAFE(po);
@@ -957,6 +972,7 @@ pmclog_process_map_in(struct pmc_owner *po, pid_t pid, uintfptr_t start,
 
 	PMCLOG_RESERVE(po, MAP_IN, recordlen);
 	PMCLOG_EMIT32(pid);
+	PMCLOG_EMIT32(0);
 	PMCLOG_EMITADDR(start);
 	PMCLOG_EMITSTRING(path,pathlen);
 	PMCLOG_DESPATCH_SYNC(po);
@@ -970,6 +986,7 @@ pmclog_process_map_out(struct pmc_owner *po, pid_t pid, uintfptr_t start,
 
 	PMCLOG_RESERVE(po, MAP_OUT, sizeof(struct pmclog_map_out));
 	PMCLOG_EMIT32(pid);
+	PMCLOG_EMIT32(0);
 	PMCLOG_EMITADDR(start);
 	PMCLOG_EMITADDR(end);
 	PMCLOG_DESPATCH(po);
@@ -991,6 +1008,7 @@ pmclog_process_pmcallocate(struct pmc *pm)
 		PMCLOG_EMIT32(pm->pm_id);
 		PMCLOG_EMIT32(pm->pm_event);
 		PMCLOG_EMIT32(pm->pm_flags);
+		PMCLOG_EMIT32(0);
 		PMCLOG_EMIT64(pm->pm_sc.pm_reloadcount);
 		ps = pmc_soft_ev_acquire(pm->pm_event);
 		if (ps != NULL)
@@ -1005,6 +1023,7 @@ pmclog_process_pmcallocate(struct pmc *pm)
 		PMCLOG_EMIT32(pm->pm_id);
 		PMCLOG_EMIT32(pm->pm_event);
 		PMCLOG_EMIT32(pm->pm_flags);
+		PMCLOG_EMIT32(0);
 		PMCLOG_EMIT64(pm->pm_sc.pm_reloadcount);
 		PMCLOG_DESPATCH_SYNC(po);
 	}
@@ -1026,7 +1045,6 @@ pmclog_process_pmcattach(struct pmc *pm, pid_t pid, char *path)
 	PMCLOG_RESERVE(po, PMCATTACH, recordlen);
 	PMCLOG_EMIT32(pm->pm_id);
 	PMCLOG_EMIT32(pid);
-	PMCLOG_EMIT32(0);
 	PMCLOG_EMITSTRING(path, pathlen);
 	PMCLOG_DESPATCH_SYNC(po);
 }
@@ -1053,14 +1071,12 @@ pmclog_process_proccreate(struct pmc_owner *po, struct proc *p, int sync)
 		PMCLOG_RESERVE(po, PROC_CREATE, sizeof(struct pmclog_proccreate));
 		PMCLOG_EMIT32(p->p_pid);
 		PMCLOG_EMIT32(p->p_flag);
-		PMCLOG_EMIT32(0);
 		PMCLOG_EMITSTRING(p->p_comm, MAXCOMLEN+1);
 		PMCLOG_DESPATCH_SYNC(po);
 	} else {
 		PMCLOG_RESERVE(po, PROC_CREATE, sizeof(struct pmclog_proccreate));
 		PMCLOG_EMIT32(p->p_pid);
 		PMCLOG_EMIT32(p->p_flag);
-		PMCLOG_EMIT32(0);
 		PMCLOG_EMITSTRING(p->p_comm, MAXCOMLEN+1);
 		PMCLOG_DESPATCH(po);
 	}
@@ -1083,11 +1099,12 @@ pmclog_process_proccsw(struct pmc *pm, struct pmc_process *pp, pmc_value_t v, st
 
 	po = pm->pm_owner;
 
-	PMCLOG_RESERVE_SAFE(po, PROCCSW, sizeof(struct pmclog_proccsw));
-	PMCLOG_EMIT32(pm->pm_id);
+	PMCLOG_RESERVE_SAFE(po, PROCCSW, sizeof(struct pmclog_proccsw), pmc_rdtsc());
 	PMCLOG_EMIT64(v);
+	PMCLOG_EMIT32(pm->pm_id);
 	PMCLOG_EMIT32(pp->pp_proc->p_pid);
 	PMCLOG_EMIT32(td->td_tid);
+	PMCLOG_EMIT32(0);
 	PMCLOG_DESPATCH_SCHED_LOCK(po);
 }
 
@@ -1104,7 +1121,6 @@ pmclog_process_procexec(struct pmc_owner *po, pmc_id_t pmid, pid_t pid,
 	PMCLOG_RESERVE(po, PROCEXEC, recordlen);
 	PMCLOG_EMIT32(pid);
 	PMCLOG_EMIT32(pmid);
-	PMCLOG_EMIT32(0);
 	PMCLOG_EMITADDR(startaddr);
 	PMCLOG_EMITSTRING(path,pathlen);
 	PMCLOG_DESPATCH_SYNC(po);
@@ -1129,7 +1145,6 @@ pmclog_process_procexit(struct pmc *pm, struct pmc_process *pp)
 	PMCLOG_RESERVE(po, PROCEXIT, sizeof(struct pmclog_procexit));
 	PMCLOG_EMIT32(pm->pm_id);
 	PMCLOG_EMIT32(pp->pp_proc->p_pid);
-	PMCLOG_EMIT32(0);
 	PMCLOG_EMIT64(pp->pp_pmcs[ri].pp_pmcval);
 	PMCLOG_DESPATCH(po);
 }
@@ -1170,6 +1185,7 @@ pmclog_process_threadcreate(struct pmc_owner *po, struct thread *td, int sync)
 		PMCLOG_EMIT32(td->td_tid);
 		PMCLOG_EMIT32(p->p_pid);
 		PMCLOG_EMIT32(p->p_flag);
+		PMCLOG_EMIT32(0);
 		PMCLOG_EMITSTRING(td->td_name, MAXCOMLEN+1);
 		PMCLOG_DESPATCH_SYNC(po);
 	} else {
@@ -1177,6 +1193,7 @@ pmclog_process_threadcreate(struct pmc_owner *po, struct thread *td, int sync)
 		PMCLOG_EMIT32(td->td_tid);
 		PMCLOG_EMIT32(p->p_pid);
 		PMCLOG_EMIT32(p->p_flag);
+		PMCLOG_EMIT32(0);
 		PMCLOG_EMITSTRING(td->td_name, MAXCOMLEN+1);
 		PMCLOG_DESPATCH(po);
 	}
diff --git a/sys/dev/hwpmc/hwpmc_mod.c b/sys/dev/hwpmc/hwpmc_mod.c
index 0a8b347447fe..1d5e28ab30ad 100644
--- a/sys/dev/hwpmc/hwpmc_mod.c
+++ b/sys/dev/hwpmc/hwpmc_mod.c
@@ -809,6 +809,19 @@ pmc_force_context_switch(void)
 	pause("pmcctx", 1);
 }
 
+uint64_t
+pmc_rdtsc(void)
+{
+#if defined(__i386__) || defined(__amd64__)
+	if (__predict_true(amd_feature & AMDID_RDTSCP))
+		return rdtscp();
+	else
+		return rdtsc();
+#else
+	return get_cyclecount();
+#endif
+}
+
 /*
  * Get the file name for an executable.  This is a simple wrapper
  * around vn_fullpath(9).
@@ -4676,6 +4689,8 @@ pmc_add_sample(int cpu, int ring, struct pmc *pm, struct trapframe *tf,
 	ps->ps_td = td;
 	ps->ps_pid = td->td_proc->p_pid;
 	ps->ps_tid = td->td_tid;
+	ps->ps_tsc = pmc_rdtsc();
+
 	ps->ps_cpu = cpu;
 	ps->ps_flags = inuserspace ? PMC_CC_F_USERSPACE : 0;