diff options
author | jkoshy <jkoshy@FreeBSD.org> | 2005-06-09 19:45:09 +0000 |
---|---|---|
committer | jkoshy <jkoshy@FreeBSD.org> | 2005-06-09 19:45:09 +0000 |
commit | 1d3209ab83aac3089f15e00934e922d222a4ecf0 (patch) | |
tree | 4970329c2802c6329dd4f6e781d84b27dbf8f412 /usr.sbin | |
parent | 4421a087425df7cc08a5671152d0ec7410bdb33e (diff) | |
download | FreeBSD-src-1d3209ab83aac3089f15e00934e922d222a4ecf0.zip FreeBSD-src-1d3209ab83aac3089f15e00934e922d222a4ecf0.tar.gz |
MFP4:
- Implement sampling modes and logging support in hwpmc(4).
- Separate MI and MD parts of hwpmc(4) and allow sharing of
PMC implementations across different architectures.
Add support for P4 (EMT64) style PMCs to the amd64 code.
- New pmcstat(8) options: -E (exit time counts) -W (counts
every context switch), -R (print log file).
- pmc(3) API changes, improve our ability to keep ABI compatibility
in the future. Add more 'alias' names for commonly used events.
- bug fixes & documentation.
Diffstat (limited to 'usr.sbin')
-rw-r--r-- | usr.sbin/pmccontrol/pmccontrol.c | 23 | ||||
-rw-r--r-- | usr.sbin/pmcstat/pmcstat.8 | 60 | ||||
-rw-r--r-- | usr.sbin/pmcstat/pmcstat.c | 590 |
3 files changed, 538 insertions, 135 deletions
diff --git a/usr.sbin/pmccontrol/pmccontrol.c b/usr.sbin/pmccontrol/pmccontrol.c index 6ffa2d1..8e52614 100644 --- a/usr.sbin/pmccontrol/pmccontrol.c +++ b/usr.sbin/pmccontrol/pmccontrol.c @@ -222,8 +222,8 @@ pmcc_do_list_state(void) int c, cpu, n, npmc, ncpu; unsigned int logical_cpus_mask; struct pmc_info *pd; - struct pmc_op_getpmcinfo *pi; - const struct pmc_op_getcpuinfo *pc; + struct pmc_pmcinfo *pi; + const struct pmc_cpuinfo *pc; if (pmc_cpuinfo(&pc) != 0) err(EX_OSERR, "Unable to determine CPU information"); @@ -280,7 +280,7 @@ pmcc_do_list_events(void) enum pmc_class c; unsigned int i, j, nevents; const char **eventnamelist; - const struct pmc_op_getcpuinfo *ci; + const struct pmc_cpuinfo *ci; if (pmc_cpuinfo(&ci) != 0) err(EX_OSERR, "Unable to determine CPU information"); @@ -307,7 +307,7 @@ static int pmcc_show_statistics(void) { - struct pmc_op_getdriverstats gms; + struct pmc_driverstats gms; if (pmc_get_driver_stats(&gms) < 0) err(EX_OSERR, "ERROR: cannot retrieve driver statistics"); @@ -316,12 +316,15 @@ pmcc_show_statistics(void) * Print statistics. */ -#define PRINT(N,V) (void) printf("%20s %d\n", (N), gms.pm_##V) - - PRINT("interrupts-processed", intr_processed); - PRINT("interrupts-ignored", intr_ignored); - PRINT("system-calls", syscalls); - PRINT("system-calls-with-errors", syscall_errors); +#define PRINT(N,V) (void) printf("%-40s %d\n", (N), gms.pm_##V) + PRINT("interrupts processed:", intr_processed); + PRINT("non-PMC interrupts:", intr_ignored); + PRINT("interrupts dropped due to lack of space:", intr_bufferfull); + PRINT("system calls:", syscalls); + PRINT("system calls with errors:", syscall_errors); + PRINT("buffer requests:", buffer_requests); + PRINT("buffer requests failed:", buffer_requests_failed); + PRINT("sampling log sweeps:", log_sweeps); return 0; } diff --git a/usr.sbin/pmcstat/pmcstat.8 b/usr.sbin/pmcstat/pmcstat.8 index 75f132b..16a2e0e 100644 --- a/usr.sbin/pmcstat/pmcstat.8 +++ b/usr.sbin/pmcstat/pmcstat.8 @@ -31,12 +31,18 @@ .Nd performance measurement with performance monitoring hardware .Sh SYNOPSIS .Nm +.Op Fl D Ar pathname .Op Fl C +.Op Fl E .Op Fl O Ar logfilename .Op Fl P Ar event-spec +.Op Fl R Ar logfilename .Op Fl S Ar event-spec +.Op Fl W .Op Fl c Ar cpu .Op Fl d +.Op Fl g +.Op Fl m .Op Fl n Ar count .Op Fl o Ar outputfile .Op Fl p Ar event-spec @@ -76,9 +82,9 @@ counting and sampling flavors. The values of all counting PMCs are printed in human readable form at regular intervals by .Nm . -The output of sampling PMCs is configured to go to log file, for later -analysis by tools like -.Xr pmcreport 8 . +The output of sampling PMCs may be configured to go to a log file for +subsequent offline analysis, or, at the expense of greater +overhead, may be configured to be processed on the fly. .Pp Hardware events to measure are specified to .Nm @@ -94,23 +100,48 @@ process' current and future children. The following options are available: .Bl -tag -width indent .It Fl C -Toggle between showing cumulative and incremental counts for +Toggle between showing cumulative or incremental counts for subsequent counting mode PMCs specified on the command line. The default is to show incremental counts. +.It Fl D Ar pathname +Create files with per-program samples in the directory named +by +.Ar pathname . +The default is to create these files in the current directory. +.It Fl E +Toggle showing per-process counts at the time a tracked process +exits for subsequent process-mode PMCs specified on the command line. +This option is useful for mapping the performance characteristics of a +complex pipeline of processes when used in conjunction with the +.Fl d +option. +The default is to not to enable per-process tracking. .It Fl O Ar logfilename Send the output of sampling mode PMCs to .Ar logfilename . -The default file name is -.Pa pmcstat.out , -in the current directory. +If this option is not specified and one of the logging options +is requested, then +.Nm +will print a human-readable version of the log to the configured +output file. .It Fl P Ar event-spec Allocate a process mode sampling PMC measuring hardware events specified in .Ar event-spec . +.It Fl R Ar logfilename +Perform offline analysis using sampling data in file +.Ar logfilename . .It Fl S Ar event-spec Allocate a system mode sampling PMC measuring hardware events specified in .Ar event-spec . +.It Fl W +Toggle logging the incremental counts seen by the threads of a +tracked process each time they are scheduled on a CPU. +This is an experimental feature intended to help analyse the +dynamic behaviour of processes in the system. +It may incur substantial overhead if enabled. +The default is for this feature to be disabled. .It Fl c Ar cpu Set the cpu for subsequent system mode PMCs specified on the command line to @@ -119,16 +150,23 @@ The default is to allocate system mode PMCs on CPU zero. .It Fl d Toggle between process mode PMCs measuring events for the target process' current and future children or only measuring events for -the attached process. +the target process. The default is to measure events for the target process alone. +.It Fl g +Produce execution profiles in a format compatible with +.Xr gprof 1 . +.It Fl m +When producing +.Xr gprof 1 +compatible execution profiles, merge profiles across multiple +invocations of the same executable. .It Fl n Ar rate Set the default sampling rate for subsequent sampling mode PMCs specified on the command line. The default is to configure PMCs to sample the CPU's instruction pointer every 65536 events. .It Fl o Ar outputfile -Send the periodic counter output of -.Nm +Send counter readings and printed representations of logged data to file .Ar outputfile . The default is to send output to @@ -188,9 +226,9 @@ sometime after .Sh AUTHORS .An Joseph Koshy Aq jkoshy@FreeBSD.org .Sh SEE ALSO +.Xr gprof 1 , .Xr execvp 3 , .Xr pmc 3 , .Xr hwpmc 4 , .Xr pmccontrol 8 , -.Xr pmcreport 8 , .Xr sysctl 8 diff --git a/usr.sbin/pmcstat/pmcstat.c b/usr.sbin/pmcstat/pmcstat.c index ee3c427..e4fc143 100644 --- a/usr.sbin/pmcstat/pmcstat.c +++ b/usr.sbin/pmcstat/pmcstat.c @@ -1,5 +1,5 @@ /*- - * Copyright (c) 2003,2004 Joseph Koshy + * Copyright (c) 2003-2005, Joseph Koshy * All rights reserved. * * Redistribution and use in source and binary forms, with or without @@ -22,7 +22,6 @@ * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF * SUCH DAMAGE. - * */ #include <sys/cdefs.h> @@ -42,6 +41,7 @@ __FBSDID("$FreeBSD$"); #include <limits.h> #include <math.h> #include <pmc.h> +#include <pmclog.h> #include <signal.h> #include <stdarg.h> #include <stdio.h> @@ -51,26 +51,55 @@ __FBSDID("$FreeBSD$"); #include <sysexits.h> #include <unistd.h> +/* + * A given invocation of pmcstat(8) can manage multiple PMCs of both + * the system-wide and per-process variety. Each of these could be in + * 'counting mode' or in 'sampling mode'. + * + * For 'counting mode' PMCs, pmcstat(8) will periodically issue a + * pmc_read() at the configured time interval and print out the value + * of the requested PMCs. + * + * For 'sampling mode' PMCs it can log to a file for offline analysis, + * or can analyse sampling data "on the fly", either by converting + * samples to printed textual form or by creating gprof(1) compatible + * profiles, one per program executed. When creating gprof(1) + * profiles it can optionally merge entries from multiple processes + * for a given executable into a single profile file. + */ + /* Operation modes */ #define FLAG_HAS_PID 0x00000001 #define FLAG_HAS_WAIT_INTERVAL 0x00000002 #define FLAG_HAS_LOG_FILE 0x00000004 #define FLAG_HAS_PROCESS 0x00000008 -#define FLAG_USING_SAMPLING 0x00000010 -#define FLAG_USING_COUNTING 0x00000020 -#define FLAG_USING_PROCESS_PMC 0x00000040 +#define FLAG_HAS_SAMPLING_PMCS 0x00000010 +#define FLAG_HAS_COUNTING_PMCS 0x00000020 +#define FLAG_HAS_PROCESS_PMCS 0x00000040 +#define FLAG_HAS_SYSTEM_PMCS 0x00000080 +#define FLAG_HAS_PIPE 0x00000100 +#define FLAG_PROCESS_LOGFILE 0x00000200 +#define FLAG_DO_GPROF 0x00000400 +#define FLAG_DO_GPROF_MERGED 0x00000800 #define DEFAULT_SAMPLE_COUNT 65536 #define DEFAULT_WAIT_INTERVAL 5.0 #define DEFAULT_DISPLAY_HEIGHT 23 -#define DEFAULT_LOGFILE_NAME "pmcstat.out" +#define DEFAULT_BUFFER_SIZE 4096 +#define WRITELOG_MAGIC 0xA55AA55A #define PRINT_HEADER_PREFIX "# " #define READPIPEFD 0 #define WRITEPIPEFD 1 #define NPIPEFD 2 +enum pmcstat_state { + PMCSTAT_FINISHED = 0, + PMCSTAT_EXITING = 1, + PMCSTAT_RUNNING = 2 +}; + struct pmcstat_ev { STAILQ_ENTRY(pmcstat_ev) ev_next; char *ev_spec; /* event specification */ @@ -78,7 +107,7 @@ struct pmcstat_ev { enum pmc_mode ev_mode; /* desired mode */ int ev_count; /* associated count if in sampling mode */ int ev_cpu; /* specific cpu if requested */ - int ev_descendants; /* attach to descendants */ + int ev_flags; /* PMC_F_* */ int ev_cumulative; /* show cumulative counts */ int ev_fieldwidth; /* print width */ int ev_fieldskip; /* #leading spaces */ @@ -87,13 +116,16 @@ struct pmcstat_ev { }; struct pmcstat_args { + int pa_required; int pa_flags; pid_t pa_pid; - FILE *pa_outputfile; - FILE *pa_logfile; - double pa_interval; + FILE *pa_outputfile; + FILE *pa_logfile; + void *pa_logparser; + char *pa_outputdir; + double pa_interval; int pa_argc; - char **pa_argv; + char **pa_argv; STAILQ_HEAD(, pmcstat_ev) pa_head; } args; @@ -103,15 +135,22 @@ int pmcstat_pipefd[NPIPEFD]; int pmcstat_kq; /* Function prototypes */ -void pmcstat_cleanup(struct pmcstat_args *_a); -void pmcstat_print_counters(struct pmcstat_args *_a); -void pmcstat_print_headers(struct pmcstat_args *_a); -void pmcstat_print_pmcs(struct pmcstat_args *_a); -void pmcstat_setup_process(struct pmcstat_args *_a); -void pmcstat_show_usage(void); -void pmcstat_start_pmcs(struct pmcstat_args *_a); -void pmcstat_start_process(struct pmcstat_args *_a); - +void pmcstat_cleanup(struct pmcstat_args *_a); +int pmcstat_close_log(struct pmcstat_args *_a); +void pmcstat_print_counters(struct pmcstat_args *_a); +void pmcstat_print_headers(struct pmcstat_args *_a); +void pmcstat_print_pmcs(struct pmcstat_args *_a); +void pmcstat_setup_process(struct pmcstat_args *_a); +void pmcstat_show_usage(void); +void pmcstat_start_pmcs(struct pmcstat_args *_a); +void pmcstat_start_process(struct pmcstat_args *_a); +void pmcstat_process_log(struct pmcstat_args *_a); +int pmcstat_print_log(struct pmcstat_args *_a); + +#define PMCSTAT_PRINT_LOG(A,T,...) do { \ + fprintf((A)->pa_outputfile, T "\t" __VA_ARGS__); \ + fprintf((A)->pa_outputfile, "\n"); \ + } while (0) /* * cleanup @@ -123,22 +162,25 @@ pmcstat_cleanup(struct pmcstat_args *a) struct pmcstat_ev *ev, *tmp; /* de-configure the log file if present. */ - if (a->pa_flags & FLAG_USING_SAMPLING) { + if (a->pa_flags & FLAG_HAS_LOG_FILE) (void) pmc_configure_logfile(-1); - (void) fclose(a->pa_logfile); - } /* release allocated PMCs. */ STAILQ_FOREACH_SAFE(ev, &a->pa_head, ev_next, tmp) if (ev->ev_pmcid != PMC_ID_INVALID) { if (pmc_release(ev->ev_pmcid) < 0) err(EX_OSERR, "ERROR: cannot release pmc " - "%d \"%s\"", ev->ev_pmcid, ev->ev_name); + "0x%x \"%s\"", ev->ev_pmcid, ev->ev_name); free(ev->ev_name); free(ev->ev_spec); STAILQ_REMOVE(&a->pa_head, ev, pmcstat_ev, ev_next); free(ev); } + + if (a->pa_logparser) { + pmclog_close(a->pa_logparser); + a->pa_logparser = NULL; + } } void @@ -151,9 +193,10 @@ pmcstat_start_pmcs(struct pmcstat_args *a) assert(ev->ev_pmcid != PMC_ID_INVALID); if (pmc_start(ev->ev_pmcid) < 0) { - warn("ERROR: Cannot start pmc %d \"%s\"", + warn("ERROR: Cannot start pmc 0x%x \"%s\"", ev->ev_pmcid, ev->ev_name); pmcstat_cleanup(a); + exit(EX_OSERR); } } @@ -255,12 +298,10 @@ pmcstat_setup_process(struct pmcstat_args *a) struct kevent kev; if (a->pa_flags & FLAG_HAS_PID) { - - STAILQ_FOREACH(ev, &args.pa_head, ev_next) + STAILQ_FOREACH(ev, &a->pa_head, ev_next) if (pmc_attach(ev->ev_pmcid, a->pa_pid) != 0) err(EX_OSERR, "ERROR: cannot attach pmc \"%s\" to " "process %d", ev->ev_name, (int) a->pa_pid); - } else { /* @@ -269,7 +310,6 @@ pmcstat_setup_process(struct pmcstat_args *a) * process reads its pipe for a token so that the parent * can finish doing its pmc_attach() calls. */ - if (pipe(pmcstat_pipefd) < 0) err(EX_OSERR, "ERROR: cannot create pipe"); @@ -288,8 +328,11 @@ pmcstat_setup_process(struct pmcstat_args *a) (void) close(pmcstat_pipefd[READPIPEFD]); /* exec() the program requested */ - execvp(*args.pa_argv, args.pa_argv); - err(EX_OSERR, "ERROR (child): execvp failed"); + execvp(*a->pa_argv, a->pa_argv); + /* and if that fails, notify the parent */ + kill(getppid(), SIGCHLD); + err(EX_OSERR, "ERROR: execvp \"%s\" failed", + *a->pa_argv); /*NOTREACHED*/ default: /* parent */ @@ -307,13 +350,12 @@ pmcstat_setup_process(struct pmcstat_args *a) } } - /* Ask to be notified via a kevent when the child exits */ - EV_SET(&kev, a->pa_pid, EVFILT_PROC, EV_ADD, NOTE_EXIT, 0, 0); - + /* Ask to be notified via a kevent when the target process exits */ + EV_SET(&kev, a->pa_pid, EVFILT_PROC, EV_ADD|EV_ONESHOT, NOTE_EXIT, 0, + NULL); if (kevent(pmcstat_kq, &kev, 1, NULL, 0, NULL) < 0) - err(EX_OSERR, "ERROR: cannot monitor process %d", + err(EX_OSERR, "ERROR: cannot monitor child process %d", a->pa_pid); - return; } @@ -332,6 +374,147 @@ pmcstat_start_process(struct pmcstat_args *a) (void) close(pmcstat_pipefd[WRITEPIPEFD]); } + +/* + * Process a log file in offline analysis mode. + */ + +void +pmcstat_process_log(struct pmcstat_args *a) +{ + int runstate; + + /* + * If gprof style profiles haven't been asked for, just print the + * log to the current output file. + */ + if ((a->pa_flags & (FLAG_DO_GPROF_MERGED|FLAG_DO_GPROF)) == 0) { + while ((runstate = pmcstat_print_log(a)) == PMCSTAT_RUNNING) + ; + return; + } + + /* convert the log to gprof compatible profiles */ + assert(0); /* To be implemented */ +} + +/* + * Print log entries available in a configured parser. + */ + +int +pmcstat_print_log(struct pmcstat_args *a) +{ + struct pmclog_ev ev; + + while (pmclog_read(a->pa_logparser, &ev) == 0) { + assert(ev.pl_state == PMCLOG_OK); + switch (ev.pl_type) { + case PMCLOG_TYPE_CLOSELOG: + PMCSTAT_PRINT_LOG(a,"close",); + break; + case PMCLOG_TYPE_DROPNOTIFY: + PMCSTAT_PRINT_LOG(a,"drop",); + break; + case PMCLOG_TYPE_INITIALIZE: + PMCSTAT_PRINT_LOG(a,"init","0x%x \"%s\"", + ev.pl_u.pl_i.pl_version, + pmc_name_of_cputype(ev.pl_u.pl_i.pl_arch)); + break; + case PMCLOG_TYPE_MAPPINGCHANGE: + PMCSTAT_PRINT_LOG(a,"mapping","%s %d %p %p \"%s\"", + ev.pl_u.pl_m.pl_type == PMCLOG_MAPPING_INSERT ? + "insert" : "delete", + ev.pl_u.pl_m.pl_pid, + (void *) ev.pl_u.pl_m.pl_start, + (void *) ev.pl_u.pl_m.pl_end, + ev.pl_u.pl_m.pl_pathname); + break; + case PMCLOG_TYPE_PCSAMPLE: + PMCSTAT_PRINT_LOG(a,"sample","0x%x %d %p", + ev.pl_u.pl_s.pl_pmcid, + ev.pl_u.pl_s.pl_pid, + (void *) ev.pl_u.pl_s.pl_pc); + break; + case PMCLOG_TYPE_PMCALLOCATE: + PMCSTAT_PRINT_LOG(a,"allocate","0x%x \"%s\" 0x%x", + ev.pl_u.pl_a.pl_pmcid, + ev.pl_u.pl_a.pl_evname, + ev.pl_u.pl_a.pl_flags); + break; + case PMCLOG_TYPE_PMCATTACH: + PMCSTAT_PRINT_LOG(a,"attach","0x%x %d \"%s\"", + ev.pl_u.pl_t.pl_pmcid, + ev.pl_u.pl_t.pl_pid, + ev.pl_u.pl_t.pl_pathname); + break; + case PMCLOG_TYPE_PMCDETACH: + PMCSTAT_PRINT_LOG(a,"detach","0x%x %d", + ev.pl_u.pl_d.pl_pmcid, + ev.pl_u.pl_d.pl_pid); + break; + case PMCLOG_TYPE_PROCCSW: + PMCSTAT_PRINT_LOG(a,"csw","0x%x %d %jd", + ev.pl_u.pl_c.pl_pmcid, + ev.pl_u.pl_c.pl_pid, + ev.pl_u.pl_c.pl_value); + break; + case PMCLOG_TYPE_PROCEXEC: + PMCSTAT_PRINT_LOG(a,"exec","%d \"%s\"", + ev.pl_u.pl_x.pl_pid, + ev.pl_u.pl_x.pl_pathname); + break; + case PMCLOG_TYPE_PROCEXIT: + PMCSTAT_PRINT_LOG(a,"exitvalue","0x%x %d %jd", + ev.pl_u.pl_e.pl_pmcid, + ev.pl_u.pl_e.pl_pid, + ev.pl_u.pl_e.pl_value); + break; + case PMCLOG_TYPE_PROCFORK: + PMCSTAT_PRINT_LOG(a,"fork","%d %d", + ev.pl_u.pl_f.pl_oldpid, + ev.pl_u.pl_f.pl_newpid); + break; + case PMCLOG_TYPE_USERDATA: + PMCSTAT_PRINT_LOG(a,"user","0x%x", + ev.pl_u.pl_u.pl_userdata); + break; + case PMCLOG_TYPE_SYSEXIT: + PMCSTAT_PRINT_LOG(a,"exit","%d", + ev.pl_u.pl_se.pl_pid); + break; + default: + fprintf(a->pa_outputfile, "unknown %d", + ev.pl_type); + } + } + + if (ev.pl_state == PMCLOG_EOF) + return PMCSTAT_FINISHED; + else if (ev.pl_state == PMCLOG_REQUIRE_DATA) + return PMCSTAT_RUNNING; + + err(EX_DATAERR, "ERROR: event parsing failed " + "(record %jd, offset 0x%jx)", + (uintmax_t) ev.pl_count + 1, ev.pl_offset); + /*NOTREACHED*/ +} + +/* + * Close a logfile, after first flushing all in-module queued data. + */ + +int +pmcstat_close_log(struct pmcstat_args *a) +{ + if (pmc_flush_logfile() < 0 || + pmc_configure_logfile(-1) < 0) + err(EX_OSERR, "ERROR: logging failed"); + a->pa_flags &= ~FLAG_HAS_LOG_FILE; + return a->pa_flags & FLAG_HAS_PIPE ? PMCSTAT_EXITING : + PMCSTAT_FINISHED; +} + void pmcstat_show_usage(void) { @@ -340,16 +523,22 @@ pmcstat_show_usage(void) "\t Measure process and/or system performance using hardware\n" "\t performance monitoring counters.\n" "\t Options include:\n" - "\t -C\t\t toggle showing cumulative counts\n" - "\t -O file\t set sampling log file to \"file\"\n" - "\t -P spec\t allocate process-private sampling PMC\n" - "\t -S spec\t allocate system-wide sampling PMC\n" - "\t -c cpu\t\t set default cpu\n" - "\t -d\t\t toggle tracking descendants\n" + "\t -C\t\t (toggle) show cumulative counts\n" + "\t -D path\t create profiles in directory \"path\"\n" + "\t -E\t\t (toggle) show counts at process exit\n" + "\t -O file\t send log output to \"file\"\n" + "\t -P spec\t allocate a process-private sampling PMC\n" + "\t -R file\t read events from \"file\"\n" + "\t -S spec\t allocate a system-wide sampling PMC\n" + "\t -W\t\t (toggle) show counts per context switch\n" + "\t -c cpu\t\t set cpu for subsequent system-wide PMCs\n" + "\t -d\t\t (toggle) track descendants\n" + "\t -g\t\t produce gprof(1) compatible profiles\n" + "\t -m\t\t merge gprof(1) profiles for executables\n" "\t -n rate\t set sampling rate\n" "\t -o file\t send print output to \"file\"\n" - "\t -p spec\t allocate process-private counting PMC\n" - "\t -s spec\t allocate system-wide counting PMC\n" + "\t -p spec\t allocate a process-private counting PMC\n" + "\t -s spec\t allocate a system-wide counting PMC\n" "\t -t pid\t\t attach to running process with pid \"pid\"\n" "\t -w secs\t set printing time interval" ); @@ -365,12 +554,16 @@ main(int argc, char **argv) double interval; int option, npmc, ncpu; int c, current_cpu, current_sampling_count; - int running; - int do_descendants, use_cumulative_counts; + int do_print, do_descendants; + int do_logproccsw, do_logprocexit; + int logfd; + int pipefd[2]; + int use_cumulative_counts; pid_t pid; char *end; + const char *errmsg; + enum pmcstat_state runstate; struct pmcstat_ev *ev; - struct pmc_op_getpmcinfo *ppmci; struct sigaction sa; struct kevent kev; struct winsize ws; @@ -378,33 +571,60 @@ main(int argc, char **argv) current_cpu = 0; current_sampling_count = DEFAULT_SAMPLE_COUNT; do_descendants = 0; + do_logproccsw = 0; + do_logprocexit = 0; use_cumulative_counts = 0; + args.pa_required = 0; args.pa_flags = 0; args.pa_pid = (pid_t) -1; args.pa_logfile = NULL; + args.pa_outputdir = NULL; args.pa_outputfile = stderr; args.pa_interval = DEFAULT_WAIT_INTERVAL; STAILQ_INIT(&args.pa_head); ev = NULL; - while ((option = getopt(argc, argv, "CO:P:S:c:dn:o:p:s:t:w:")) != -1) + while ((option = getopt(argc, argv, "CD:EO:P:R:S:Wc:dgmn:o:p:s:t:w:")) + != -1) switch (option) { case 'C': /* cumulative values */ use_cumulative_counts = !use_cumulative_counts; + args.pa_required |= FLAG_HAS_COUNTING_PMCS; break; case 'c': /* CPU */ current_cpu = strtol(optarg, &end, 0); if (*end != '\0' || current_cpu < 0) errx(EX_USAGE, - "ERROR: Illegal CPU number \"%s\"", + "ERROR: Illegal CPU number \"%s\".", optarg); - + args.pa_required |= FLAG_HAS_SYSTEM_PMCS; break; case 'd': /* toggle descendents */ do_descendants = !do_descendants; + args.pa_required |= FLAG_HAS_PROCESS_PMCS; + break; + + case 'D': + args.pa_outputdir = optarg; + break; + + case 'g': /* produce gprof compatible profiles */ + args.pa_flags |= FLAG_DO_GPROF; + args.pa_required |= FLAG_HAS_SAMPLING_PMCS; + break; + + case 'm': /* produce merged profiles */ + args.pa_flags |= FLAG_DO_GPROF_MERGED; + args.pa_required |= FLAG_HAS_SAMPLING_PMCS; + break; + + case 'E': /* log process exit */ + do_logprocexit = !do_logprocexit; + args.pa_required |= (FLAG_HAS_PROCESS_PMCS | + FLAG_HAS_COUNTING_PMCS | FLAG_HAS_LOG_FILE); break; case 'p': /* process virtual counting PMC */ @@ -412,7 +632,7 @@ main(int argc, char **argv) case 'P': /* process virtual sampling PMC */ case 'S': /* system-wide sampling PMC */ if ((ev = malloc(sizeof(*ev))) == NULL) - errx(EX_SOFTWARE, "ERROR: Out of memory"); + errx(EX_SOFTWARE, "ERROR: Out of memory."); switch (option) { case 'p': ev->ev_mode = PMC_MODE_TC; break; @@ -421,14 +641,22 @@ main(int argc, char **argv) case 'S': ev->ev_mode = PMC_MODE_SS; break; } - if (option == 'P' || option == 'p') - args.pa_flags |= FLAG_USING_PROCESS_PMC; + if (option == 'P' || option == 'p') { + args.pa_flags |= FLAG_HAS_PROCESS_PMCS; + args.pa_required |= (FLAG_HAS_PROCESS | + FLAG_HAS_PID); + } - if (option == 'P' || option == 'S') - args.pa_flags |= FLAG_USING_SAMPLING; + if (option == 'P' || option == 'S') { + args.pa_flags |= FLAG_HAS_SAMPLING_PMCS; + args.pa_required |= FLAG_HAS_LOG_FILE; + } if (option == 'p' || option == 's') - args.pa_flags |= FLAG_USING_COUNTING; + args.pa_flags |= FLAG_HAS_COUNTING_PMCS; + + if (option == 's' || option == 'S') + args.pa_flags |= FLAG_HAS_SYSTEM_PMCS; ev->ev_spec = strdup(optarg); @@ -442,7 +670,14 @@ main(int argc, char **argv) else ev->ev_cpu = PMC_CPU_ANY; - ev->ev_descendants = do_descendants; + ev->ev_flags = 0; + if (do_descendants) + ev->ev_flags |= PMC_F_DESCENDANTS; + if (do_logprocexit) + ev->ev_flags |= PMC_F_LOG_PROCEXIT; + if (do_logproccsw) + ev->ev_flags |= PMC_F_LOG_PROCCSW; + ev->ev_cumulative = use_cumulative_counts; ev->ev_saved = 0LL; @@ -458,50 +693,68 @@ main(int argc, char **argv) break; + case 'R': /* read an existing log file */ + if ((logfd = open(optarg, O_RDONLY, 0)) < 0) + err(EX_OSERR, "ERROR: Cannot open \"%s\" for " + "reading", optarg); + if ((args.pa_logparser = pmclog_open(logfd)) + == NULL) + err(EX_OSERR, "ERROR: Cannot create parser"); + args.pa_flags |= FLAG_PROCESS_LOGFILE; + break; + case 'n': /* sampling count */ current_sampling_count = strtol(optarg, &end, 0); if (*end != '\0' || current_sampling_count <= 0) errx(EX_USAGE, - "ERROR: Illegal count value \"%s\"", + "ERROR: Illegal count value \"%s\".", optarg); + args.pa_required |= FLAG_HAS_SAMPLING_PMCS; break; case 'o': /* outputfile */ if (args.pa_outputfile != NULL) (void) fclose(args.pa_outputfile); - if ((args.pa_outputfile = fopen(optarg, "w")) == NULL) errx(EX_OSERR, "ERROR: cannot open \"%s\" for " - "writing", optarg); + "writing.", optarg); + args.pa_required |= FLAG_HAS_COUNTING_PMCS; + break; case 'O': /* sampling output */ if (args.pa_logfile != NULL) - (void) fclose(args.pa_logfile); - + errx(EX_OSERR, "ERROR: option -O may only be " + "specified once."); if ((args.pa_logfile = fopen(optarg, "w")) == NULL) errx(EX_OSERR, "ERROR: cannot open \"%s\" for " - "writing", optarg); + "writing.", optarg); + args.pa_flags |= FLAG_HAS_LOG_FILE; break; case 't': /* target pid */ pid = strtol(optarg, &end, 0); if (*end != '\0' || pid <= 0) errx(EX_USAGE, "ERROR: Illegal pid value " - "\"%s\"", optarg); + "\"%s\".", optarg); args.pa_flags |= FLAG_HAS_PID; + args.pa_required |= FLAG_HAS_PROCESS_PMCS; args.pa_pid = pid; - break; case 'w': /* wait interval */ interval = strtod(optarg, &end); if (*end != '\0' || interval <= 0) errx(EX_USAGE, "ERROR: Illegal wait interval " - "value \"%s\"", optarg); + "value \"%s\".", optarg); args.pa_flags |= FLAG_HAS_WAIT_INTERVAL; args.pa_interval = interval; + break; + case 'W': /* toggle LOG_CSW */ + do_logproccsw = !do_logproccsw; + args.pa_required |= (FLAG_HAS_PROCESS_PMCS | + FLAG_HAS_COUNTING_PMCS | FLAG_HAS_LOG_FILE); break; case '?': @@ -521,25 +774,84 @@ main(int argc, char **argv) * Check invocation syntax. */ - if (STAILQ_EMPTY(&args.pa_head)) { + if (args.pa_flags & FLAG_PROCESS_LOGFILE) { + errmsg = NULL; + if (args.pa_flags & FLAG_HAS_PROCESS) + errmsg = "a command line specification"; + else if (args.pa_flags & FLAG_HAS_PID) + errmsg = "option -t"; + else if (!STAILQ_EMPTY(&args.pa_head)) + errmsg = "a PMC event specification"; + if (errmsg) + errx(EX_USAGE, "ERROR: option -R may not be used with " + "%s.", errmsg); + } else if (STAILQ_EMPTY(&args.pa_head)) { warnx("ERROR: At least one PMC event must be specified"); pmcstat_show_usage(); } - if (argc == 0) { - if (args.pa_pid == -1) { - if (args.pa_flags & FLAG_USING_PROCESS_PMC) - errx(EX_USAGE, "ERROR: the -P or -p options " - "require a target process"); - } else if ((args.pa_flags & FLAG_USING_PROCESS_PMC) == 0) - errx(EX_USAGE, - "ERROR: option -t requires a process-mode pmc " - "specification"); - } else if (args.pa_pid != -1) + /* check for -t pid without a process PMC spec */ + if ((args.pa_required & FLAG_HAS_PID) && + (args.pa_flags & FLAG_HAS_PROCESS_PMCS) == 0) + errx(EX_USAGE, "ERROR: option -t requires a process mode PMC " + "to be specified."); + + /* check for process-mode options without a command or -t pid */ + if ((args.pa_required & FLAG_HAS_PROCESS_PMCS) && + (args.pa_flags & (FLAG_HAS_PROCESS | FLAG_HAS_PID)) == 0) + errx(EX_USAGE, "ERROR: options -d,-E,-p,-P,-W require a " + "command line or target process."); + + /* check for -p | -P without a target process of some sort */ + if ((args.pa_required & (FLAG_HAS_PROCESS | FLAG_HAS_PID)) && + (args.pa_flags & (FLAG_HAS_PROCESS | FLAG_HAS_PID)) == 0) + errx(EX_USAGE, "ERROR: the -P or -p options require a " + "target process or a command line."); + + /* check for process-mode options without a process-mode PMC */ + if ((args.pa_required & FLAG_HAS_PROCESS_PMCS) && + (args.pa_flags & FLAG_HAS_PROCESS_PMCS) == 0) + errx(EX_USAGE, "ERROR: options -d,-E,-W require a " + "process mode PMC to be specified."); + + /* check for -c cpu and not system mode PMCs */ + if ((args.pa_required & FLAG_HAS_SYSTEM_PMCS) && + (args.pa_flags & FLAG_HAS_SYSTEM_PMCS) == 0) + errx(EX_USAGE, "ERROR: option -c requires at least one " + "system mode PMC to be specified."); + + /* check for counting mode options without a counting PMC */ + if ((args.pa_required & FLAG_HAS_COUNTING_PMCS) && + (args.pa_flags & FLAG_HAS_COUNTING_PMCS) == 0) + errx(EX_USAGE, "ERROR: options -C,-o,-W require at least one " + "counting mode PMC to be specified."); + + /* check for sampling mode options without a sampling PMC spec */ + if ((args.pa_required & FLAG_HAS_SAMPLING_PMCS) && + (args.pa_flags & FLAG_HAS_SAMPLING_PMCS) == 0) + errx(EX_USAGE, "ERROR: options -n,-O require at least one " + "sampling mode PMC to be specified."); + + if ((args.pa_flags & (FLAG_HAS_PID | FLAG_HAS_PROCESS)) == + (FLAG_HAS_PID | FLAG_HAS_PROCESS)) errx(EX_USAGE, "ERROR: option -t cannot be specified with a command " - "name"); + "line."); + + /* check if -O was spuriously specified */ + if ((args.pa_flags & FLAG_HAS_LOG_FILE) && + (args.pa_required & FLAG_HAS_LOG_FILE) == 0) + errx(EX_USAGE, + "ERROR: option -O is used only with options " + "-E,-P,-S and -W."); + /* if we've been asked to process a log file, do that and exit */ + if (args.pa_flags & FLAG_PROCESS_LOGFILE) { + pmcstat_process_log(&args); + exit(EX_OK); + } + + /* otherwise, we've been asked to collect data */ if (pmc_init() < 0) err(EX_UNAVAILABLE, "ERROR: Initialization of the pmc(3) library failed"); @@ -556,15 +868,9 @@ main(int argc, char **argv) * Allocate PMCs. */ - if (pmc_pmcinfo(0, &ppmci) < 0) - err(EX_OSERR, "ERROR: cannot retrieve pmc information"); - - assert(ppmci != NULL); - STAILQ_FOREACH(ev, &args.pa_head, ev_next) if (pmc_allocate(ev->ev_spec, ev->ev_mode, - (ev->ev_descendants ? PMC_F_DESCENDANTS : 0), - ev->ev_cpu, &ev->ev_pmcid) < 0) + ev->ev_flags, ev->ev_cpu, &ev->ev_pmcid) < 0) err(EX_OSERR, "ERROR: Cannot allocate %s-mode pmc with " "specification \"%s\"", PMC_IS_SYSTEM_MODE(ev->ev_mode) ? "system" : "process", @@ -614,25 +920,48 @@ main(int argc, char **argv) } EV_SET(&kev, SIGINT, EVFILT_SIGNAL, EV_ADD, 0, 0, NULL); - if (kevent(pmcstat_kq, &kev, 1, NULL, 0, NULL) < 0) err(EX_OSERR, "ERROR: Cannot register kevent for SIGINT"); - if (args.pa_flags & FLAG_USING_SAMPLING) { + EV_SET(&kev, SIGIO, EVFILT_SIGNAL, EV_ADD, 0, 0, NULL); + if (kevent(pmcstat_kq, &kev, 1, NULL, 0, NULL) < 0) + err(EX_OSERR, "ERROR: Cannot register kevent for SIGIO"); - /* - * configure log file - */ + /* + * An exec() failure of a forked child is signalled by the + * child sending the parent a SIGCHLD. We don't register an + * actual signal handler for SIGCHLD, but instead use our + * kqueue to pick up the signal. + */ + EV_SET(&kev, SIGCHLD, EVFILT_SIGNAL, EV_ADD, 0, 0, NULL); + if (kevent(pmcstat_kq, &kev, 1, NULL, 0, NULL) < 0) + err(EX_OSERR, "ERROR: Cannot register kevent for SIGCHLD"); - if (args.pa_logfile == NULL) - if ((args.pa_logfile = - fopen(DEFAULT_LOGFILE_NAME, "w")) == NULL) - err(EX_CANTCREAT, "ERROR: Cannot open sampling " - "log file \"%s\"", DEFAULT_LOGFILE_NAME); + /* + * Configure the specified log file or setup a default log + * consumer via a pipe. + */ + if (args.pa_required & FLAG_HAS_LOG_FILE) { + + if (args.pa_logfile == NULL) { + if (pipe(pipefd) < 0) + err(EX_OSERR, "ERROR: pipe(2) failed"); + + EV_SET(&kev, pipefd[READPIPEFD], EVFILT_READ, EV_ADD, + 0, 0, NULL); + + if (kevent(pmcstat_kq, &kev, 1, NULL, 0, NULL) < 0) + err(EX_OSERR, "ERROR: Cannot register kevent"); + + logfd = pipefd[WRITEPIPEFD]; + + args.pa_flags |= (FLAG_HAS_PIPE | FLAG_HAS_LOG_FILE); + args.pa_logparser = pmclog_open(pipefd[READPIPEFD]); + } else + logfd = fileno(args.pa_logfile); - if (pmc_configure_logfile(fileno(args.pa_logfile)) < 0) - err(EX_OSERR, "ERROR: Cannot configure sampling " - "log"); + if (pmc_configure_logfile(logfd) < 0) + err(EX_OSERR, "ERROR: Cannot configure log file"); STAILQ_FOREACH(ev, &args.pa_head, ev_next) if (PMC_IS_SAMPLING_MODE(ev->ev_mode) && @@ -642,7 +971,7 @@ main(int argc, char **argv) } /* setup a timer for any counting mode PMCs */ - if (args.pa_flags & FLAG_USING_COUNTING) { + if (args.pa_flags & FLAG_HAS_COUNTING_PMCS) { EV_SET(&kev, 0, EVFILT_TIMER, EV_ADD, 0, args.pa_interval * 1000, NULL); @@ -674,8 +1003,8 @@ main(int argc, char **argv) * loop till either the target process (if any) exits, or we * are killed by a SIGINT. */ - - running = 1; + runstate = PMCSTAT_RUNNING; + do_print = 0; do { if ((c = kevent(pmcstat_kq, NULL, 0, &kev, 1, NULL)) <= 0) { if (errno != EINTR) @@ -688,26 +1017,43 @@ main(int argc, char **argv) errc(EX_OSERR, kev.data, "ERROR: kevent failed"); switch (kev.filter) { - case EVFILT_PROC: /* target process exited */ - running = 0; - /* FALLTHROUGH */ - - case EVFILT_TIMER: /* print out counting PMCs */ - pmcstat_print_pmcs(&args); + case EVFILT_PROC: /* target has exited */ + if (args.pa_flags & FLAG_HAS_LOG_FILE) + runstate = pmcstat_close_log(&args); + break; - if (running == 0) /* final newline */ - (void) fprintf(args.pa_outputfile, "\n"); + case EVFILT_READ: /* log file data is present */ + runstate = pmcstat_print_log(&args); break; case EVFILT_SIGNAL: - if (kev.ident == SIGINT) { + if (kev.ident == SIGCHLD) { + /* + * The child process sends us a + * SIGCHLD if its exec() failed. We + * wait for it to exit and then exit + * ourselves. + */ + (void) wait(&c); + runstate = PMCSTAT_FINISHED; + } else if (kev.ident == SIGIO) { + /* + * We get a SIGIO if a PMC loses all + * of its targets, or if logfile + * writes encounter an error. + */ + if (args.pa_flags & FLAG_HAS_LOG_FILE) + runstate = pmcstat_close_log(&args); + do_print = 1; /* print PMCs at exit */ + runstate = PMCSTAT_FINISHED; + } else if (kev.ident == SIGINT) { /* pass the signal on to the child process */ if ((args.pa_flags & FLAG_HAS_PROCESS) && (args.pa_flags & FLAG_HAS_PID) == 0) if (kill(args.pa_pid, SIGINT) != 0) - err(EX_OSERR, "cannot kill " - "child"); - running = 0; + err(EX_OSERR, "ERROR: cannot " + "signal child process"); + runstate = PMCSTAT_FINISHED; } else if (kev.ident == SIGWINCH) { if (ioctl(fileno(args.pa_outputfile), TIOCGWINSZ, &ws) < 0) @@ -718,9 +1064,25 @@ main(int argc, char **argv) assert(0); break; + + case EVFILT_TIMER: /* print out counting PMCs */ + do_print = 1; + break; + } - } while (running); + if (do_print) { + pmcstat_print_pmcs(&args); + if (runstate == PMCSTAT_FINISHED) /* final newline */ + (void) fprintf(args.pa_outputfile, "\n"); + do_print = 0; + } + + } while (runstate != PMCSTAT_FINISHED); + + /* flush any pending log entries */ + if (args.pa_flags & FLAG_HAS_LOG_FILE) + pmc_flush_logfile(); pmcstat_cleanup(&args); |