1 /**
2 * Copyright (c) 2021-2024 Huawei Device Co., Ltd.
3 * Licensed under the Apache License, Version 2.0 (the "License");
4 * you may not use this file except in compliance with the License.
5 * You may obtain a copy of the License at
6 *
7 * http://www.apache.org/licenses/LICENSE-2.0
8 *
9 * Unless required by applicable law or agreed to in writing, software
10 * distributed under the License is distributed on an "AS IS" BASIS,
11 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 * See the License for the specific language governing permissions and
13 * limitations under the License.
14 */
15
16 #include "libpandabase/utils/time.h"
17 #include "libpandabase/utils/type_converter.h"
18 #include "runtime/include/runtime.h"
19 #include "runtime/include/panda_vm.h"
20 #include "runtime/mem/gc/gc_stats.h"
21 #include "runtime/mem/mem_stats.h"
22
23 namespace ark::mem {
24
GetStatistics()25 PandaString GCStats::GetStatistics()
26 {
27 PandaStringStream statistic;
28 statistic << time::GetCurrentTimeString() << " ";
29
30 statistic << GC_NAMES[ToIndex(gcType_)] << " ";
31 statistic << "freed " << objectsFreed_ << "(" << helpers::MemoryConverter(objectsFreedBytes_) << "), ";
32 statistic << largeObjectsFreed_ << "(" << helpers::MemoryConverter(largeObjectsFreedBytes_) << ") LOS objects, ";
33
34 constexpr uint16_t MAX_PERCENT = 100;
35 size_t totalHeap = mem::MemConfig::GetHeapSizeLimit();
36 ASSERT(totalHeap != 0);
37 size_t allocatedNow = memStats_->GetFootprintHeap();
38 ASSERT(allocatedNow <= totalHeap);
39 uint16_t percent = round((1 - (allocatedNow * 1.0 / totalHeap)) * MAX_PERCENT);
40 statistic << percent << "% free, " << helpers::MemoryConverter(allocatedNow) << "/"
41 << helpers::MemoryConverter(totalHeap) << ", ";
42 bool initialMarkPause = GetPhasePause(PauseTypeStats::INITIAL_MARK_PAUSE) != 0U;
43 bool remarkPause = IsGenerationalGCType(gcType_) && (GetPhasePause(PauseTypeStats::REMARK_PAUSE) != 0U);
44 statistic << GetPhasePauseStat(PauseTypeStats::COMMON_PAUSE)
45 << (initialMarkPause ? GetPhasePauseStat(PauseTypeStats::INITIAL_MARK_PAUSE) : "")
46 << (remarkPause ? GetPhasePauseStat(PauseTypeStats::REMARK_PAUSE) : "")
47 << " total: " << helpers::TimeConverter(lastDuration_);
48 return statistic.str();
49 }
50
GetFinalStatistics(HeapManager * heapManager)51 PandaString GCStats::GetFinalStatistics(HeapManager *heapManager)
52 {
53 auto totalTime = ConvertTimeToPeriod(time::GetCurrentTimeInNanos() - startTime_, true);
54 auto totalTimeGc = helpers::TimeConverter(totalDuration_);
55 auto totalAllocated = memStats_->GetAllocatedHeap();
56 auto totalFreed = memStats_->GetFreedHeap();
57 auto totalObjects = memStats_->GetTotalObjectsAllocated();
58
59 auto currentMemory = memStats_->GetFootprintHeap();
60 auto totalMemory = heapManager->GetTotalMemory();
61 auto maxMemory = heapManager->GetMaxMemory();
62
63 Histogram<uint64_t> durationInfo(allNumberDurations_->begin(), allNumberDurations_->end());
64
65 if (countGcPeriod_ != 0U) {
66 durationInfo.AddValue(countGcPeriod_);
67 }
68 if (totalTime > durationInfo.GetCountDifferent()) {
69 durationInfo.AddValue(0, totalTime - durationInfo.GetCountDifferent());
70 }
71 PandaStringStream statistic;
72
73 statistic << heapManager->GetGC()->DumpStatistics() << "\n";
74
75 statistic << "Total time spent in GC: " << totalTimeGc << "\n";
76
77 statistic << "Mean GC size throughput " << helpers::MemoryConverter(totalAllocated / totalTimeGc.GetDoubleValue())
78 << "/" << totalTimeGc.GetLiteral() << "\n";
79 statistic << "Mean GC object throughput: " << std::scientific << totalObjects / totalTimeGc.GetDoubleValue()
80 << " objects/" << totalTimeGc.GetLiteral() << "\n";
81 statistic << "Total number of allocations " << totalObjects << "\n";
82 statistic << "Total bytes allocated " << helpers::MemoryConverter(totalAllocated) << "\n";
83 statistic << "Total bytes freed " << helpers::MemoryConverter(totalFreed) << "\n\n";
84
85 statistic << "Free memory " << helpers::MemoryConverter(helpers::UnsignedDifference(totalMemory, currentMemory))
86 << "\n";
87 statistic << "Free memory until GC " << helpers::MemoryConverter(heapManager->GetFreeMemory()) << "\n";
88 statistic << "Free memory until OOME "
89 << helpers::MemoryConverter(helpers::UnsignedDifference(maxMemory, currentMemory)) << "\n";
90 statistic << "Total memory " << helpers::MemoryConverter(totalMemory) << "\n";
91
92 {
93 os::memory::LockHolder lock(mutatorStatsLock_);
94 statistic << "Total mutator paused time: " << helpers::TimeConverter(totalMutatorPause_) << "\n";
95 }
96 statistic << "Total time waiting for GC to complete: " << helpers::TimeConverter(totalPause_) << "\n";
97 statistic << "Total GC count: " << durationInfo.GetSum() << "\n";
98 statistic << "Total GC time: " << totalTimeGc << "\n";
99 statistic << "Total blocking GC count: " << durationInfo.GetSum() << "\n";
100 statistic << "Total blocking GC time: " << totalTimeGc << "\n";
101 statistic << "Histogram of GC count per 10000 ms: " << durationInfo.GetTopDump() << "\n";
102 statistic << "Histogram of blocking GC count per 10000 ms: " << durationInfo.GetTopDump() << "\n";
103
104 statistic << "Native bytes registered: " << heapManager->GetGC()->GetNativeBytesRegistered() << "\n\n";
105
106 statistic << "Max memory " << helpers::MemoryConverter(maxMemory) << "\n";
107
108 return statistic.str();
109 }
110
GetPhasePauseStat(PauseTypeStats pauseType)111 PandaString GCStats::GetPhasePauseStat(PauseTypeStats pauseType)
112 {
113 PandaStringStream statistic;
114 statistic << " phase: " << ToString(pauseType)
115 << " paused: " << helpers::TimeConverter(lastPause_[ToIndex(pauseType)]);
116 return statistic.str();
117 }
118
GetPhasePause(PauseTypeStats pauseType)119 uint64_t GCStats::GetPhasePause(PauseTypeStats pauseType)
120 {
121 return lastPause_[ToIndex(pauseType)];
122 }
123
GCStats(MemStatsType * memStats,GCType gcTypeFromRuntime,InternalAllocatorPtr allocator)124 GCStats::GCStats(MemStatsType *memStats, GCType gcTypeFromRuntime, InternalAllocatorPtr allocator)
125 : memStats_(memStats), allocator_(allocator)
126 {
127 startTime_ = time::GetCurrentTimeInNanos();
128 allNumberDurations_ = allocator_->New<PandaVector<uint64_t>>(allocator_->Adapter());
129 gcType_ = gcTypeFromRuntime;
130 }
131
~GCStats()132 GCStats::~GCStats()
133 {
134 gcType_ = GCType::INVALID_GC;
135
136 if (allNumberDurations_ != nullptr) {
137 allocator_->Delete(allNumberDurations_);
138 }
139 allNumberDurations_ = nullptr;
140 }
141
StartMutatorLock()142 void GCStats::StartMutatorLock()
143 {
144 os::memory::LockHolder lock(mutatorStatsLock_);
145 if (countMutator_ == 0) {
146 mutatorStartTime_ = time::GetCurrentTimeInNanos();
147 }
148 ++countMutator_;
149 }
150
StopMutatorLock()151 void GCStats::StopMutatorLock()
152 {
153 os::memory::LockHolder lock(mutatorStatsLock_);
154 if (countMutator_ == 0) {
155 return;
156 }
157 if (countMutator_ == 1) {
158 totalMutatorPause_ += time::GetCurrentTimeInNanos() - mutatorStartTime_;
159 mutatorStartTime_ = 0;
160 }
161 --countMutator_;
162 }
163
StartCollectStats()164 void GCStats::StartCollectStats()
165 {
166 memStats_->ClearLastYoungObjectsMovedBytes();
167 objectsFreed_ = memStats_->GetTotalObjectsFreed();
168 objectsFreedBytes_ = memStats_->GetFootprintHeap();
169 largeObjectsFreed_ = memStats_->GetTotalHumongousObjectsFreed();
170 largeObjectsFreedBytes_ = memStats_->GetFootprint(SpaceType::SPACE_TYPE_HUMONGOUS_OBJECT);
171 }
172
StopCollectStats(GCInstanceStats * instanceStats)173 void GCStats::StopCollectStats(GCInstanceStats *instanceStats)
174 {
175 objectsFreed_ = memStats_->GetTotalObjectsFreed() - objectsFreed_;
176 largeObjectsFreed_ = memStats_->GetTotalHumongousObjectsFreed() - largeObjectsFreed_;
177
178 size_t currentObjectsFreedBytes = memStats_->GetFootprintHeap();
179 size_t currentLargeObjectsFreedBytes = memStats_->GetFootprint(SpaceType::SPACE_TYPE_HUMONGOUS_OBJECT);
180
181 if (objectsFreedBytes_ < currentObjectsFreedBytes) {
182 objectsFreedBytes_ = 0;
183 } else {
184 objectsFreedBytes_ -= currentObjectsFreedBytes;
185 }
186
187 if (largeObjectsFreedBytes_ < currentLargeObjectsFreedBytes) {
188 largeObjectsFreedBytes_ = 0;
189 } else {
190 largeObjectsFreedBytes_ -= currentLargeObjectsFreedBytes;
191 }
192 if ((instanceStats != nullptr) && (objectsFreed_ > 0)) {
193 instanceStats->AddMemoryValue(objectsFreedBytes_, MemoryTypeStats::ALL_FREED_BYTES);
194 instanceStats->AddObjectsValue(objectsFreed_, ObjectTypeStats::ALL_FREED_OBJECTS);
195 }
196 }
197
ConvertTimeToPeriod(uint64_t timeInNanos,bool ceil)198 uint64_t GCStats::ConvertTimeToPeriod(uint64_t timeInNanos, bool ceil)
199 {
200 std::chrono::nanoseconds nanos(timeInNanos);
201 if (ceil) {
202 using ResultDuration = std::chrono::duration<double, PERIOD>;
203 return std::ceil(std::chrono::duration_cast<ResultDuration>(nanos).count());
204 }
205 using ResultDuration = std::chrono::duration<uint64_t, PERIOD>;
206 return std::chrono::duration_cast<ResultDuration>(nanos).count();
207 }
208
AddPause(uint64_t pause,GCInstanceStats * instanceStats,PauseTypeStats pauseType)209 void GCStats::AddPause(uint64_t pause, GCInstanceStats *instanceStats, PauseTypeStats pauseType)
210 {
211 // COMMON_PAUSE can be accounted in different methods but it cannot be interleaved with other pause types
212 ASSERT(prevPauseType_ == PauseTypeStats::COMMON_PAUSE || pauseType != PauseTypeStats::COMMON_PAUSE);
213 if ((instanceStats != nullptr) && (pause > 0)) {
214 instanceStats->AddTimeValue(pause, TimeTypeStats::ALL_PAUSED_TIME);
215 }
216 auto &lastPause = lastPause_[ToIndex(pauseType)];
217 // allow accounting in different methods for COMMON_PAUSE only
218 ASSERT(lastPause == 0 || pauseType == PauseTypeStats::COMMON_PAUSE);
219 lastPause += pause;
220 totalPause_ += pause;
221 #ifndef NDEBUG
222 prevPauseType_ = pauseType;
223 #endif
224 }
225
ResetLastPause()226 void GCStats::ResetLastPause()
227 {
228 for (auto pauseType = PauseTypeStats::COMMON_PAUSE; pauseType != PauseTypeStats::PAUSE_TYPE_STATS_LAST;
229 pauseType = ToPauseTypeStats(ToIndex(pauseType) + 1)) {
230 lastPause_[ToIndex(pauseType)] = 0U;
231 }
232 #ifndef NDEBUG
233 prevPauseType_ = PauseTypeStats::COMMON_PAUSE;
234 #endif
235 }
236
RecordDuration(uint64_t duration,GCInstanceStats * instanceStats)237 void GCStats::RecordDuration(uint64_t duration, GCInstanceStats *instanceStats)
238 {
239 uint64_t startTimeDuration = ConvertTimeToPeriod(time::GetCurrentTimeInNanos() - startTime_ - duration);
240 // every PERIOD
241 if ((countGcPeriod_ != 0U) && (lastStartDuration_ != startTimeDuration)) {
242 allNumberDurations_->push_back(countGcPeriod_);
243 countGcPeriod_ = 0U;
244 }
245 lastStartDuration_ = startTimeDuration;
246 ++countGcPeriod_;
247 if ((instanceStats != nullptr) && (duration > 0)) {
248 instanceStats->AddTimeValue(duration, TimeTypeStats::ALL_TOTAL_TIME);
249 }
250 lastDuration_ = duration;
251 totalDuration_ += duration;
252 }
253
GCScopedStats(GCStats * stats,GCInstanceStats * instanceStats)254 GCScopedStats::GCScopedStats(GCStats *stats, GCInstanceStats *instanceStats)
255 : startTime_(time::GetCurrentTimeInNanos()), instanceStats_(instanceStats), stats_(stats)
256 {
257 stats_->StartCollectStats();
258 }
259
~GCScopedStats()260 GCScopedStats::~GCScopedStats()
261 {
262 stats_->StopCollectStats(instanceStats_);
263 stats_->RecordDuration(time::GetCurrentTimeInNanos() - startTime_, instanceStats_);
264 }
265
GCScopedPauseStats(GCStats * stats,GCInstanceStats * instanceStats,PauseTypeStats pauseType)266 GCScopedPauseStats::GCScopedPauseStats(GCStats *stats, GCInstanceStats *instanceStats, PauseTypeStats pauseType)
267 : startTime_(time::GetCurrentTimeInNanos()), instanceStats_(instanceStats), stats_(stats), pauseType_(pauseType)
268 {
269 }
270
~GCScopedPauseStats()271 GCScopedPauseStats::~GCScopedPauseStats()
272 {
273 stats_->AddPause(time::GetCurrentTimeInNanos() - startTime_, instanceStats_, pauseType_);
274 }
275
GetDump(GCType gcType)276 PandaString GCInstanceStats::GetDump(GCType gcType)
277 {
278 PandaStringStream statistic;
279
280 bool youngSpace = timeStats_[ToIndex(TimeTypeStats::YOUNG_TOTAL_TIME)].GetSum() > 0U;
281 bool allSpace = timeStats_[ToIndex(TimeTypeStats::ALL_TOTAL_TIME)].GetSum() > 0U;
282 bool minorGc = copiedBytes_.GetCount() > 0U;
283 bool wasDeleted = reclaimBytes_.GetCount() > 0U;
284 bool wasMoved = memoryStats_[ToIndex(MemoryTypeStats::MOVED_BYTES)].GetCount() > 0U;
285
286 if (youngSpace) {
287 statistic << GetYoungSpaceDump(gcType);
288 } else if (allSpace) {
289 statistic << GetAllSpacesDump(gcType);
290 }
291
292 if (wasDeleted) {
293 statistic << "Average GC reclaim bytes ratio " << reclaimBytes_.GetAvg() << " over " << reclaimBytes_.GetCount()
294 << " GC cycles \n";
295 }
296
297 if (minorGc) {
298 statistic << "Average minor GC copied live bytes ratio " << copiedBytes_.GetAvg() << " over "
299 << copiedBytes_.GetCount() << " minor GCs \n";
300 }
301
302 if (wasMoved) {
303 statistic << "Cumulative bytes moved "
304 << memoryStats_[ToIndex(MemoryTypeStats::MOVED_BYTES)].GetGeneralStatistic() << "\n";
305 statistic << "Cumulative objects moved "
306 << objectsStats_[ToIndex(ObjectTypeStats::MOVED_OBJECTS)].GetGeneralStatistic() << "\n";
307 }
308
309 return statistic.str();
310 }
311
GetYoungSpaceDump(GCType gcType)312 PandaString GCInstanceStats::GetYoungSpaceDump(GCType gcType)
313 {
314 PandaStringStream statistic;
315 statistic << "young " << GC_NAMES[ToIndex(gcType)]
316 << " paused: " << timeStats_[ToIndex(TimeTypeStats::YOUNG_PAUSED_TIME)].GetGeneralStatistic() << "\n";
317
318 auto &youngTotalTimeHist = timeStats_[ToIndex(TimeTypeStats::YOUNG_TOTAL_TIME)];
319 auto youngTotalTime = helpers::TimeConverter(youngTotalTimeHist.GetSum());
320 auto youngTotalFreedObj = objectsStats_[ToIndex(ObjectTypeStats::YOUNG_FREED_OBJECTS)].GetSum();
321 auto youngTotalFreedBytes = memoryStats_[ToIndex(MemoryTypeStats::YOUNG_FREED_BYTES)].GetSum();
322
323 statistic << "young " << GC_NAMES[ToIndex(gcType)] << " total time: " << youngTotalTime
324 << " mean time: " << helpers::TimeConverter(youngTotalTimeHist.GetAvg()) << "\n";
325 statistic << "young " << GC_NAMES[ToIndex(gcType)] << " freed: " << youngTotalFreedObj << " with total size "
326 << helpers::MemoryConverter(youngTotalFreedBytes) << "\n";
327
328 statistic << "young " << GC_NAMES[ToIndex(gcType)] << " throughput: " << std::scientific
329 << youngTotalFreedObj / youngTotalTime.GetDoubleValue() << "objects/" << youngTotalTime.GetLiteral()
330 << " / " << helpers::MemoryConverter(youngTotalFreedBytes / youngTotalTime.GetDoubleValue()) << "/"
331 << youngTotalTime.GetLiteral() << "\n";
332
333 return statistic.str();
334 }
335
GetAllSpacesDump(GCType gcType)336 PandaString GCInstanceStats::GetAllSpacesDump(GCType gcType)
337 {
338 PandaStringStream statistic;
339
340 statistic << GC_NAMES[ToIndex(gcType)]
341 << " paused: " << timeStats_[ToIndex(TimeTypeStats::ALL_PAUSED_TIME)].GetGeneralStatistic() << "\n";
342
343 auto &totalTimeHist = timeStats_[ToIndex(TimeTypeStats::ALL_TOTAL_TIME)];
344 auto totalTime = helpers::TimeConverter(totalTimeHist.GetSum());
345 auto totalFreedObj = objectsStats_[ToIndex(ObjectTypeStats::ALL_FREED_OBJECTS)].GetSum();
346 auto totalFreedBytes = memoryStats_[ToIndex(MemoryTypeStats::ALL_FREED_BYTES)].GetSum();
347
348 statistic << GC_NAMES[ToIndex(gcType)] << " total time: " << totalTime
349 << " mean time: " << helpers::TimeConverter(totalTimeHist.GetAvg()) << "\n";
350 statistic << GC_NAMES[ToIndex(gcType)] << " freed: " << totalFreedObj << " with total size "
351 << helpers::MemoryConverter(totalFreedBytes) << "\n";
352
353 statistic << GC_NAMES[ToIndex(gcType)] << " throughput: " << std::scientific
354 << totalFreedObj / totalTime.GetDoubleValue() << "objects/" << totalTime.GetLiteral() << " / "
355 << helpers::MemoryConverter(totalFreedBytes / totalTime.GetDoubleValue()) << "/" << totalTime.GetLiteral()
356 << "\n";
357
358 return statistic.str();
359 }
360
361 } // namespace ark::mem
362