Changeset: 2376fdbbba52 for MonetDB
URL: http://dev.monetdb.org/hg/MonetDB?cmd=changeset;node=2376fdbbba52
Modified Files:
clients/mapiclient/tomograph.c
monetdb5/mal/mal_profiler.c
Branch: Feb2013
Log Message:
Reduce sys IO calls in profiler
First assemble the complete message before locking the stream
and sending the message. It improves the performance somewhat.
(transplanted from 9b64f3f84fa7365dcab5a500dc15212f564087f2)
diffs (truncated from 540 to 300 lines):
diff --git a/clients/mapiclient/tomograph.c b/clients/mapiclient/tomograph.c
--- a/clients/mapiclient/tomograph.c
+++ b/clients/mapiclient/tomograph.c
@@ -822,11 +822,10 @@ static void updmap(int idx)
fnd = i;
break;
}
- } else if (colors[i].mod[0] == '*') {
- fnd = i;
- break;
}
+ if ( colors[i].col == 0 )
+ fnd = i-1;
colors[fnd].freq++;
colors[fnd].timeused += box[idx].clkend - box[idx].clkstart;
box[idx].color = fnd;
diff --git a/monetdb5/mal/mal_profiler.c b/monetdb5/mal/mal_profiler.c
--- a/monetdb5/mal/mal_profiler.c
+++ b/monetdb5/mal/mal_profiler.c
@@ -155,14 +155,28 @@ deactivateCounter(str name)
* Offline processing
* The offline processing structure is the easiest. We merely have to
* produce a correct tuple format for the front-end.
+ * To avoid unnecessary locks we first built the event as a string
+ * It uses a local logbuffer[LOGLEN] and logbase, logtop, loglen
*/
-#define log(...)
\
+#define LOGLEN 8192
+#define lognew() loglen = 0; logbase = logbuffer;
+#define logadd(...)
\
do {
\
+ (void) snprintf(logbase+loglen, LOGLEN -1 - loglen,
__VA_ARGS__); \
+ loglen += (int) strlen(logbase+loglen);
\
+ } while (0)
+#define logsent()
\
+ do {
\
+ MT_lock_set(&mal_profileLock, "profileLock");
\
if (eventstream)
\
- if (mnstr_printf(eventstream, __VA_ARGS__) < 0) {
\
+ if (mnstr_write(eventstream, logbuffer,loglen,1 ) < 0)
{ \
closeProfilerStream();
\
}
\
+ flushLog();
\
+ eventcounter++;
\
+ MT_lock_unset(&mal_profileLock, "profileLock");
\
} while (0)
+
#define flushLog() if (eventstream) mnstr_flush(eventstream);
/*
@@ -196,83 +210,86 @@ profilerEvent(int idx, MalBlkPtr mb, Mal
static void
offlineProfilerHeader(void)
{
- MT_lock_set(&mal_profileLock, "profileLock");
+ char logbuffer[LOGLEN], *logbase;
+ int loglen;
+
if (eventstream == NULL) {
- MT_lock_unset(&mal_profileLock, "profileLock");
return ;
}
- log("# ");
+ lognew();
+ logadd("# ");
if (profileCounter[PROFevent].status) {
- log("event,\tstatus,\t");
+ logadd("event,\tstatus,\t");
}
if (profileCounter[PROFtime].status) {
- log("time,\t");
+ logadd("time,\t");
}
if (profileCounter[PROFthread].status) {
- log("thread,\t");
+ logadd("thread,\t");
}
if (profileCounter[PROFflow].status)
- log("claim,\tmemory,\t");
+ logadd("claim,\tmemory,\t");
if (profileCounter[PROFfunc].status) {
- log("function,\t");
+ logadd("function,\t");
}
if (profileCounter[PROFpc].status) {
- log("pc,\t");
+ logadd("pc,\t");
}
if (profileCounter[PROFticks].status) {
- log("usec,\t");
+ logadd("usec,\t");
}
if (profileCounter[PROFcpu].status) {
- log("utime,\t");
- log("cutime,\t");
- log("stime,\t");
- log("cstime,\t");
+ logadd("utime,\t");
+ logadd("cutime,\t");
+ logadd("stime,\t");
+ logadd("cstime,\t");
}
if (profileCounter[PROFmemory].status) {
- log("rss,\t");
+ logadd("rss,\t");
/*
- log("maxrss,\t");
- log("arena,\t");
- log("ordblks,\t");
- log("smblks,\t");
- log("hblkhd,\t");
- log("hblks,\t");
- log("fsmblks,\t");
- log("uordblks,\t");
+ logadd("maxrss,\t");
+ logadd("arena,\t");
+ logadd("ordblks,\t");
+ logadd("smblks,\t");
+ logadd("hblkhd,\t");
+ logadd("hblks,\t");
+ logadd("fsmblks,\t");
+ logadd("uordblks,\t");
*/
}
if (profileCounter[PROFreads].status)
- log("blk reads,\t");
+ logadd("blk reads,\t");
if (profileCounter[PROFwrites].status)
- log("blk writes,\t");
+ logadd("blk writes,\t");
if (profileCounter[PROFprocess].status) {
- log("pg reclaim,\t");
- log("pg faults,\t");
- log("swaps,\t");
- log("ctxt switch,\t");
- log("inv switch,\t");
+ logadd("pg reclaim,\t");
+ logadd("pg faults,\t");
+ logadd("swaps,\t");
+ logadd("ctxt switch,\t");
+ logadd("inv switch,\t");
}
if (profileCounter[PROFrbytes].status)
- log("rbytes,\t");
+ logadd("rbytes,\t");
if (profileCounter[PROFwbytes].status)
- log("wbytes,\t");
+ logadd("wbytes,\t");
if (profileCounter[PROFaggr].status)
- log("count,\t totalticks,\t");
+ logadd("count,\t totalticks,\t");
if (profileCounter[PROFstmt].status)
- log("stmt,\t");
+ logadd("stmt,\t");
if (profileCounter[PROFtype].status)
- log("types,\t");
+ logadd("types,\t");
if (profileCounter[PROFuser].status)
- log("user,\t");
- log("# name\n");
- flushLog();
- MT_lock_unset(&mal_profileLock, "profileLock");
+ logadd("user,\t");
+ logadd("# name\n");
+ logsent();
}
void
offlineProfilerEvent(int idx, MalBlkPtr mb, MalStkPtr stk, int pc, int start)
{
+ char logbuffer[LOGLEN], *logbase;
+ int loglen;
/*static struct Mallinfo prevMalloc;*/
InstrPtr pci = getInstrPtr(mb, pc);
@@ -293,16 +310,13 @@ offlineProfilerEvent(int idx, MalBlkPtr
offlineProfilerHeader();
delayswitch--;
}
- MT_lock_set(&mal_profileLock, "profileLock");
if (eventstream == NULL) {
- MT_lock_unset(&mal_profileLock, "profileLock");
return ;
}
if (delayswitch == 0) {
delayswitch = -1;
}
if (!profileAll && mb->profiler[pc].trace == FALSE) {
- MT_lock_unset(&mal_profileLock, "profileLock");
return;
}
#ifdef HAVE_TIMES
@@ -316,15 +330,16 @@ offlineProfilerEvent(int idx, MalBlkPtr
#endif
/* make basic profile event tuple */
- log("[ ");
+ lognew();
+ logadd("[ ");
if (profileCounter[PROFevent].status) {
- log("%d,\t", eventcounter);
+ logadd("%d,\t", eventcounter);
}
if (profileCounter[PROFstart].status) {
if ( start) {
- log("\"start\",\t");
+ logadd("\"start\",\t");
} else {
- log("\"done\" ,\t");
+ logadd("\"done\" ,\t");
}
}
if (profileCounter[PROFtime].status) {
@@ -341,78 +356,78 @@ offlineProfilerEvent(int idx, MalBlkPtr
c[-5] = 0;
}
tbuf[10] = '"';
- log("%s", tbuf + 10);
- log(".%06d\",\t", (int)mb->profiler[pc].clock.tv_usec);
+ logadd("%s", tbuf + 10);
+ logadd(".%06d\",\t",
(int)mb->profiler[pc].clock.tv_usec);
} else
- log("%s,\t", "nil");
+ logadd("%s,\t", "nil");
}
if (profileCounter[PROFthread].status) {
- log(" %d,\t", THRgettid());
+ logadd(" %d,\t", THRgettid());
}
if (profileCounter[PROFflow].status) {
- log("%d,\t", memoryclaims);
- log(LLFMT",\t", memoryclaims?((lng)(MEMORY_THRESHOLD *
monet_memory)-memorypool)/1024/1024:0);
+ logadd("%d,\t", memoryclaims);
+ logadd(LLFMT",\t", memoryclaims?((lng)(MEMORY_THRESHOLD *
monet_memory)-memorypool)/1024/1024:0);
}
if (profileCounter[PROFfunc].status) {
if (getModuleId(getInstrPtr(mb,0)) &&
getFunctionId(getInstrPtr(mb,0))) {
- log("\"%s.%s\",\t", getModuleId(getInstrPtr(mb,0)),
getFunctionId(getInstrPtr(mb,0)));
+ logadd("\"%s.%s\",\t", getModuleId(getInstrPtr(mb,0)),
getFunctionId(getInstrPtr(mb,0)));
} else
- log("\"%s\",\t", operatorName(pci->token));
+ logadd("\"%s\",\t", operatorName(pci->token));
}
if (profileCounter[PROFpc].status) {
- log("%d,\t", getPC(mb, pci));
+ logadd("%d,\t", getPC(mb, pci));
}
if (profileCounter[PROFticks].status) {
- log(LLFMT ",\t", mb->profiler[pc].ticks);
+ logadd(LLFMT ",\t", mb->profiler[pc].ticks);
}
#ifdef HAVE_TIMES
if (profileCounter[PROFcpu].status && delayswitch < 0) {
- log("%ld,\t", (long) (newTms.tms_utime -
mb->profiler[pc].timer.tms_utime));
- log("%ld,\t", (long) (newTms.tms_cutime -
mb->profiler[pc].timer.tms_cutime));
- log("%ld,\t", (long) (newTms.tms_stime -
mb->profiler[pc].timer.tms_stime));
- log("%ld,\t", (long) (newTms.tms_cstime -
mb->profiler[pc].timer.tms_cstime));
+ logadd("%ld,\t", (long) (newTms.tms_utime -
mb->profiler[pc].timer.tms_utime));
+ logadd("%ld,\t", (long) (newTms.tms_cutime -
mb->profiler[pc].timer.tms_cutime));
+ logadd("%ld,\t", (long) (newTms.tms_stime -
mb->profiler[pc].timer.tms_stime));
+ logadd("%ld,\t", (long) (newTms.tms_cstime -
mb->profiler[pc].timer.tms_cstime));
}
#endif
if (profileCounter[PROFmemory].status && delayswitch < 0) {
- log(SZFMT ",\t", MT_getrss()/1024/1024);
+ logadd(SZFMT ",\t", MT_getrss()/1024/1024);
/*
#ifdef HAVE_SYS_RESOURCE_H
- log("%ld,\t", infoUsage.ru_maxrss);
+ logadd("%ld,\t", infoUsage.ru_maxrss);
#endif
- log(SZFMT ",\t", (size_t)(infoMalloc.arena - prevMalloc.arena));
- log(SZFMT ",\t", (size_t)(infoMalloc.ordblks -
prevMalloc.ordblks));
- log(SZFMT ",\t", (size_t)(infoMalloc.smblks -
prevMalloc.smblks));
- log(SZFMT ",\t", (size_t)(infoMalloc.hblkhd -
prevMalloc.hblkhd));
- log(SZFMT ",\t", (size_t)(infoMalloc.hblks - prevMalloc.hblks));
- log(SZFMT ",\t", (size_t)(infoMalloc.fsmblks -
prevMalloc.fsmblks));
- log(SZFMT ",\t", (size_t)(infoMalloc.uordblks -
prevMalloc.uordblks));
+ logadd(SZFMT ",\t", (size_t)(infoMalloc.arena -
prevMalloc.arena));
+ logadd(SZFMT ",\t", (size_t)(infoMalloc.ordblks -
prevMalloc.ordblks));
+ logadd(SZFMT ",\t", (size_t)(infoMalloc.smblks -
prevMalloc.smblks));
+ logadd(SZFMT ",\t", (size_t)(infoMalloc.hblkhd -
prevMalloc.hblkhd));
+ logadd(SZFMT ",\t", (size_t)(infoMalloc.hblks -
prevMalloc.hblks));
+ logadd(SZFMT ",\t", (size_t)(infoMalloc.fsmblks -
prevMalloc.fsmblks));
+ logadd(SZFMT ",\t", (size_t)(infoMalloc.uordblks -
prevMalloc.uordblks));
prevMalloc = infoMalloc;
*/
}
#ifdef HAVE_SYS_RESOURCE_H
if ((profileCounter[PROFreads].status ||
profileCounter[PROFwrites].status) && delayswitch < 0) {
- log("%ld,\t", infoUsage.ru_inblock - prevUsage.ru_inblock);
- log("%ld,\t", infoUsage.ru_oublock - prevUsage.ru_oublock);
+ logadd("%ld,\t", infoUsage.ru_inblock - prevUsage.ru_inblock);
+ logadd("%ld,\t", infoUsage.ru_oublock - prevUsage.ru_oublock);
prevUsage = infoUsage;
}
_______________________________________________
checkin-list mailing list
checkin-list@monetdb.org
http://mail.monetdb.org/mailman/listinfo/checkin-list
