Fix compression measurement

* fix conflict in compression which is GC_free should be invoked during GC is enabled
* add GC overhead profile
* add memory dump interval option

Signed-off-by: HyukWoo Park <hyukwoo.park@samsung.com>
This commit is contained in:
HyukWoo Park 2021-12-20 14:32:00 +09:00 committed by Patrick Kim
commit dfba6d6bd5
6 changed files with 47 additions and 37 deletions

View file

@ -260,6 +260,11 @@ public:
return *m_holder;
}
bool isInitialized() const
{
return m_holder != nullptr;
}
private:
void initHolderSpace(T* initialValue)
{

View file

@ -178,6 +178,8 @@ void CompressibleString::decompress()
ASSERT(m_isCompressed);
ASSERT(m_bufferData.length);
uint64_t currentTick = fastTickCount();
bool has8Bit = m_bufferData.has8BitContent;
if (has8Bit) {
decompressWorker<LChar>();
@ -185,6 +187,7 @@ void CompressibleString::decompress()
decompressWorker<char16_t>();
}
Global::addHeapProfileDecompTime(fastTickCount() - currentTick);
Global::increaseHeapProfileDecompCount();
}
@ -198,6 +201,8 @@ bool CompressibleString::compressWorker()
ASSERT(m_bufferData.length > 0);
ASSERT(!GC_is_disabled());
uint64_t currentTick = fastTickCount();
GC_disable();
size_t originByteLength = m_bufferData.length * sizeof(StringType);
@ -215,7 +220,7 @@ bool CompressibleString::compressWorker()
int compressedLength = LZ4::LZ4_compress_default(m_bufferData.bufferAs8Bit + srcIndex, (char*)tempBuffer, srcSize, boundLength);
if (!compressedLength) {
// compression fail
ESCARGOT_LOG_INFO("Compression Failed\n");
ESCARGOT_LOG_ERROR("Compression Failed\n");
delete[] tempBuffer;
GC_enable();
@ -232,11 +237,11 @@ bool CompressibleString::compressWorker()
m_vmInstance->compressibleStringsUncomressedBufferSize() -= decomressedBufferSize();
GC_enable();
// immediately free the original string after compression when there is no reference on stack
deallocateStringDataBuffer(const_cast<void*>(m_bufferData.buffer), m_bufferData.length * (m_bufferData.has8BitContent ? 1 : 2));
GC_enable();
m_bufferData.buffer = nullptr;
m_isCompressed = true;
@ -248,6 +253,7 @@ bool CompressibleString::compressWorker()
ESCARGOT_LOG_INFO("CompressibleString::compressWorker %fKB -> %fKB\n", originByteLength / 1024.f, compressedSize / 1024.f);
*/
Global::addHeapProfileCompTime(fastTickCount() - currentTick);
Global::increaseHeapProfileCompCount();
return true;
}

View file

@ -93,7 +93,7 @@ void Global::HeapProfile::printResult()
{
ESCARGOT_LOG_INFO("=== HeapProfile Result ===\n");
ESCARGOT_LOG_INFO("GC_Count: %zu\nComp_Count: %zu\nDecomp_Count: %zu\n", gcCount, compCount, decompCount);
ESCARGOT_LOG_INFO("GC_Time: %" PRIu64 "\nComp_Time: %" PRIu64 "\nDecomp_Time:%" PRIu64 "\nComp_Stack_Search_Time: %" PRIu64 "\n", gcTime, compTime, decompTime, compStackSearchTime);
ESCARGOT_LOG_INFO("GC_Time: %" PRIu64 "\nComp_Time: %" PRIu64 "\nDecomp_Time:%" PRIu64 "\n", gcTime, compTime, decompTime);
}
Global::HeapProfile* Global::heapProfile()

View file

@ -74,20 +74,20 @@ public:
: gcCount(0)
, compCount(0)
, decompCount(0)
, lastGCMarkTime(0)
, gcTime(0)
, compTime(0)
, decompTime(0)
, compStackSearchTime(0)
{
}
size_t gcCount;
size_t compCount;
size_t decompCount;
uint64_t lastGCMarkTime;
uint64_t gcTime;
uint64_t compTime;
uint64_t decompTime;
uint64_t compStackSearchTime;
void printResult();
};
@ -99,10 +99,19 @@ public:
static void increaseHeapProfileGCCount() { g_heapProfile->gcCount++; }
static void increaseHeapProfileCompCount() { g_heapProfile->compCount++; }
static void increaseHeapProfileDecompCount() { g_heapProfile->decompCount++; }
static void addHeapProfileGCTime(uint64_t time) { g_heapProfile->gcTime += time; }
static void markHeapProfileGCMarkStartTime(uint64_t time)
{
ASSERT(g_heapProfile->lastGCMarkTime == 0);
g_heapProfile->lastGCMarkTime = time;
}
static void markHeapProfileGCReclaimEndTime(uint64_t time)
{
ASSERT(time >= g_heapProfile->lastGCMarkTime);
g_heapProfile->gcTime += (time - g_heapProfile->lastGCMarkTime);
g_heapProfile->lastGCMarkTime = 0;
}
static void addHeapProfileCompTime(uint64_t time) { g_heapProfile->compTime += time; }
static void addHeapProfileDecompTime(uint64_t time) { g_heapProfile->decompTime += time; }
static void addHeapProfileCompStackSearchTime(uint64_t time) { g_heapProfile->compStackSearchTime += time; }
};
} // namespace Escargot

View file

@ -207,6 +207,7 @@ void vmMarkStartCallback(void* data)
{
VMInstance* self = (VMInstance*)data;
Global::increaseHeapProfileGCCount();
Global::markHeapProfileGCMarkStartTime(fastTickCount());
#ifdef ESCARGOT_DEBUGGER
if (!self->m_debuggerEnabled) {
@ -267,6 +268,8 @@ void vmReclaimEndCallback(void* data)
}
}
Global::markHeapProfileGCReclaimEndTime(fastTickCount());
// disabled in default due to massive logs
//ESCARGOT_LOG_INFO("Heap After GC: %f MB\n", GC_get_heap_size() / 1024.f / 1024.f);

View file

@ -36,7 +36,6 @@
#include "api/EscargotPublic.h"
#include "malloc.h"
#include "gc.h"
#include <inttypes.h>
@ -926,7 +925,8 @@ PersistentRefHolder<ContextRef> createEscargotContext(VMInstanceRef* instance, b
return context;
}
uint64_t g_lastTick = 0;
static uint64_t g_lastTick = 0;
static uint64_t g_dumpInterval = 1000; // default interval is set to 1 second
static uint64_t fastTickCount()
{
@ -941,8 +941,8 @@ static uint64_t fastTickCount()
static void printGCMemory(void* data)
{
uint64_t currentTick = fastTickCount() ;
if (currentTick - g_lastTick >= 1000) {
uint64_t currentTick = fastTickCount();
if (currentTick - g_lastTick >= g_dumpInterval) {
g_lastTick = currentTick;
fprintf(static_cast<FILE*>(data), "Tick %" PRIu64 ": Heap usage[%f MB]\n", fastTickCount(), Memory::heapSize() / 1024.f / 1024.f);
}
@ -968,7 +968,7 @@ int main(int argc, char* argv[])
Memory::setGCFrequency(24);
PersistentRefHolder<VMInstanceRef> instance = VMInstanceRef::create();
PersistentRefHolder<ContextRef> context = createEscargotContext(instance.get());
PersistentRefHolder<ContextRef> context;
if (getenv("GC_FREE_SPACE_DIVISOR") && strlen(getenv("GC_FREE_SPACE_DIVISOR"))) {
int d = atoi(getenv("GC_FREE_SPACE_DIVISOR"));
@ -999,23 +999,6 @@ int main(int argc, char* argv[])
fileName = argv[i] + sizeof("--filename-as=") - 1;
continue;
}
if (strcmp(argv[i], "--start-debug-server") == 0) {
context->initDebugger(nullptr);
continue;
}
if (strcmp(argv[i], "--debugger-wait-source") == 0) {
StringRef* sourceName;
while (true) {
StringRef* clientSourceRef = context->getClientSource(&sourceName);
if (!clientSourceRef) {
break;
}
if (!evalScript(context, clientSourceRef, sourceName, false, false))
return 3;
runShell = false;
}
continue;
}
if (strcmp(argv[i], "--dump-memory-usage") == 0) {
memoryUsageLog = fopen("memoryUsage.log", "w");
g_lastTick = fastTickCount();
@ -1024,15 +1007,12 @@ int main(int argc, char* argv[])
Memory::addGCEventListener(Memory::RECLAIM_END, printGCMemory, memoryUsageLog);
continue;
}
} else { // `-option` case
if (strcmp(argv[i], "-e") == 0) {
runShell = false;
i++;
StringRef* src = StringRef::createFromUTF8(argv[i], strlen(argv[i]));
if (!evalScript(context, src, StringRef::createFromASCII("shell input"), false, false))
return 3;
if (strstr(argv[i], "--dump-memory-interval=") == argv[i]) {
std::string interval = argv[i] + sizeof("--dump-memory-interval=") - 1;
g_dumpInterval = atoi(interval.c_str());
continue;
}
} else { // `-option` case
if (strcmp(argv[i], "-f") == 0) {
continue;
}
@ -1042,6 +1022,13 @@ int main(int argc, char* argv[])
continue;
}
if (!context.isInitialized()) {
// postpone allocation of Context to here
// initialization of Context triggers several GC
// so, register of gc event with `--dump-memory-usage` should be done before Context creation
context.reset(createEscargotContext(instance.get()));
}
FILE* fp = fopen(argv[i], "r");
if (fp) {
fclose(fp);