V8垃圾收集器回调，用于测量GC活动 [英] V8 garbage collector callbacks for measuring GC activity
本文介绍了V8垃圾收集器回调，用于测量GC活动的处理方法，对大家解决问题具有一定的参考价值，需要的朋友们下面随着小编来一起学习吧！
问题描述
我有一个关于V8 6.7.240 GC行为和AddGCPrologueCallback/AddGCEpilogueCallback回调的小问题.
问题背后的一个小故事:我们使用V8引擎启动自定义JS代码，并且为了限制执行时间，我们有一个watchdog(带有isolate->TerminateExecution()调用的单独线程)来监视代码并在发生情况时将其杀死长时间运行，但与GC活动有关.
因此，如果代码执行超时等于200ms，则GC活动占用300ms，而代码占用199ms，我们会没事的(199ms< 200ms，不包括300ms)./p>
另一方面，如果代码执行超时等于200ms，则GC活动将占用300ms，而代码占用201ms将成为执行超时(201ms> 200ms，300ms不包括在内) ).
如您所见，进行精确的GC测量非常重要，因为如果GC活动所花费的时间超过了回调所指示的时间，则可能会导致watchdog注意到代码运行时间过长并杀死它的情况，但是实际上，GC活动(以及停止世界"方法)吃"了时间而没有任何迹象.
似乎正是我们在测试和调试过程中注意到的.让我们看看:
V8侧:
// init step
api,v8::Context::New
[api,v8::FunctionTemplate::New]
// a little bit fancy way of converting string to object
// like JSON:Parse call, but doing that using global JSON object
// no problem with that, just part of the log
api,v8::String::NewFromUtf8
api,v8::Object::Get
api,v8::String::NewFromUtf8
api,v8::Object::Get
api,v8::String::NewFromUtf8
timer-event-start,V8.GCIncrementalMarking,6406056058
timer-event-end,V8.GCIncrementalMarking,6406056581
api,v8::Function::Call
// actually function run
// script->Run(context);
timer-event-start,V8.Execute,6406057062
timer-event-start,V8.GCIncrementalMarking,6406057179
timer-event-end,V8.GCIncrementalMarking,6406059180
timer-event-start,V8.GCIncrementalMarking,6406060424
timer-event-end,V8.GCIncrementalMarking,6406062569
timer-event-start,V8.GCIncrementalMarking,6406063674
timer-event-end,V8.GCIncrementalMarking,6406065864
timer-event-start,V8.GCIncrementalMarking,6406066891
timer-event-end,V8.GCIncrementalMarking,6406068970
timer-event-start,V8.GCIncrementalMarking,6406069912
timer-event-end,V8.GCIncrementalMarking,6406070711
timer-event-start,V8.GCIncrementalMarking,6406071368
timer-event-end,V8.GCIncrementalMarking,6406073392
timer-event-start,V8.GCIncrementalMarking,6406074204
timer-event-end,V8.GCIncrementalMarking,6406076411
timer-event-start,V8.GCIncrementalMarking,6406077223
timer-event-end,V8.GCIncrementalMarking,6406079326
timer-event-start,V8.GCIncrementalMarking,6406080096
timer-event-end,V8.GCIncrementalMarking,6406082253
timer-event-start,V8.GCIncrementalMarking,6406083041
timer-event-end,V8.GCIncrementalMarking,6406085169
timer-event-start,V8.GCIncrementalMarking,6406085754
timer-event-end,V8.GCIncrementalMarking,6406087852
timer-event-start,V8.GCIncrementalMarking,6406088753
timer-event-end,V8.GCIncrementalMarking,6406090888
timer-event-start,V8.GCIncrementalMarking,6406091704
timer-event-end,V8.GCIncrementalMarking,6406093860
timer-event-start,V8.GCIncrementalMarking,6406094638
timer-event-end,V8.GCIncrementalMarking,6406096819
timer-event-start,V8.GCIncrementalMarking,6406097737
timer-event-end,V8.GCIncrementalMarking,6406099851
timer-event-start,V8.GCIncrementalMarking,6406100651
timer-event-end,V8.GCIncrementalMarking,6406102158
timer-event-start,V8.GCIncrementalMarking,6406102830
timer-event-end,V8.GCIncrementalMarking,6406102949
timer-event-start,V8.GCIncrementalMarkingFinalize,6406103476
timer-event-end,V8.GCIncrementalMarkingFinalize,6406103720
timer-event-start,V8.GCIncrementalMarking,6406103781
timer-event-end,V8.GCIncrementalMarking,6406103805
timer-event-start,V8.GCFinalizeMC,6406106106
markcompact,begin,37,733899,1573929817539
sfi-move,0x26c8c6b42258,0x39727ab446f0
sfi-move,0x26c8c6b423d0,0x39727ab44858
code-move,0x26c8c6b424a8,0x39727ab44920
code-move,0x26c8c6b42990,0x39727ab44e08
[delete,MemoryChunk,0x20803a500000]
markcompact,end,37,750515,1573929817560
timer-event-end,V8.GCFinalizeMC,6406126613
[delete,MemoryChunk,0x2fcf14300000]
timer-event-start,V8.GCIncrementalMarkingStart,
timer-event-end,V8.GCIncrementalMarkingStart,6406148920
timer-event-start,V8.GCIncrementalMarking,6406148975
timer-event-end,V8.GCIncrementalMarking,6406150059
timer-event-start,V8.GCIncrementalMarking,6406151014
timer-event-end,V8.GCIncrementalMarking,6406152657
timer-event-start,V8.GCIncrementalMarking,6406153356
timer-event-end,V8.GCIncrementalMarking,6406154995
timer-event-start,V8.GCIncrementalMarking,6406155703
timer-event-end,V8.GCIncrementalMarking,6406157341
new,MemoryChunk,0x24eee1900000,524288
timer-event-start,V8.GCIncrementalMarking,6406158486
timer-event-end,V8.GCIncrementalMarking,6406160149
new,MemoryChunk,0x7f310200000,524288
timer-event-start,V8.GCIncrementalMarking,6406161218
timer-event-end,V8.GCIncrementalMarking,6406162914
new,MemoryChunk,0x178aad500000,524288
timer-event-start,V8.GCIncrementalMarking,6406163990
timer-event-end,V8.GCIncrementalMarking,6406165681
new,MemoryChunk,0x34d7b2580000,524288
timer-event-start,V8.GCIncrementalMarking,6406166748
timer-event-end,V8.GCIncrementalMarking,6406168439
new,MemoryChunk,0x225fec080000,524288
timer-event-start,V8.GCIncrementalMarking,6406169481
timer-event-end,V8.GCIncrementalMarking,6406171229
new,MemoryChunk,0x502e7380000,524288
timer-event-start,V8.GCIncrementalMarking,6406172280
timer-event-end,V8.GCIncrementalMarking,6406174003
new,MemoryChunk,0x208b2af00000,524288
timer-event-start,V8.GCIncrementalMarking,6406175047
timer-event-end,V8.GCIncrementalMarking,6406176787
new,MemoryChunk,0x39ffd8400000,524288
timer-event-start,V8.GCIncrementalMarking,6406177851
timer-event-end,V8.GCIncrementalMarking,6406179600
new,MemoryChunk,0x10408d480000,524288
timer-event-start,V8.GCIncrementalMarking,6406180631
timer-event-end,V8.GCIncrementalMarking,6406182384
new,MemoryChunk,0x25c069e80000,524288
timer-event-start,V8.GCIncrementalMarking,6406183415
timer-event-end,V8.GCIncrementalMarking,6406185165
new,MemoryChunk,0x20cb51c80000,524288
timer-event-start,V8.GCIncrementalMarking,6406186210
timer-event-end,V8.GCIncrementalMarking,6406186919
new,MemoryChunk,0xe774a300000,524288
timer-event-start,V8.GCIncrementalMarking,6406187940
timer-event-end,V8.GCIncrementalMarking,6406188387
new,MemoryChunk,0x23a0a1180000,524288
timer-event-start,V8.GCIncrementalMarking,6406189172
timer-event-end,V8.GCIncrementalMarking,6406189924
new,MemoryChunk,0x16bb70600000,524288
timer-event-start,V8.GCIncrementalMarking,6406190724
timer-event-end,V8.GCIncrementalMarking,6406192029
new,MemoryChunk,0x18b8a0200000,524288
timer-event-start,V8.GCIncrementalMarking,6406192894
timer-event-end,V8.GCIncrementalMarking,6406194253
new,MemoryChunk,0x11c87c180000,524288
timer-event-start,V8.GCIncrementalMarking,6406195137
timer-event-end,V8.GCIncrementalMarking,6406196462
new,MemoryChunk,0x353b80280000,524288
timer-event-start,V8.GCIncrementalMarking,6406197381
timer-event-end,V8.GCIncrementalMarking,6406198513
new,MemoryChunk,0x991e5a80000,524288
timer-event-start,V8.GCIncrementalMarking,6406199347
timer-event-end,V8.GCIncrementalMarking,6406200659
new,MemoryChunk,0x77559500000,524288
timer-event-start,V8.GCIncrementalMarking,6406201554
timer-event-end,V8.GCIncrementalMarking,6406202952
new,MemoryChunk,0x51fcc580000,524288
timer-event-start,V8.GCIncrementalMarking,6406203842
timer-event-end,V8.GCIncrementalMarking,6406205229
new,MemoryChunk,0x11134ca80000,524288
timer-event-start,V8.GCIncrementalMarking,6406206124
timer-event-end,V8.GCIncrementalMarking,6406207561
new,MemoryChunk,0x17b32eb00000,524288
timer-event-start,V8.GCIncrementalMarking,6406208473
timer-event-end,V8.GCIncrementalMarking,6406209913
new,MemoryChunk,0xa7929400000,524288
timer-event-start,V8.GCIncrementalMarking,6406210795
timer-event-end,V8.GCIncrementalMarking,6406212249
new,MemoryChunk,0x1f76e7200000,524288
timer-event-start,V8.GCIncrementalMarking,6406213115
timer-event-end,V8.GCIncrementalMarking,6406214629
new,MemoryChunk,0x4bb9cd00000,524288
timer-event-start,V8.GCIncrementalMarking,6406215548
timer-event-end,V8.GCIncrementalMarking,6406216079
new,MemoryChunk,0x26fd04080000,524288
timer-event-start,V8.GCIncrementalMarking,6406216911
timer-event-end,V8.GCIncrementalMarking,6406217106
timer-event-start,V8.GCIncrementalMarkingFinalize,6406217606
timer-event-end,V8.GCIncrementalMarkingFinalize,6406217921
new,MemoryChunk,0x3e8b51000000,524288
timer-event-start,V8.GCIncrementalMarking,6406218332
timer-event-end,V8.GCIncrementalMarking,6406218348
timer-event-start,V8.GCFinalizeMC,6406218897
markcompact,begin,38,36462,1573929817653
markcompact,end,38,54306,1573929817670
timer-event-end,V8.GCFinalizeMC,6406237199
new,MemoryChunk,0x3e70a1a00000,524288
new,MemoryChunk,0x14c9e4180000,524288
new,MemoryChunk,0x335947c80000,524288
timer-event-start,V8.GCIncrementalMarkingStart,6406263779
timer-event-end,V8.GCIncrementalMarkingStart,6406264145
new,MemoryChunk,0x1bf6fd00000,524288
timer-event-start,V8.GCIncrementalMarking,6406264575
timer-event-end,V8.GCIncrementalMarking,6406266175
new,MemoryChunk,0x109d6f780000,524288
timer-event-start,V8.GCIncrementalMarking,6406267498
timer-event-end,V8.GCIncrementalMarking,6406269125
new,MemoryChunk,0xcf3b9200000,524288
timer-event-start,V8.GCIncrementalMarking,6406270226
timer-event-end,V8.GCIncrementalMarking,6406271868
new,MemoryChunk,0x33eb2c880000,524288
timer-event-start,V8.GCIncrementalMarking,6406272919
timer-event-end,V8.GCIncrementalMarking,6406274608
new,MemoryChunk,0x10c056a80000,524288
timer-event-start,V8.GCIncrementalMarking,6406275660
timer-event-end,V8.GCIncrementalMarking,6406277318
new,MemoryChunk,0x1846c1880000,524288
timer-event-start,V8.GCIncrementalMarking,6406278406
timer-event-end,V8.GCIncrementalMarking,6406280119
new,MemoryChunk,0x21eed5900000,524288
timer-event-start,V8.GCIncrementalMarking,6406281176
timer-event-end,V8.GCIncrementalMarking,6406282888
new,MemoryChunk,0x323ac6b80000,524288
timer-event-start,V8.GCIncrementalMarking,6406283954
timer-event-end,V8.GCIncrementalMarking,6406285682
new,MemoryChunk,0x3c2009d00000,524288
timer-event-start,V8.GCIncrementalMarking,6406286739
timer-event-end,V8.GCIncrementalMarking,6406288466
new,MemoryChunk,0x3d504cd00000,524288
timer-event-start,V8.GCIncrementalMarking,6406289535
timer-event-end,V8.GCIncrementalMarking,6406291291
new,MemoryChunk,0x235494980000,524288
timer-event-start,V8.GCIncrementalMarking,6406292373
timer-event-end,V8.GCIncrementalMarking,6406294127
new,MemoryChunk,0xecfc3600000,524288
timer-event-start,V8.GCIncrementalMarking,6406295191
timer-event-end,V8.GCIncrementalMarking,6406296997
new,MemoryChunk,0x1a2eae600000,524288
timer-event-start,V8.GCIncrementalMarking,6406298083
timer-event-end,V8.GCIncrementalMarking,6406299894
timer-event-end,V8.Execute,6406300603
应用程序方面:
(1) // kGCTypeIncrementalMarking
[18:43:37.536(1573929817536752)][DEBUG]: GCPrologueCallback type: 4
[18:43:37.536(1573929817536955)][DEBUG]: GCEpilogCallback type: 4
Total: 203 micro
(2) // kGCTypeMarkSweepCompact
[18:43:37.539(1573929817539368)][DEBUG]: GCPrologueCallback type: 2
[18:43:37.559(1573929817559840)][DEBUG]: GCEpilogCallback type: 2
Total: 20472 micro
(3) // kGCTypeIncrementalMarking
[18:43:37.650(1573929817650874)][DEBUG]: GCPrologueCallback type: 4
[18:43:37.651(1573929817651154)][DEBUG]: GCEpilogCallback type: 4
Total: 280 micro
(4) // kGCTypeMarkSweepCompact
[18:43:37.652(1573929817652160)][DEBUG]: GCPrologueCallback type: 2
[18:43:37.670(1573929817670422)][DEBUG]: GCEpilogCallback type: 2
Total: 18262 micro
所以，总共39217微秒或40毫秒.
以这种方式读取V8日志太复杂了.因此，我通过测量timer-event-start/timer-event-end事件之间的时间对它进行了一些后处理.
(V8.GCIncrementalMarking, 523)
(V8.GCIncrementalMarking, 2001)
(V8.GCIncrementalMarking, 2145)
(V8.GCIncrementalMarking, 2190)
(V8.GCIncrementalMarking, 2079)
(V8.GCIncrementalMarking, 799)
(V8.GCIncrementalMarking, 2024)
(V8.GCIncrementalMarking, 2207)
(V8.GCIncrementalMarking, 2103)
(V8.GCIncrementalMarking, 2157)
(V8.GCIncrementalMarking, 2128)
(V8.GCIncrementalMarking, 2098)
(V8.GCIncrementalMarking, 2135)
(V8.GCIncrementalMarking, 2156)
(V8.GCIncrementalMarking, 2181)
(V8.GCIncrementalMarking, 2114)
(V8.GCIncrementalMarking, 1507)
(V8.GCIncrementalMarking, 119)
(V8.GCIncrementalMarkingFinalize, 244) (1)
(V8.GCIncrementalMarking, 24)
(V8.GCFinalizeMC, 20507) (2)
(V8.GCIncrementalMarkingStart, 428)
(V8.GCIncrementalMarking, 1084)
(V8.GCIncrementalMarking, 1643)
(V8.GCIncrementalMarking, 1639)
(V8.GCIncrementalMarking, 1638)
(V8.GCIncrementalMarking, 1663)
(V8.GCIncrementalMarking, 1696)
(V8.GCIncrementalMarking, 1691)
(V8.GCIncrementalMarking, 1691)
(V8.GCIncrementalMarking, 1748)
(V8.GCIncrementalMarking, 1723)
(V8.GCIncrementalMarking, 1740)
(V8.GCIncrementalMarking, 1749)
(V8.GCIncrementalMarking, 1753)
(V8.GCIncrementalMarking, 1750)
(V8.GCIncrementalMarking, 709)
(V8.GCIncrementalMarking, 447)
(V8.GCIncrementalMarking, 752)
(V8.GCIncrementalMarking, 1305)
(V8.GCIncrementalMarking, 1359)
(V8.GCIncrementalMarking, 1325)
(V8.GCIncrementalMarking, 1132)
(V8.GCIncrementalMarking, 1312)
(V8.GCIncrementalMarking, 1398)
(V8.GCIncrementalMarking, 1387)
(V8.GCIncrementalMarking, 1437)
(V8.GCIncrementalMarking, 1440)
(V8.GCIncrementalMarking, 1454)
(V8.GCIncrementalMarking, 1514)
(V8.GCIncrementalMarking, 531)
(V8.GCIncrementalMarking, 195)
(V8.GCIncrementalMarkingFinalize, 315) (3)
(V8.GCIncrementalMarking, 16)
(V8.GCFinalizeMC, 18302) (4)
(V8.GCIncrementalMarkingStart, 366)
(V8.GCIncrementalMarking, 1600)
(V8.GCIncrementalMarking, 1627)
(V8.GCIncrementalMarking, 1642)
(V8.GCIncrementalMarking, 1689)
(V8.GCIncrementalMarking, 1658)
(V8.GCIncrementalMarking, 1713)
(V8.GCIncrementalMarking, 1712)
(V8.GCIncrementalMarking, 1728)
(V8.GCIncrementalMarking, 1727)
(V8.GCIncrementalMarking, 1756)
(V8.GCIncrementalMarking, 1754)
(V8.GCIncrementalMarking, 1806)
(V8.GCIncrementalMarking, 1811)
(Total, 135996)
如您所见，我们只能匹配4种情况，但是许多GCIncrementalMarking活动并未引起注意.
真正的总时间等于136ms.我们可以在应用程序端进行测量，远远超过40ms！.
我知道Orinoco和并行方法，但是我不知道对GCIncrementalMarking的调用是否会阻止代码执行.
我们已经注意到相同的情况两次，在所有情况下，与V8日志文件相比，在所有情况下代码终止的原因都是应用程序端的GC测量不正确.
这是故意的，我们不能这么信任GC回调吗?还是我错过了什么?
作为临时解决方案，我们已将V8降级为5.6.316，并且可以正常运行..
6.7.240具有新的GC方法，这可能是该问题的根源吗?
PS. --single-threaded-gc的--single-threaded-gc也无济于事
PPS.一些与V8和GC逻辑相关的代码:
void cnode::V8Runner::init() {
v8::V8::InitializeICU();
v8::Platform *platform = v8::platform::CreateDefaultPlatform();
v8::V8::InitializePlatform(platform);
v8::V8::Initialize();
auto flags = "--log --log-all --logfile=/tmp/v8.log --nolazy";
auto isolate = cnode::V8Runner::getIsolate();
isolate->AddGCPrologueCallback(cnode::V8Runner::_GCPrologue);
isolate->AddGCEpilogueCallback(cnode::V8Runner::_GCEpilog);
}
void cnode::V8Runner::_GCPrologue(v8::Isolate *isolate, v8::GCType type,
v8::GCCallbackFlags flags) {
cnode::V8Runner::_GCPrologueTimePoint = std::chrono::high_resolution_clock::now();
cnode::V8Runner::_GCEpilogTimePoint = std::chrono::high_resolution_clock::now();
LOG_DEBUG("GCPrologueCallback type: %d", type);
}
void cnode::V8Runner::_GCEpilog(v8::Isolate *isolate, v8::GCType type,
v8::GCCallbackFlags flags) {
cnode::V8Runner::_GCEpilogTimePoint = std::chrono::high_resolution_clock::now();
std::chrono::milliseconds _GCPrologueTimePointMs = std::chrono::duration_cast<std::chrono::milliseconds>(
cnode::V8Runner::_GCPrologueTimePoint.time_since_epoch());
std::chrono::milliseconds _GCEpilogTimePointMs = std::chrono::duration_cast<std::chrono::milliseconds>(
cnode::V8Runner::_GCEpilogTimePoint.time_since_epoch());
const int diff = _GCEpilogTimePointMs.count() - _GCPrologueTimePointMs.count();
cnode::V8Runner::_currentGCActionMs += diff;
cnode::V8Runner::_GCPrologueTimePoint = std::chrono::high_resolution_clock::now();
cnode::V8Runner::_GCEpilogTimePoint = std::chrono::high_resolution_clock::now();
LOG_DEBUG("GCEpilogCallback type: %d", type);
}
PPPS.
这篇文章发表后，我决定在每次执行代码后使用手动调用Isolate::LowMemoryNotification()的方式来重新检查这一点.
原始V8日志:
api,v8::Context::New
api,v8::FunctionTemplate::New
api,v8::ObjectTemplate::New
[api,v8::FunctionTemplate::New]
api,v8::String::NewFromUtf8
api,v8::JSON::Parse
[new,MemoryChunk,0x1940b7d00000,524288]
timer-event-start,V8.GCIncrementalMarkingStart,4351782723
timer-event-end,V8.GCIncrementalMarkingStart,4351783066
new,MemoryChunk,0x106dca200000,524288
timer-event-start,V8.GCIncrementalMarking,4351783463
timer-event-end,V8.GCIncrementalMarking,4351785131
new,MemoryChunk,0x225019c00000,524288
timer-event-start,V8.GCIncrementalMarking,4351786485
timer-event-end,V8.GCIncrementalMarking,4351788194
new,MemoryChunk,0xdfc50c80000,524288
timer-event-start,V8.GCIncrementalMarking,4351789202
timer-event-end,V8.GCIncrementalMarking,4351790879
new,MemoryChunk,0x26861a780000,524288
timer-event-start,V8.GCIncrementalMarking,4351791905
timer-event-end,V8.GCIncrementalMarking,4351793611
new,MemoryChunk,0x44086a00000,524288
timer-event-start,V8.GCIncrementalMarking,4351794615
timer-event-end,V8.GCIncrementalMarking,4351796319
new,MemoryChunk,0x4debd600000,524288
timer-event-start,V8.GCIncrementalMarking,4351797315
timer-event-end,V8.GCIncrementalMarking,4351799066
new,MemoryChunk,0x2db69c500000,524288
timer-event-start,V8.GCIncrementalMarking,4351800060
timer-event-end,V8.GCIncrementalMarking,4351801814
new,MemoryChunk,0x1f1825000000,524288
timer-event-start,V8.GCIncrementalMarking,4351802804
timer-event-end,V8.GCIncrementalMarking,4351804535
new,MemoryChunk,0x86246080000,524288
timer-event-start,V8.GCIncrementalMarking,4351805573
timer-event-end,V8.GCIncrementalMarking,4351807383
new,MemoryChunk,0xfc3bb580000,524288
timer-event-start,V8.GCIncrementalMarking,4351808377
timer-event-end,V8.GCIncrementalMarking,4351810192
new,MemoryChunk,0x10451e500000,524288
timer-event-start,V8.GCIncrementalMarking,4351811223
timer-event-end,V8.GCIncrementalMarking,4351813019
new,MemoryChunk,0x16e643c00000,524288
timer-event-start,V8.GCIncrementalMarking,4351814010
timer-event-end,V8.GCIncrementalMarking,4351815842
new,MemoryChunk,0x2a4379600000,524288
timer-event-start,V8.GCIncrementalMarking,4351816837
timer-event-end,V8.GCIncrementalMarking,4351818621
new,MemoryChunk,0x18436f400000,524288
timer-event-start,V8.GCIncrementalMarking,4351819650
timer-event-end,V8.GCIncrementalMarking,4351821491
new,MemoryChunk,0x3b377700000,524288
timer-event-start,V8.GCIncrementalMarking,4351822503
timer-event-end,V8.GCIncrementalMarking,4351824007
new,MemoryChunk,0x1f2f22600000,524288
timer-event-start,V8.GCIncrementalMarking,4351825011
timer-event-end,V8.GCIncrementalMarking,4351825827
new,MemoryChunk,0x1cd733a80000,524288
timer-event-start,V8.GCIncrementalMarking,4351826871
timer-event-end,V8.GCIncrementalMarking,4351827291
new,MemoryChunk,0x3cf039a80000,524288
timer-event-start,V8.GCIncrementalMarking,4351828058
timer-event-end,V8.GCIncrementalMarking,4351828500
new,MemoryChunk,0x31ae7100000,524288
timer-event-start,V8.GCIncrementalMarking,4351829286
timer-event-end,V8.GCIncrementalMarking,4351830586
new,MemoryChunk,0x2265e4c00000,524288
timer-event-start,V8.GCIncrementalMarking,4351831462
timer-event-end,V8.GCIncrementalMarking,4351832806
new,MemoryChunk,0x34586ae00000,524288
timer-event-start,V8.GCIncrementalMarking,4351833700
timer-event-end,V8.GCIncrementalMarking,4351835122
new,MemoryChunk,0x21c0aa580000,524288
timer-event-start,V8.GCIncrementalMarking,4351836000
timer-event-end,V8.GCIncrementalMarking,4351837409
new,MemoryChunk,0x2d29cda00000,524288
timer-event-start,V8.GCIncrementalMarking,4351838280
timer-event-end,V8.GCIncrementalMarking,4351839701
new,MemoryChunk,0x216cbbb80000,524288
timer-event-start,V8.GCIncrementalMarking,4351840569
timer-event-end,V8.GCIncrementalMarking,4351842015
new,MemoryChunk,0x1fb82e480000,524288
timer-event-start,V8.GCIncrementalMarking,4351842910
timer-event-end,V8.GCIncrementalMarking,4351844380
new,MemoryChunk,0x329529f00000,524288
timer-event-start,V8.GCIncrementalMarking,4351845255
timer-event-end,V8.GCIncrementalMarking,4351846654
new,MemoryChunk,0x957ccf80000,524288
timer-event-start,V8.GCIncrementalMarking,4351847553
timer-event-end,V8.GCIncrementalMarking,4351848991
new,MemoryChunk,0x2df008e00000,524288
timer-event-start,V8.GCIncrementalMarking,4351849864
timer-event-end,V8.GCIncrementalMarking,4351851358
new,MemoryChunk,0x8be2be80000,524288
timer-event-start,V8.GCIncrementalMarking,4351852237
timer-event-end,V8.GCIncrementalMarking,4351853720
new,MemoryChunk,0x146846980000,524288
timer-event-start,V8.GCIncrementalMarking,4351854588
timer-event-end,V8.GCIncrementalMarking,4351856080
new,MemoryChunk,0x367cfe280000,524288
timer-event-start,V8.GCIncrementalMarking,4351856969
timer-event-end,V8.GCIncrementalMarking,4351858491
new,MemoryChunk,0x6ed38180000,524288
timer-event-start,V8.GCIncrementalMarking,4351859382
timer-event-end,V8.GCIncrementalMarking,4351860900
new,MemoryChunk,0xfbd5f600000,524288
timer-event-start,V8.GCIncrementalMarking,4351861805
timer-event-end,V8.GCIncrementalMarking,4351863367
new,MemoryChunk,0x1a5e01680000,524288
timer-event-start,V8.GCIncrementalMarking,4351864277
timer-event-end,V8.GCIncrementalMarking,4351865092
new,MemoryChunk,0x24120d700000,524288
timer-event-start,V8.GCIncrementalMarking,4351865984
timer-event-end,V8.GCIncrementalMarking,4351866048
new,MemoryChunk,0x125d39480000,524288
timer-event-start,V8.GCIncrementalMarking,4351866808
timer-event-end,V8.GCIncrementalMarking,4351866824
timer-event-start,V8.GCIncrementalMarkingFinalize,4351867246
timer-event-end,V8.GCIncrementalMarkingFinalize,4351867419
new,MemoryChunk,0x2f31d9400000,524288
timer-event-start,V8.GCIncrementalMarking,4351867767
timer-event-end,V8.GCIncrementalMarking,4351867774
timer-event-start,V8.GCFinalizeMC,4351869855
markcompact,begin,7143,825650,1575032707066
markcompact,end,7143,846265,1575032707086
timer-event-end,V8.GCFinalizeMC,4351890363
[new,MemoryChunk,0x19b52bb00000,524288]
timer-event-start,V8.GCLowMemoryNotification,4351984850
timer-event-start,V8.GCCompactor,4351984910
markcompact,begin,7143,949018,1575032707181
[delete,MemoryChunk,0xd202f700000]
markcompact,end,7144,188469,1575032707268
timer-event-end,V8.GCCompactor,4352073048
[delete,MemoryChunk,0x1c887fa80000]
timer-event-start,V8.GCCompactor,4352073343
markcompact,begin,7144,192691,1575032707270
new,MemoryChunk,0x33c543500000,524288
new,MemoryChunk,0xd4241800000,524288
[sfi-move,0x8b6f5421390,0xd424181d470]
[delete,MemoryChunk,0x1455b1780000]
markcompact,end,7144,453893,1575032707371
timer-event-end,V8.GCCompactor,4352175676
delete,MemoryChunk,0x25fae9b80000
delete,MemoryChunk,0x2590e9700000
timer-event-end,V8.GCLowMemoryNotification,4352175844
api,v8::ObjectTemplate::New
api,v8::FunctionTemplate::New
api,v8::String::NewFromUtf8
应用程序日志:
(1) // kGCTypeIncrementalMarking
[13:05:07.063(1575032707063270)][DEBUG]: GCPrologueCallback type: 4
[13:05:07.063(1575032707063418)][DEBUG]: GCEpilogCallback type: 4
Total: 148micro
(2) // kGCTypeMarkSweepCompact
[13:05:07.065(1575032707065876)][DEBUG]: GCPrologueCallback type: 2
[13:05:07.086(1575032707086356)][DEBUG]: GCEpilogCallback type: 2
Total: 20480 micro
(3) // kGCTypeMarkSweepCompact
[13:05:07.180(1575032707180925)][DEBUG]: GCPrologueCallback type: 2
[13:05:07.269(1575032707269036)][DEBUG]: GCEpilogCallback type: 2
(4) // kGCTypeMarkSweepCompact
[13:05:07.269(1575032707269366)][DEBUG]: GCPrologueCallback type: 2
[13:05:07.371(1575032707371667)][DEBUG]: GCEpilogCallback type: 2
V8后处理后的日志:
(V8.GCIncrementalMarkingStart, 343) (1)?
(V8.GCIncrementalMarking, 1668)
(V8.GCIncrementalMarking, 1709)
(V8.GCIncrementalMarking, 1677)
(V8.GCIncrementalMarking, 1706)
(V8.GCIncrementalMarking, 1704)
(V8.GCIncrementalMarking, 1751)
(V8.GCIncrementalMarking, 1754)
(V8.GCIncrementalMarking, 1731)
(V8.GCIncrementalMarking, 1810)
(V8.GCIncrementalMarking, 1815)
(V8.GCIncrementalMarking, 1796)
(V8.GCIncrementalMarking, 1832)
(V8.GCIncrementalMarking, 1784)
(V8.GCIncrementalMarking, 1841)
(V8.GCIncrementalMarking, 1504)
(V8.GCIncrementalMarking, 816)
(V8.GCIncrementalMarking, 420)
(V8.GCIncrementalMarking, 442)
(V8.GCIncrementalMarking, 1300)
(V8.GCIncrementalMarking, 1344)
(V8.GCIncrementalMarking, 1422)
(V8.GCIncrementalMarking, 1409)
(V8.GCIncrementalMarking, 1421)
(V8.GCIncrementalMarking, 1446)
(V8.GCIncrementalMarking, 1470)
(V8.GCIncrementalMarking, 1399)
(V8.GCIncrementalMarking, 1438)
(V8.GCIncrementalMarking, 1494)
(V8.GCIncrementalMarking, 1483)
(V8.GCIncrementalMarking, 1492)
(V8.GCIncrementalMarking, 1522)
(V8.GCIncrementalMarking, 1518)
(V8.GCIncrementalMarking, 1562)
(V8.GCIncrementalMarking, 815)
(V8.GCIncrementalMarking, 64)
(V8.GCIncrementalMarking, 16)
(V8.GCIncrementalMarkingFinalize, 173)
(V8.GCIncrementalMarking, 7)
(V8.GCFinalizeMC, 20508) (2)
// call to LowMemoryNotification
(V8.GCCompactor, 88138) (3)
(V8.GCCompactor, 102333) (4)
(V8.GCLowMemoryNotification, 190994)
(Total, 452871)
当我看到此消息时，我的第一个想法是-V8.GCLowMemoryNotification(190994)包括V8.GCCompactor(88138)和V8.GCCompactor(102333).毕竟(88138 + 102333)< 190994，这是有道理的，对吧?
因此，V8.GCFinalizeMC中可能还包括了V8.GCIncrementalMarking.但是事实并非如此-20508比GCIncrementalMarking s的值(50555)小得多.
这个故事的最终结果是一样的-执行超时.代码的时间限制等于200ms.
对LowMemoryNotification的呼叫不包括在watchdog监视中.所以452871 - 190994 = 261877.
请记住，我们尊重GC的活动，因此261877 - 20508 = 241369.仍然大于200毫秒.
但是，如果我们开始计算所有V8.GCIncrementalMarking活动(50555微秒)，则最终结果将为241369 - 50555 = 190814. 190ms-不是超时！
我仍然认为V8(6.7.240)在GC活动方面不能提供足够的准确性.
解决方案
V8开发人员在此处.如果我正确理解了这个问题，那么答案是:在一个主要GC周期的开始/结尾处调用GC序言/结尾回调，该周期包括(可能是数百个)增量标记步骤和一个最后的确定阶段要更长一些，所有这些都与常规程序执行混杂在一起.不会在每个增量标记步骤周围调用回调，也不会在较小的GC周期(清除"，奇怪的是，上面的各种日志中完全没有这些回调)周围调用回调，并且不打算提供精确的计时信息.抱歉.
理想情况下，您无需执行任何操作.对于大多数程序而言，花在GC上的时间大约占整体执行时间的1％到10％之间，所以没关系.
如果您确实坚持跟踪在主要GC上花费的主线程时间，那么最好的选择可能是关闭增量标记(标志--noincremental-marking).请注意，这将使用户体验更加混乱(而不是数百个sub-1ms的暂停，而您将获得几秒钟的暂停)，但是也许在您不关心的情况下.我没有建议涵盖次要GC.
那就是说，如果您允许提出更笼统的评论，我会对整体方法产生怀疑. GC活动由分配触发，可以视为分配成本的一部分.如果您的目标是公平地"对待程序(甚至在竞争意义上呢?)，那么我将绝对将GC时间包括在每个程序的时间预算中. GC并不是随机地将行为不端的代码突如其来"的东西-必须花大量时间在GC活动上才是分配大量代码的结果.如果代码希望保留在一定的时间预算内，那么最好尝试分配尽可能少的时间，这只是快速/高效的一个方面.
底层的心理模型也许是一种非常简单的内存管理策略，例如许多代码片段可以在没有任何GC活动的情况下运行，并且每个代码片段分配了几兆字节，然后其中一个是不幸的稻草，它破坏了骆驼的后背，超过了一定的阈值，并且运行速度很慢，可以清理所有人的垃圾.还有别的吗?在这样的VM中，您的方法将完全有意义，但这与V8的工作方式相去甚远.
此外，GC并不是主线程的唯一中断，还存在(函数的最前部分)函数优化，该函数周围没有任何嵌入程序控制的回调.如果您想排除所有干扰，则必须破解V8才能创建一种排除干扰的方法.另一方面，我上面的论点也适用于此:优化不是随机发生的，它发生在长时间运行的代码上，通常对整体性能有利(否则我们就不会这样做)，所以我认为公平/适当地将其包括在预算中，就像GC时间一样.
I have a small question related to V8 6.7.240 GC behavior and AddGCPrologueCallback/AddGCEpilogueCallback callbacks.
A little story behind the problem: we launch custom JS code using V8 engine, and in order to limit execution by time we have a watchdog (separate thread with isolate->TerminateExecution() call) that monitors code and kills it in case of long running, but with respect to GC activity.
So, if code execution timeout equals to 200ms, GC activity takes 300ms and code takes 199ms we will be okay (199ms < 200ms, 300ms is not included).
On the other hand, if code execution timeout equals to 200ms, GC activity takes 300ms and code takes 201ms that will be execution timeout (201ms > 200ms, 300ms is not included).
As you can see, that's really important to have precise GC measurements, cuz in case GC activity takes more than callbacks indicates, that may lead to situation in which watchdog will notice that code runs too long and kill it, but in reality the GC activity (along with 'stop the world' approach) 'eating' time without any indication of that.
Seems like that's exactly what we have noticed during our testing and debugging. Lets see:
V8 side:
// init step
api,v8::Context::New
[api,v8::FunctionTemplate::New]
// a little bit fancy way of converting string to object
// like JSON:Parse call, but doing that using global JSON object
// no problem with that, just part of the log
api,v8::String::NewFromUtf8
api,v8::Object::Get
api,v8::String::NewFromUtf8
api,v8::Object::Get
api,v8::String::NewFromUtf8
timer-event-start,V8.GCIncrementalMarking,6406056058
timer-event-end,V8.GCIncrementalMarking,6406056581
api,v8::Function::Call
// actually function run
// script->Run(context);
timer-event-start,V8.Execute,6406057062
timer-event-start,V8.GCIncrementalMarking,6406057179
timer-event-end,V8.GCIncrementalMarking,6406059180
timer-event-start,V8.GCIncrementalMarking,6406060424
timer-event-end,V8.GCIncrementalMarking,6406062569
timer-event-start,V8.GCIncrementalMarking,6406063674
timer-event-end,V8.GCIncrementalMarking,6406065864
timer-event-start,V8.GCIncrementalMarking,6406066891
timer-event-end,V8.GCIncrementalMarking,6406068970
timer-event-start,V8.GCIncrementalMarking,6406069912
timer-event-end,V8.GCIncrementalMarking,6406070711
timer-event-start,V8.GCIncrementalMarking,6406071368
timer-event-end,V8.GCIncrementalMarking,6406073392
timer-event-start,V8.GCIncrementalMarking,6406074204
timer-event-end,V8.GCIncrementalMarking,6406076411
timer-event-start,V8.GCIncrementalMarking,6406077223
timer-event-end,V8.GCIncrementalMarking,6406079326
timer-event-start,V8.GCIncrementalMarking,6406080096
timer-event-end,V8.GCIncrementalMarking,6406082253
timer-event-start,V8.GCIncrementalMarking,6406083041
timer-event-end,V8.GCIncrementalMarking,6406085169
timer-event-start,V8.GCIncrementalMarking,6406085754
timer-event-end,V8.GCIncrementalMarking,6406087852
timer-event-start,V8.GCIncrementalMarking,6406088753
timer-event-end,V8.GCIncrementalMarking,6406090888
timer-event-start,V8.GCIncrementalMarking,6406091704
timer-event-end,V8.GCIncrementalMarking,6406093860
timer-event-start,V8.GCIncrementalMarking,6406094638
timer-event-end,V8.GCIncrementalMarking,6406096819
timer-event-start,V8.GCIncrementalMarking,6406097737
timer-event-end,V8.GCIncrementalMarking,6406099851
timer-event-start,V8.GCIncrementalMarking,6406100651
timer-event-end,V8.GCIncrementalMarking,6406102158
timer-event-start,V8.GCIncrementalMarking,6406102830
timer-event-end,V8.GCIncrementalMarking,6406102949
timer-event-start,V8.GCIncrementalMarkingFinalize,6406103476
timer-event-end,V8.GCIncrementalMarkingFinalize,6406103720
timer-event-start,V8.GCIncrementalMarking,6406103781
timer-event-end,V8.GCIncrementalMarking,6406103805
timer-event-start,V8.GCFinalizeMC,6406106106
markcompact,begin,37,733899,1573929817539
sfi-move,0x26c8c6b42258,0x39727ab446f0
sfi-move,0x26c8c6b423d0,0x39727ab44858
code-move,0x26c8c6b424a8,0x39727ab44920
code-move,0x26c8c6b42990,0x39727ab44e08
[delete,MemoryChunk,0x20803a500000]
markcompact,end,37,750515,1573929817560
timer-event-end,V8.GCFinalizeMC,6406126613
[delete,MemoryChunk,0x2fcf14300000]
timer-event-start,V8.GCIncrementalMarkingStart,
timer-event-end,V8.GCIncrementalMarkingStart,6406148920
timer-event-start,V8.GCIncrementalMarking,6406148975
timer-event-end,V8.GCIncrementalMarking,6406150059
timer-event-start,V8.GCIncrementalMarking,6406151014
timer-event-end,V8.GCIncrementalMarking,6406152657
timer-event-start,V8.GCIncrementalMarking,6406153356
timer-event-end,V8.GCIncrementalMarking,6406154995
timer-event-start,V8.GCIncrementalMarking,6406155703
timer-event-end,V8.GCIncrementalMarking,6406157341
new,MemoryChunk,0x24eee1900000,524288
timer-event-start,V8.GCIncrementalMarking,6406158486
timer-event-end,V8.GCIncrementalMarking,6406160149
new,MemoryChunk,0x7f310200000,524288
timer-event-start,V8.GCIncrementalMarking,6406161218
timer-event-end,V8.GCIncrementalMarking,6406162914
new,MemoryChunk,0x178aad500000,524288
timer-event-start,V8.GCIncrementalMarking,6406163990
timer-event-end,V8.GCIncrementalMarking,6406165681
new,MemoryChunk,0x34d7b2580000,524288
timer-event-start,V8.GCIncrementalMarking,6406166748
timer-event-end,V8.GCIncrementalMarking,6406168439
new,MemoryChunk,0x225fec080000,524288
timer-event-start,V8.GCIncrementalMarking,6406169481
timer-event-end,V8.GCIncrementalMarking,6406171229
new,MemoryChunk,0x502e7380000,524288
timer-event-start,V8.GCIncrementalMarking,6406172280
timer-event-end,V8.GCIncrementalMarking,6406174003
new,MemoryChunk,0x208b2af00000,524288
timer-event-start,V8.GCIncrementalMarking,6406175047
timer-event-end,V8.GCIncrementalMarking,6406176787
new,MemoryChunk,0x39ffd8400000,524288
timer-event-start,V8.GCIncrementalMarking,6406177851
timer-event-end,V8.GCIncrementalMarking,6406179600
new,MemoryChunk,0x10408d480000,524288
timer-event-start,V8.GCIncrementalMarking,6406180631
timer-event-end,V8.GCIncrementalMarking,6406182384
new,MemoryChunk,0x25c069e80000,524288
timer-event-start,V8.GCIncrementalMarking,6406183415
timer-event-end,V8.GCIncrementalMarking,6406185165
new,MemoryChunk,0x20cb51c80000,524288
timer-event-start,V8.GCIncrementalMarking,6406186210
timer-event-end,V8.GCIncrementalMarking,6406186919
new,MemoryChunk,0xe774a300000,524288
timer-event-start,V8.GCIncrementalMarking,6406187940
timer-event-end,V8.GCIncrementalMarking,6406188387
new,MemoryChunk,0x23a0a1180000,524288
timer-event-start,V8.GCIncrementalMarking,6406189172
timer-event-end,V8.GCIncrementalMarking,6406189924
new,MemoryChunk,0x16bb70600000,524288
timer-event-start,V8.GCIncrementalMarking,6406190724
timer-event-end,V8.GCIncrementalMarking,6406192029
new,MemoryChunk,0x18b8a0200000,524288
timer-event-start,V8.GCIncrementalMarking,6406192894
timer-event-end,V8.GCIncrementalMarking,6406194253
new,MemoryChunk,0x11c87c180000,524288
timer-event-start,V8.GCIncrementalMarking,6406195137
timer-event-end,V8.GCIncrementalMarking,6406196462
new,MemoryChunk,0x353b80280000,524288
timer-event-start,V8.GCIncrementalMarking,6406197381
timer-event-end,V8.GCIncrementalMarking,6406198513
new,MemoryChunk,0x991e5a80000,524288
timer-event-start,V8.GCIncrementalMarking,6406199347
timer-event-end,V8.GCIncrementalMarking,6406200659
new,MemoryChunk,0x77559500000,524288
timer-event-start,V8.GCIncrementalMarking,6406201554
timer-event-end,V8.GCIncrementalMarking,6406202952
new,MemoryChunk,0x51fcc580000,524288
timer-event-start,V8.GCIncrementalMarking,6406203842
timer-event-end,V8.GCIncrementalMarking,6406205229
new,MemoryChunk,0x11134ca80000,524288
timer-event-start,V8.GCIncrementalMarking,6406206124
timer-event-end,V8.GCIncrementalMarking,6406207561
new,MemoryChunk,0x17b32eb00000,524288
timer-event-start,V8.GCIncrementalMarking,6406208473
timer-event-end,V8.GCIncrementalMarking,6406209913
new,MemoryChunk,0xa7929400000,524288
timer-event-start,V8.GCIncrementalMarking,6406210795
timer-event-end,V8.GCIncrementalMarking,6406212249
new,MemoryChunk,0x1f76e7200000,524288
timer-event-start,V8.GCIncrementalMarking,6406213115
timer-event-end,V8.GCIncrementalMarking,6406214629
new,MemoryChunk,0x4bb9cd00000,524288
timer-event-start,V8.GCIncrementalMarking,6406215548
timer-event-end,V8.GCIncrementalMarking,6406216079
new,MemoryChunk,0x26fd04080000,524288
timer-event-start,V8.GCIncrementalMarking,6406216911
timer-event-end,V8.GCIncrementalMarking,6406217106
timer-event-start,V8.GCIncrementalMarkingFinalize,6406217606
timer-event-end,V8.GCIncrementalMarkingFinalize,6406217921
new,MemoryChunk,0x3e8b51000000,524288
timer-event-start,V8.GCIncrementalMarking,6406218332
timer-event-end,V8.GCIncrementalMarking,6406218348
timer-event-start,V8.GCFinalizeMC,6406218897
markcompact,begin,38,36462,1573929817653
markcompact,end,38,54306,1573929817670
timer-event-end,V8.GCFinalizeMC,6406237199
new,MemoryChunk,0x3e70a1a00000,524288
new,MemoryChunk,0x14c9e4180000,524288
new,MemoryChunk,0x335947c80000,524288
timer-event-start,V8.GCIncrementalMarkingStart,6406263779
timer-event-end,V8.GCIncrementalMarkingStart,6406264145
new,MemoryChunk,0x1bf6fd00000,524288
timer-event-start,V8.GCIncrementalMarking,6406264575
timer-event-end,V8.GCIncrementalMarking,6406266175
new,MemoryChunk,0x109d6f780000,524288
timer-event-start,V8.GCIncrementalMarking,6406267498
timer-event-end,V8.GCIncrementalMarking,6406269125
new,MemoryChunk,0xcf3b9200000,524288
timer-event-start,V8.GCIncrementalMarking,6406270226
timer-event-end,V8.GCIncrementalMarking,6406271868
new,MemoryChunk,0x33eb2c880000,524288
timer-event-start,V8.GCIncrementalMarking,6406272919
timer-event-end,V8.GCIncrementalMarking,6406274608
new,MemoryChunk,0x10c056a80000,524288
timer-event-start,V8.GCIncrementalMarking,6406275660
timer-event-end,V8.GCIncrementalMarking,6406277318
new,MemoryChunk,0x1846c1880000,524288
timer-event-start,V8.GCIncrementalMarking,6406278406
timer-event-end,V8.GCIncrementalMarking,6406280119
new,MemoryChunk,0x21eed5900000,524288
timer-event-start,V8.GCIncrementalMarking,6406281176
timer-event-end,V8.GCIncrementalMarking,6406282888
new,MemoryChunk,0x323ac6b80000,524288
timer-event-start,V8.GCIncrementalMarking,6406283954
timer-event-end,V8.GCIncrementalMarking,6406285682
new,MemoryChunk,0x3c2009d00000,524288
timer-event-start,V8.GCIncrementalMarking,6406286739
timer-event-end,V8.GCIncrementalMarking,6406288466
new,MemoryChunk,0x3d504cd00000,524288
timer-event-start,V8.GCIncrementalMarking,6406289535
timer-event-end,V8.GCIncrementalMarking,6406291291
new,MemoryChunk,0x235494980000,524288
timer-event-start,V8.GCIncrementalMarking,6406292373
timer-event-end,V8.GCIncrementalMarking,6406294127
new,MemoryChunk,0xecfc3600000,524288
timer-event-start,V8.GCIncrementalMarking,6406295191
timer-event-end,V8.GCIncrementalMarking,6406296997
new,MemoryChunk,0x1a2eae600000,524288
timer-event-start,V8.GCIncrementalMarking,6406298083
timer-event-end,V8.GCIncrementalMarking,6406299894
timer-event-end,V8.Execute,6406300603
Application side:
(1) // kGCTypeIncrementalMarking
[18:43:37.536(1573929817536752)][DEBUG]: GCPrologueCallback type: 4
[18:43:37.536(1573929817536955)][DEBUG]: GCEpilogCallback type: 4
Total: 203 micro
(2) // kGCTypeMarkSweepCompact
[18:43:37.539(1573929817539368)][DEBUG]: GCPrologueCallback type: 2
[18:43:37.559(1573929817559840)][DEBUG]: GCEpilogCallback type: 2
Total: 20472 micro
(3) // kGCTypeIncrementalMarking
[18:43:37.650(1573929817650874)][DEBUG]: GCPrologueCallback type: 4
[18:43:37.651(1573929817651154)][DEBUG]: GCEpilogCallback type: 4
Total: 280 micro
(4) // kGCTypeMarkSweepCompact
[18:43:37.652(1573929817652160)][DEBUG]: GCPrologueCallback type: 2
[18:43:37.670(1573929817670422)][DEBUG]: GCEpilogCallback type: 2
Total: 18262 micro
So, 39217 microseconds or 40ms in total.
Read V8 log in that way is too complicated. So I did some post-processing on it by measuring time between timer-event-start/timer-event-end events.
(V8.GCIncrementalMarking, 523)
(V8.GCIncrementalMarking, 2001)
(V8.GCIncrementalMarking, 2145)
(V8.GCIncrementalMarking, 2190)
(V8.GCIncrementalMarking, 2079)
(V8.GCIncrementalMarking, 799)
(V8.GCIncrementalMarking, 2024)
(V8.GCIncrementalMarking, 2207)
(V8.GCIncrementalMarking, 2103)
(V8.GCIncrementalMarking, 2157)
(V8.GCIncrementalMarking, 2128)
(V8.GCIncrementalMarking, 2098)
(V8.GCIncrementalMarking, 2135)
(V8.GCIncrementalMarking, 2156)
(V8.GCIncrementalMarking, 2181)
(V8.GCIncrementalMarking, 2114)
(V8.GCIncrementalMarking, 1507)
(V8.GCIncrementalMarking, 119)
(V8.GCIncrementalMarkingFinalize, 244) (1)
(V8.GCIncrementalMarking, 24)
(V8.GCFinalizeMC, 20507) (2)
(V8.GCIncrementalMarkingStart, 428)
(V8.GCIncrementalMarking, 1084)
(V8.GCIncrementalMarking, 1643)
(V8.GCIncrementalMarking, 1639)
(V8.GCIncrementalMarking, 1638)
(V8.GCIncrementalMarking, 1663)
(V8.GCIncrementalMarking, 1696)
(V8.GCIncrementalMarking, 1691)
(V8.GCIncrementalMarking, 1691)
(V8.GCIncrementalMarking, 1748)
(V8.GCIncrementalMarking, 1723)
(V8.GCIncrementalMarking, 1740)
(V8.GCIncrementalMarking, 1749)
(V8.GCIncrementalMarking, 1753)
(V8.GCIncrementalMarking, 1750)
(V8.GCIncrementalMarking, 709)
(V8.GCIncrementalMarking, 447)
(V8.GCIncrementalMarking, 752)
(V8.GCIncrementalMarking, 1305)
(V8.GCIncrementalMarking, 1359)
(V8.GCIncrementalMarking, 1325)
(V8.GCIncrementalMarking, 1132)
(V8.GCIncrementalMarking, 1312)
(V8.GCIncrementalMarking, 1398)
(V8.GCIncrementalMarking, 1387)
(V8.GCIncrementalMarking, 1437)
(V8.GCIncrementalMarking, 1440)
(V8.GCIncrementalMarking, 1454)
(V8.GCIncrementalMarking, 1514)
(V8.GCIncrementalMarking, 531)
(V8.GCIncrementalMarking, 195)
(V8.GCIncrementalMarkingFinalize, 315) (3)
(V8.GCIncrementalMarking, 16)
(V8.GCFinalizeMC, 18302) (4)
(V8.GCIncrementalMarkingStart, 366)
(V8.GCIncrementalMarking, 1600)
(V8.GCIncrementalMarking, 1627)
(V8.GCIncrementalMarking, 1642)
(V8.GCIncrementalMarking, 1689)
(V8.GCIncrementalMarking, 1658)
(V8.GCIncrementalMarking, 1713)
(V8.GCIncrementalMarking, 1712)
(V8.GCIncrementalMarking, 1728)
(V8.GCIncrementalMarking, 1727)
(V8.GCIncrementalMarking, 1756)
(V8.GCIncrementalMarking, 1754)
(V8.GCIncrementalMarking, 1806)
(V8.GCIncrementalMarking, 1811)
(Total, 135996)
As you can see we can match only 4 cases, but lots of GCIncrementalMarking activity was unnoticed.
And the true total time equals to 136ms. A lot more than 40ms!, that we were able to measure on application side..
I'm aware of Orinoco and parallel approach, but I've no idea whether calls to GCIncrementalMarking blocks code execution or not.
We've noticed same situation a couple of times and in all cases the reason to code termination was incorrect GC measurement on application side in comparison to V8 log file.
Is it intentional and we cannot trust to GC callbacks so much ? Or I've missed something ?
As a temporary solution, we've downgraded V8 to 5.6.316 and it works okay on it..
6.7.240 has new GC approach, can it be the root of that problem ?
PS. --single-threaded-gc for 6.7.240 doesn't help either
PPS. some code related to V8 and GC logic:
void cnode::V8Runner::init() {
v8::V8::InitializeICU();
v8::Platform *platform = v8::platform::CreateDefaultPlatform();
v8::V8::InitializePlatform(platform);
v8::V8::Initialize();
auto flags = "--log --log-all --logfile=/tmp/v8.log --nolazy";
auto isolate = cnode::V8Runner::getIsolate();
isolate->AddGCPrologueCallback(cnode::V8Runner::_GCPrologue);
isolate->AddGCEpilogueCallback(cnode::V8Runner::_GCEpilog);
}
void cnode::V8Runner::_GCPrologue(v8::Isolate *isolate, v8::GCType type,
v8::GCCallbackFlags flags) {
cnode::V8Runner::_GCPrologueTimePoint = std::chrono::high_resolution_clock::now();
cnode::V8Runner::_GCEpilogTimePoint = std::chrono::high_resolution_clock::now();
LOG_DEBUG("GCPrologueCallback type: %d", type);
}
void cnode::V8Runner::_GCEpilog(v8::Isolate *isolate, v8::GCType type,
v8::GCCallbackFlags flags) {
cnode::V8Runner::_GCEpilogTimePoint = std::chrono::high_resolution_clock::now();
std::chrono::milliseconds _GCPrologueTimePointMs = std::chrono::duration_cast<std::chrono::milliseconds>(
cnode::V8Runner::_GCPrologueTimePoint.time_since_epoch());
std::chrono::milliseconds _GCEpilogTimePointMs = std::chrono::duration_cast<std::chrono::milliseconds>(
cnode::V8Runner::_GCEpilogTimePoint.time_since_epoch());
const int diff = _GCEpilogTimePointMs.count() - _GCPrologueTimePointMs.count();
cnode::V8Runner::_currentGCActionMs += diff;
cnode::V8Runner::_GCPrologueTimePoint = std::chrono::high_resolution_clock::now();
cnode::V8Runner::_GCEpilogTimePoint = std::chrono::high_resolution_clock::now();
LOG_DEBUG("GCEpilogCallback type: %d", type);
}
PPPS.
After this post I decided to recheck this using manual call to Isolate::LowMemoryNotification() after each code execution.
Raw V8 Log:
api,v8::Context::New
api,v8::FunctionTemplate::New
api,v8::ObjectTemplate::New
[api,v8::FunctionTemplate::New]
api,v8::String::NewFromUtf8
api,v8::JSON::Parse
[new,MemoryChunk,0x1940b7d00000,524288]
timer-event-start,V8.GCIncrementalMarkingStart,4351782723
timer-event-end,V8.GCIncrementalMarkingStart,4351783066
new,MemoryChunk,0x106dca200000,524288
timer-event-start,V8.GCIncrementalMarking,4351783463
timer-event-end,V8.GCIncrementalMarking,4351785131
new,MemoryChunk,0x225019c00000,524288
timer-event-start,V8.GCIncrementalMarking,4351786485
timer-event-end,V8.GCIncrementalMarking,4351788194
new,MemoryChunk,0xdfc50c80000,524288
timer-event-start,V8.GCIncrementalMarking,4351789202
timer-event-end,V8.GCIncrementalMarking,4351790879
new,MemoryChunk,0x26861a780000,524288
timer-event-start,V8.GCIncrementalMarking,4351791905
timer-event-end,V8.GCIncrementalMarking,4351793611
new,MemoryChunk,0x44086a00000,524288
timer-event-start,V8.GCIncrementalMarking,4351794615
timer-event-end,V8.GCIncrementalMarking,4351796319
new,MemoryChunk,0x4debd600000,524288
timer-event-start,V8.GCIncrementalMarking,4351797315
timer-event-end,V8.GCIncrementalMarking,4351799066
new,MemoryChunk,0x2db69c500000,524288
timer-event-start,V8.GCIncrementalMarking,4351800060
timer-event-end,V8.GCIncrementalMarking,4351801814
new,MemoryChunk,0x1f1825000000,524288
timer-event-start,V8.GCIncrementalMarking,4351802804
timer-event-end,V8.GCIncrementalMarking,4351804535
new,MemoryChunk,0x86246080000,524288
timer-event-start,V8.GCIncrementalMarking,4351805573
timer-event-end,V8.GCIncrementalMarking,4351807383
new,MemoryChunk,0xfc3bb580000,524288
timer-event-start,V8.GCIncrementalMarking,4351808377
timer-event-end,V8.GCIncrementalMarking,4351810192
new,MemoryChunk,0x10451e500000,524288
timer-event-start,V8.GCIncrementalMarking,4351811223
timer-event-end,V8.GCIncrementalMarking,4351813019
new,MemoryChunk,0x16e643c00000,524288
timer-event-start,V8.GCIncrementalMarking,4351814010
timer-event-end,V8.GCIncrementalMarking,4351815842
new,MemoryChunk,0x2a4379600000,524288
timer-event-start,V8.GCIncrementalMarking,4351816837
timer-event-end,V8.GCIncrementalMarking,4351818621
new,MemoryChunk,0x18436f400000,524288
timer-event-start,V8.GCIncrementalMarking,4351819650
timer-event-end,V8.GCIncrementalMarking,4351821491
new,MemoryChunk,0x3b377700000,524288
timer-event-start,V8.GCIncrementalMarking,4351822503
timer-event-end,V8.GCIncrementalMarking,4351824007
new,MemoryChunk,0x1f2f22600000,524288
timer-event-start,V8.GCIncrementalMarking,4351825011
timer-event-end,V8.GCIncrementalMarking,4351825827
new,MemoryChunk,0x1cd733a80000,524288
timer-event-start,V8.GCIncrementalMarking,4351826871
timer-event-end,V8.GCIncrementalMarking,4351827291
new,MemoryChunk,0x3cf039a80000,524288
timer-event-start,V8.GCIncrementalMarking,4351828058
timer-event-end,V8.GCIncrementalMarking,4351828500
new,MemoryChunk,0x31ae7100000,524288
timer-event-start,V8.GCIncrementalMarking,4351829286
timer-event-end,V8.GCIncrementalMarking,4351830586
new,MemoryChunk,0x2265e4c00000,524288
timer-event-start,V8.GCIncrementalMarking,4351831462
timer-event-end,V8.GCIncrementalMarking,4351832806
new,MemoryChunk,0x34586ae00000,524288
timer-event-start,V8.GCIncrementalMarking,4351833700
timer-event-end,V8.GCIncrementalMarking,4351835122
new,MemoryChunk,0x21c0aa580000,524288
timer-event-start,V8.GCIncrementalMarking,4351836000
timer-event-end,V8.GCIncrementalMarking,4351837409
new,MemoryChunk,0x2d29cda00000,524288
timer-event-start,V8.GCIncrementalMarking,4351838280
timer-event-end,V8.GCIncrementalMarking,4351839701
new,MemoryChunk,0x216cbbb80000,524288
timer-event-start,V8.GCIncrementalMarking,4351840569
timer-event-end,V8.GCIncrementalMarking,4351842015
new,MemoryChunk,0x1fb82e480000,524288
timer-event-start,V8.GCIncrementalMarking,4351842910
timer-event-end,V8.GCIncrementalMarking,4351844380
new,MemoryChunk,0x329529f00000,524288
timer-event-start,V8.GCIncrementalMarking,4351845255
timer-event-end,V8.GCIncrementalMarking,4351846654
new,MemoryChunk,0x957ccf80000,524288
timer-event-start,V8.GCIncrementalMarking,4351847553
timer-event-end,V8.GCIncrementalMarking,4351848991
new,MemoryChunk,0x2df008e00000,524288
timer-event-start,V8.GCIncrementalMarking,4351849864
timer-event-end,V8.GCIncrementalMarking,4351851358
new,MemoryChunk,0x8be2be80000,524288
timer-event-start,V8.GCIncrementalMarking,4351852237
timer-event-end,V8.GCIncrementalMarking,4351853720
new,MemoryChunk,0x146846980000,524288
timer-event-start,V8.GCIncrementalMarking,4351854588
timer-event-end,V8.GCIncrementalMarking,4351856080
new,MemoryChunk,0x367cfe280000,524288
timer-event-start,V8.GCIncrementalMarking,4351856969
timer-event-end,V8.GCIncrementalMarking,4351858491
new,MemoryChunk,0x6ed38180000,524288
timer-event-start,V8.GCIncrementalMarking,4351859382
timer-event-end,V8.GCIncrementalMarking,4351860900
new,MemoryChunk,0xfbd5f600000,524288
timer-event-start,V8.GCIncrementalMarking,4351861805
timer-event-end,V8.GCIncrementalMarking,4351863367
new,MemoryChunk,0x1a5e01680000,524288
timer-event-start,V8.GCIncrementalMarking,4351864277
timer-event-end,V8.GCIncrementalMarking,4351865092
new,MemoryChunk,0x24120d700000,524288
timer-event-start,V8.GCIncrementalMarking,4351865984
timer-event-end,V8.GCIncrementalMarking,4351866048
new,MemoryChunk,0x125d39480000,524288
timer-event-start,V8.GCIncrementalMarking,4351866808
timer-event-end,V8.GCIncrementalMarking,4351866824
timer-event-start,V8.GCIncrementalMarkingFinalize,4351867246
timer-event-end,V8.GCIncrementalMarkingFinalize,4351867419
new,MemoryChunk,0x2f31d9400000,524288
timer-event-start,V8.GCIncrementalMarking,4351867767
timer-event-end,V8.GCIncrementalMarking,4351867774
timer-event-start,V8.GCFinalizeMC,4351869855
markcompact,begin,7143,825650,1575032707066
markcompact,end,7143,846265,1575032707086
timer-event-end,V8.GCFinalizeMC,4351890363
[new,MemoryChunk,0x19b52bb00000,524288]
timer-event-start,V8.GCLowMemoryNotification,4351984850
timer-event-start,V8.GCCompactor,4351984910
markcompact,begin,7143,949018,1575032707181
[delete,MemoryChunk,0xd202f700000]
markcompact,end,7144,188469,1575032707268
timer-event-end,V8.GCCompactor,4352073048
[delete,MemoryChunk,0x1c887fa80000]
timer-event-start,V8.GCCompactor,4352073343
markcompact,begin,7144,192691,1575032707270
new,MemoryChunk,0x33c543500000,524288
new,MemoryChunk,0xd4241800000,524288
[sfi-move,0x8b6f5421390,0xd424181d470]
[delete,MemoryChunk,0x1455b1780000]
markcompact,end,7144,453893,1575032707371
timer-event-end,V8.GCCompactor,4352175676
delete,MemoryChunk,0x25fae9b80000
delete,MemoryChunk,0x2590e9700000
timer-event-end,V8.GCLowMemoryNotification,4352175844
api,v8::ObjectTemplate::New
api,v8::FunctionTemplate::New
api,v8::String::NewFromUtf8
Application log:
(1) // kGCTypeIncrementalMarking
[13:05:07.063(1575032707063270)][DEBUG]: GCPrologueCallback type: 4
[13:05:07.063(1575032707063418)][DEBUG]: GCEpilogCallback type: 4
Total: 148micro
(2) // kGCTypeMarkSweepCompact
[13:05:07.065(1575032707065876)][DEBUG]: GCPrologueCallback type: 2
[13:05:07.086(1575032707086356)][DEBUG]: GCEpilogCallback type: 2
Total: 20480 micro
(3) // kGCTypeMarkSweepCompact
[13:05:07.180(1575032707180925)][DEBUG]: GCPrologueCallback type: 2
[13:05:07.269(1575032707269036)][DEBUG]: GCEpilogCallback type: 2
(4) // kGCTypeMarkSweepCompact
[13:05:07.269(1575032707269366)][DEBUG]: GCPrologueCallback type: 2
[13:05:07.371(1575032707371667)][DEBUG]: GCEpilogCallback type: 2
V8 Log after post-processing:
(V8.GCIncrementalMarkingStart, 343) (1)?
(V8.GCIncrementalMarking, 1668)
(V8.GCIncrementalMarking, 1709)
(V8.GCIncrementalMarking, 1677)
(V8.GCIncrementalMarking, 1706)
(V8.GCIncrementalMarking, 1704)
(V8.GCIncrementalMarking, 1751)
(V8.GCIncrementalMarking, 1754)
(V8.GCIncrementalMarking, 1731)
(V8.GCIncrementalMarking, 1810)
(V8.GCIncrementalMarking, 1815)
(V8.GCIncrementalMarking, 1796)
(V8.GCIncrementalMarking, 1832)
(V8.GCIncrementalMarking, 1784)
(V8.GCIncrementalMarking, 1841)
(V8.GCIncrementalMarking, 1504)
(V8.GCIncrementalMarking, 816)
(V8.GCIncrementalMarking, 420)
(V8.GCIncrementalMarking, 442)
(V8.GCIncrementalMarking, 1300)
(V8.GCIncrementalMarking, 1344)
(V8.GCIncrementalMarking, 1422)
(V8.GCIncrementalMarking, 1409)
(V8.GCIncrementalMarking, 1421)
(V8.GCIncrementalMarking, 1446)
(V8.GCIncrementalMarking, 1470)
(V8.GCIncrementalMarking, 1399)
(V8.GCIncrementalMarking, 1438)
(V8.GCIncrementalMarking, 1494)
(V8.GCIncrementalMarking, 1483)
(V8.GCIncrementalMarking, 1492)
(V8.GCIncrementalMarking, 1522)
(V8.GCIncrementalMarking, 1518)
(V8.GCIncrementalMarking, 1562)
(V8.GCIncrementalMarking, 815)
(V8.GCIncrementalMarking, 64)
(V8.GCIncrementalMarking, 16)
(V8.GCIncrementalMarkingFinalize, 173)
(V8.GCIncrementalMarking, 7)
(V8.GCFinalizeMC, 20508) (2)
// call to LowMemoryNotification
(V8.GCCompactor, 88138) (3)
(V8.GCCompactor, 102333) (4)
(V8.GCLowMemoryNotification, 190994)
(Total, 452871)
When I saw this, my first idea was - V8.GCLowMemoryNotification (190994) includes V8.GCCompactor(88138) and V8.GCCompactor(102333)..after all (88138 + 102333) < 190994, it makes sense, right ?
So, probably V8.GCIncrementalMarking is also included into V8.GCFinalizeMC. But it turns out it's not the case - 20508 is much smaller than the amount of GCIncrementalMarkings values (50555).
The final result of this story is the same - execution timeout. Time limit for code equals to 200ms.
Call to LowMemoryNotification IS NOT included to the watchdog monitoring. So 452871 - 190994 = 261877.
And remember, we respect GC activity, so 261877 - 20508 = 241369. Still larger than 200ms.
BUT, if we will start to count all V8.GCIncrementalMarking activities (50555microseconds), the final result will be 241369 - 50555 = 190814. 190ms - not a timeout!
I’m still thinking that V8 (6.7.240) does not provide enough accuracy in terms of GC activity.
解决方案
V8 developer here. If I understand this question correctly, then the answer is: GC prologue/epilogue callbacks are invoked at the beginning/end of a major GC cycle, which consists of (possibly hundreds of) incremental marking steps and a somewhat longer finalization phase in the end, all intermingled with regular program execution. The callbacks are not invoked around every incremental marking step, also not invoked around minor GC cycles ("scavenges", which are curiously missing entirely from your various logs above) and are not intended to provide precise timing information. Sorry.
Ideally, you wouldn't have to do any of this. For most programs, time spent in GC is somewhere between 1% and 10% of overall execution time, so shouldn't matter much.
If you do insist on tracking main-thread time spent on major GCs, then your best bet is probably to turn off incremental marking (flag --noincremental-marking). Note that this will make the user experience choppier (instead of hundreds of sub-1ms pauses you'll get a few second-long pauses), but maybe in your scenario you don't care. I don't have a suggestion for covering minor GCs.
That said, if you allow a more general comment, I have doubts on the overall approach. GC activity is triggered by allocations and can be seen as part of the cost of allocating. If your goal is to treat programs "fairly" (maybe even in a competitive sense?), then I would absolutely include GC time in each program's time budget. GC is not something that "randomly strikes well-behaved code out of the blue" -- having to spend time on GC activity is what happens to code that allocates a lot; if code wants to stay in a certain time budget then it better try to allocate as little as possible, which is just one aspect of being fast/efficient.
Maybe the underlying mental model is one of a very simple memory management strategy, where e.g. many snippets of code can run without any GC activity and allocate a couple of megabytes each, and then one of them is the unlucky straw that breaks the camel's back, crosses some threshold, and runs in a major slowdown that cleans up the garbage that everyone else left behind? In such a VM your approach would make total sense, but this is far from how V8 works.
Also, GC is not the only interruption of the main thread, there is also (the foreground parts of) function optimization, which doesn't have any embedder-controlled callbacks around it. If you wanted to exclude all interruptions, you'd have to hack V8 to create a way to exclude those too. On the other hand, my argument from above applies here too: optimization doesn't happen randomly, it happens to long-running code and is usually beneficial to overall performance (otherwise we wouldn't do it), so I think it would be fair/appropriate to include it in the budget just like GC time.
这篇关于V8垃圾收集器回调，用于测量GC活动的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
查看全文
