1 /*
2 * Copyright (C) Freespace Open 2013. All rights reserved.
3 *
4 * All source code herein is the property of Freespace Open. You may not sell
5 * or otherwise commercially exploit the source or things you created based on the
6 * source.
7 *
8 */
9
10 #include "globalincs/pstypes.h"
11 #include "globalincs/systemvars.h"
12 #include "io/timer.h"
13 #include "cmdline/cmdline.h"
14
15 #include <fstream>
16
17 //======================CODE TO PROFILE PERFORMANCE=====================
18
19 /*
20 * Usage information:
21 * In order to gather profiling data for a single function call, you can use the PROFILE macro as defined in
22 * pstypes.h.
23 * Example:
24 * PROFILE("Render", game_render_frame( cid ));
25 *
26 * If you want to profile a block of function calls, you will need to use the profile_begin()/profile_end() calls.
27 * Example:
28 * profile_begin("Some Code");
29 * ...some code...
30 * profile_end("Some Code");
31 * Note that the parameter passed MUST be globally unique across all instances of profiling invocations.
32 *
33 * Profiling invocations can be nested as deep as necessary; this will show up in the readout as indentations.
34 */
35
36 SCP_vector<profile_sample> samples;
37 SCP_vector<profile_sample_history> history;
38
39 float start_profile_time = 0.0f;
40 float end_profile_time = 0.0f;
41
42 char profile_output[2048] = "";
43 std::ofstream profiling_file;
44
45 /**
46 * @brief Called once at engine initialization to set the timer
47 */
profile_init()48 void profile_init()
49 {
50 start_profile_time = f2fl(timer_get_fixed_seconds());
51
52 if (Cmdline_profile_write_file)
53 {
54 profiling_file.open("profiling.csv");
55
56 if (!profiling_file.good())
57 {
58 mprintf(("Failed to open profiling output file 'profiling.csv'!"));
59 }
60 }
61 }
62
profile_deinit()63 void profile_deinit()
64 {
65 if (Cmdline_profile_write_file)
66 {
67 if (profiling_file.is_open())
68 {
69 profiling_file.flush();
70 profiling_file.close();
71 }
72 }
73 }
74
75 /**
76 * Used to start profiling a section of code. A section started by profile_begin needs to be closed off by calling
77 * profile_end with the same argument.
78 * @param name A globally unique string that will be displayed in the HUD readout
79 */
profile_begin(char * name)80 void profile_begin(char* name)
81 {
82 if (Cmdline_frame_profile)
83 {
84 for(int i = 0; i < (int)samples.size(); i++) {
85 if(samples[i].valid && !strcmp(samples[i].name, name) ) {
86 // found the profile sample
87 samples[i].open_profiles++;
88 samples[i].profile_instances++;
89 samples[i].start_time = f2fl(timer_get_fixed_seconds());
90 Assert(samples[i].open_profiles == 1); // max 1 open at once
91 return;
92 }
93 }
94
95 // create a new profile sample
96 profile_sample new_sample;
97
98 strcpy_s(new_sample.name, name);
99 new_sample.valid = true;
100 new_sample.open_profiles = 1;
101 new_sample.profile_instances = 1;
102 new_sample.accumulator = 0.0f;
103 new_sample.start_time = f2fl(timer_get_fixed_seconds());
104 new_sample.children_sample_time = 0.0f;
105
106 samples.push_back(new_sample);
107 }
108 }
109
110 /**
111 * Used to end profiling of a section of code. Note that the parameter given MUST match that of the preceding call
112 * to profile_begin
113 * @param name A globally unique string that will be displayed in the HUD readout
114 */
profile_end(char * name)115 void profile_end(char* name)
116 {
117 if (Cmdline_frame_profile) {
118 int num_parents = 0;
119
120 for(int i = 0; i < (int)samples.size(); i++) {
121 if(samples[i].valid && !strcmp(samples[i].name, name) ) {
122 int inner = 0;
123 int parent = -1;
124 float end_time = f2fl(timer_get_fixed_seconds());
125 samples[i].open_profiles--;
126
127 // count all parents and find the immediate parent
128 while(inner < (int)samples.size() && samples[inner].valid) {
129 if(samples[inner].open_profiles > 0) {
130 // found a parent (any open profiles are parents)
131 num_parents++;
132
133 if(parent < 0) {
134 // replace invalid parent (index)
135 parent = inner;
136 } else if(samples[inner].start_time >= samples[parent].start_time) {
137 // replace with more immediate parent
138 parent = inner;
139 }
140 }
141 inner++;
142 }
143
144 // remember the current number of parents of the sample
145 samples[i].num_parents = num_parents;
146
147 if(parent >= 0) {
148 // record this time in children_sample_time (add it in)
149 samples[parent].children_sample_time += end_time - samples[i].start_time;
150 }
151
152 // save sample time in accumulator
153 samples[i].accumulator += end_time - samples[i].start_time;
154
155 return;
156 }
157 }
158 }
159 }
160
161 /**
162 * Builds the output text.
163 */
profile_dump_output()164 void profile_dump_output()
165 {
166 if (Cmdline_frame_profile) {
167 end_profile_time = f2fl(timer_get_fixed_seconds());
168
169 if (Cmdline_profile_write_file)
170 {
171 profiling_file << end_profile_time << ";" << (end_profile_time - start_profile_time) << std::endl;
172 }
173
174 strcpy_s(profile_output, "");
175 strcat(profile_output, " Avg : Min : Max : # : Profile Name\n");
176 strcat(profile_output, "----------------------------------------\n");
177
178 for(int i = 0; i < (int)samples.size(); i++) {
179 float sample_time, percent_time, avg_time, min_time, max_time;
180 char line[256], name[256], indented_name[256];
181 char avg[16], min[16], max[16], num[16];
182
183 Assert(samples[i].open_profiles == 0);
184
185 sample_time = samples[i].accumulator - samples[i].children_sample_time;
186
187 if (end_profile_time == start_profile_time) {
188 percent_time = 0.0f;
189 } else {
190 percent_time = (sample_time / (end_profile_time - start_profile_time)) *100.0f;
191 }
192
193 avg_time = min_time = max_time = percent_time;
194
195 // add new measurement into the history and get avg, min, and max
196 store_profile_in_history(samples[i].name, percent_time);
197 get_profile_from_history(samples[i].name, &avg_time, &min_time, &max_time);
198 // format the data
199 sprintf(avg, "%3.1f", avg_time);
200 sprintf(min, "%3.1f", min_time);
201 sprintf(max, "%3.1f", max_time);
202 sprintf(num, "%3d", samples[i].profile_instances);
203
204 strcpy(indented_name, samples[i].name);
205 for(uint indent = 0; indent < samples[i].num_parents; indent++) {
206 sprintf(name, " %s", indented_name);
207 strcpy_s(indented_name, name);
208 }
209
210 sprintf(line, "%5s : %5s : %5s : %3s : %s\n", avg, min, max, num, indented_name);
211 strcat(profile_output, line);
212 }
213
214 samples.clear();
215 start_profile_time = f2fl(timer_get_fixed_seconds());
216 }
217 }
218
219 /**
220 * Stores profile data in in the profile history lookup. This is used internally by the profiling code and should
221 * not be called outside of it.
222 * @param name The globally unique name for this profile (see profile_begin()/profile_end())
223 * @param percent How much time the profiled section took to execute (as a percentage of overall frametime)
224 */
store_profile_in_history(char * name,float percent)225 void store_profile_in_history(char* name, float percent)
226 {
227 float old_ratio;
228 float new_ratio = 0.8f * f2fl(Frametime);
229
230 if(new_ratio > 1.0f) {
231 new_ratio = 1.0f;
232 }
233
234 old_ratio = 1.0f - new_ratio;
235
236 for(int i = 0; i < (int)history.size(); i++) {
237 if( history[i].valid && !strcmp(history[i].name, name) ) {
238 // found the sample
239 history[i].avg = (history[i].avg * old_ratio) + (percent * new_ratio);
240
241 if( percent < history[i].min ) {
242 history[i].min = percent;
243 } else {
244 history[i].min = (history[i].min*old_ratio) + (percent*new_ratio);
245 }
246
247 if( percent > history[i].max) {
248 history[i].max = percent;
249 } else {
250 history[i].max = (history[i].max * old_ratio) + (percent * new_ratio);
251 }
252 return;
253 }
254 }
255
256 // add to history
257 profile_sample_history new_history;
258
259 strcpy_s(new_history.name, name);
260 new_history.valid = true;
261 new_history.avg = new_history.min = new_history.max = percent;
262
263 history.push_back(new_history);
264 }
265
266 /**
267 * Gets the min, max and average values for a given profile
268 * @param name The globally unique name for this profile (see profile_begin()/profile_end())
269 * @param avg Pointer to a float in which the average value will be stored (or 0.0 if no value has been saved)
270 * @param min Pointer to a float in which the minimum value will be stored (or 0.0 if no value has been saved)
271 * @param max Pointer to a float in which the maximum value will be stored (or 0.0 if no value has been saved)
272 */
get_profile_from_history(char * name,float * avg,float * min,float * max)273 void get_profile_from_history(char* name, float* avg, float* min, float* max)
274 {
275 for(int i = 0; i < (int)history.size(); i++) {
276 if(!strcmp(history[i].name, name)) {
277 *avg = history[i].avg;
278 *min = history[i].min;
279 *max = history[i].max;
280 return;
281 }
282 }
283 *avg = *min = *max = 0.0f;
284 }