mal_profiler.mx

一个内存数据库的源代码这是服务器端还有客户端

	}
	if (profileCounter[PROFlabel].status) {
		log("%d,\t", mb->profiler[pc].ticks);
	}
	if (profileCounter[PROFstmt].status) {
		/* generate actual call statement */
		stmt = call2str(MCgetClient(),mb, stk, getPC(mb, pci));
		c = stmt+1;

		while (c && *c && isspace((int) *c))
			c++;
		log(" \"%s\",\t", c);
	}
#ifdef HAVE_TIMES
	if (profileCounter[PROFcpu].status) {
		log("%d,\t", newTms.tms_utime - mb->profiler[pc].timer.tms_utime);
		log("%d,\t", newTms.tms_cutime - mb->profiler[pc].timer.tms_cutime);
		log("%d,\t", newTms.tms_stime - mb->profiler[pc].timer.tms_stime);
		log("%d,\t", newTms.tms_cstime - mb->profiler[pc].timer.tms_cstime);
	}
#endif

	if (profileCounter[PROFmemory].status) {
#ifdef HAVE_SYS_RESOURCE_H
		log("%d,\t", infoUsage.ru_maxrss);
#endif
		log("%d,\t", infoMalloc.arena - prevMalloc.arena);
		log("%d,\t", infoMalloc.ordblks - prevMalloc.ordblks);
		log("%d,\t", infoMalloc.smblks - prevMalloc.smblks);
		log("%d,\t", infoMalloc.hblkhd - prevMalloc.hblkhd);
		log("%d,\t", infoMalloc.hblks - prevMalloc.hblks);
		log("%d,\t", infoMalloc.fsmblks - prevMalloc.fsmblks);
		log("%d,\t", infoMalloc.uordblks - prevMalloc.uordblks);
		prevMalloc = infoMalloc;
	}
#ifdef HAVE_SYS_RESOURCE_H
	if (profileCounter[PROFio].status) {
		log("%d,\t", infoUsage.ru_minflt - prevUsage.ru_minflt);
		log("%d,\t", infoUsage.ru_majflt - prevUsage.ru_majflt);
		log("%d,\t", infoUsage.ru_nswap - prevUsage.ru_nswap);
		log("%d,\t", infoUsage.ru_inblock - prevUsage.ru_inblock);
		log("%d,\t", infoUsage.ru_oublock - prevUsage.ru_oublock);
		log("%d,\t", infoUsage.ru_nvcsw - prevUsage.ru_nvcsw);
		log("%d,\t", infoUsage.ru_nivcsw - prevUsage.ru_nivcsw);
		prevUsage = infoUsage;
	}
#endif
	if (profileCounter[PROFevent].status) {
		log("%d ]\n", eventcounter);
	} else {
		log0(" ]\n");
	}
	eventcounter++;
	flushLog();
	mal_unset_lock(profileLock, "profileLock");
}
#endif
@+ Postprocessing events
The offlineProfilerEvent below illustrates information that could be
saved in XML format for post-processing. Compared to the
profilerRecord above, it is more verbose and contains more
information relevant for off-line analysis.
@c
void
infoHeapProfile(Heap *hp, str nme)
{
	char buf[PATHLENGTH], *p = buf;

	if (!hp)
		return;

	while (*nme)
		*p++ = *nme++;
	strcpy(p, "free");
	log0(buf);
	log("=\"%d\" ", hp->free);
	strcpy(p, "size");
	log0(buf);
	log("=\"%d\" ", hp->size);
	if (hp->maxsize) {
		strcpy(p, "maxsize");
		log0(buf);
		log("=\"%d\" ", hp->maxsize);
	}
	strcpy(p, "storage");
	if (hp->base) {
		log0(buf);
		log("=\"%s\" ", (hp->base == NULL) ? "absent" : (hp->storage == STORE_MMAP) ? (hp->filename ? "memory mapped" : "anonymous vm") : (hp->storage == STORE_PRIV) ? "private map" : "malloced");
	}
	if (hp->filename) {
		strcpy(p, "filename");
		log0(buf);
		log("=\"%s\" ", hp->filename ? hp->filename : "no file");
	}
}
void
HASHinfoProfile(Hash *h, str s)
{
	char buf[MAXPATHLEN];
	int i;

	if (!h)
		return;
	snprintf(buf, MAXPATHLEN, "%s=\"\" mask=\"", s);
	i = strlen(buf);
	snprintf(buf + i, MAXPATHLEN - i, SZFMT "\" lim=\"", (size_t)h->mask);
	i = strlen(buf);
	snprintf(buf + i, MAXPATHLEN - i, SZFMT "\"", (size_t)h->lim);
	log0(buf);
}

void
offlineProfilerEvent(Module cntxt, MalBlkPtr mb, MalStkPtr stk, int pc)
{
#ifdef MALprofiler
#ifdef HAVE_TIMES
	struct tms newTms;
#endif
	struct mallinfo infoMalloc;

#ifdef HAVE_SYS_RESOURCE_H
	struct rusage infoUsage;
	static struct rusage prevUsage;
#endif
	static struct mallinfo prevMalloc;
	str stmt, c;
	InstrPtr pci= getInstrPtr(mb,pc);

	(void) cntxt;		/* still unused */

	if (!profileAll && mb->profiler[pc].trace == FALSE)
		return;
	if (getDestVar(pci) <= 0)
		return;
	if (delayswitch > 0) {
		delayswitch--;
		return;
	}
	@:getEventStream()@	/* profilerEvent -> void */
	if (delayswitch == 0) {
		log0("<MonetProfile>\n");
		delayswitch = -1;
	}
#ifdef HAVE_TIMES
	times(&newTms);
#endif
	infoMalloc = MT_mallinfo();
#ifdef HAVE_SYS_RESOURCE_H
	getrusage(RUSAGE_SELF, &infoUsage);
#endif

	/* make XML record */
	log0("<event>\n");
	if (profileCounter[PROFcpu].status) {
#ifdef HAVE_TIMES
		log("\t<tms utime=\"%d\" ", 
			newTms.tms_utime - mb->profiler[pc].timer.tms_utime);
		log("cutime=\"%d\" ", 
			newTms.tms_cutime - mb->profiler[pc].timer.tms_cutime);
		log("stime=\"%d\" ", 
			newTms.tms_stime - mb->profiler[pc].timer.tms_stime);
		log("cstime=\"%d\" ", 
			newTms.tms_cstime - mb->profiler[pc].timer.tms_cstime);
#endif
		log("ticks=\"%d\" ", GDKusec() - mb->profiler[pc].clk);
		log0("/>\n");
	}

	if (profileCounter[PROFstmt].status) {
		log0("\t<mal");
		stmt = instruction2str(mb, pci, FALSE);
		c = strchr(stmt, ']');

		if (c)
			c++;
		else
			c = stmt+1;

		while (c && *c && isspace((int) *c))
			c++;

		log0(" stmt=\"");
		for (; c && *c; c++) {
			if (*c == '#')
				break;
			if (*c == '\n')
				break;
			if (*c == '"') {
				log0("&quot;");
			} else if (*c == '&') {
				log0("&amp;");
			} else if (*c == '\'') {
				log0("&apos;");
			} else
				stream_printf(eventstream, "%c", *c);
		}
		log0("\"");

		log(" module=\"%s\"", (getModuleId(pci) ? getModuleId(pci) : "unknown"));
		log(" function=\"%s\"", (getFunctionId(pci) ? getFunctionId(pci) : "unknown"));
		log(" calls=\"%d\"", mb->profiler[pc].counter);

		if (mb->profiler[pc].counter) {
			double avg = mb->profiler[pc].ticks / (mb->profiler[pc].counter +0.0);

			log(" average=\"%5.2f\"", avg);
		}
		log0("/>\n");
	}

@-
The property tracing option inspects the destination variable
and emits its key properties. This is primarilly meant to
inspect the properties of BATs and their propagation.
@c
	if (profileCounter[2].status) {
		ValPtr v;
		VarPtr w;
		str s;
		str mode, access;

		v = &stk->stk[getDestVar(pci)];
		w = getVar(mb, getDestVar(pci));
		s = getTypeName(v->vtype);

		log0("\t<prop ");
		log("type=\"%s\" ", s);
		GDKfree(s);
		if (w->isaconstant)
			log0("constant=\"true\" ");
		if (w->isatypevar)
			log0("typevar=\"true\" ");

		log0("value=\"");
		if (isaBatType(w->type))
			stream_printf(eventstream, "%s", BATgetId(BBPdescriptor(v->val.bval)));
		else if (isaBatType(w->type))
			stream_printf(eventstream, "Column name not yet known");
		else if (isaBatType(w->type))
			stream_printf(eventstream, "Column name not yet known");
		else if (w->type == TYPE_str) {
			char *t, *tt;

			s = GDKmalloc(v->len + 1);
			for (t = s, tt = v->val.sval; *tt; tt++, t++) {
				if (*tt == '<') {
					strcpy(t, "&lt;");
					t += 3;
				} else if (*tt == '>') {
					strcpy(t, "&gt;");
					t += 3;
				} else
					*t = *tt;
			}
		} else
			ATOMprint(v->vtype, VALptr(v), eventstream);
		log0("\" ");
		if (isaBatType(w->type)) {
			BAT *b = BATdescriptor(v->val.bval);

			if (b) {
				if (b->batPersistence & PERSISTENT)
					mode = "persistent";
				else if (b->batPersistence & SESSION)
					mode = "session";
				else if (b->batPersistence & TRANSIENT)
					mode = "transient";
				else
					mode = "unknown";

				switch (b->batRestricted) {
				case BAT_READ:
					access = "read-only";
					break;
				case BAT_WRITE:
					access = "updatable";
					break;
				case BAT_APPEND:
					access = "append-only";
					break;
				default:
					access = "unknown";
				}

				log("count=\"%d\" ", BATcount(b));
				/*log( "version=\"%d\" ", b->GDKversion); */
				/*log( "batCacheid=\"%d\" ", b->batCacheid); */
				/*log( "batParentid=\"%d\" ", b->batParentid); */
				/*log( "batSharecnt=\"%d\" ", b->batSharecnt); */
				/*log( "head=\"%d\" ", ATOMname(b->htype)); */
				/*log( "tail=\"%d\" ", ATOMname(b->ttype)); */
				log("batPersistence=\"%s\" ", mode);
				log("batRestricted=\"%s\" ", access);
				log("batRefcnt=\"%d\" ", BBP_refs(b->batCacheid));
				if (!BATdirty(b))
					log("batDirty=\"%s\" ", BATdirty(b) ? "dirty" : "clean");
				if (b->batSet)
					log("batSet=\"%d\" ", b->batSet);
				if (b->void_tid)
					log("void_tid=\"%d\" ", b->void_tid);
				if (b->void_cnt)
					log("void_cnt=\"%d\" ", b->void_cnt);

				if (BAThordered(b))
					log("hsorted=\"%d\" ", BAThordered(b));
				/*log( "hident",  b->hident); */
				if (BAThdense(b))
					log("hdense=\"%d\" ", BAThdense(b));
				if (b->hseqbase)
					log("hseqbase=\"%d\" ", b->hseqbase);
				if (b->hkey)
					log("hkey=\"%d\" ", b->hkey);
				/*log( "hloc=\"%d\" ", b->hloc); */
				/* log( "hvarsized=\"%d\" ", b->hvarsized); */
				if (b->halign)
					log("halign=\"%d\" ", b->halign);

				/*log( "tident", b->tident); */
				if (BATtdense(b))
					log("tdense=\"%d\" ", BATtdense(b));
				if (b->tseqbase)
					log("tseqbase=\"%d\" ", b->tseqbase);
				if (BATtordered(b))
					log("tsorted=\"%d\" ", BATtordered(b));
				if (b->tkey)
					log("tkey=\"%d\" ", b->tkey);
				/*log( "tloc=\"%d\" ", b->tloc); */
				/*log( "tvarsized=\"%d\" ", b->tvarsized); */
				if (b->talign)
					log("talign=\"%d\" ", b->talign);

				/*log( "batInserted=\"%d\" ", BUNindex(b, b->batInserted)); */
				/*log( "batDeleted=\"%d\" ", BUNindex(b, b->batDeleted)); */
				/*log( "batHole=\"%d\" ", BUNindex(b, b->batHole)); */
				/*log( "top=\"%d\" ", BUNindex(b, (Bunbase(b) + b->batBuns->free))); */
				if (b->batStamp)
					log("batStamp=\"%d\" ", b->batStamp);
				log("curStamp=\"%d\" ", BBPcurstamp());
				if (b->batCopiedtodisk)
					log("batCopiedtodisk=\"%d\" ", b->batCopiedtodisk);
				if (b->batDirtydesc)
					log("batDirtydesc=\"%s\" ", b->batDirtydesc ? "dirty" : "clean");

				if (b->batDirtybuns)
					log("batDirtybuns=\"%s\" ", b->batDirtybuns ? "dirty" : "clean");
				infoHeapProfile(b->batBuns, "batBuns");

				if (b->hheapdirty)
					log("hheapdirty=\"%s\" ", b->hheapdirty ? "dirty" : "clean");
				infoHeapProfile(b->hheap, "hheap");

				if (b->theapdirty)
					log("theapdirty=\"%s\" ", b->theapdirty ? "dirty" : "clean");
				infoHeapProfile(b->theap, "theap");

				if (b->hhash) {
					HASHinfoProfile(b->hhash, "hhash");
				}
				if (b->thash) {
					HASHinfoProfile(b->thash, "thash");
				}
				BBPunfix(b->batCacheid);
			}
		}
		log0("/>\n");
	}

	if (profileCounter[3].status) {
		log0("\t<memory ");
#ifdef HAVE_SYS_RESOURCE_H
		log("maxrss=\"%d\" ", infoUsage.ru_maxrss);
#endif
		log("arena=\"%d\" ", infoMalloc.arena - prevMalloc.arena);
		log("ordblks=\"%d\" ", infoMalloc.ordblks - prevMalloc.ordblks);
		log("smblks=\"%d\" ", infoMalloc.smblks - prevMalloc.smblks);
		log("\n\thblkhd=\"%d\" ", infoMalloc.hblkhd - prevMalloc.hblkhd);
		log("hblks=\"%d\" ", infoMalloc.hblks - prevMalloc.hblks);
		log("fsmblks=\"%d\" ", infoMalloc.fsmblks - prevMalloc.fsmblks);
		log("uordblks=\"%d\" ", infoMalloc.uordblks - prevMalloc.uordblks);
		prevMalloc = infoMalloc;
		log0("/>\n");
	}

	if (profileCounter[PROFio].status) {
		log0("\t<io ");
#ifdef HAVE_SYS_RESOURCE_H
		log("minflt=\"%d\" ", infoUsage.ru_minflt - prevUsage.ru_minflt);
		log("majflt=\"%d\" ", infoUsage.ru_majflt - prevUsage.ru_majflt);
		log("nswap=\"%d\" ", infoUsage.ru_nswap - prevUsage.ru_nswap);
		log("\n\tinblock=\"%d\" ", infoUsage.ru_inblock - prevUsage.ru_inblock);
		log("oublock=\"%d\" ", infoUsage.ru_oublock - prevUsage.ru_oublock);
		log("nvcsw=\"%d\" ", infoUsage.ru_nvcsw - prevUsage.ru_nvcsw);
		log("nivcsw=\"%d\" ", infoUsage.ru_nivcsw - prevUsage.ru_nivcsw);
		prevUsage = infoUsage;
#endif
		log0("/>\n");
	}

	log0("</event>\n");
	mal_unset_lock(profileLock, "profileLock");
	stream_flush(eventstream);
#endif
}

str
setLogFile(Module cntxt, str fname)
{
	(void) cntxt;		/* still unused */
#ifdef MALprofiler
	if( ! profileLockInitialized) {
		MT_lock_init(&profileLock);
		profileLockInitialized= 1;
	}
	mal_set_lock(profileLock, "profileLock");
	eventstream = open_wastream(fname);
	if (eventstream == NULL) {
		throw(IO, "mal.profiler", "Could not create event stream file");
	}
	mal_unset_lock(profileLock, "profileLock");
#else
	stream_printf(GDKout, "# Monet not compiled for profiling\n");
#endif
	return MAL_SUCCEED;
}

str
openProfilerStream(void)
{
	Client c = MCgetClient();

	malProfileMode = TRUE;
	eventstream = c->fdout;
	delayswitch = 1;	/* avoid an incomplete initial profile event */
	return MAL_SUCCEED;
}

str
closeProfilerStream(void)
{
	Client c = MCgetClient();

	if (offlineProfiling)
		log0("</MonetProfile>\n");
	if (eventstream && eventstream != c->fdout){
		close_stream(eventstream);
		eventstream= 0;
	}
	malProfileMode = FALSE;
	eventstream = NULL;
	return MAL_SUCCEED;
}

str
setStartPoint(Module cntxt, str mod, str fcn)
{
	(void) cntxt;
	(void) mod;
	(void) fcn;		/* still unused */
#ifdef MALprofiler
	@:getEventStream(MAL_SUCCEED /*? or MAL_? ? */ )@
	stream_printf(GDKout, "# start point not set\n");
	mal_unset_lock(profileLock, "profileLock");
#else
	stream_printf(GDKout, "# Monet not compiled for profiling\n");
#endif
	return MAL_SUCCEED;
}

str
setEndPoint(Module cntxt, str mod, str fcn)
{
	(void) cntxt;
	(void) mod;
	(void) fcn;		/* still unused */
#ifdef MALprofiler
	@:getEventStream(MAL_SUCCEED /*? or MAL_? ? */ )@