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