From 80c8299b9e52e5e27f0f4c688a267d5f99f270b0 Mon Sep 17 00:00:00 2001 From: Rainer Schuetze Date: Sun, 1 Feb 2015 15:51:54 +0100 Subject: [PATCH 1/4] allow GC API profiling with --DRT-gcopt=profile:2 --- src/gc/config.d | 2 +- src/gc/gc.d | 238 ++++++++++++++++++++++++++++++++++++------------ 2 files changed, 183 insertions(+), 57 deletions(-) diff --git a/src/gc/config.d b/src/gc/config.d index fc83f18b6f..0404ec5901 100644 --- a/src/gc/config.d +++ b/src/gc/config.d @@ -23,7 +23,7 @@ extern extern(C) __gshared string[] rt_options; struct Config { bool disable; // start disabled - bool profile; // enable profiling with summary when terminating program + byte profile; // enable profiling with summary when terminating program bool precise; // enable precise scanning bool concurrent; // enable concurrent collection diff --git a/src/gc/gc.d b/src/gc/gc.d index 29481a5a90..d67821de9e 100644 --- a/src/gc/gc.d +++ b/src/gc/gc.d @@ -26,6 +26,7 @@ module gc.gc; //debug = PTRCHECK; // more pointer checking //debug = PTRCHECK2; // thorough but slow pointer checking //debug = INVARIANT; // enable invariants +//debug = PROFILE_API; // profile API calls for config.profile > 1 /*************** Configuration *********************/ @@ -53,12 +54,67 @@ private alias BlkInfo = core.memory.GC.BlkInfo; version (GNU) import gcc.builtins; -debug (PRINTF_TO_FILE) import core.stdc.stdio : fprintf, fopen, fflush, FILE; -else import core.stdc.stdio : printf; // needed to output profiling results +debug (PRINTF_TO_FILE) import core.stdc.stdio : sprintf, fprintf, fopen, fflush, FILE; +else import core.stdc.stdio : sprintf, printf; // needed to output profiling results import core.time; alias currTime = MonoTime.currTime; +// high performance time measurements without additional translations +alias MonoTimeNative = long; +alias DurationNative = long; + +version(OSX) extern(C) ulong mach_absolute_time() nothrow @nogc; + +@property MonoTimeNative currTimeNative() nothrow +{ + version(Windows) + { + import core.sys.windows.windows; + long ticks; + if(QueryPerformanceCounter(&ticks) == 0) + { + // This probably cannot happen on Windows 95 or later + assert(0, "Call to QueryPerformanceCounter failed."); + } + return ticks; + } + else version(OSX) + { + return mach_absolute_time(); + } + else version(Posix) + { + import core.sys.posix.time; + import core.sys.posix.sys.time; + + timespec ts; + if(clock_gettime(CLOCK_MONOTONIC, &ts) != 0) + assert(0, "Call to clock_gettime failed."); + + return ts.tv_sec * 1_000_000_000L + ts.tv_nsec; + } + else + static assert(false, "no native timer function"); +} + +MonoTime toMonoTime(MonoTimeNative tm) +{ + version(Windows) + return MonoTime(tm); + else version(OSX) + return MonoTime(tm); + else version(Posix) + return MonoTime(convClockFreq(tm, 1_000_000_000L, MonoTime.ticksPerSecond)); + else + static assert(false, "no native timer function"); +} + +Duration toDuration(DurationNative dur) +{ + return toMonoTime(dur) - MonoTime(0); +} + debug(PRINTF_TO_FILE) { private __gshared MonoTime gcStartTick; @@ -110,6 +166,18 @@ __gshared Duration maxPauseTime; __gshared size_t numCollections; __gshared size_t maxPoolMemory; +__gshared long numMallocs; +__gshared long numFrees; +__gshared long numReallocs; +__gshared long numExtends; +__gshared long numOthers; +__gshared DurationNative mallocTime; +__gshared DurationNative freeTime; +__gshared DurationNative reallocTime; +__gshared DurationNative extendTime; +__gshared DurationNative otherTime; +__gshared DurationNative lockTime; + private { extern (C) @@ -331,6 +399,42 @@ struct GC } + private void runLocked(alias time, alias count)(scope void delegate() nothrow dg) + { + debug(PROFILE_API) + { + MonoTimeNative tm = void; + if (GC.config.profile > 1) + tm = currTimeNative; + } + + gcLock.lock(); + + debug(PROFILE_API) + { + if (GC.config.profile > 1) + { + count++; + MonoTimeNative now = currTimeNative; + lockTime += now - tm; + tm = now; + } + } + + dg(); + + debug(PROFILE_API) + { + if (GC.config.profile > 1) + { + MonoTimeNative now = currTimeNative; + time += now - tm; + } + } + + gcLock.unlock(); + } + /** * */ @@ -356,9 +460,10 @@ struct GC return oldb; } - gcLock.lock(); - auto rc = go(); - gcLock.unlock(); + uint rc = void; + runLocked!(otherTime, numOthers)({ + rc = go(); + }); return rc; } @@ -389,9 +494,10 @@ struct GC return oldb; } - gcLock.lock(); - auto rc = go(); - gcLock.unlock(); + uint rc = void; + runLocked!(otherTime, numOthers)({ + rc = go(); + }); return rc; } @@ -422,13 +528,13 @@ struct GC return oldb; } - gcLock.lock(); - auto rc = go(); - gcLock.unlock(); + uint rc = void; + runLocked!(otherTime, numOthers)({ + rc = go(); + }); return rc; } - /** * */ @@ -448,11 +554,9 @@ struct GC // Since a finalizer could launch a new thread, we always need to lock // when collecting. The safest way to do this is to simply always lock // when allocating. - { - gcLock.lock(); + runLocked!(mallocTime, numMallocs)({ p = mallocNoSync(size, bits, *alloc_size, ti); - gcLock.unlock(); - } + }); if (!(bits & BlkAttr.NO_SCAN)) { @@ -513,9 +617,9 @@ struct GC // when collecting. The safest way to do this is to simply always lock // when allocating. { - gcLock.lock(); - p = mallocNoSync(size, bits, *alloc_size, ti); - gcLock.unlock(); + runLocked!(mallocTime, numMallocs)({ + p = mallocNoSync(size, bits, *alloc_size, ti); + }); } memset(p, 0, size); @@ -539,11 +643,9 @@ struct GC // Since a finalizer could launch a new thread, we always need to lock // when collecting. The safest way to do this is to simply always lock // when allocating. - { - gcLock.lock(); + runLocked!(reallocTime, numReallocs)({ p = reallocNoSync(p, size, bits, *alloc_size, ti); - gcLock.unlock(); - } + }); if (p !is oldp && !(bits & BlkAttr.NO_SCAN)) { @@ -709,9 +811,10 @@ struct GC */ size_t extend(void* p, size_t minsize, size_t maxsize, const TypeInfo ti = null) nothrow { - gcLock.lock(); - auto rc = extendNoSync(p, minsize, maxsize, ti); - gcLock.unlock(); + size_t rc = void; + runLocked!(extendTime, numExtends)({ + rc = extendNoSync(p, minsize, maxsize, ti); + }); return rc; } @@ -818,7 +921,9 @@ struct GC } gcLock.lock(); - freeNoSync(p); + runLocked!(freeTime, numFrees)({ + freeNoSync(p); + }); gcLock.unlock(); } @@ -900,9 +1005,10 @@ struct GC return null; } - gcLock.lock(); - auto rc = addrOfNoSync(p); - gcLock.unlock(); + void* rc = void; + runLocked!(otherTime, numOthers)({ + rc = addrOfNoSync(p); + }); return rc; } @@ -935,9 +1041,10 @@ struct GC return 0; } - gcLock.lock(); - auto rc = sizeOfNoSync(p); - gcLock.unlock(); + size_t rc = void; + runLocked!(otherTime, numOthers)({ + rc = sizeOfNoSync(p); + }); return rc; } @@ -989,9 +1096,10 @@ struct GC return i; } - gcLock.lock(); - auto rc = queryNoSync(p); - gcLock.unlock(); + BlkInfo rc = void; + runLocked!(otherTime, numOthers)({ + rc = queryNoSync(p); + }); return rc; } @@ -1029,9 +1137,9 @@ struct GC return; } - gcLock.lock(); - checkNoSync(p); - gcLock.unlock(); + runLocked!(otherTime, numOthers)({ + checkNoSync(p); + }); } @@ -1086,9 +1194,9 @@ struct GC return; } - gcLock.lock(); - gcx.addRoot(p); - gcLock.unlock(); + runLocked!(otherTime, numOthers)({ + gcx.addRoot(p); + }); } @@ -1102,9 +1210,9 @@ struct GC return; } - gcLock.lock(); - gcx.removeRoot(p); - gcLock.unlock(); + runLocked!(otherTime, numOthers)({ + gcx.removeRoot(p); + }); } @@ -1137,9 +1245,9 @@ struct GC //debug(PRINTF) printf("+GC.addRange(p = %p, sz = 0x%zx), p + sz = %p\n", p, sz, p + sz); - gcLock.lock(); - gcx.addRange(p, p + sz, ti); - gcLock.unlock(); + runLocked!(otherTime, numOthers)({ + gcx.addRange(p, p + sz, ti); + }); //debug(PRINTF) printf("-GC.addRange()\n"); } @@ -1155,9 +1263,9 @@ struct GC return; } - gcLock.lock(); - gcx.removeRange(p); - gcLock.unlock(); + runLocked!(otherTime, numOthers)({ + gcx.removeRange(p); + }); } /** @@ -1165,9 +1273,9 @@ struct GC */ void runFinalizers(in void[] segment) nothrow { - gcLock.lock(); - gcx.runFinalizers(segment); - gcLock.unlock(); + runLocked!(otherTime, numOthers)({ + gcx.runFinalizers(segment); + }); } private auto rangeIterImpl(scope int delegate(ref Range) nothrow dg) nothrow @@ -1424,9 +1532,27 @@ struct Gcx long gcTime = (recoverTime + sweepTime + markTime + prepTime).total!("msecs"); printf("\tGrand total GC time: %lld milliseconds\n", gcTime); long pauseTime = (markTime + prepTime).total!("msecs"); - printf("GC summary:%5lld MB,%5lld GC%5lld ms, Pauses%5lld ms <%5lld ms\n", + + char[30] apitxt; + apitxt[0] = 0; + debug(PROFILE_API) if (GC.config.profile > 1) + { + printf("\n"); + printf("\tmalloc: %llu calls, %lld ms\n", cast(ulong)numMallocs, mallocTime.toDuration.total!"msecs"); + printf("\trealloc: %llu calls, %lld ms\n", cast(ulong)numReallocs, reallocTime.toDuration.total!"msecs"); + printf("\tfree: %llu calls, %lld ms\n", cast(ulong)numFrees, freeTime.toDuration.total!"msecs"); + printf("\textend: %llu calls, %lld ms\n", cast(ulong)numExtends, extendTime.toDuration.total!"msecs"); + printf("\tother: %llu calls, %lld ms\n", cast(ulong)numOthers, otherTime.toDuration.total!"msecs"); + printf("\tlock time: %lld ms\n", lockTime.toDuration.total!"msecs"); + + DurationNative apiTime = mallocTime + reallocTime + freeTime + extendTime + otherTime + lockTime; + printf("\tGC API: %lld ms\n", apiTime.toDuration.total!"msecs"); + sprintf(apitxt.ptr, " API%5ld ms", apiTime.toDuration.total!"msecs"); + } + + printf("GC summary:%5lld MB,%5lld GC%5lld ms, Pauses%5lld ms <%5lld ms%s\n", cast(long) maxPoolMemory >> 20, cast(ulong)numCollections, gcTime, - pauseTime, maxPause); + pauseTime, maxPause, apitxt.ptr); } debug(INVARIANT) initialized = false; From 91a7b7479e427effa95b535c2f31040e99f7f3ff Mon Sep 17 00:00:00 2001 From: Rainer Schuetze Date: Sun, 15 Feb 2015 09:27:05 +0100 Subject: [PATCH 2/4] fix option parser for byte options fix parsing "help" print floats with %g instead of %f for a shorter display --- src/gc/config.d | 43 ++++++++++++++++++++++++------------------- 1 file changed, 24 insertions(+), 19 deletions(-) diff --git a/src/gc/config.d b/src/gc/config.d index 0404ec5901..95c6fb724f 100644 --- a/src/gc/config.d +++ b/src/gc/config.d @@ -23,7 +23,7 @@ extern extern(C) __gshared string[] rt_options; struct Config { bool disable; // start disabled - byte profile; // enable profiling with summary when terminating program + ubyte profile; // enable profiling with summary when terminating program bool precise; // enable precise scanning bool concurrent; // enable concurrent collection @@ -60,7 +60,7 @@ struct Config string s = "GC options are specified as white space separated assignments: disable:0|1 - start disabled (%d) - profile:0|1 - enable profiling with summary when terminating program (%d) + profile:0|1|2 - enable profiling with summary when terminating program (%d) precise:0|1 - enable precise scanning (not implemented yet) concurrent:0|1 - enable concurrent collection (not implemented yet) @@ -207,28 +207,33 @@ unittest scope (exit) inUnittest = false; Config conf; - assert(!conf.parseOptions("profile")); - assert(!conf.parseOptions("profile:")); - assert(!conf.parseOptions("profile:5")); - assert(conf.parseOptions("profile:y") && conf.profile); - assert(conf.parseOptions("profile:n") && !conf.profile); - assert(conf.parseOptions("profile:Y") && conf.profile); - assert(conf.parseOptions("profile:N") && !conf.profile); - assert(conf.parseOptions("profile:1") && conf.profile); - assert(conf.parseOptions("profile:0") && !conf.profile); - - assert(conf.parseOptions("profile=y") && conf.profile); - assert(conf.parseOptions("profile=n") && !conf.profile); - - assert(conf.parseOptions("profile:1 minPoolSize:16")); - assert(conf.profile); + assert(!conf.parseOptions("disable")); + assert(!conf.parseOptions("disable:")); + assert(!conf.parseOptions("disable:5")); + assert(conf.parseOptions("disable:y") && conf.disable); + assert(conf.parseOptions("disable:n") && !conf.disable); + assert(conf.parseOptions("disable:Y") && conf.disable); + assert(conf.parseOptions("disable:N") && !conf.disable); + assert(conf.parseOptions("disable:1") && conf.disable); + assert(conf.parseOptions("disable:0") && !conf.disable); + + assert(conf.parseOptions("disable=y") && conf.disable); + assert(conf.parseOptions("disable=n") && !conf.disable); + + assert(conf.parseOptions("profile=0") && conf.profile == 0); + assert(conf.parseOptions("profile=1") && conf.profile == 1); + assert(conf.parseOptions("profile=2") && conf.profile == 2); + assert(!conf.parseOptions("profile=256")); + + assert(conf.parseOptions("disable:1 minPoolSize:16")); + assert(conf.disable); assert(conf.minPoolSize == 16); assert(conf.parseOptions("heapSizeFactor:3.1")); assert(conf.heapSizeFactor == 3.1f); - assert(conf.parseOptions("heapSizeFactor:3.1234567890 profile:0")); + assert(conf.parseOptions("heapSizeFactor:3.1234567890 disable:0")); assert(conf.heapSizeFactor > 3.123f); - assert(!conf.profile); + assert(!conf.disable); assert(!conf.parseOptions("heapSizeFactor:3.0.2.5")); assert(conf.parseOptions("heapSizeFactor:2")); assert(conf.heapSizeFactor == 2.0f); From 1f32e80de5420d9ea7f278ba797c49c790369035 Mon Sep 17 00:00:00 2001 From: Rainer Schuetze Date: Tue, 17 Feb 2015 21:21:31 +0100 Subject: [PATCH 3/4] replace runLocked with doLock/doUnlock mixin --- src/gc/gc.d | 158 +++++++++++++++++++++++++--------------------------- 1 file changed, 75 insertions(+), 83 deletions(-) diff --git a/src/gc/gc.d b/src/gc/gc.d index d67821de9e..4cc3a9ff3f 100644 --- a/src/gc/gc.d +++ b/src/gc/gc.d @@ -399,40 +399,39 @@ struct GC } - private void runLocked(alias time, alias count)(scope void delegate() nothrow dg) + mixin template doLock() { debug(PROFILE_API) { - MonoTimeNative tm = void; - if (GC.config.profile > 1) - tm = currTimeNative; + MonoTimeNative tm = (GC.config.profile > 1 ? currTimeNative : 0); } - gcLock.lock(); + bool locked = (gcLock.lock(), true); debug(PROFILE_API) { - if (GC.config.profile > 1) - { - count++; - MonoTimeNative now = currTimeNative; - lockTime += now - tm; - tm = now; - } + MonoTimeNative tm2 = (GC.config.profile > 1 ? currTimeNative : 0); } + } - dg(); - + mixin template doUnlock(alias time, alias count) + { debug(PROFILE_API) { - if (GC.config.profile > 1) - { - MonoTimeNative now = currTimeNative; - time += now - tm; - } + bool unlocked = () { + if (GC.config.profile > 1) + { + count++; + MonoTimeNative now = currTimeNative; + lockTime += tm2 - tm; + time += now - tm2; + } + gcLock.unlock(); + return true; + }(); } - - gcLock.unlock(); + else + bool unlocked = (gcLock.unlock(), true); } /** @@ -460,10 +459,9 @@ struct GC return oldb; } - uint rc = void; - runLocked!(otherTime, numOthers)({ - rc = go(); - }); + mixin doLock!(); + uint rc = go(); + mixin doUnlock!(otherTime, numOthers); return rc; } @@ -494,10 +492,9 @@ struct GC return oldb; } - uint rc = void; - runLocked!(otherTime, numOthers)({ - rc = go(); - }); + mixin doLock!(); + uint rc = go(); + mixin doUnlock!(otherTime, numOthers); return rc; } @@ -528,10 +525,9 @@ struct GC return oldb; } - uint rc = void; - runLocked!(otherTime, numOthers)({ - rc = go(); - }); + mixin doLock!(); + uint rc = go(); + mixin doUnlock!(otherTime, numOthers); return rc; } @@ -554,9 +550,9 @@ struct GC // Since a finalizer could launch a new thread, we always need to lock // when collecting. The safest way to do this is to simply always lock // when allocating. - runLocked!(mallocTime, numMallocs)({ - p = mallocNoSync(size, bits, *alloc_size, ti); - }); + mixin doLock!(); + p = mallocNoSync(size, bits, *alloc_size, ti); + mixin doUnlock!(mallocTime, numMallocs); if (!(bits & BlkAttr.NO_SCAN)) { @@ -616,11 +612,9 @@ struct GC // Since a finalizer could launch a new thread, we always need to lock // when collecting. The safest way to do this is to simply always lock // when allocating. - { - runLocked!(mallocTime, numMallocs)({ - p = mallocNoSync(size, bits, *alloc_size, ti); - }); - } + mixin doLock!(); + p = mallocNoSync(size, bits, *alloc_size, ti); + mixin doUnlock!(mallocTime, numMallocs); memset(p, 0, size); if (!(bits & BlkAttr.NO_SCAN)) @@ -643,9 +637,9 @@ struct GC // Since a finalizer could launch a new thread, we always need to lock // when collecting. The safest way to do this is to simply always lock // when allocating. - runLocked!(reallocTime, numReallocs)({ - p = reallocNoSync(p, size, bits, *alloc_size, ti); - }); + mixin doLock!(); + p = reallocNoSync(p, size, bits, *alloc_size, ti); + mixin doUnlock!(mallocTime, numMallocs); if (p !is oldp && !(bits & BlkAttr.NO_SCAN)) { @@ -811,10 +805,10 @@ struct GC */ size_t extend(void* p, size_t minsize, size_t maxsize, const TypeInfo ti = null) nothrow { - size_t rc = void; - runLocked!(extendTime, numExtends)({ - rc = extendNoSync(p, minsize, maxsize, ti); - }); + mixin doLock!(); + size_t rc = extendNoSync(p, minsize, maxsize, ti); + mixin doUnlock!(extendTime, numExtends); + return rc; } @@ -920,11 +914,9 @@ struct GC return; } - gcLock.lock(); - runLocked!(freeTime, numFrees)({ - freeNoSync(p); - }); - gcLock.unlock(); + mixin doLock!(); + freeNoSync(p); + mixin doUnlock!(freeTime, numFrees); } @@ -1005,10 +997,10 @@ struct GC return null; } - void* rc = void; - runLocked!(otherTime, numOthers)({ - rc = addrOfNoSync(p); - }); + mixin doLock!(); + void* rc = addrOfNoSync(p); + mixin doUnlock!(otherTime, numOthers); + return rc; } @@ -1041,10 +1033,10 @@ struct GC return 0; } - size_t rc = void; - runLocked!(otherTime, numOthers)({ - rc = sizeOfNoSync(p); - }); + mixin doLock!(); + size_t rc = sizeOfNoSync(p); + mixin doUnlock!(otherTime, numOthers); + return rc; } @@ -1096,10 +1088,10 @@ struct GC return i; } - BlkInfo rc = void; - runLocked!(otherTime, numOthers)({ - rc = queryNoSync(p); - }); + mixin doLock!(); + BlkInfo rc = queryNoSync(p); + mixin doUnlock!(otherTime, numOthers); + return rc; } @@ -1137,9 +1129,9 @@ struct GC return; } - runLocked!(otherTime, numOthers)({ - checkNoSync(p); - }); + mixin doLock!(); + checkNoSync(p); + mixin doUnlock!(otherTime, numOthers); } @@ -1194,9 +1186,9 @@ struct GC return; } - runLocked!(otherTime, numOthers)({ - gcx.addRoot(p); - }); + mixin doLock!(); + gcx.addRoot(p); + mixin doUnlock!(otherTime, numOthers); } @@ -1210,9 +1202,9 @@ struct GC return; } - runLocked!(otherTime, numOthers)({ - gcx.removeRoot(p); - }); + mixin doLock!(); + gcx.removeRoot(p); + mixin doUnlock!(otherTime, numOthers); } @@ -1245,9 +1237,9 @@ struct GC //debug(PRINTF) printf("+GC.addRange(p = %p, sz = 0x%zx), p + sz = %p\n", p, sz, p + sz); - runLocked!(otherTime, numOthers)({ - gcx.addRange(p, p + sz, ti); - }); + mixin doLock!(); + gcx.addRange(p, p + sz, ti); + mixin doUnlock!(otherTime, numOthers); //debug(PRINTF) printf("-GC.addRange()\n"); } @@ -1263,9 +1255,9 @@ struct GC return; } - runLocked!(otherTime, numOthers)({ - gcx.removeRange(p); - }); + mixin doLock!(); + gcx.removeRange(p); + mixin doUnlock!(otherTime, numOthers); } /** @@ -1273,9 +1265,9 @@ struct GC */ void runFinalizers(in void[] segment) nothrow { - runLocked!(otherTime, numOthers)({ - gcx.runFinalizers(segment); - }); + mixin doLock!(); + gcx.runFinalizers(segment); + mixin doUnlock!(otherTime, numOthers); } private auto rangeIterImpl(scope int delegate(ref Range) nothrow dg) nothrow From a0ea10074922ad589b25ae2641f19967e3a36687 Mon Sep 17 00:00:00 2001 From: Rainer Schuetze Date: Wed, 18 Feb 2015 22:28:16 +0100 Subject: [PATCH 4/4] replace MonoTimeNative with Monotime.currTime.ticks --- src/gc/gc.d | 99 ++++++++++++++--------------------------------------- 1 file changed, 25 insertions(+), 74 deletions(-) diff --git a/src/gc/gc.d b/src/gc/gc.d index 4cc3a9ff3f..232b52d5b3 100644 --- a/src/gc/gc.d +++ b/src/gc/gc.d @@ -59,61 +59,7 @@ else import core.stdc.stdio : sprintf, printf; // needed to ou import core.time; alias currTime = MonoTime.currTime; - -// high performance time measurements without additional translations -alias MonoTimeNative = long; -alias DurationNative = long; - -version(OSX) extern(C) ulong mach_absolute_time() nothrow @nogc; - -@property MonoTimeNative currTimeNative() nothrow -{ - version(Windows) - { - import core.sys.windows.windows; - long ticks; - if(QueryPerformanceCounter(&ticks) == 0) - { - // This probably cannot happen on Windows 95 or later - assert(0, "Call to QueryPerformanceCounter failed."); - } - return ticks; - } - else version(OSX) - { - return mach_absolute_time(); - } - else version(Posix) - { - import core.sys.posix.time; - import core.sys.posix.sys.time; - - timespec ts; - if(clock_gettime(CLOCK_MONOTONIC, &ts) != 0) - assert(0, "Call to clock_gettime failed."); - - return ts.tv_sec * 1_000_000_000L + ts.tv_nsec; - } - else - static assert(false, "no native timer function"); -} - -MonoTime toMonoTime(MonoTimeNative tm) -{ - version(Windows) - return MonoTime(tm); - else version(OSX) - return MonoTime(tm); - else version(Posix) - return MonoTime(convClockFreq(tm, 1_000_000_000L, MonoTime.ticksPerSecond)); - else - static assert(false, "no native timer function"); -} - -Duration toDuration(DurationNative dur) -{ - return toMonoTime(dur) - MonoTime(0); -} +long currTicks() { return MonoTime.ticksPerSecond ? MonoTime.currTime.ticks : 0; } debug(PRINTF_TO_FILE) { @@ -171,12 +117,12 @@ __gshared long numFrees; __gshared long numReallocs; __gshared long numExtends; __gshared long numOthers; -__gshared DurationNative mallocTime; -__gshared DurationNative freeTime; -__gshared DurationNative reallocTime; -__gshared DurationNative extendTime; -__gshared DurationNative otherTime; -__gshared DurationNative lockTime; +__gshared long mallocTime; // using ticks instead of MonoTime for better performance +__gshared long freeTime; +__gshared long reallocTime; +__gshared long extendTime; +__gshared long otherTime; +__gshared long lockTime; private { @@ -403,14 +349,14 @@ struct GC { debug(PROFILE_API) { - MonoTimeNative tm = (GC.config.profile > 1 ? currTimeNative : 0); + long tm = (GC.config.profile > 1 ? currTicks : 0); } bool locked = (gcLock.lock(), true); debug(PROFILE_API) { - MonoTimeNative tm2 = (GC.config.profile > 1 ? currTimeNative : 0); + long tm2 = (GC.config.profile > 1 ? currTicks : 0); } } @@ -422,7 +368,7 @@ struct GC if (GC.config.profile > 1) { count++; - MonoTimeNative now = currTimeNative; + long now = currTicks; lockTime += tm2 - tm; time += now - tm2; } @@ -1529,17 +1475,22 @@ struct Gcx apitxt[0] = 0; debug(PROFILE_API) if (GC.config.profile > 1) { + static Duration toDuration(long dur) + { + return MonoTime(dur) - MonoTime(0); + } + printf("\n"); - printf("\tmalloc: %llu calls, %lld ms\n", cast(ulong)numMallocs, mallocTime.toDuration.total!"msecs"); - printf("\trealloc: %llu calls, %lld ms\n", cast(ulong)numReallocs, reallocTime.toDuration.total!"msecs"); - printf("\tfree: %llu calls, %lld ms\n", cast(ulong)numFrees, freeTime.toDuration.total!"msecs"); - printf("\textend: %llu calls, %lld ms\n", cast(ulong)numExtends, extendTime.toDuration.total!"msecs"); - printf("\tother: %llu calls, %lld ms\n", cast(ulong)numOthers, otherTime.toDuration.total!"msecs"); - printf("\tlock time: %lld ms\n", lockTime.toDuration.total!"msecs"); - - DurationNative apiTime = mallocTime + reallocTime + freeTime + extendTime + otherTime + lockTime; - printf("\tGC API: %lld ms\n", apiTime.toDuration.total!"msecs"); - sprintf(apitxt.ptr, " API%5ld ms", apiTime.toDuration.total!"msecs"); + printf("\tmalloc: %llu calls, %lld ms\n", cast(ulong)numMallocs, toDuration(mallocTime).total!"msecs"); + printf("\trealloc: %llu calls, %lld ms\n", cast(ulong)numReallocs, toDuration(reallocTime).total!"msecs"); + printf("\tfree: %llu calls, %lld ms\n", cast(ulong)numFrees, toDuration(freeTime).total!"msecs"); + printf("\textend: %llu calls, %lld ms\n", cast(ulong)numExtends, toDuration(extendTime).total!"msecs"); + printf("\tother: %llu calls, %lld ms\n", cast(ulong)numOthers, toDuration(otherTime).total!"msecs"); + printf("\tlock time: %lld ms\n", toDuration(lockTime).total!"msecs"); + + long apiTime = mallocTime + reallocTime + freeTime + extendTime + otherTime + lockTime; + printf("\tGC API: %lld ms\n", toDuration(apiTime).total!"msecs"); + sprintf(apitxt.ptr, " API%5ld ms", toDuration(apiTime).total!"msecs"); } printf("GC summary:%5lld MB,%5lld GC%5lld ms, Pauses%5lld ms <%5lld ms%s\n",