V8垃圾收集器回调,用于测量GC活动
V8 garbage collector callbacks for measuring GC activity
我有一个关于V86.7.240
GC行为和AddGCPrologueCallback
/AddGCEpilogueCallback
回调的小问题。
这个问题背后的一个小故事:我们使用V8引擎启动自定义JS代码,为了限制按时间执行,我们有一个watchdog
(带有isolate->TerminateExecution()
调用的独立线程),它监视代码并在长时间运行时杀死它,但与GC活动有关。
因此,如果代码执行超时等于200ms
,GC活动占用300ms
,代码占用199ms
,我们就可以了(199ms
<200ms
,不包括300ms
)。
另一方面,如果代码执行超时等于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。远远超过40毫秒!,我们能够在应用程序方面进行测量。。
我知道Orinoco和并行方法,但我不知道对GCIncrementalMarking
的调用是否会阻止代码执行。
我们已经多次注意到同样的情况,在所有情况下,代码终止的原因都是与V8日志文件相比,应用程序端的GC测量不正确。
这是故意的吗?我们不能这么信任GC回调?或者我错过了什么?作为一个临时解决方案,我们已经将V8降级为5.6.316
,它在上面运行良好。
6.7.240
有了新的GC方法,这会是问题的根源吗?
PS。--single-threaded-gc
对6.7.240
也没有帮助
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.GCCCompactor(10233)。毕竟(88138+100233)<190994,这是有道理的,对吧?
因此,可能V8.GCIncrementalMarking
也包含在V8.GCFinalizeMC
中。但事实并非如此——20508
远小于GCIncrementalMarking
的值(50555
)。
这个故事的最终结果是相同的——执行超时。代码的时间限制等于200ms
。
对LowMemoryNotification
的调用不包括在watchdog
监控中。所以452871 - 190994 = 261877
。
记住,我们尊重GC活动,所以261877 - 20508 = 241369
。仍大于200ms。
但是,如果我们开始计算所有V8.GCIncrementalMarking
活动(50555
微秒),最终结果将是241369 - 50555 = 190814
。190ms
-不是超时!
我仍然认为V8(6.7.240
)在GC活动方面没有提供足够的准确性。
V8开发人员。如果我正确理解了这个问题,那么答案是:GC序言/尾声回调是在主GC周期的开始/结束时调用的,它由(可能有数百个)增量标记步骤和最后一个更长的完成阶段组成,所有这些都与常规程序执行相混合。回调不会在每个增量标记步骤周围调用,也不会在较小的GC周期("清除",奇怪的是,上面的各种日志中完全没有这些)周围调用,并且不打算提供精确的定时信息。很抱歉
理想情况下,你不必做任何这些。对于大多数程序来说,花在GC上的时间大约是总执行时间的1%到10%,所以应该没什么关系。
如果你坚持跟踪花在主要GC上的主线程时间,那么你最好的选择可能是关闭增量标记(标志--noincremental-marking
)。请注意,这将使用户体验更加断断续续(你会得到几秒钟的长暂停,而不是数百次低于1ms的暂停),但在你的场景中,你可能并不在乎。我没有关于覆盖次要GC的建议。
也就是说,如果你允许更一般性的评论,我对整体方法持怀疑态度。GC活动是由分配触发的,可以看作是分配成本的一部分。如果你的目标是"公平"对待项目(甚至可能是在竞争的意义上?),那么我绝对会在每个项目的时间预算中包括GC时间。GC并不是"突然随机地攻击行为良好的代码"——必须在GC活动上花费时间是分配大量代码的情况;如果代码想保持在一定的时间预算内,那么最好尽量少分配,这只是快速/高效的一个方面。
也许底层的心理模型是一种非常简单的内存管理策略,例如,许多代码片段可以在没有任何GC活动的情况下运行,每个代码片段分配几兆字节,然后其中一个是不幸的稻草,它打破了骆驼的背,跨过了一些阈值,并以大幅度的速度运行,清理了其他人留下的垃圾?在这样的虚拟机中,您的方法完全有意义,但这与V8的工作方式相去甚远。
此外,GC并不是主线程的唯一中断,还有(的前台部分)函数优化,它周围没有任何嵌入程序控制的回调。如果你想排除所有中断,你必须破解V8来创建一种排除这些中断的方法。另一方面,我上面的论点也适用于此:优化不是随机发生的,它发生在长时间运行的代码中,通常有利于整体性能(否则我们不会这么做),所以我认为将其像GC时间一样包含在预算中是公平/合适的。
- 1d 智能指针不适用于语法 (*)++
- 使用C++库在Android项目中修改gradle中的cmake参数,用于插入指令的测试
- 用于访问容器<T>数据成员的正确 API
- 在C++中测量postscript字体宽度
- 重载操作程序时出错>>用于类中的字符串 memebr
- 如何防止 c++ 在从浮点型转换为双精度型(不适用于 IO)时添加额外的小数?
- C++中的cin.ignore()函数不适用于整个流
- 没有用于初始化C++中的变量模板的匹配构造函数
- 用于C++中带有数组和指针的循环
- 为什么它不适用于Visual 2019的原因
- 使用在用于SFINAE的void_t中具有参数的方法
- 在createdialog创建的窗口中捕获用于编辑控件的OnMouseMove消息
- 重载==不适用于二进制树
- 用于测量微秒的QueryPerformanceCounter的奇怪行为
- V8垃圾收集器回调,用于测量GC活动
- 用于测量重载运算符和成员函数的时间的函数
- 测量 l1/l2 缓存中加载的用于读取(包括预取)的行数
- C用于测量带宽的套接字
- 更准确的计时器,用于测量来自 Python 的外部.exe运行时
- 配置 VS2010 用于贪婪投影三角测量