1 /*
2 * Copyright (c) 2023 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 "platform/ohos/rs_jank_stats.h"
17
18 #include <algorithm>
19 #include <chrono>
20 #include <sstream>
21 #include <sys/time.h>
22 #include <unistd.h>
23
24 #include "hisysevent.h"
25 #include "rs_trace.h"
26
27 #include "common/rs_common_def.h"
28 #include "platform/common/rs_log.h"
29
30 namespace OHOS {
31 namespace Rosen {
32 namespace {
33 constexpr float VSYNC_PERIOD = 16.6; // 16.6ms
34 constexpr int64_t TRACE_TIMEOUT = 5000; // 5s
35 constexpr int64_t JANK_TIMEOUT = 10000; // 10s
36 constexpr int64_t S_TO_NS = 1000000000; // s to ns
37 }
38
GetInstance()39 RSJankStats& RSJankStats::GetInstance()
40 {
41 static RSJankStats instance;
42 return instance;
43 }
44
SetStartTime()45 void RSJankStats::SetStartTime()
46 {
47 std::unique_lock<std::mutex> lock(animateJankFramesMutex_);
48 for (auto &[uniqueId, jankFrames] : animateJankFrames_) {
49 jankFrames.isReportEventResponse_ = jankFrames.isSetReportEventResponse_;
50 jankFrames.isSetReportEventResponse_ = false;
51 jankFrames.isReportEventComplete_ = jankFrames.isSetReportEventComplete_;
52 jankFrames.isSetReportEventComplete_ = false;
53 jankFrames.isReportEventJankFrame_ = jankFrames.isSetReportEventJankFrame_;
54 jankFrames.isSetReportEventJankFrame_ = false;
55 }
56 lock.unlock();
57 startTime_ = GetCurrentSystimeMs();
58 if (isfirstSetStart_) {
59 lastReportTime_ = startTime_;
60 isfirstSetStart_ = false;
61 }
62 }
63
SetEndTime()64 void RSJankStats::SetEndTime()
65 {
66 if (startTime_ == 0) {
67 ROSEN_LOGE("RSJankStats::SetEndTime startTime is not initialized");
68 return;
69 }
70 endTime_ = GetCurrentSystimeMs();
71 int64_t duration = endTime_ - startTime_;
72 if (duration >= VSYNC_PERIOD) {
73 SetRSJankStats(static_cast<int32_t>(duration / VSYNC_PERIOD));
74 }
75 std::unique_lock<std::mutex> lock(animateJankFramesMutex_);
76 for (auto &[uniqueId, jankFrames] : animateJankFrames_) {
77 TraceId traceId = static_cast<TraceId>(uniqueId);
78 if (jankFrames.isReportEventResponse_) {
79 ReportEventResponse(jankFrames, traceId);
80 UpdateJankFrame(duration, jankFrames);
81 }
82 if (jankFrames.isReportEventComplete_) {
83 ReportEventComplete(jankFrames, traceId);
84 }
85 if (jankFrames.isReportEventJankFrame_) {
86 ReportEventJankFrame(jankFrames);
87 }
88 }
89 lock.unlock();
90 if (isFirstFrame_) {
91 ReportEventFirstFrame();
92 }
93 if (++traceCheckCnt_ >= TRACE_CHECK_FREQ) {
94 int64_t checkEraseTime = GetCurrentSystimeMs();
95 EraseIf(aSyncTraces_, [checkEraseTime](const auto& pair) -> bool {
96 bool needErase = checkEraseTime - pair.second.createTime_ > TRACE_TIMEOUT;
97 if (needErase) {
98 RS_ASYNC_TRACE_END(pair.second.traceName_, pair.first);
99 }
100 return needErase;
101 });
102 traceCheckCnt_ = 0;
103 }
104 }
105
SetRSJankStats(int32_t times)106 void RSJankStats::SetRSJankStats(int32_t times)
107 {
108 size_t type = JANK_FRAME_INVALID;
109 if (times < 6) { // JANK_FRAME_6_FREQ : (0,6)
110 type = JANK_FRAME_6_FREQ;
111 } else if (times < 15) { // JANK_FRAME_15_FREQ : [6,15)
112 type = JANK_FRAME_15_FREQ;
113 } else if (times < 20) { // JANK_FRAME_20_FREQ : [15,20)
114 type = JANK_FRAME_20_FREQ;
115 } else if (times < 36) { // JANK_FRAME_36_FREQ : [20,36)
116 type = JANK_FRAME_36_FREQ;
117 } else if (times < 48) { // JANK_FRAME_48_FREQ : [36,48)
118 type = JANK_FRAME_48_FREQ;
119 } else if (times < 60) { // JANK_FRAME_60_FREQ : [48,60)
120 type = JANK_FRAME_60_FREQ;
121 } else if (times < 120) { // JANK_FRAME_120_FREQ : [60,120)
122 type = JANK_FRAME_120_FREQ;
123 } else if (times < 180) { // JANK_FRAME_180_FREQ : [120,180)
124 type = JANK_FRAME_180_FREQ;
125 } else {
126 ROSEN_LOGW("RSInterfaces::SetJankStatas Jank Frame Skip more than 180");
127 return;
128 }
129 if (rsJankStats_[type] != USHRT_MAX) {
130 rsJankStats_[type]++;
131 }
132 isNeedReport_ = true;
133 }
134
UpdateJankFrame(int64_t duration,JankFrames & jankFrames)135 void RSJankStats::UpdateJankFrame(int64_t duration, JankFrames& jankFrames)
136 {
137 jankFrames.totalFrames_++;
138 jankFrames.totalFrameTime_ += duration;
139 jankFrames.maxFrameTime_ = std::max(jankFrames.maxFrameTime_, duration);
140 if (duration >= VSYNC_PERIOD) {
141 int32_t missedFramed = static_cast<int32_t>(duration / VSYNC_PERIOD);
142 jankFrames.totalMissedFrames_ += missedFramed;
143 jankFrames.seqMissedFrames_ =
144 jankFrames.seqMissedFrames_ ? (jankFrames.seqMissedFrames_ + missedFramed) : missedFramed;
145 jankFrames.maxSeqMissedFrames_ =
146 std::max(jankFrames.maxSeqMissedFrames_, jankFrames.seqMissedFrames_);
147 } else {
148 jankFrames.seqMissedFrames_ = 0;
149 }
150 }
151
ReportJankStats()152 void RSJankStats::ReportJankStats()
153 {
154 if (!isNeedReport_) {
155 ROSEN_LOGW("RSJankStats::ReportJankStats Nothing need to report");
156 return;
157 }
158 if (lastReportTime_ == 0) {
159 ROSEN_LOGE("RSJankStats::ReportJankStats lastReportTime is not initialized");
160 return;
161 }
162 int64_t reportTime = GetCurrentSystimeMs();
163 int64_t reportDuration = reportTime - lastReportTime_;
164 auto reportName = "JANK_STATS_RS";
165 HiSysEventWrite(OHOS::HiviewDFX::HiSysEvent::Domain::GRAPHIC, reportName,
166 OHOS::HiviewDFX::HiSysEvent::EventType::STATISTIC, "STARTTIME", lastReportTime_, "DURATION", reportDuration,
167 "JANK_STATS", rsJankStats_, "JANK_STATS_VER", 1);
168 std::fill(rsJankStats_.begin(), rsJankStats_.end(), 0);
169 lastReportTime_ = reportTime;
170 isNeedReport_ = false;
171 }
172
SetReportEventResponse(DataBaseRs info)173 void RSJankStats::SetReportEventResponse(DataBaseRs info)
174 {
175 int64_t setTime = GetCurrentSystimeMs();
176 std::unique_lock<std::mutex> lock(animateJankFramesMutex_);
177 EraseIf(animateJankFrames_, [setTime](const auto& pair) -> bool {
178 return setTime - pair.second.setTime_ > JANK_TIMEOUT;
179 });
180 if (animateJankFrames_.find(info.uniqueId) == animateJankFrames_.end()) {
181 JankFrames jankFrames;
182 jankFrames.info_ = info;
183 jankFrames.isSetReportEventResponse_ = true;
184 jankFrames.setTime_ = setTime;
185 animateJankFrames_.emplace(info.uniqueId, jankFrames);
186 } else {
187 animateJankFrames_[info.uniqueId].info_ = info;
188 animateJankFrames_[info.uniqueId].isSetReportEventResponse_ = true;
189 }
190 }
191
SetReportEventComplete(DataBaseRs info)192 void RSJankStats::SetReportEventComplete(DataBaseRs info)
193 {
194 int64_t setTime = GetCurrentSystimeMs();
195 std::unique_lock<std::mutex> lock(animateJankFramesMutex_);
196 if (animateJankFrames_.find(info.uniqueId) == animateJankFrames_.end()) {
197 ROSEN_LOGW("RSJankStats::SetReportEventComplete Not find exited uniqueId");
198 JankFrames jankFrames;
199 jankFrames.info_ = info;
200 jankFrames.isSetReportEventComplete_ = true;
201 jankFrames.setTime_ = setTime;
202 animateJankFrames_.emplace(info.uniqueId, jankFrames);
203 } else {
204 animateJankFrames_[info.uniqueId].info_ = info;
205 animateJankFrames_[info.uniqueId].isSetReportEventComplete_ = true;
206 }
207 }
208
SetReportEventJankFrame(DataBaseRs info)209 void RSJankStats::SetReportEventJankFrame(DataBaseRs info)
210 {
211 std::unique_lock<std::mutex> lock(animateJankFramesMutex_);
212 if (animateJankFrames_.find(info.uniqueId) == animateJankFrames_.end()) {
213 ROSEN_LOGW("RSJankStats::SetReportEventJankFrame Not find exited uniqueId");
214 } else {
215 animateJankFrames_[info.uniqueId].info_ = info;
216 animateJankFrames_[info.uniqueId].isSetReportEventJankFrame_ = true;
217 }
218 }
219
SetFirstFrame()220 void RSJankStats::SetFirstFrame()
221 {
222 isFirstFrame_ = true;
223 }
224
SetPid(pid_t pid)225 void RSJankStats::SetPid(pid_t pid)
226 {
227 appPid_ = pid;
228 }
229
ReportEventResponse(const JankFrames & jankFrames,const TraceId traceId)230 void RSJankStats::ReportEventResponse(const JankFrames& jankFrames, const TraceId traceId)
231 {
232 auto reportName = "INTERACTION_RESPONSE_LATENCY";
233 auto info = jankFrames.info_;
234 int64_t inputTime = ConvertTimeToSystime(info.inputTime);
235 int64_t beginVsyncTime = ConvertTimeToSystime(info.beginVsyncTime);
236 int64_t responseLatency = endTime_ - inputTime;
237 if (aSyncTraces_.find(traceId) == aSyncTraces_.end()) {
238 std::stringstream traceNameStream;
239 traceNameStream << info.sceneId << ", "<< info.bundleName << ", " << info.pageUrl << ", " << inputTime << ".";
240 std::string traceName = traceNameStream.str();
241 TraceStats traceStat;
242 traceStat.traceName_ = traceName;
243 traceStat.createTime_ = GetCurrentSystimeMs();
244 aSyncTraces_[traceId] = traceStat;
245 RS_ASYNC_TRACE_BEGIN(traceName, traceId);
246 }
247 HiSysEventWrite(OHOS::HiviewDFX::HiSysEvent::Domain::GRAPHIC, reportName,
248 OHOS::HiviewDFX::HiSysEvent::EventType::STATISTIC, "APP_PID", info.appPid, "VERSION_CODE", info.versionCode,
249 "VERSION_NAME", info.versionName, "BUNDLE_NAME", info.bundleName, "ABILITY_NAME", info.abilityName,
250 "PROCESS_NAME", info.processName, "PAGE_URL", info.pageUrl, "SCENE_ID", info.sceneId,
251 "SOURCE_TYPE", info.sourceType, "NOTE", info.note, "INPUT_TIME", static_cast<uint64_t>(inputTime),
252 "ANIMATION_START_TIME", static_cast<uint64_t>(beginVsyncTime), "RENDER_TIME", static_cast<uint64_t>(endTime_),
253 "RESPONSE_LATENCY", static_cast<uint64_t>(responseLatency));
254 }
255
ReportEventComplete(const JankFrames & jankFrames,const TraceId traceId)256 void RSJankStats::ReportEventComplete(const JankFrames& jankFrames, const TraceId traceId)
257 {
258 auto reportName = "INTERACTION_COMPLETED_LATENCY";
259 auto info = jankFrames.info_;
260 int64_t inputTime = ConvertTimeToSystime(info.inputTime);
261 int64_t beginVsyncTime = ConvertTimeToSystime(info.beginVsyncTime);
262 int64_t endVsyncTime = ConvertTimeToSystime(info.endVsyncTime);
263 int64_t animationStartLatency = beginVsyncTime - inputTime;
264 int64_t animationEndLatency = endVsyncTime - beginVsyncTime;
265 int64_t completedLatency = endTime_ - inputTime;
266 HiSysEventWrite(OHOS::HiviewDFX::HiSysEvent::Domain::GRAPHIC, reportName,
267 OHOS::HiviewDFX::HiSysEvent::EventType::STATISTIC, "APP_PID", info.appPid, "VERSION_CODE", info.versionCode,
268 "VERSION_NAME", info.versionName, "BUNDLE_NAME", info.bundleName, "ABILITY_NAME", info.abilityName,
269 "PROCESS_NAME", info.processName, "PAGE_URL", info.pageUrl, "SCENE_ID", info.sceneId,
270 "SOURCE_TYPE", info.sourceType, "NOTE", info.note, "INPUT_TIME", static_cast<uint64_t>(inputTime),
271 "ANIMATION_START_LATENCY", static_cast<uint64_t>(animationStartLatency), "ANIMATION_END_LATENCY",
272 static_cast<uint64_t>(animationEndLatency), "E2E_LATENCY", static_cast<uint64_t>(completedLatency));
273 if (aSyncTraces_.find(traceId) != aSyncTraces_.end()) {
274 RS_ASYNC_TRACE_END(aSyncTraces_[traceId].traceName_, traceId);
275 aSyncTraces_.erase(traceId);
276 }
277 }
278
ReportEventJankFrame(const JankFrames & jankFrames) const279 void RSJankStats::ReportEventJankFrame(const JankFrames& jankFrames) const
280 {
281 auto reportName = "INTERACTION_RENDER_JANK";
282 float aveFrameTime = jankFrames.totalFrameTime_ / static_cast<float>(jankFrames.totalFrames_);
283 auto info = jankFrames.info_;
284 HiSysEventWrite(OHOS::HiviewDFX::HiSysEvent::Domain::GRAPHIC, reportName,
285 OHOS::HiviewDFX::HiSysEvent::EventType::STATISTIC, "UNIQUE_ID", info.uniqueId, "SCENE_ID", info.sceneId,
286 "PROCESS_NAME", info.processName, "MODULE_NAME", info.bundleName, "ABILITY_NAME", info.abilityName, "PAGE_URL",
287 info.pageUrl, "TOTAL_FRAMES", jankFrames.totalFrames_, "TOTAL_MISSED_FRAMES", jankFrames.totalMissedFrames_,
288 "MAX_FRAMETIME", static_cast<uint64_t>(jankFrames.maxFrameTime_), "AVERAGE_FRAMETIME", aveFrameTime,
289 "MAX_SEQ_MISSED_FRAMES", jankFrames.maxSeqMissedFrames_, "IS_FOLD_DISP", 0);
290 }
291
ReportEventFirstFrame()292 void RSJankStats::ReportEventFirstFrame()
293 {
294 auto reportName = "FIRST_FRAME_DRAWN";
295 HiSysEventWrite(OHOS::HiviewDFX::HiSysEvent::Domain::GRAPHIC, reportName,
296 OHOS::HiviewDFX::HiSysEvent::EventType::BEHAVIOR, "APP_PID", appPid_);
297 isFirstFrame_ = false;
298 }
299
ConvertTimeToSystime(int64_t time) const300 int64_t RSJankStats::ConvertTimeToSystime(int64_t time) const
301 {
302 if (time == 0) {
303 ROSEN_LOGW("RSJankStats::ConvertTimeToSystime, time is error");
304 return 0;
305 }
306 struct timespec ts = { 0, 0 };
307 if (clock_gettime(CLOCK_MONOTONIC, &ts) != 0) {
308 return 0;
309 }
310 int64_t nowTime = static_cast<int64_t>(ts.tv_sec) * S_TO_NS + static_cast<int64_t>(ts.tv_nsec);
311 int64_t curSysTime = GetCurrentSystimeMs();
312 int64_t sysTime = curSysTime - (nowTime - time) / MS_TO_NS;
313 return sysTime;
314 }
315
GetCurrentSystimeMs() const316 int64_t RSJankStats::GetCurrentSystimeMs() const
317 {
318 auto curTime = std::chrono::system_clock::now().time_since_epoch();
319 int64_t curSysTime = std::chrono::duration_cast<std::chrono::milliseconds>(curTime).count();
320 return curSysTime;
321 }
322
323 } // namespace Rosen
324 } // namespace OHOS
325