Add a flush of the current PMC log buffer before displaying the next top.

As the underlying block is 4KB if the PMC throughput is low the measurement
will be reported on the next tick. pmcstat(8) use the modified flush API to
reclaim current buffer before displaying next top.

MFC after:	1 month

10 files changed, 96 insertions, 29 deletions

diff --git a/lib/libpmc/libpmc.c b/lib/libpmc/libpmc.c
index 1d86a82..f0d5b0c 100644
--- a/lib/libpmc/libpmc.c
+++ b/lib/libpmc/libpmc.c
@@ -2596,6 +2596,12 @@ pmc_flush_logfile(void)
 }
 
 int
+pmc_close_logfile(void)
+{
+	return (PMC_CALL(CLOSELOG,0));
+}
+
+int
 pmc_get_driver_stats(struct pmc_driverstats *ds)
 {
 	struct pmc_op_getdriverstats gms;
diff --git a/lib/libpmc/pmc.3 b/lib/libpmc/pmc.3
index 2403e64..2431080 100644
--- a/lib/libpmc/pmc.3
+++ b/lib/libpmc/pmc.3
@@ -322,6 +322,10 @@ to write logged events to.
 Flush all pending log data in
 .Xr hwpmc 4 Ns Ap s
 buffers.
+.It Fn pmc_close_logfile
+Flush all pending log data and close
+.Xr hwpmc 4 Ns Ap s
+side of the stream.
 .It Fn pmc_writelog
 Append arbitrary user data to the current log file.
 .El
diff --git a/lib/libpmc/pmc.h b/lib/libpmc/pmc.h
index 5b1ad07..2be88b1 100644
--- a/lib/libpmc/pmc.h
+++ b/lib/libpmc/pmc.h
@@ -76,6 +76,7 @@ int	pmc_attach(pmc_id_t _pmcid, pid_t _pid);
 int	pmc_capabilities(pmc_id_t _pmc, uint32_t *_caps);
 int	pmc_configure_logfile(int _fd);
 int	pmc_flush_logfile(void);
+int	pmc_close_logfile(void);
 int	pmc_detach(pmc_id_t _pmcid, pid_t _pid);
 int	pmc_disable(int _cpu, int _pmc);
 int	pmc_enable(int _cpu, int _pmc);
diff --git a/lib/libpmc/pmc_configure_logfile.3 b/lib/libpmc/pmc_configure_logfile.3
index a33688c..399f21a 100644
--- a/lib/libpmc/pmc_configure_logfile.3
+++ b/lib/libpmc/pmc_configure_logfile.3
@@ -29,7 +29,8 @@
 .Sh NAME
 .Nm pmc_configure_logfile ,
 .Nm pmc_flush_logfile ,
-.Nm pmc_writelog
+.Nm pmc_writelog ,
+.Nm pmc_close_logfile
 .Nd log file management
 .Sh LIBRARY
 .Lb libpmc
@@ -41,6 +42,8 @@
 .Fn pmc_flush_logfile void
 .Ft int
 .Fn pmc_writelog "uint32_t userdata"
+.Ft int
+.Fn pmc_close_logfile void
 .Sh DESCRIPTION
 The functions manage logging of
 .Xr hwpmc 4
@@ -72,6 +75,12 @@ Function
 will append a log entry containing the value of argument
 .Fa userdata
 to the log file.
+.Pp
+Function
+.Fn pmc_close_logfile
+will flush all pending log data and close
+.Xr hwpmc 4 Ns Ap s
+side of the stream.
 .Sh RETURN VALUES
 .Rv -std
 .Sh ERRORS
diff --git a/sys/dev/hwpmc/hwpmc_logging.c b/sys/dev/hwpmc/hwpmc_logging.c
index c0f8b0d..5f5cd90 100644
--- a/sys/dev/hwpmc/hwpmc_logging.c
+++ b/sys/dev/hwpmc/hwpmc_logging.c
@@ -238,7 +238,7 @@ pmclog_get_buffer(struct pmc_owner *po)
 static void
 pmclog_loop(void *arg)
 {
-	int error, last_buffer;
+	int error;
 	struct pmc_owner *po;
 	struct pmclog_buffer *lb;
 	struct proc *p;
@@ -253,7 +253,6 @@ pmclog_loop(void *arg)
 	p = po->po_owner;
 	td = curthread;
 	mycred = td->td_ucred;
-	last_buffer = 0;
 
 	PROC_LOCK(p);
 	ownercred = crhold(p->p_ucred);
@@ -286,14 +285,22 @@ pmclog_loop(void *arg)
 			if ((lb = TAILQ_FIRST(&po->po_logbuffers)) == NULL) {
 				mtx_unlock_spin(&po->po_mtx);
 
+				if (po->po_flags & PMC_PO_SHUTDOWN) {
+					mtx_unlock(&pmc_kthread_mtx);
+					/*
+			 		 * Close the file to get PMCLOG_EOF
+					 * error in pmclog(3).
+					 */
+					fo_close(po->po_file, curthread);
+					mtx_lock(&pmc_kthread_mtx);
+				}
+
 				(void) msleep(po, &pmc_kthread_mtx, PWAIT,
 				    "pmcloop", 0);
 				continue;
 			}
 
 			TAILQ_REMOVE(&po->po_logbuffers, lb, plb_next);
-			if (po->po_flags & PMC_PO_SHUTDOWN)
-				last_buffer = TAILQ_EMPTY(&po->po_logbuffers);
 			mtx_unlock_spin(&po->po_mtx);
 		}
 
@@ -336,14 +343,6 @@ pmclog_loop(void *arg)
 			break;
 		}
 
-		if (last_buffer) {
-			/*
-			 * Close the file to get PMCLOG_EOF error
-			 * in pmclog(3).
-			 */
-			fo_close(po->po_file, curthread);
-		}
-
 		mtx_lock(&pmc_kthread_mtx);
 
 		/* put the used buffer back into the global pool */
@@ -693,6 +692,7 @@ int
 pmclog_flush(struct pmc_owner *po)
 {
 	int error;
+	struct pmclog_buffer *lb;
 
 	PMCDBG(LOG,FLS,1, "po=%p", po);
 
@@ -715,11 +715,38 @@ pmclog_flush(struct pmc_owner *po)
 	}
 
 	/*
-	 * Schedule the current buffer if any.
+	 * Schedule the current buffer if any and not empty.
+	 */
+	mtx_lock_spin(&po->po_mtx);
+	lb = po->po_curbuf;
+	if (lb && lb->plb_ptr != lb->plb_base) {
+		pmclog_schedule_io(po);
+	} else
+		error = ENOBUFS;
+	mtx_unlock_spin(&po->po_mtx);
+
+ error:
+	mtx_unlock(&pmc_kthread_mtx);
+
+	return (error);
+}
+
+int
+pmclog_close(struct pmc_owner *po)
+{
+
+	PMCDBG(LOG,CLO,1, "po=%p", po);
+
+	mtx_lock(&pmc_kthread_mtx);
+
+	/*
+	 * Schedule the current buffer.
 	 */
 	mtx_lock_spin(&po->po_mtx);
 	if (po->po_curbuf)
 		pmclog_schedule_io(po);
+	else
+		wakeup_one(po);
 	mtx_unlock_spin(&po->po_mtx);
 
 	/*
@@ -728,13 +755,11 @@ pmclog_flush(struct pmc_owner *po)
 	 */
 	po->po_flags |= PMC_PO_SHUTDOWN;
 
- error:
 	mtx_unlock(&pmc_kthread_mtx);
 
-	return (error);
+	return (0);
 }
 
-
 void
 pmclog_process_callchain(struct pmc *pm, struct pmc_sample *ps)
 {
diff --git a/sys/dev/hwpmc/hwpmc_mod.c b/sys/dev/hwpmc/hwpmc_mod.c
index fc82908..7ca7a47 100644
--- a/sys/dev/hwpmc/hwpmc_mod.c
+++ b/sys/dev/hwpmc/hwpmc_mod.c
@@ -2891,7 +2891,7 @@ pmc_syscall_handler(struct thread *td, void *syscall_args)
 			error = pmclog_configure_log(md, po, cl.pm_logfd);
 		} else if (po->po_flags & PMC_PO_OWNS_LOGFILE) {
 			pmclog_process_closelog(po);
-			error = pmclog_flush(po);
+			error = pmclog_close(po);
 			if (error == 0) {
 				LIST_FOREACH(pm, &po->po_pmcs, pm_next)
 				    if (pm->pm_flags & PMC_F_NEEDS_LOGFILE &&
@@ -2907,7 +2907,6 @@ pmc_syscall_handler(struct thread *td, void *syscall_args)
 	}
 	break;
 
-
 	/*
 	 * Flush a log file.
 	 */
@@ -2928,6 +2927,25 @@ pmc_syscall_handler(struct thread *td, void *syscall_args)
 	break;
 
 	/*
+	 * Close a log file.
+	 */
+
+	case PMC_OP_CLOSELOG:
+	{
+		struct pmc_owner *po;
+
+		sx_assert(&pmc_sx, SX_XLOCKED);
+
+		if ((po = pmc_find_owner_descriptor(td->td_proc)) == NULL) {
+			error = EINVAL;
+			break;
+		}
+
+		error = pmclog_close(po);
+	}
+	break;
+
+	/*
 	 * Retrieve hardware configuration.
 	 */
 
diff --git a/sys/sys/pmc.h b/sys/sys/pmc.h
index bcc2898..6819ece 100644
--- a/sys/sys/pmc.h
+++ b/sys/sys/pmc.h
@@ -302,7 +302,8 @@ enum pmc_event {
 	__PMC_OP(PMCSETCOUNT, "Set initial count/sampling rate")	\
 	__PMC_OP(PMCSTART, "Start a PMC")				\
 	__PMC_OP(PMCSTOP, "Stop a PMC")					\
-	__PMC_OP(WRITELOG, "Write a cookie to the log file")
+	__PMC_OP(WRITELOG, "Write a cookie to the log file")		\
+	__PMC_OP(CLOSELOG, "Close log file")
 
 
 enum pmc_ops {
diff --git a/sys/sys/pmclog.h b/sys/sys/pmclog.h
index 44c5c6c..f2b6480 100644
--- a/sys/sys/pmclog.h
+++ b/sys/sys/pmclog.h
@@ -243,6 +243,7 @@ int	pmclog_configure_log(struct pmc_mdep *_md, struct pmc_owner *_po,
     int _logfd);
 int	pmclog_deconfigure_log(struct pmc_owner *_po);
 int	pmclog_flush(struct pmc_owner *_po);
+int	pmclog_close(struct pmc_owner *_po);
 void	pmclog_initialize(void);
 void	pmclog_process_callchain(struct pmc *_pm, struct pmc_sample *_ps);
 void	pmclog_process_closelog(struct pmc_owner *po);
diff --git a/usr.sbin/pmcstat/pmcstat.c b/usr.sbin/pmcstat/pmcstat.c
index 31ef877..5d9db61 100644
--- a/usr.sbin/pmcstat/pmcstat.c
+++ b/usr.sbin/pmcstat/pmcstat.c
@@ -552,7 +552,7 @@ main(int argc, char **argv)
 	int hcpu, option, npmc, ncpu;
 	int c, check_driver_stats, current_cpu, current_sampling_count;
 	int do_callchain, do_descendants, do_logproccsw, do_logprocexit;
-	int do_print;
+	int do_print, do_read;
 	size_t dummy;
 	int graphdepth;
 	int pipefd[2], rfd;
@@ -1328,7 +1328,7 @@ main(int argc, char **argv)
 	 * are killed by a SIGINT.
 	 */
 	runstate = PMCSTAT_RUNNING;
-	do_print = 0;
+	do_print = do_read = 0;
 	do {
 		if ((c = kevent(pmcstat_kq, NULL, 0, &kev, 1, NULL)) <= 0) {
 			if (errno != EINTR)
@@ -1351,8 +1351,10 @@ main(int argc, char **argv)
 			    (args.pa_flags & FLAG_DO_TOP)) {
 				if (pmcstat_keypress_log())
 					runstate = pmcstat_close_log();
-			} else
+			} else {
+				do_read = 0;
 				runstate = pmcstat_process_log();
+			}
 			break;
 
 		case EVFILT_SIGNAL:
@@ -1377,9 +1379,6 @@ main(int argc, char **argv)
 				/* Kill the child process if we started it */
 				if (args.pa_flags & FLAG_HAS_COMMANDLINE)
 					pmcstat_kill_process();
-				/* Close the pipe to self, if present. */
-				if (args.pa_flags & FLAG_HAS_PIPE)
-					(void) close(pipefd[READPIPEFD]);
 				runstate = pmcstat_close_log();
 			} else if (kev.ident == SIGWINCH) {
 				if (ioctl(fileno(args.pa_printfile),
@@ -1394,12 +1393,15 @@ main(int argc, char **argv)
 			break;
 
 		case EVFILT_TIMER: /* print out counting PMCs */
+			if ((args.pa_flags & FLAG_DO_TOP) &&
+			     pmc_flush_logfile() != ENOBUFS)
+				do_read = 1;
 			do_print = 1;
 			break;
 
 		}
 
-		if (do_print) {
+		if (do_print && !do_read) {
 			if ((args.pa_required & FLAG_HAS_OUTPUT_LOGFILE) == 0) {
 				pmcstat_print_pmcs();
 				if (runstate == PMCSTAT_FINISHED && /* final newline */
@@ -1420,7 +1422,7 @@ main(int argc, char **argv)
 
 	/* flush any pending log entries */
 	if (args.pa_flags & (FLAG_HAS_OUTPUT_LOGFILE | FLAG_HAS_PIPE))
-		pmc_flush_logfile();
+		pmc_close_logfile();
 
 	pmcstat_cleanup();
 
diff --git a/usr.sbin/pmcstat/pmcstat_log.c b/usr.sbin/pmcstat/pmcstat_log.c
index b7dc956..6d0403f 100644
--- a/usr.sbin/pmcstat/pmcstat_log.c
+++ b/usr.sbin/pmcstat/pmcstat_log.c
@@ -1702,7 +1702,7 @@ pmcstat_close_log(void)
 	 * so keep the status to EXITING.
 	 */
 	if (args.pa_logfd != -1) {
-		if (pmc_flush_logfile() < 0)
+		if (pmc_close_logfile() < 0)
 			err(EX_OSERR, "ERROR: logging failed");
 	}