.TLLimbo profilers in Inferno.AUJ R Firth.AIVita Nuova.br13 June 2002.SP 4.NH 1Introduction.LPCurrently there are three application level profiling tools in theInferno package. .I Profis a time profiler which, by sampling, can provide statisticson the percentage of time spent on each line of limbo source. .I Cprofis acoverage profiler which provides the execution profile for limbo sourcecode. It can accumulate results over a series of runs to allow fullcoverage testing. Finally, .I mprofis a memory profiler which providesstatistics on the amount of memory used by each lineof limbo source..LPTwo gui versions of these tools currently exist. .I Wm/cprofshows thecoverage per module and highlights those lines which have not beenexecuted or have been only partially executed. .I Wm/mprofshows the memoryusage per module and highlights lines with high memory allocation indarker shades of red..I Profitself does not have a gui equivalent as itwas originally written to determine why acme was so slow when using it'sglobal editing command. A gui for it was not a requirement at that stage..LPAll these tools use a common library module.CW /module/profile.mand.CW /appl/lib/profile.bthat acts as the direct interface with the kernel profiling device..LPNote that none of these tools give kernel profile statistics. For that, the devmem driver should be used..LPAlthough the use of these tools is very similar, there are a few differenceswhen it comes to interactive testing as the profilers were written toanswer different questions. Thus .I proftries to determine 'why is blah soslow ?', .I cproftries to accumulate coverage records over time and .I mproftries togive a series of memory statistics at intervals during the execution ofa program or series of programs..NH 1Prof.LPThe time profiler works by sampling. A kernel procedure sleeps for thegiven sample time and then notes the particular dis instruction currentlybeing executed before repeating the process. After many such samples, an accurate profile can be obtained..LPAt it's simplest we can profile a particular command by giving the commandto execute followed by any arguments to the command eg.sp.RS	prof wm/polyhedra.RE.spprofiles the polyhedra displayer. After letting the latter run for a reasonableamount of time, we exit and then get the following statistics..br.DSModule: Wmlib(/dis/lib/wmlib.dis) 34	0.06		str = load String String->PATH; **** module sampling points 1 **** .DE.DSModule: Bufio(/dis/lib/bufio.dis) 340	0.06			n := 0;341	0.12			while(b.index < b.size){342	0.99				(ch, i, nil) = sys->byte2char(b.buffer[0:b.size], b.index); **** module sampling points 19 **** Module: Polyfill(/dis/math/polyfill.dis) 37	10.80		for(i := 0; i < n; i++)38	19.86			b0[i] = b1[i] = ∞;57	0.06		p.y += y;58	1.18		dst.line((left, y), (right, y), Endsquare, Endsquare, 0, src, p);63	0.12		prevx := ∞;64	9.93		for(x := left; x <= right; x++){65	20.61			if(z+e < zbuf0[k] || (z-e <= zbuf1[k] && x != right && prevx != ∞)){66	6.46				zbuf0[k] = z-e;67	5.71				zbuf1[k] = z+e;68	0.74				if(prevx == ∞)69	0.74					prevx = x;71	0.12			else if(prevx != ∞){72	0.25				fillline(dst, prevx, x-1, y, src, p);73	2.61				prevx = ∞;75	4.35			z += dx;76	3.17			k++;78	0.06		if(prevx != ∞)79	0.87			fillline(dst, prevx, right, y, src, p);80	0.06	}152	0.06			return (vx/z, mod);186	0.06			sp.dzrem = mod(sp.num, sp.den) << fixshift;187	0.06			sp.dz += sdiv(sp.dzrem, sp.den);217	0.62			for(q = p = 0; p < ep; p++) {218	0.37				sp = seg[p];220	0.12					continue;221	0.12				sp.z += sp.dz;222	0.19				sp.zerr += sp.dzrem;223	0.12				if(sp.zerr >= sp.den) {224	0.19					sp.z++;225	0.25					sp.zerr -= sp.den;226	0.25					if(sp.zerr < 0 || sp.zerr >= sp.den)227	0.25						sys->print("bad ratzerr1: %d den %d dzrem %d\n", sp.zerr, sp.den, sp.dzrem);229	0.31				seg[q] = sp;230	0.31				q++;233	0.25			for(p = next; seg[p] != nil; p++) {234	0.06				sp = seg[p];247	0.12			ep = q;248	0.06			next = p;257	0.06				continue;260	0.62			zsort(seg, ep);262	0.25			for(p = 0; p < ep; p++) {263	0.19				sp = seg[p];264	0.06				cnt = 0;265	0.06				x = sp.z;266	0.25				ix = (x + onehalf) >> fixshift;267	0.06				if(ix >= maxx)271	0.06				cnt += sp.d;272	0.12				p++;273	0.25				sp = seg[p];275	0.06					if(p == ep) {277	0.06						return;279	0.06					cnt += sp.d;280	0.12					if((cnt&wind) == 0)283	0.19					sp = seg[p];286	0.25				ix2 = (x2 + onehalf) >> fixshift;291	1.92				filllinez(dst, ix, ix2, iy, zv+ix*dx, er, dx, k+ix-zr.min.x, zbuf0, zbuf1, src, spt);293	0.06			y += (1<<fixshift);294	0.31			iy++;295	0.06			k += xlen;296	0.06			zv += dy;298	0.06	}310	0.06				done = 1;311	0.12				q--;312	0.25				for(p = 0; p < q; p++) {313	0.87					if(seg[p].z > seg[p+1].z) {367	0.06			t = a[0]; a[0] = a[i]; a[i] = t;373	0.06				while(i < n && ycompare(a[i], a[0]) < 0);379	0.12				t = a[i]; a[i] = a[j]; a[j] = t;384	0.06				qsortycompare(a, j); **** module sampling points 1584 **** Module: Polyhedra(/dis/wm/polyhedra.dis) 327	0.12		return (int (geo.sx*v.x)+geo.tx, int (geo.sy*v.y)+geo.ty);471	0.06					if(allf || dot(geo.view, newn[j]) < 0.0)472	0.06						polyfilla(fv[j], new, newn[j], dot(geo.light, newn[j]), geo, concave, inc);496	0.06			ap[j] = map(vtx, geo);512	0.06			if(a <= -LIMIT || a >= LIMIT)531	0.06			fillpoly(RDisp, ap, ~0, face, (0, 0), geo.zstate, dc, dx, dy); **** module sampling points 7 ****  **** total sampling points 1611 ****.DE.brThe output lists all lines in all modules with a sampling point. Each lineshows the line number in the corresponding source file, the percentage oftime spent on that line and the source code. We can see that about 60% ofthe sampling points occur on lines 37, 38, 64 and 65 of the Polyfill module.With this information we might then try to speed up this part of the codeby altering the algorithm or making the limbo code more efficient (forinstance by moving constant calculations or addressing out of loops)..LPThe number of sampling points is also shown. The sampling rate can beincreased with the -s option to give better granularity.This will cause a decrease in apparent performance but increases theaccuracy of the results. The above example showed the results for allmodules sampled. We might have restricted attention to the two mainpolyhedra modules instead by executing.sp.RS	prof -m Polyhedra -m Polyfill wm/polyhedra.RE.spSee the manual page for other options to .I profand further examples..NH1Cprof.LPCoverage of instructions is achieved by running a special dis instruction execute routine in place of the usual one (just as the debugger does).This routine notes down eachinstruction as it is executed. The profile device then passes this informationto .I cprofvia the io system..LPThe coverage profiler is used in a similar way to the time profiler..sp.RS	cprof -m Zeros zeros 1024 2880.RE.spgives.br.DSModule: Zeros(zeros.dis)	56% coverage 1	 	implement Zeros;2	 	3	 	include "sys.m";4	 		sys: Sys;5	 	include "arg.m";6	 		arg: Arg;7	 	include "string.m";8	 		str: String;9	 	include "keyring.m";10	 	include "security.m";11	 		random: Random;12	 	13	 	include "draw.m";14	 	15	 	Zeros: module16	 	{17	 		init: fn(nil: ref Draw->Context, argv: list of string);18	 	};19	 	20	 	init(nil: ref Draw->Context, argv: list of string)21	 	{22	 		z: array of byte;23	 		i: int;24	+		sys = load Sys Sys->PATH;25	+		arg = load Arg Arg->PATH;26	+		str = load String String->PATH;27	 	28	+		if(sys == nil || arg == nil)29	-			return;30	 	31	+		bs := 0;32	+		n := 0;33	+		val := 0;34	+		rflag := 0;35	+		arg->init(argv);36	+		while ((c := arg->opt()) != 0)37	-			case c {38	-			'r' => rflag = 1;39	-			'v' => (val, nil) = str->toint(arg->arg(), 16);40	-			* => sys->raise(sys->sprint("fail: unknown option (%c)\n", c));41	 			}.DE.DS42	+		argv = arg->argv();43	+		if(len argv >= 1)44	+			bs = int hd argv;45	 		else46	-			bs = 1;47	+		if (len argv >= 2)48	+			n = int hd tl argv;49	 		else50	-			n = 1;51	+		if(bs == 0 || n == 0) {52	-			sys->fprint(sys->fildes(2), "usage: zeros [-r] [-v value] blocksize [number]\n");53	-			sys->raise("fail: usage");54	 		}55	+		if (rflag) {56	-			random = load Random Random->PATH;57	-			if (random == nil)58	-				sys->raise("fail: no security module\n");59	-			z = random->randombuf(random->NotQuiteRandom, bs);60	 		}61	 		else {62	+			z = array[bs] of byte;63	+			for(i=0;i<bs;i++)64	+				z[i] = byte val;65	 		}66	+		for(i=0;i<n;i++)67	+			sys->write(sys->fildes(1), z, bs);68	+	} **** module dis instructions 39725 ****.DE.brHere the -m option has restricted attention to the Zeros module itself.The output shows the source line number, an indicator of coverage andthe source. The indicator is + if the line has been executed, - ifit hasn't and ? if only part of it has (for instance a loop statement that hasnever had it's iteration part executed). Lines with no indicator have nocorresponding dis instructions associated with them. Another option (-f)shows coverage frequencies instead..LPAn alternative to .I cprofis .I wm/cprofwhich shows the statistics graphically.It's options are pretty much the same as those to .I cprof .Unexecuted and partially executed lines of code are shown in colour. See the man page for exact details of the colouring convention.LPResults may be accumulated with the -r option so that multiple runs ofcode can be made. The resulting statistics go into a file <xxx>.prf when<xxx>.dis is the corresponding dis file. See the manual page for furtherdetails on how to use this option and then review the accumulated results..NH 1Mprof.LPWhen memory profiling, the kernel profile device associates each heap allocation with a line of limbo source and each heap deallocation with the line oflimbo source that allocated it. In this way, current memory usage andhigh-water usage can be determined on a line by line basis..LPHere it seems that memory usage at a particular point in the execution ofa program is more appropriate than the post-mortem approach of .I profand .I cprof, so an interactive example is described (though .I mprofcan beused non-interactively and .I profinteractively if so desired). See the manualpages for complete details and further examples..LPTo do this we execute.sp.RS	mprof -b -m Polyhedra.RE.spwhich kicks off profiling and restricts attention to the Polyhedra modulewhenever it runs. The -b simply says begin profiling. Note that no commandto execute is given to .I mprofat this stage. Then run the command.sp.RS	wm/polyhedra &.RE.spand interact with it. Now show memory statistics.sp.RS	mprof.RE.spThis gives.br.DSModule: Polyhedra(/dis/wm/polyhedra.dis) 44	100	100		sys = load Sys Sys->PATH;45	132	132		draw = load Draw Draw->PATH;46	68	68		tk = load Tk Tk->PATH;47	1788	1788		wmlib = load Wmlib Wmlib->PATH;48	232	232		bufio = load Bufio Bufio->PATH;49	68	68		math = load Math Math->PATH;50	204	204		rand = load Rand Rand->PATH;51	0	3504		daytime = load Daytime Daytime->PATH;52	544	544		polyfill = load Polyfill Polyfill->PATH;53	1824	1824		smenu = load Smenu Smenu->PATH;86	36	36		cmdch := chan of string;95	36	36		sync := chan of int;96	36	36		chanθ := chan of real;103	68	68		shade = array[NSHADES] of ref Image;116	36	36		yieldc := chan of int;120	36	36		sm := array[2] of ref Scrollmenu;378	68	176			s += " (" + string p.indx + ")";403	36	36		vec := array[2] of array of Vector;404	740	740		vec[0] = array[V] of Vector;405	740	740		vec[1] = array[V] of Vector;407	36	36			norm = array[2] of array of Vector;408	612	612			norm[0] = array[F] of Vector;409	612	612			norm[1] = array[F] of Vector;492	68	68		ap := array[n+1] of Point;609	164	164		geo := ref Geom;610	36	36		TM := array[4] of array of real;612	272	272			TM[i] = array[4] of real;663	8000	8000			p := ref Polyhedron;707	740	740		p.v = array[p.V] of Vector;710	612	612		p.f = array[p.F] of Vector;713	132	132		p.fv = array[p.F] of array of int;716	164	164		p.vf = array[p.V] of array of int;729	9504	9640			return s[0: len s - 1];750	3672	3672		a := array[n+2] of int;768	0	136				return (n, s[i+1:]);779	0	104				return (r, s[i+1:]);802	0	68			s = s[1:];806	0	72			s = s[0: ln-1];.DE.DS866	0	200		cmd(mainwin, ".f1.txt configure -text {" + s + "}");874	0	356		labs := array[n] of string;881	0	5128			labs[i++] = string q.indx + " " + name;884	0	68		cmd(top, mname + " configure -borderwidth 3");920	0	104			cmd(win, ". configure -height " + string (scrsize.y - bd * 2));934	0	244		cmd(win, ". configure -x " + string actr.min.x + " -y " + string actr.min.y); Module totals	31416	33984.DE.brWe get the source line number, the amount of memory in bytescurrently allocated on that line, the high-water mark in bytes and then the source. Thusloading the Sys module on line 44 used 100 bytes and this memory isstill allocated. Loading Daytime on line 51 used 3504 bytes but this is nowreleased (because the module pointer is set to nil in the source and thememory has been reclaimed). The string concatenation on line 378 currently uses 68 bytes but at it's worst it was 176 bytes..LPFurther interaction with wm/polyhedra can now be done and memorystatistics reviewed before theprofiling session is ended, throwing away the accumulated memorystatistics inside the kernel with.sp.RS	mprof -c.RE.spThe -c option simply says cease profiling..LPAn alternative to .I mprofis .I wm/mprofwhich shows the statistics graphically.It's options are pretty much the same as those to .I mprof .Lines of codewhich have allocated more of the memory are shown in darker shades of red..NH 1Manual pages.LPFurther information and other examples are given in the followingmanual pages :-.sp.RS.I cprof(1).br.I mprof(1).br.I prof(1).br.I wm-cprof(1).br.I wm-mprof(1).RE.spFor the lower level library module interface to these profilers.sp.RS.I prof(2).RE.spFor the kernel profile device which gathers timing, coverage and memorystatistics.sp.RS.I prof(3).RE.br.NH 1Sources.LPThe relevant sources are.sp.RS.CW /module/profile.m.br.CW /appl/lib/profile.b.br.CW /appl/cmd/cprof.b.br.CW /appl/cmd/mprof.b.br.CW /appl/cmd/prof.b.br.CW /appl/wm/cprof.b.br.CW /appl/wm/mprof.b

Lines 1–500 of 514. Load more