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