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(gc_type_)] << " ";
31 statistic << "freed " << objects_freed_ << "(" << helpers::MemoryConverter(objects_freed_bytes_) << "), ";
32 statistic << large_objects_freed_ << "(" << helpers::MemoryConverter(large_objects_freed_bytes_)
33 << ") LOS objects, ";
34
35 constexpr uint16_t MAX_PERCENT = 100;
36 size_t total_heap = mem::MemConfig::GetHeapSizeLimit();
37 size_t allocated_now = mem_stats_->GetFootprintHeap();
38 ASSERT(allocated_now <= total_heap);
39 uint16_t percent = round((1 - (allocated_now * 1.0 / total_heap)) * MAX_PERCENT);
40 ASSERT(percent <= MAX_PERCENT);
41 statistic << percent << "% free, " << helpers::MemoryConverter(allocated_now) << "/"
42 << helpers::MemoryConverter(total_heap) << ", ";
43 statistic << "paused " << helpers::TimeConverter(last_pause_) << " total "
44 << helpers::TimeConverter(last_duration_);
45
46 return statistic.str();
47 }
48
GetFinalStatistics(HeapManager * heap_manager)49 PandaString GCStats::GetFinalStatistics(HeapManager *heap_manager)
50 {
51 auto total_time = ConvertTimeToPeriod(time::GetCurrentTimeInNanos() - start_time_, true);
52 auto total_time_gc = helpers::TimeConverter(total_duration_);
53 auto total_allocated = mem_stats_->GetAllocatedHeap();
54 auto total_freed = mem_stats_->GetFreedHeap();
55 auto total_objects = mem_stats_->GetTotalObjectsAllocated();
56
57 auto current_memory = mem_stats_->GetFootprintHeap();
58 auto total_memory = heap_manager->GetTotalMemory();
59 auto max_memory = heap_manager->GetMaxMemory();
60
61 Histogram<uint64_t> duration_info(all_number_durations_->begin(), all_number_durations_->end());
62
63 if (count_gc_period_ != 0U) {
64 duration_info.AddValue(count_gc_period_);
65 }
66 if (total_time > duration_info.GetCountDifferent()) {
67 duration_info.AddValue(0, total_time - duration_info.GetCountDifferent());
68 }
69 PandaStringStream statistic;
70
71 // TODO: iteration for all GCs when they become multiple
72 statistic << heap_manager->GetGC()->DumpStatistics() << "\n";
73
74 statistic << "Total time spent in GC: " << total_time_gc << "\n";
75
76 statistic << "Mean GC size throughput "
77 << helpers::MemoryConverter(total_allocated / total_time_gc.GetDoubleValue()) << "/"
78 << total_time_gc.GetLiteral() << "\n";
79 statistic << "Mean GC object throughput: " << std::scientific << total_objects / total_time_gc.GetDoubleValue()
80 << " objects/" << total_time_gc.GetLiteral() << "\n";
81 statistic << "Total number of allocations " << total_objects << "\n";
82 statistic << "Total bytes allocated " << helpers::MemoryConverter(total_allocated) << "\n";
83 statistic << "Total bytes freed " << helpers::MemoryConverter(total_freed) << "\n\n";
84
85 statistic << "Free memory " << helpers::MemoryConverter(helpers::UnsignedDifference(total_memory, current_memory))
86 << "\n";
87 statistic << "Free memory until GC " << helpers::MemoryConverter(heap_manager->GetFreeMemory()) << "\n";
88 statistic << "Free memory until OOME "
89 << helpers::MemoryConverter(helpers::UnsignedDifference(max_memory, total_memory)) << "\n";
90 statistic << "Total memory " << helpers::MemoryConverter(total_memory) << "\n";
91
92 {
93 os::memory::LockHolder lock(mutator_stats_lock_);
94 statistic << "Total mutator paused time: " << helpers::TimeConverter(total_mutator_pause_) << "\n";
95 }
96 statistic << "Total time waiting for GC to complete: " << helpers::TimeConverter(total_pause_) << "\n";
97 statistic << "Total GC count: " << duration_info.GetSum() << "\n";
98 statistic << "Total GC time: " << total_time_gc << "\n";
99 statistic << "Total blocking GC count: " << duration_info.GetSum() << "\n";
100 statistic << "Total blocking GC time: " << total_time_gc << "\n";
101 statistic << "Histogram of GC count per 10000 ms: " << duration_info.GetTopDump() << "\n";
102 statistic << "Histogram of blocking GC count per 10000 ms: " << duration_info.GetTopDump() << "\n";
103
104 // TODO: add "native bytes total" and "native bytes total at last GC" with malloc function
105 statistic << "Native bytes registered: " << heap_manager->GetGC()->GetNativeBytesRegistered() << "\n\n";
106
107 statistic << "Max memory " << helpers::MemoryConverter(max_memory) << "\n";
108
109 return statistic.str();
110 }
111
GCStats(MemStatsType * mem_stats,GCType gc_type_from_runtime,InternalAllocatorPtr allocator)112 GCStats::GCStats(MemStatsType *mem_stats, GCType gc_type_from_runtime, InternalAllocatorPtr allocator)
113 : mem_stats_(mem_stats), allocator_(allocator)
114 {
115 start_time_ = time::GetCurrentTimeInNanos();
116 all_number_durations_ = allocator_->New<PandaVector<uint64_t>>(allocator_->Adapter());
117 gc_type_ = gc_type_from_runtime;
118 }
119
~GCStats()120 GCStats::~GCStats()
121 {
122 gc_type_ = GCType::INVALID_GC;
123
124 if (all_number_durations_ != nullptr) {
125 allocator_->Delete(all_number_durations_);
126 }
127 all_number_durations_ = nullptr;
128 }
129
StartMutatorLock()130 void GCStats::StartMutatorLock()
131 {
132 os::memory::LockHolder lock(mutator_stats_lock_);
133 if (count_mutator_ == 0) {
134 mutator_start_time_ = time::GetCurrentTimeInNanos();
135 }
136 ++count_mutator_;
137 }
138
StopMutatorLock()139 void GCStats::StopMutatorLock()
140 {
141 os::memory::LockHolder lock(mutator_stats_lock_);
142 if (count_mutator_ == 0) {
143 return;
144 }
145 if (count_mutator_ == 1) {
146 total_mutator_pause_ += time::GetCurrentTimeInNanos() - mutator_start_time_;
147 mutator_start_time_ = 0;
148 }
149 --count_mutator_;
150 }
151
StartCollectStats()152 void GCStats::StartCollectStats()
153 {
154 mem_stats_->ClearLastYoungObjectsMovedBytes();
155 objects_freed_ = mem_stats_->GetTotalObjectsFreed();
156 objects_freed_bytes_ = mem_stats_->GetFootprintHeap();
157 large_objects_freed_ = mem_stats_->GetTotalHumongousObjectsFreed();
158 large_objects_freed_bytes_ = mem_stats_->GetFootprint(SpaceType::SPACE_TYPE_HUMONGOUS_OBJECT);
159 }
160
StopCollectStats(GCInstanceStats * instance_stats)161 void GCStats::StopCollectStats(GCInstanceStats *instance_stats)
162 {
163 objects_freed_ = mem_stats_->GetTotalObjectsFreed() - objects_freed_;
164 large_objects_freed_ = mem_stats_->GetTotalHumongousObjectsFreed() - large_objects_freed_;
165
166 size_t current_objects_freed_bytes = mem_stats_->GetFootprintHeap();
167 size_t current_large_objects_freed_bytes = mem_stats_->GetFootprint(SpaceType::SPACE_TYPE_HUMONGOUS_OBJECT);
168
169 if (objects_freed_bytes_ < current_objects_freed_bytes) {
170 objects_freed_bytes_ = 0;
171 } else {
172 objects_freed_bytes_ -= current_objects_freed_bytes;
173 }
174
175 if (large_objects_freed_bytes_ < current_large_objects_freed_bytes) {
176 large_objects_freed_bytes_ = 0;
177 } else {
178 large_objects_freed_bytes_ -= current_large_objects_freed_bytes;
179 }
180 if ((instance_stats != nullptr) && (objects_freed_ > 0)) {
181 instance_stats->AddMemoryValue(objects_freed_bytes_, MemoryTypeStats::ALL_FREED_BYTES);
182 instance_stats->AddObjectsValue(objects_freed_, ObjectTypeStats::ALL_FREED_OBJECTS);
183 }
184 }
185
ConvertTimeToPeriod(uint64_t time_in_nanos,bool ceil)186 uint64_t GCStats::ConvertTimeToPeriod(uint64_t time_in_nanos, bool ceil)
187 {
188 std::chrono::nanoseconds nanos(time_in_nanos);
189 if (ceil) {
190 using RESULT_DURATION = std::chrono::duration<double, PERIOD>;
191 return std::ceil(std::chrono::duration_cast<RESULT_DURATION>(nanos).count());
192 }
193 using RESULT_DURATION = std::chrono::duration<uint64_t, PERIOD>;
194 return std::chrono::duration_cast<RESULT_DURATION>(nanos).count();
195 }
196
RecordPause(uint64_t pause,GCInstanceStats * instance_stats)197 void GCStats::RecordPause(uint64_t pause, GCInstanceStats *instance_stats)
198 {
199 if ((instance_stats != nullptr) && (pause > 0)) {
200 instance_stats->AddTimeValue(pause, TimeTypeStats::ALL_PAUSED_TIME);
201 }
202 last_pause_ = pause;
203 total_pause_ += pause;
204 }
205
RecordDuration(uint64_t duration,GCInstanceStats * instance_stats)206 void GCStats::RecordDuration(uint64_t duration, GCInstanceStats *instance_stats)
207 {
208 uint64_t start_time_duration = ConvertTimeToPeriod(time::GetCurrentTimeInNanos() - start_time_ - duration);
209 // every PERIOD
210 if ((count_gc_period_ != 0U) && (last_start_duration_ != start_time_duration)) {
211 all_number_durations_->push_back(count_gc_period_);
212 count_gc_period_ = 0U;
213 }
214 last_start_duration_ = start_time_duration;
215 ++count_gc_period_;
216 if ((instance_stats != nullptr) && (duration > 0)) {
217 instance_stats->AddTimeValue(duration, TimeTypeStats::ALL_TOTAL_TIME);
218 }
219 last_duration_ = duration;
220 total_duration_ += duration;
221 }
222
GCScopedStats(GCStats * stats,GCInstanceStats * instance_stats)223 GCScopedStats::GCScopedStats(GCStats *stats, GCInstanceStats *instance_stats)
224 : start_time_(time::GetCurrentTimeInNanos()), instance_stats_(instance_stats), stats_(stats)
225 {
226 stats_->StartCollectStats();
227 }
228
~GCScopedStats()229 GCScopedStats::~GCScopedStats()
230 {
231 stats_->StopCollectStats(instance_stats_);
232 stats_->RecordDuration(time::GetCurrentTimeInNanos() - start_time_, instance_stats_);
233 }
234
GCScopedPauseStats(GCStats * stats,GCInstanceStats * instance_stats)235 GCScopedPauseStats::GCScopedPauseStats(GCStats *stats, GCInstanceStats *instance_stats)
236 : start_time_(time::GetCurrentTimeInNanos()), instance_stats_(instance_stats), stats_(stats)
237 {
238 }
239
~GCScopedPauseStats()240 GCScopedPauseStats::~GCScopedPauseStats()
241 {
242 stats_->RecordPause(time::GetCurrentTimeInNanos() - start_time_, instance_stats_);
243 }
244
GetDump(GCType gc_type)245 PandaString GCInstanceStats::GetDump(GCType gc_type)
246 {
247 PandaStringStream statistic;
248
249 bool young_space = time_stats_[ToIndex(TimeTypeStats::YOUNG_TOTAL_TIME)].GetSum() > 0U;
250 bool all_space = time_stats_[ToIndex(TimeTypeStats::ALL_TOTAL_TIME)].GetSum() > 0U;
251 bool minor_gc = copied_bytes_.GetCount() > 0U;
252 bool was_deleted = reclaim_bytes_.GetCount() > 0U;
253 bool was_moved = memory_stats_[ToIndex(MemoryTypeStats::MOVED_BYTES)].GetCount() > 0U;
254
255 if (young_space) {
256 statistic << GetYoungSpaceDump(gc_type);
257 } else if (all_space) {
258 statistic << GetAllSpacesDump(gc_type);
259 }
260
261 if (was_deleted) {
262 statistic << "Average GC reclaim bytes ratio " << reclaim_bytes_.GetAvg() << " over "
263 << reclaim_bytes_.GetCount() << " GC cycles \n";
264 }
265
266 if (minor_gc) {
267 statistic << "Average minor GC copied live bytes ratio " << copied_bytes_.GetAvg() << " over "
268 << copied_bytes_.GetCount() << " minor GCs \n";
269 }
270
271 if (was_moved) {
272 statistic << "Cumulative bytes moved "
273 << memory_stats_[ToIndex(MemoryTypeStats::MOVED_BYTES)].GetGeneralStatistic() << "\n";
274 statistic << "Cumulative objects moved "
275 << objects_stats_[ToIndex(ObjectTypeStats::MOVED_OBJECTS)].GetGeneralStatistic() << "\n";
276 }
277
278 return statistic.str();
279 }
280
GetYoungSpaceDump(GCType gc_type)281 PandaString GCInstanceStats::GetYoungSpaceDump(GCType gc_type)
282 {
283 PandaStringStream statistic;
284 statistic << "young " << GC_NAMES[ToIndex(gc_type)]
285 << " paused: " << time_stats_[ToIndex(TimeTypeStats::YOUNG_PAUSED_TIME)].GetGeneralStatistic() << "\n";
286
287 auto &young_total_time_hist = time_stats_[ToIndex(TimeTypeStats::YOUNG_TOTAL_TIME)];
288 auto young_total_time = helpers::TimeConverter(young_total_time_hist.GetSum());
289 auto young_total_freed_obj = objects_stats_[ToIndex(ObjectTypeStats::YOUNG_FREED_OBJECTS)].GetSum();
290 auto young_total_freed_bytes = memory_stats_[ToIndex(MemoryTypeStats::YOUNG_FREED_BYTES)].GetSum();
291
292 statistic << "young " << GC_NAMES[ToIndex(gc_type)] << " total time: " << young_total_time
293 << " mean time: " << helpers::TimeConverter(young_total_time_hist.GetAvg()) << "\n";
294 statistic << "young " << GC_NAMES[ToIndex(gc_type)] << " freed: " << young_total_freed_obj << " with total size "
295 << helpers::MemoryConverter(young_total_freed_bytes) << "\n";
296
297 statistic << "young " << GC_NAMES[ToIndex(gc_type)] << " throughput: " << std::scientific
298 << young_total_freed_obj / young_total_time.GetDoubleValue() << "objects/"
299 << young_total_time.GetLiteral() << " / "
300 << helpers::MemoryConverter(young_total_freed_bytes / young_total_time.GetDoubleValue()) << "/"
301 << young_total_time.GetLiteral() << "\n";
302
303 return statistic.str();
304 }
305
GetAllSpacesDump(GCType gc_type)306 PandaString GCInstanceStats::GetAllSpacesDump(GCType gc_type)
307 {
308 PandaStringStream statistic;
309
310 statistic << GC_NAMES[ToIndex(gc_type)]
311 << " paused: " << time_stats_[ToIndex(TimeTypeStats::ALL_PAUSED_TIME)].GetGeneralStatistic() << "\n";
312
313 auto &total_time_hist = time_stats_[ToIndex(TimeTypeStats::ALL_TOTAL_TIME)];
314 auto total_time = helpers::TimeConverter(total_time_hist.GetSum());
315 auto total_freed_obj = objects_stats_[ToIndex(ObjectTypeStats::ALL_FREED_OBJECTS)].GetSum();
316 auto total_freed_bytes = memory_stats_[ToIndex(MemoryTypeStats::ALL_FREED_BYTES)].GetSum();
317
318 statistic << GC_NAMES[ToIndex(gc_type)] << " total time: " << total_time
319 << " mean time: " << helpers::TimeConverter(total_time_hist.GetAvg()) << "\n";
320 statistic << GC_NAMES[ToIndex(gc_type)] << " freed: " << total_freed_obj << " with total size "
321 << helpers::MemoryConverter(total_freed_bytes) << "\n";
322
323 statistic << GC_NAMES[ToIndex(gc_type)] << " throughput: " << std::scientific
324 << total_freed_obj / total_time.GetDoubleValue() << "objects/" << total_time.GetLiteral() << " / "
325 << helpers::MemoryConverter(total_freed_bytes / total_time.GetDoubleValue()) << "/"
326 << total_time.GetLiteral() << "\n";
327
328 return statistic.str();
329 }
330
331 } // namespace panda::mem
332