Hi,
I am getting back to gmon/profil(2), replying to all feedback. Sorry for the
delay.
On Wed, May 03, 2023 at 08:45:39AM -0500, Scott Cheloha wrote:
> On Tue, Apr 11, 2023 at 09:28:31AM +0200, Sebastien Marie wrote:
>
> > One place where I needed to cheat a bit is at moncontrol(0) call in
> > _mcleanup()
> > function.
> >
> > moncontrol(0) will stop profiling (change the state to GMON_PROF_OFF), and
> > it is
> > calling profil(2) to disable program counter profiling. _mcleanup() is the
> > atexit(3) handler.
> >
> > Instead of changing pledge(2) permission for profil(2) (which could go deep
> > in
> > the kernel to change the clockrate with setstatclockrate()), I just assumed
> > that
> > it isn't necessary to disable it here: we are in atexit(3), so the process
> > is
> > about to call _exit(2), and the kernel will stop the profiling itself if
> > still
> > running.
>
> This is an acceptable workaround if you are using moncontrol(3).
> profil(2) is set up before main() and the teardown is transparent to
> the process. We can probably neglect to turn profil(2) off.
>
> If you wanted to be *really* safe you could remove the write
> permissions from the profil(2) buffer with mprotect(2) during
> _mcleanup(). This would prevent the kernel from racing with you.
>
> On the other hand, it would be really nice if profil(2) could fit into
> the "stdio" pledge(2) promise. I don't quite know what the
> implications of that would be.
>
> profil(2) tells the kernel: write sample data at *this* address.
> Later, if that piece of memory is not readable and writable by the
> calling process, the copyin(9) or copyout(9) will fail when the thread
> is returning from the clock interrupt and profil(2) is quietly
> disabled for the process.
>
> Is that set of actions a security concern? Sorry if that's a dumb
> question.
>
> It seems like the process is basically just operating on its own
> memory, but maybe it violates the spirit of the "stdio" promise?
>
I didn't change profil(2) regarding pledge(2) as I basically doesn't understand
the underline kernel code (which is a very good reason for me). All I saw is it
is playing which {start,stop}profclock(9) which is going deep in the kernel,
and
regulary write in user supplied memory address.
So, as I had a somehow valid workaround (have profil(2) enabled before any
pledge(2) call, and don't call it at end), I didn't looked to add profil(2) to
"stdio". It wasn't strictly required.
Please note that adding it in "stdio" means almost every programs (even sshd
sandbox) will gain it.
> > For post-execution gmon.out extraction, an helper might be needed:
> > ktrace.out
> > could contain multiple gmon.out files.
> >
> > ## compile and collect profil information (-tu option on ktrace is optional)
> > $ cc -static -pg test.c
> > $ ktrace -di -tu ./a.out
> >
> > ## get gmon.out file
> > $ kdump -u gmon.out | unvis > gmon.out
> >
> > ## get gmon.out.$name.$pid for multiple processes
> > ## - first get pid process-name
> > ## - extract each gmon.out for each pid and store in "gmon.out.$name.$pid"
> > file
> > $ kdump -tu | sed -ne 's/^ \([0-9][0-9]*\) \([^ ]*\) .*/\1 \2/p' | sort -u \
> > | while read pid name; do kdump -u gmon.out -p $pid | unvis >
> > gmon.out.$name.$pid ; done
> >
> > kdump diff from otto@ mallocdump is need for 'kdump -u label'.
>
> Have you taken a shot at changing kdump(8) to produce the gmon.out
> files gprof(1) expects?
>
> If not, I will take a shot at it.
I looked a bit at kdump(8) to see how to be more user-friendly. Currently, I
only added an option to produce binary data with -u label (basically to not use
vis(3)).
When you have only on process data, it means using:
$ kdump -U -u gmon.out > gmon.out
I didn't look to make kdump(8) directly create files as it is currently a
read-only tool (pledged "stdio rpath getpw"). But it might be a way.
On Thu, May 04, 2023 at 11:09:34AM +0200, Omar Polo wrote:
> On 2023/04/11 09:28:31 +0200, Sebastien Marie <[email protected]> wrote:
>
> I've used this to profile `gotadmin pack' a couple of times. got uses
> several "libexec helpers" to parse data on disk, so profiling usually
> gets awkward. You'd need to build only the program you're interested
> in (e.g. got-read-pack) with PROFILE=1 and collect the data. $PROFDIR
> doesn't work out-of-the-box due to unveil (PROFILE builds disable
> pledge but leave unveil and permit "gmon.out" rwc.) With gotd it gets
> a little more tricky since it's a single binary that gets fork+exec'd
> multiple times. The argument popped up recently on the mailing list:
>
> http://marc.gameoftrees.org/mail/1683051301.32966_0.html
>
> With this instead, I can do one single run and collect the data for
> all processes, and keep pledge/unveil in place.
>
> To test, I've rebuilt and installed libc (and libz, and libutil -
> probably wasn't needed), ran unifdef -m -UPROFILE on got and rebuild
> with PROFILE=1 (needed to get -pg -static and the various -l*_p.)
>
I did most of my tests with got(1) too, in mostly the same way that you (but I
prefered change the Makefile to not pass -DPROFILE).
Only a new libc are required to test (the diff doesn't change the
instrumentation done by cc).
> I've uploaded the png obtained with `gprof2dot | dot -Tpng' here:
>
> https://ftp.omarpolo.com/tmp/
>
> There are two directories: one for `gotadmin pack -a' in src.git and
> one in got.git.
>
> I've observed that not always the profile data seems fine. Each run,
> I have a few processes that report 100% on every function. At first I
> thought it was an issue in how PROFILE=1 builds are done, but then I
> noticed that "good" and "bad" data can be gathered for different run
> of the same executable.
>
> Compare for example
>
> https://ftp.omarpolo.com/tmp/pack-got/profile.got-read-pack.52583.png
> (bad)
>
> and
>
> https://ftp.omarpolo.com/tmp/pack-got/profile.got-read-pack.37417.png
> (good)
>
> both originating from the same run. I still have the gmon.out files
> if needed.
It might be interesting to know if you have the same problem with current gmon.
> One comment below
>
> > --- lib/libc/gmon/gmon.c
> > +++ lib/libc/gmon/gmon.c
> > @@ -51,6 +52,32 @@ void
> > PROTO_NORMAL(moncontrol);
> > PROTO_DEPRECATED(monstartup);
> >
> > +static void
> > +montrace(void *addr, size_t len)
> > +{
> > + for (;;) {
> > + if (len < KTR_USER_MAXLEN) {
>
> should be len <= KTR_USER_MAXLEN ?
>
yes, utrace(2) will accept KTR_USER_MAXLEN bytes for data.
I think I mixed errors condition presented in the man page (the label should
not
be longer than KTR_USER_MAXIDLEN-1, but for data it is KTR_USER_MAXLEN).
> > + if (utrace("gmon.out", addr, len) == -1)
> > + ERR("error on utrace(), truncated gmon.out");
> > + return;
> > + }
> > + if (utrace("gmon.out", addr, KTR_USER_MAXLEN) == -1)
> > + ERR("error on utrace(), truncated gmon.out");
>
> ERR expands to write(2, "..."), so I'd add a return here (very
> unlikely for utrace to fail, but if we check for failures we should
> also return IMHO)
I added the return.
Below an updated diff. It includes kdump(8) -U option.
Thanks
--
Sebastien Marie
diff e5bbc67172ce757f6e3f1f35e95f307733e7a018
39747cbba49da1d3b062fdff8672c79c825f4ed0
commit - e5bbc67172ce757f6e3f1f35e95f307733e7a018
commit + 39747cbba49da1d3b062fdff8672c79c825f4ed0
blob - f09ffd91837040d44fb17a9e8c0197c72ba9459a
blob + f917f94a8263abcdf28b4a16674d81ba3f58530c
--- lib/libc/gmon/gmon.c
+++ lib/libc/gmon/gmon.c
@@ -29,6 +29,7 @@
*/
#include <sys/time.h>
+#include <sys/ktrace.h>
#include <sys/gmon.h>
#include <sys/mman.h>
#include <sys/sysctl.h>
@@ -51,6 +52,34 @@ void
PROTO_NORMAL(moncontrol);
PROTO_DEPRECATED(monstartup);
+static void
+montrace(void *addr, size_t len)
+{
+ for (;;) {
+ if (len <= KTR_USER_MAXLEN) {
+ if (utrace("gmon.out", addr, len) == -1)
+ ERR("error on utrace(), truncated gmon.out");
+ return;
+ }
+ if (utrace("gmon.out", addr, KTR_USER_MAXLEN) == -1) {
+ ERR("error on utrace(), truncated gmon.out");
+ return;
+ }
+
+ len -= KTR_USER_MAXLEN;
+ addr += KTR_USER_MAXLEN;
+ }
+}
+
+#ifdef DEBUG
+static int
+monlog(char *msg)
+{
+ size_t len = strlen(msg);
+ return utrace("gmon.log", msg, len);
+}
+#endif
+
void
monstartup(u_long lowpc, u_long highpc)
{
@@ -136,7 +165,6 @@ _mcleanup(void)
void
_mcleanup(void)
{
- int fd;
int fromindex;
int endfrom;
u_long frompc;
@@ -147,11 +175,8 @@ _mcleanup(void)
struct clockinfo clockinfo;
const int mib[2] = { CTL_KERN, KERN_CLOCKRATE };
size_t size;
- char *profdir;
- char *proffile;
- char buf[PATH_MAX];
#ifdef DEBUG
- int log, len;
+ int len;
char dbuf[200];
#endif
@@ -169,67 +194,16 @@ _mcleanup(void)
clockinfo.profhz = clockinfo.hz; /* best guess */
}
- moncontrol(0);
+ /*
+ * Do not call moncontrol(0) (neither profil(2)) as we might be pledged.
+ * We are in _mcleanup(), so the process is inside exit(3).
+ */
+ p->state = GMON_PROF_OFF;
- if (issetugid() == 0 && (profdir = getenv("PROFDIR")) != NULL) {
- char *s, *t, *limit;
- pid_t pid;
- long divisor;
-
- /* If PROFDIR contains a null value, no profiling
- output is produced */
- if (*profdir == '\0') {
- return;
- }
-
- limit = buf + sizeof buf - 1 - 10 - 1 -
- strlen(__progname) - 1;
- t = buf;
- s = profdir;
- while((*t = *s) != '\0' && t < limit) {
- t++;
- s++;
- }
- *t++ = '/';
-
- /*
- * Copy and convert pid from a pid_t to a string. For
- * best performance, divisor should be initialized to
- * the largest power of 10 less than PID_MAX.
- */
- pid = getpid();
- divisor=10000;
- while (divisor > pid) divisor /= 10; /* skip leading zeros */
- do {
- *t++ = (pid/divisor) + '0';
- pid %= divisor;
- } while (divisor /= 10);
- *t++ = '.';
-
- s = __progname;
- while ((*t++ = *s++) != '\0')
- ;
-
- proffile = buf;
- } else {
- proffile = "gmon.out";
- }
-
- fd = open(proffile , O_CREAT|O_TRUNC|O_WRONLY, 0664);
- if (fd == -1) {
- perror( proffile );
- return;
- }
#ifdef DEBUG
- log = open("gmon.log", O_CREAT|O_TRUNC|O_WRONLY, 0664);
- if (log == -1) {
- perror("mcount: gmon.log");
- close(fd);
- return;
- }
snprintf(dbuf, sizeof dbuf, "[mcleanup1] kcount 0x%x ssiz %d\n",
p->kcount, p->kcountsize);
- write(log, dbuf, strlen(dbuf));
+ monlog(dbuf);
#endif
hdr = (struct gmonhdr *)&gmonhdr;
bzero(hdr, sizeof(*hdr));
@@ -238,8 +212,8 @@ _mcleanup(void)
hdr->ncnt = p->kcountsize + sizeof(gmonhdr);
hdr->version = GMONVERSION;
hdr->profrate = clockinfo.profhz;
- write(fd, (char *)hdr, sizeof *hdr);
- write(fd, p->kcount, p->kcountsize);
+ montrace(hdr, sizeof *hdr);
+ montrace(p->kcount, p->kcountsize);
endfrom = p->fromssize / sizeof(*p->froms);
for (fromindex = 0; fromindex < endfrom; fromindex++) {
if (p->froms[fromindex] == 0)
@@ -254,15 +228,14 @@ _mcleanup(void)
"[mcleanup2] frompc 0x%x selfpc 0x%x count %d\n" ,
frompc, p->tos[toindex].selfpc,
p->tos[toindex].count);
- write(log, dbuf, strlen(dbuf));
+ monlog(dbuf);
#endif
rawarc.raw_frompc = frompc;
rawarc.raw_selfpc = p->tos[toindex].selfpc;
rawarc.raw_count = p->tos[toindex].count;
- write(fd, &rawarc, sizeof rawarc);
+ montrace(&rawarc, sizeof rawarc);
}
}
- close(fd);
#ifdef notyet
if (p->kcount != NULL) {
munmap(p->kcount, p->kcountsize);
blob - 936c630a1096cec78204ac075c6df83a2744e8e2
blob + 8c91cddf450404159851a2429154c2e283ad0bac
--- usr.bin/kdump/kdump.1
+++ usr.bin/kdump/kdump.1
@@ -37,7 +37,7 @@
.Nd display kernel trace data
.Sh SYNOPSIS
.Nm kdump
-.Op Fl dHlnRTXx
+.Op Fl dHlnRTUXx
.Op Fl f Ar file
.Op Fl m Ar maxdata
.Op Fl p Ar pid
@@ -116,9 +116,19 @@ escaping, without
.Ar label
as strings with
.Xr vis 3
-escaping, without
+escaping (if
+.Fl U
+isn't used),
+without
.Xr ktrace 2
header information.
+.It Fl U
+Display
+.Xr utrace 2
+tracepoints as binary data (without
+.Xr vis 3
+escaping) when used with
+.Fl u label .
.It Fl X
Display I/O data with hexadecimal data and printable ASCII characters
side by side.
blob - 6b1c118cdcd75fb5003c08990fb4c46c4455c827
blob + 791c409ae1dc84fa697f64e6b6425a034a974f3a
--- usr.bin/kdump/kdump.c
+++ usr.bin/kdump/kdump.c
@@ -84,11 +84,11 @@ int needtid, tail, basecol;
} timestamp = TIMESTAMP_NONE;
int decimal, iohex, fancy = 1, maxdata = INT_MAX;
-int needtid, tail, basecol;
+int needtid, tail, basecol, utracevis = 1;
char *tracefile = DEF_TRACEFILE;
struct ktr_header ktr_header;
pid_t pid_opt = -1;
-char* utracefilter;
+char *utracefilter;
#define eqs(s1, s2) (strcmp((s1), (s2)) == 0)
@@ -169,7 +169,7 @@ main(int argc, char *argv[])
screenwidth = 80;
}
- while ((ch = getopt(argc, argv, "f:dHlm:np:RTt:u:xX")) != -1)
+ while ((ch = getopt(argc, argv, "f:dHlm:np:RTt:u:UxX")) != -1)
switch (ch) {
case 'f':
tracefile = optarg;
@@ -218,6 +218,11 @@ main(int argc, char *argv[])
utracefilter = optarg;
trpoints = KTRFAC_USER;
break;
+ case 'U':
+ if (isatty(STDOUT_FILENO) == 1)
+ errx(1, "couldn't enable utrace binary output
on terminal");
+ utracevis = 0;
+ break;
case 'x':
iohex = 1;
break;
@@ -1267,8 +1272,13 @@ showbuf(unsigned char *dp, size_t datalen)
char visbuf[4 * KTR_USER_MAXLEN + 1];
if (utracefilter != NULL) {
- strvisx(visbuf, dp, datalen, VIS_SAFE | VIS_OCTAL);
- printf("%s", visbuf);
+ if (utracevis) {
+ strvisx(visbuf, dp, datalen, VIS_SAFE | VIS_OCTAL);
+ printf("%s", visbuf);
+ } else {
+ for (i = 0; i < datalen; i++)
+ putchar(dp[i]);
+ }
return;
}
if (iohex == 1) {
